Add ability to use systemd journald, rather than log file #82

Closed
wants to merge 34 commits into
from

Projects

None yet

5 participants

@kwirk
Collaborator
kwirk commented Oct 28, 2012

I was interested in having fail2ban working with systemd's journald. I've added code to allow fail2ban to read from journald and also allow to set match filters as per journalctl. As far as I can tell, all/most the regex filters still work.

It required use of a python interface to journald, which I couldn't find anywhere, so I've knocked one up myself. It's python c-api wrap around the systemd journal C API, sd-journal. Code for this is on my github https://github.com/kwirk/pyjournalctl

Initial testing shows all working okay, but if anyone else could do some testing, that would be great.

Any feedback appreciated.

@yarikoptic yarikoptic and 1 other commented on an outdated diff Oct 28, 2012
server/filterjournald.py
+ ##
+ # Get current journal match filter
+ #
+ # @param path log file path
+
+ def getJournalMatch(self):
+ return self.__matches
+
+ ##
+ # Main loop.
+ #
+ # Peridocily check for new journal entries matching the filter and
+ # handover to FailManager
+
+ def run(self):
+ self.setActive(True)
@yarikoptic
yarikoptic Oct 28, 2012 Fail2Ban member

I am not familiar (yet) with systemd at all, but I wonder if in principle it could be possible to avoid pulling -- may be there is a way to "subscribe" to notifications upon new entries?

@kwirk
kwirk Oct 28, 2012 collaborator

I've implemented the sd_journal_wait method, which blocks indefinitely or for a number of microseconds: d6b4c4c

Not sure if its a bug, but currently journald ignores any match filters, and sd_journal_wait returns on any journal write.

@yarikoptic
Member

thanks for the PR...
Ideally it needs a unittest but not sure how to wrap it around
I will try to have a closer look within a couple of days

@wilbowma
wilbowma commented Jan 9, 2013

Any movement on this? I'd love to see journald support in fail2ban.

@yarikoptic yarikoptic and 1 other commented on an outdated diff Jan 9, 2013
config/jail.conf
+# Below are examples for using journald backend
+# Use journalmatch to set filters, as per journalctl
+# Duplicate field names are 'or'ed with each other
+[ssh-journal-iptables]
+
+enabled = false
+filter = sshd
+backend = journald
+action = iptables[name=SSH, port=ssh, protocol=tcp]
+ sendmail-whois[name=SSH, dest=you@example.com, sender=fail2ban@example.com]
+# If using sshd.service
+journalmatch = _SYSTEMD_UNIT=sshd.service
+ PRIORITY=5
+ PRIORITY=6
+# Note if using sshd.socket, above will not work. Use below
+#journalmatch = _COMM=sshd
@yarikoptic
yarikoptic Jan 9, 2013 Fail2Ban member

I wonder

  1. could not journalmatch become a single regexp avoiding need for two different specifications?
    e.g. _(SYSTEMD_UNIT=sshd.service|COMM=sshd) ?
  2. shouldn't journalmatch be actually specified in the correspoding filter.d/ file instead of a jail definition?
@kwirk
kwirk Jan 13, 2013 collaborator

Thanks for the comments:

  1. I agree, although the way that filters can be defined in journalctl does not lend it self to regexp. (see examples: journalctl man page). I can copy the journalctl implementation e.g. _SYSTEMD_UNIT=sshd.service + COMM=sshd
  2. I originally was swapping out logpath which is why I put it here, but I'm indifferent on this to be honest and happy to change it?
@yarikoptic
Member

@bluephoenix47 shame on me -- but I haven't had a chance to even try it yet... have you tried this one and it works fine for you?

@wilbowma
wilbowma commented Jan 9, 2013

I haven't tried it yet. I just ran across when trying to find a way to integrate my postfix log (which is logged via systemd/journald) with fail2ban.

I intend to give it a shot this weekend. I'll report back progress.

@yarikoptic
Member

thanks in advance!

On Wed, 09 Jan 2013, bluephoenix47 wrote:

I haven't tried it yet. I just ran across when trying to find a way to
integrate my postfix log (which is logged via systemd/journald) with
fail2ban.

I intend to give it a shot this weekend. I'll report back progress.

Yaroslav O. Halchenko
Postdoctoral Fellow, Department of Psychological and Brain Sciences
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

@wilbowma

Sorry for the delay; my ISP and I are having some disagreements.

I have not been able to get this forked version to work using either journald, or logpath jails that work under unmodified fail2ban. The server starts up fine and puts the information I'd expect to see in the log, but filters are never triggered.

Here are some logs and stuff:
jail.conf: http://sprunge.us/CgNV
fail2ban.log: http://sprunge.us/APJK
journalctl -u sshd: http://sprunge.us/BXFE
journalctl -u postfix: http://sprunge.us/HiPS

@kwirk
Collaborator
kwirk commented Jan 17, 2013

@bluephoenix47 Thanks for testing.

Could you confirm what version of python and systemd is install.

Could you also try setting the loglevel = 4 in fail2ban.conf

@wilbowma

Name : python2
Version : 2.7.3-3

Name : systemd
Version : 196-2t

fail2ban.log: http://sprunge.us/UhAh

@kwirk kwirk Merge tag '0.8.8' into systemd-journald
Primarily a bugfix release 0.8.8

Conflicts:
	server/jail.py
fe6ade6
@kwirk
Collaborator
kwirk commented Jan 18, 2013

@bluephoenix47 Sorry for the delay. I've tried to decipher the log, but I currently cant work out what the issue is. I've merge 0.8.8 into the branch, just in case its related to where I originally branched from.

I'll look at developing some testcases...

kwirk added some commits Jan 20, 2013
@kwirk kwirk Updated filterjournald for pyjournalctl 0.5.0
Now handles rare case of multiple of the same field in log entry.
Also no longer has issue with GIL on blocking calls
fa388b2
@kwirk kwirk Added tests for journald backend
Due to actually having to use the journal for testing, the test cannot
use the modified TZ and time environment as the other tests do. Therefore
the tests for journald backend run in separate test at end of other
tests (if applicable).
849e5ea
@kwirk
Collaborator
kwirk commented Jan 20, 2013

I've now added some simple tests based off of the current filter tests. The tests work by actually sending message to the journal, so they require the systemd python module for this. It should be include with systemd install, or an additional package from your distro's repository (e.g. in Fedora the package is called systemd-python).

I also found issues with blocking C calls, so I've updated pyjournalctl to release the python GIL. I recommend updating to pyjournalctl 0.5.0 before running tests, as it will likely cause issues without. (Available on github or pypi)

Thanks again for any testing :)

@kwirk kwirk Minor change for journald backend test
This avoids a race condition causing test results to vary
4a5371b
@pedrosland

I tested this today with ssh (manually) and it looks good. Great job @kwirk :). I'll keep running this with debug logging for the next few days and see what happens.

$ python2 --version
Python 2.7.3

$ systemd --version
systemd 197
+PAM -LIBWRAP -AUDIT -SELINUX -IMA -SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ

PS. Looks like travis/github link is stuck. Travis says this passes.

@yarikoptic yarikoptic commented on an outdated diff Jan 25, 2013
server/filterjournald.py
+#
+# You should have received a copy of the GNU General Public License
+# along with Fail2Ban; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+
+# Original author: Cyril Jaquier
+
+__author__ = "Cyril Jaquier, Lee Clemens, Yaroslav Halchenko"
+__copyright__ = "Copyright (c) 2004 Cyril Jaquier, 2011-2012 Lee Clemens, 2012 Yaroslav Halchenko"
+__license__ = "GPL"
+
+from failmanager import FailManagerEmpty
+from filter import Filter
+from mytime import MyTime
+
+import time, logging, datetime, pyjournalctl
@yarikoptic
yarikoptic Jan 25, 2013 Fail2Ban member

it is usually a good habit (if not PEP8 advisory do not remember) to keep standard library imports separate from additional ones (i.e. pyjournalctl here)

@yarikoptic yarikoptic commented on an outdated diff Jan 25, 2013
server/filterjournald.py
+ logMessage))
+ self.__modified = True
+ else:
+ break
+ if self.__modified:
+ try:
+ while True:
+ ticket = self.failManager.toBan()
+ self.jail.putFailTicket(ticket)
+ except FailManagerEmpty:
+ self.failManager.cleanup(MyTime.time())
+ self.dateDetector.sortTemplate()
+ self.__modified = False
+ self.__journalctl.wait(self.getSleepTime())
+ else:
+ self.__journalctl.wait(self.getSleepTime())
@yarikoptic
yarikoptic Jan 25, 2013 Fail2Ban member

so above 3 lines could be replaced with a single .wait at "else" level?

@yarikoptic yarikoptic commented on an outdated diff Jan 25, 2013
server/filterjournald.py
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# Fail2Ban is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with Fail2Ban; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+
+# Original author: Cyril Jaquier
+
+__author__ = "Cyril Jaquier, Lee Clemens, Yaroslav Halchenko"
@yarikoptic
yarikoptic Jan 25, 2013 Fail2Ban member

where is Steven here? ;-)

@yarikoptic
Member

@kwirk it is a shame but we have only a year old systemd on Debian (and you seems to require >=187), thus I can't even build pyjournalctl... I should look into constructing myself some recent Fedora's vagrant box I guess to get at least some testing done

@yarikoptic yarikoptic commented on an outdated diff Jan 25, 2013
config/jail.conf
@@ -306,3 +306,28 @@ action = iptables-allports[name=recidive]
bantime = 604800 ; 1 week
findtime = 86400 ; 1 day
maxretry = 5
+
+# Below are examples for using journald backend
+# Use journalmatch to set filters, as per journalctl
+# Duplicate field names are 'or'ed with each other
+[ssh-journal-iptables]
+
+enabled = false
+filter = sshd
+backend = journald
+action = iptables[name=SSH, port=ssh, protocol=tcp]
+ sendmail-whois[name=SSH, dest=you@example.com, sender=fail2ban@example.com]
+# If using sshd.service
+journalmatch = _SYSTEMD_UNIT=sshd.service + _COMM=sshd
@yarikoptic
yarikoptic Jan 25, 2013 Fail2Ban member

now that they are both in a single entry and no choice is needed -- I still wonder if those shold not become a part of filter definition?
Or do you see them differing much on different distributions/releases so would not be able to cover them all somehow?

@wilbowma

@kwirk I still can't get this working; I've create an AUR package (I presume you might use Arch given you appear to support the python2-pyjournalctl pacakge in the AUR). Since others appear to have this working perhaps I've packaged it incorrectly.

@kwirk
Collaborator
kwirk commented Jan 25, 2013

@bluephoenix47 I've built your package and it seems to work okay on my system. Do all the fail2ban-testcases pass okay?

@kwirk
Collaborator
kwirk commented Jan 25, 2013

@yarikoptic Thanks for the feedback. I agree that journalmatch should be moved to the filter definition as journald/systemd should be (pretty much)standard across distributions. I'll look at making the changes proposed...

@pedrosland

@bluephoenix47 I created this PKGBUILD http://sprunge.us/IWhE. It needs the files from the abs fail2ban. I hacked this PKGBUILD together. I suggest you try using iptables rules instead of ufw. I installed pyjournalctl using pip2 (python2-pip) for my test. Ufw prevented all new ssh connections but it did add the deny rule. I tried your ufw commands and I couldn't get "insert 1" to work. I've never used ufw and perhaps it shows :). I can't reach the AUR from my computer atm to compare our PKGBUILDs.

@wilbowma

@kwirk No, there are a few failures, and the journald tests don't run
(it looks like Arch has only python3 bindings for systemd, according to
an inspection of pacman -Ql systemd).

Results of python2 fail2ban-testcases for fail2ban/fail2ban branch master:
http://sprunge.us/NjfV
Results of python2 fail2ban-testcases for kwirk/fail2ban branch systemd-journald:
http://sprunge.us/YVCY

On Fri, Jan 25, 2013 at 12:47:54PM -0800, Steven Hiscocks wrote:

@bluephoenix47 I've built your package and it seems to work okay on my system. Do all the fail2ban-testcases pass okay?


Reply to this email directly or view it on GitHub:
#82 (comment)

@wilbowma

@pedrosland I've got UFW working fine with the normal fail2ban package
(I've changed the action.d/ufw.conf file recently but it still does ufw
insert 1 etc), but that's a seperate discussion. Even with iptables I
cannot get this to work with journald. The fail2ban jails never trigger,
so it doesn't matter what action they're supposed to take.

Our PKGBUILDs differ in very minimal ways; I also based mine off the ABS
fail2ban and use the ABS fail2ban files. I, however, use @kwirk's AUR
package as a dependency instead of installing it via python2-pip.

On Fri, Jan 25, 2013 at 01:04:05PM -0800, pedrosland wrote:

@bluephoenix47 I created this PKGBUILD http://sprunge.us/IWhE. It needs the files from the abs fail2ban. I hacked this PKGBUILD together. I suggest you try using iptables rules instead of ufw. I installed pyjournalctl using pip2 (python2-pip) for my test. Ufw prevented all new ssh connections but it did add the deny rule. I tried your ufw commands and I couldn't get "insert 1" to work. I've never used ufw and perhaps it shows :). I can't reach the AUR from my computer atm to compare our PKGBUILDs.


Reply to this email directly or view it on GitHub:
#82 (comment)

@kwirk
Collaborator
kwirk commented Jan 25, 2013

@bluephoenix47 That doesn't seem right. Checking the PKGBUILD for systemd, it appears that build config sets python to python2. Maybe try updating or reinstalling systemd.

I'd also try installing python2-systemd straight from AUR.

@pedrosland

For comparison here are my results. I don't have pyinotify so I don't expect that one to pass. I also know that gamin hasn't worked for ages. I haven't looked into why - if it is fail2ban or Arch that has the problem.

@wilbowma

@kwirk You're right; systemd was out of date and there now exists
python2 files.

python2-systemd doesn't seem to exist in the AUR.

My test log now resembles that of @pedrosland:
http://sprunge.us/DOQa

Now jails with a log work, but the journald jails still do not.

On Fri, Jan 25, 2013 at 01:27:21PM -0800, Steven Hiscocks wrote:

@bluephoenix47 That doesn't seem right. Checking the PKGBUILD for systemd, it appears that build config sets python to python2. Maybe try updating or reinstalling systemd.

I'd also try installing python2-systemd straight from AUR.


Reply to this email directly or view it on GitHub:
#82 (comment)

kwirk added some commits Jan 26, 2013
@kwirk kwirk journalmatch now read from filter conf
Also some minor changes
8f668a6
@kwirk kwirk Added generic JournalFilter for path/match checks
This ensures that add/del/getLogPath and add/del/getJournalMatch are
called only FileFilter and JournalFilter respectively
230007c
@kwirk
Collaborator
kwirk commented Jan 26, 2013

I tried this on a fresh install of Fedora, and all the tests, including Gamin, pyinotify and journald pass.Gamin tests also fail on my Arch Linux build and there seems to be a library name difference for pyinotify so these test don't run at all. Not sure if issues with tests failing are related to #103.

On Fedora I did have issues with jail reader trying to add the default log paths to the journal filter. I think this didn't trip on Arch Linux as the default log path /var/log/messages doesn't exist. Commit 230007c has resolved this. This may be the issue you were having @bluephoenix47?

@kwirk kwirk Updated postfix filter to include SASL regex
Also switched journald postfix example in jail to use postfix filter
33ab8aa
@yarikoptic

So it is an interface class, not a dummy ;-)

@yarikoptic

no need to override init since no changes

Collaborator

Not sure what I was thinking there...? Also applies for status...

Member

a possible scenario you might have had: I found such overrides needed when I needed to provide a customization to the __doc__ of the method

@wilbowma

@kwirk I'm begining to suspect this is a problem with the regex. I just tried the following regex (copied and adjusted from sshd.conf) at http://ksamuel.pythonanywhere.com/ against an entry in journald, and didn't get a match until I deleted all the prefix regex stuff. I can't do any more debugging right now, but I'll take a harder look later.

^\s*(?:\S+ )?(?:kernel: \[\d+\.\d+\] )?(?:@vserver_\S+ )?(?:(?:\[\d+\])?:\s+[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?|[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?(?:\[\d+\])?:)?\s*[iI](?:llegal|nvalid) user .* from (?:::f{4,6}:)?(?P<host>[\w\-.^_]+)\s*$

Jan 26 15:58:52 li572-116 sshd[13603]: Invalid user meow from 209.6.232.207

@yarikoptic
Member

FWIW

$> ./fail2ban-regex 'Jan 26 15:58:52 li572-116 sshd[13603]: Invalid user meow from 209.6.232.207' '^\s*(?:\S+ )?(?:kernel: \[\d+\.\d+\] )?(?:@vserver_\S+ )?(?:(?:\[\d+\])?:\s+[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?|[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?(?:\[\d+\])?:)?\s*[iI](?:llegal|nvalid) user .* from (?:::f{4,6}:)?(?P<host>[\w\-.^_]+)\s*$'

Running tests
=============

Use regex line : ^\s*(?:\S+ )?(?:kernel: \[\d+\.\d+\] )?(?:@vserver...
Use single line: Jan 26 15:58:52 li572-116 sshd[13603]: Invalid use...


Results
=======

Failregex: 1 total
|- #) [# of hits] regular expression
|  1) [1] ^\s*(?:\S+ )?(?:kernel: \[\d+\.\d+\] )?(?:@vserver_\S+ )?(?:(?:\[\d+\])?:\s+[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?|[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?(?:\[\d+\])?:)?\s*[iI](?:llegal|nvalid) user .* from (?:::f{4,6}:)?(?P<host>[\w\-.^_]+)\s*$
`-

Ignoreregex: 0 total

Summary
=======

Addresses found:
[1]
    209.6.232.207 (Sat Jan 26 15:58:52 2013)

Date template hits:
2 hit(s): MONTH Day Hour:Minute:Second

Success, the total number of match is 1

However, look at the above section 'Running tests' which could contain important
information.

seems to be all good

On Sat, 26 Jan 2013, William J. Bowman wrote:

@kwirk I'm begining to suspect this is a problem with the regex. I just tried the following at http://ksamuel.pythonanywhere.com/ regex against a lot entry in journald, and didn't get a match. I can't do any more debugging right now, but I'll take a harder look later.

^\s*(?:\S+ )?(?:kernel: \[\d+\.\d+\] )?(?:@vserver_\S+ )?(?:(?:\[\d+\])?:\s+[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?|[\[\(]?sshd(?:\(\S+\))?[\]\)]?:?(?:\[\d+\])?:)?\s*[iI](?:llegal|nvalid) user .* from (?:::f{4,6}:)?(?P<host>[\w\-.^_]+)\s*$

Jan 26 15:58:52 li572-116 sshd[13603]: Invalid user meow from 209.6.232.207

Yaroslav O. Halchenko
Postdoctoral Fellow, Department of Psychological and Brain Sciences
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

@kwirk
Collaborator
kwirk commented Jan 26, 2013

@bluephoenix47 I think what might be tripping up on http://ksamuel.pythonanywhere.com/ is if you've left in the timestamp. Fail2ban removes the timestamp from the line before checking against the regex. If you try your example without the timestamp its all hunky dory.

@wilbowma

Ah what a fool I was. I'll keep looking for what could be the cause of
my issues.

On Sat, Jan 26, 2013 at 01:45:34PM -0800, Steven Hiscocks wrote:

@bluephoenix47 I think what might be tripping up on http://ksamuel.pythonanywhere.com/ is if you've left in the timestamp. Fail2ban removes the timestamp from the line before checking against the regex. If you try your example without the timestamp its all hunky dory.


Reply to this email directly or view it on GitHub:
#82 (comment)

@wilbowma

Well I certainly can't figure this out. I run the test cases with -l debug, but these logs don't mean much to me. When I check journalctl, I do see some lines inserted by the journal tests.

Debug log of testcases: http://sprunge.us/fNIe
Output from testcases: http://sprunge.us/NfBi

By the way, on arch pyinotify is under python2-pyinotify, and those tests seem to work fine.

@kwirk
Collaborator
kwirk commented Jan 29, 2013

@bluephoenix47 It's not apparent what the issues are from the outputs you posted. Might be worth testing with the recent fail2ban-regex changes I've made to check if the regex is matching okay:

python2 fail2ban-regex -m "SYSLOG_IDENTIFIER=fail2ban-testcases" systemd-journal '(?:(?:Authentication failure|Failed [-/\w+]+) for(?: [iI](?:llegal|nvalid) user)?|[Ii](?:llegal|nvalid) user|ROOT LOGIN REFUSED) .*(?: from|FROM) <HOST>'
@kwirk
Collaborator
kwirk commented Feb 2, 2013

The last commit has no functional changes. I wanted to standardise the naming of journal (some places was it was journald).
I also changed the naming of the backend to pyjournalctl as this aligns with naming for other backends, being based on the python module being used. This also would allow other journal based backends, utilising JournalFilter from server.filter, to be added in future.
One issues is that fail2ban-regex journal option is currently reliant of pyjournalctl, as python doesn't have a standard interface like it does with files :)

I think this is pretty much ready. It'd be nice to get more people testing it, as @bluephoenix47 and @pedrosland have had mixed success.
@yarikoptic Did you have chance to try testing on Fedora (FYI watch out for selinux ;) )? Are there any more changes you think are required?

@kwirk
Collaborator
kwirk commented Feb 6, 2013

Just a heads up that you may want to put this pull request on hold for now as systemd devs have shown interest in subsuming pyjournalctl into systemd upstream (see email train http://www.mail-archive.com/systemd-devel@lists.freedesktop.org/msg08387.html)

It should only require minor changes to current pull request (imports and naming) if this goes ahead.

@yarikoptic
Member

That is great news indeed! Thanks for all you work and keeping us up to date.

Steven Hiscocks notifications@github.com wrote:

Just a heads up that you may want to put this pull request on hold for
now as systemd devs have shown interest in subsuming pyjournalctl
into systemd upstream (see email train
http://www.mail-archive.com/systemd-devel@lists.freedesktop.org/msg08387.html)

It should only require minor changes to current pull request (imports
and naming) if this goes ahead.


Reply to this email directly or view it on GitHub:
#82 (comment)

Sent from a phone which beats iPhone.

@pedrosland

That is really good.

Re testing, I restarted fail2ban the other day (still using the same version as before) and it hasn't been working. I'll look into this as soon as I can.

@kwirk
Collaborator
kwirk commented Feb 10, 2013

@pedrosland Thanks 😄. There must be a bug in there somewhere which I'm not replicating on my testing.

Any results of the tests, debug logs and also use of fail2ban-regex would be great.

@pedrosland
$ journalctl _SYSTEMD_UNIT=sshd.service + _COMM=sshd
Feb 10 13:00:23 host1 sshd[25945]: pam_unix(sshd:session): session opened for user test by (uid=0)
Feb 10 13:03:37 host1 sshd[26406]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=xxx.xx.254.4  user=test
Feb 10 13:03:39 host1 sshd[26406]: Failed password for test from xxx.xx.254.4 port 45082 ssh2
Feb 10 13:03:43 host1 sshd[26406]: Failed password for test from xxx.xx.254.4 port 45082 ssh2
Feb 10 13:03:47 host1 sshd[26406]: Failed password for test from xxx.xx.254.4 port 45082 ssh2
Feb 10 13:03:47 host1 sshd[26406]: Connection closed by xxx.xx.254.4 [preauth]
Feb 10 13:03:47 host1 sshd[26406]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=xxx.xx.254.4  user=test
$ fail2ban-client status ssh-journal-iptables
Status for the jail: ssh-journal-iptables
|- filter
|  |- Match list:       _SYSTEMD_UNIT=sshd.service + _COMM=sshd
|  |- Currently failed: 0
|  `- Total failed:     0
`- action
   |- Currently banned: 0
   |  `- IP list:
   `- Total banned:     0

fail2ban.log extract:

2013-02-09 09:38:43,728 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*(?:error: PAM: )?Authentication failure for .* from <HOST>\\s*$']
2013-02-09 09:38:43,735 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*(?:error: PAM: )?User not known to the underlying authentication module for .* from <HOST>\\s*$']
2013-02-09 09:38:43,742 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*Failed (?:password|publickey) for .* from <HOST>(?: port \\d*)?(?: ssh\\d*)?\\s*$']
2013-02-09 09:38:43,750 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*ROOT LOGIN REFUSED.* FROM <HOST>\\s*$']
2013-02-09 09:38:43,757 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*[iI](?:llegal|nvalid) user .* from <HOST>\\s*$']
2013-02-09 09:38:43,765 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*User .+ from <HOST> not allowed because not listed in AllowUsers\\s*$']
2013-02-09 09:38:43,773 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*User .+ from <HOST> not allowed because listed in DenyUsers\\s*$']
2013-02-09 09:38:43,781 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*(?:pam_unix\\(sshd:auth\\):\\s)?authentication failure; logname=\\S* uid=\\S* euid=\\S* tty=\\S* ruser=\\S* rhost=<HOS
T>(?:\\s+user=.*)?\\s*$']
2013-02-09 09:38:43,790 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*refused connect from \\S+ \\(<HOST>\\)\\s*$']
2013-02-09 09:38:43,795 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addfailregex', "^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?ssh
d(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*User .+ from <HOST> not allowed because none of user's groups are listed in AllowGroups\\s*$"]
2013-02-09 09:38:43,805 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'addaction', 'iptables']
2013-02-09 09:38:43,805 fail2ban.actions.action: DEBUG  Created Action
2013-02-09 09:38:43,806 fail2ban.comm   : DEBUG  Command: ['set', 'ssh-journal-iptables', 'actionban', 'iptables', 'iptables -I fail2ban-<name> 1 -s <ip> -j DROP']

...

2013-02-09 09:38:43,836 fail2ban.comm   : DEBUG  Command: ['start', 'ssh-journal-iptables']
2013-02-09 09:38:43,837 fail2ban.actions.action: DEBUG  iptables -N fail2ban-SSH
iptables -A fail2ban-SSH -j RETURN
iptables -I INPUT -p tcp --dport ssh -j fail2ban-SSH
2013-02-09 09:38:43,837 fail2ban.jail   : INFO   Jail 'ssh-journal-iptables' started
2013-02-09 09:38:43,844 fail2ban.comm   : DEBUG  Command: ['start', 'postfix-smtp-iptables']
2013-02-09 09:38:43,845 fail2ban.filter : DEBUG  /var/log/mail.log has been modified
2013-02-09 09:38:43,846 fail2ban.actions.action: DEBUG  iptables -N fail2ban-postfix-smtp
iptables -A fail2ban-postfix-smtp -j RETURN
iptables -I INPUT -p tcp --dport smtp -j fail2ban-postfix-smtp
2013-02-09 09:38:43,846 fail2ban.jail   : INFO   Jail 'postfix-smtp-iptables' started
2013-02-09 09:38:43,907 fail2ban.actions.action: DEBUG  iptables -N fail2ban-SSH
iptables -A fail2ban-SSH -j RETURN
iptables -I INPUT -p tcp --dport ssh -j fail2ban-SSH returned successfully
2013-02-09 09:38:43,967 fail2ban.actions.action: DEBUG  iptables -N fail2ban-postfix-smtp
iptables -A fail2ban-postfix-smtp -j RETURN
iptables -I INPUT -p tcp --dport smtp -j fail2ban-postfix-smtp returned successfully
2013-02-09 09:38:43,979 fail2ban.datetemplate: DEBUG  Correcting deduced year from 2013 to 2012 since 1386359380.000000 > 1360402723.978864
2013-02-09 09:38:44,000 fail2ban.filter : DEBUG  Processing line with time:1354823380.0 and ip:190.129.45.250
2013-02-09 09:38:44,000 fail2ban.filter : DEBUG  Ignore line since time 1354823380.0 < 1360402724.0 - 600
2013-02-09 09:38:44,002 fail2ban.datetemplate: DEBUG  Correcting deduced year from 2013 to 2012 since 1386371569.000000 > 1360402724.002070
2013-02-09 09:38:44,002 fail2ban.filter : DEBUG  Processing line with time:1354835569.0 and ip:121.175.226.188
2013-02-09 09:38:44,002 fail2ban.filter : DEBUG  Ignore line since time 1354835569.0 < 1360402724.0 - 600

...

2013-02-10 12:34:24,213 fail2ban.filter : DEBUG  /var/log/mail.log has been modified
2013-02-10 12:34:24,214 fail2ban.filter.datedetector: DEBUG  Sorting the template list
2013-02-10 13:01:35,192 fail2ban.comm   : DEBUG  Command: ['status']
2013-02-10 13:01:47,735 fail2ban.comm   : DEBUG  Command: ['ssh-journal-iptables', 'status']
2013-02-10 13:01:47,735 fail2ban.comm   : WARNING Command ['ssh-journal-iptables', 'status'] has failed. Received Exception('Invalid command',)
2013-02-10 13:01:50,684 fail2ban.comm   : DEBUG  Command: ['status', 'ssh-journal-iptables']
2013-02-10 13:03:50,791 fail2ban.comm   : DEBUG  Command: ['status', 'ssh-journal-iptables']
2013-02-10 13:08:57,168 fail2ban.comm   : DEBUG  Command: ['ssh-journal-iptables', 'status']
2013-02-10 13:08:57,168 fail2ban.comm   : WARNING Command ['ssh-journal-iptables', 'status'] has failed. Received Exception('Invalid command',)
2013-02-10 13:09:01,385 fail2ban.comm   : DEBUG  Command: ['status', 'ssh-journal-iptables']

There are loads of these fail2ban.datetemplate and fail2ban.filter entries then eventually just .filter ones and ones for postfix. There is nothing at 13:03 when I tried to trigger fail2ban myself. I have a postfix jail working. It reads from file using polling and also uses iptables to ban. If you want me to upload more of the log file, I can. Yes, I do get confused about the status command.

I used the latest version of fail2ban-regex since I saw there were some changes.

$ python2 fail2ban-regex  -m "_SYSTEMD_UNIT=sshd.service + _COMM=sshd" systemd-journal '^\\s*(?:\\S+ )?(?:kernel: \\[\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:)?\\s*Failed (?:password|publickey) for .* from <HOST>(?: port \\d*)?(?: ssh\\d*)?\\s*$'
...
Failregex: 0 total

Ignoreregex: 0 total
...

It looks to me like the regex fails but I have no idea why it was working. When reading back over log files at startup, does it ask journal for something like --since=[now-searchtime] (1360402724.0 - 600 in the log above)?

@pedrosland

Oh, forgot tests.
Running version of fail2ban: http://sprunge.us/Mfha
latest version of fail2ban: http://sprunge.us/jNYd

@kwirk
Collaborator
kwirk commented Feb 10, 2013

@pedrosland Thanks.

When starting the filter, pyjournalctl calls seek_realtime to now - findtime. Maybe this is related... I would still expect the fail2ban-regex to work though.

Do you think you could run the tests with debug python2 fail2ban-testcases -l debug?
I also get complaints about fail2ban-regex. I not sure if the regex is correct for some reason. Could you try python2 fail2ban-regex -m "_SYSTEMD_UNIT=sshd.service + _COMM=sshd" systemd-journal /etc/fail2ban/filter.d/sshd.conf

@pedrosland

Running version: python2 fail2ban-testcases -l debug
http://sprunge.us/Oeha

Latest version: python2 fail2ban-testcases -l debug
This did not complete after more than 10 mins and I killed it.
http://sprunge.us/FjjV

Latest version: python2 fail2ban-regex -m "_SYSTEMD_UNIT=sshd.service + _COMM=sshd" systemd-journal /etc/fail2ban/filter.d/sshd.conf

Failregex: 0 total

Ignoreregex: 0 total

I'm happy to try more commands since I'm not sure how helpful these are going to be.

@kwirk
Collaborator
kwirk commented Feb 10, 2013

Looks like the testcases are getting stuck on Gamin, so that's a red herring.

The fact that fail2ban regex returned nothing is very interesting, as that doesn't even make use of the filter, but does use the formatJournalEntry from the filter. This converts the journal lines into syslog like format.

What version of pyjournalctl are you using?

If you try the following patch on fail2ban-regex, it should print the logs lines its getting from the journal, converted to syslog format, to stderr http://pastie.org/pastes/6110718/text

@pedrosland

I agree with what you say about Gamin. I don't think it has anything to do with pyjournalctl calling seek_realtime. I was just asking out of curiosity since that would make it more efficient especially since people won't use logrotate with journald but I see you've already ticked that box :).

pyjournalctl v0.5.0

fail2ban-regex doesn't report much about journald so the code in that patch is never called. Sorry I led you on the wrong direction. Here is the full output from the fail2ban-regex command above.

Running tests
=============

Use regex file : /etc/fail2ban/filter.d/sshd.conf
Use systemd journal match: _SYSTEMD_UNIT=sshd.service + _COMM=sshd

Results
=======

Failregex: 0 total

Ignoreregex: 0 total

Summary
=======

Sorry, no match

Look at the above section 'Running tests' which could contain important
information.
@kwirk
Collaborator
kwirk commented Feb 10, 2013

@pedrosland the patch should print out every line in the log which matches journal match, i.e. ., so looks like no lines are being passed to the filter. Do you get output from that patch if you use:
python2 fail2ban-regex -m ALL systemd-journal /etc/fail2ban/filter.d/sshd.conf
This should start spitting out every line from the journal.

(FYI I've raised a bug report for gamin and a comment just now looks like the fix is going to be applied, so the gamin tests should be working soon.)

@pedrosland

python2 fail2ban-regex -m ALL systemd-journal /etc/fail2ban/filter.d/sshd.conf gives the same (except ALL for the journal match) for both the version I'm running and the latest version of your journal fail2ban branch. I patched them both.

Thanks for the gamin bug report. I've been meaning to post one for a while but I actually forgot about it until I started using fail2ban with journald.

@kwirk
Collaborator
kwirk commented Feb 10, 2013

@pedrosland Okay. This may be an issue with pyjournalctl. Suggest updating pyjournalctl to latest (0.7). Also, could you try running some of the examples in https://github.com/kwirk/pyjournalctl/blob/0.7.0/README.rst (you can run as doctest python2 -m doctest README.rst. You can ignore the error on line 66). Just to confirm, with the patch that adds the print statement, no log entries are being printed to stderr with -m ALL?

@wilbowma

I'm back to testing again. I've updated to the most recent versions of the systemd-journald branch, and pyjournalctl.

stdout output of python fail2ban-testcases -l debug: http://sprunge.us/VLGO
stderr output: http://sprunge.us/BUCO

Running python2 fail2ban-regex -m "_SYSTEMD_UNIT=sshd.service + _COMM=ssh" systemd-journal /etc/fail2ban/filter.d/sshd.conf doesn't work for me, unless I run as root. However, when I do, I get some weird results regarding dates, and it only prints out failures from before the new year (which is about when I disabled password login and put LIMIT SSH on my firewall).

Log of fail2ban-regex: http://sprunge.us/ZVSJ

Output not captured in log despite redirects:

...
Correcting deduced year from 2013 to 2012 since 1388172574.000000 > 1361053503.470622
Correcting deduced year from 2013 to 2012 since 1388269680.000000 > 1361053503.600362
Correcting deduced year from 2013 to 2012 since 1388270085.000000 > 1361053503.603106
Correcting deduced year from 2013 to 2012 since 1388270458.000000 > 1361053503.605671
Correcting deduced year from 2013 to 2012 since 1388270854.000000 > 1361053503.610548
Correcting deduced year from 2013 to 2012 since 1388271226.000000 > 1361053503.614659
Correcting deduced year from 2013 to 2012 since 1388271625.000000 > 1361053503.618839
Correcting deduced year from 2013 to 2012 since 1388271998.000000 > 1361053503.622994
Correcting deduced year from 2013 to 2012 since 1388272400.000000 > 1361053503.626744
Correcting deduced year from 2013 to 2012 since 1388272776.000000 > 1361053503.629411
Correcting deduced year from 2013 to 2012 since 1388362325.000000 > 1361053503.662569
Correcting deduced year from 2013 to 2012 since 1388363614.000000 > 1361053503.673910
Correcting deduced year from 2013 to 2012 since 1388364332.000000 > 1361053503.727764
Correcting deduced year from 2013 to 2012 since 1388364334.000000 > 1361053503.731663
Correcting deduced year from 2013 to 2012 since 1388364336.000000 > 1361053503.735871
Correcting deduced year from 2013 to 2012 since 1388364338.000000 > 1361053503.740160
Correcting deduced year from 2013 to 2012 since 1388364339.000000 > 1361053503.746078
Correcting deduced year from 2013 to 2012 since 1388468333.000000 > 1361053503.775402
Correcting deduced year from 2013 to 2012 since 1388468333.000000 > 1361053503.779620
Correcting deduced year from 2013 to 2012 since 1388468334.000000 > 1361053503.783125
Correcting deduced year from 2013 to 2012 since 1388468335.000000 > 1361053503.786534
Correcting deduced year from 2013 to 2012 since 1388468336.000000 > 1361053503.790015
...

Snippets from journalctl:

Dec 17 00:46:21 li572-116 sshd[16900]: pam_unix(sshd:auth): authentication failu
re; logname= uid=0 euid=0 tty=ssh ruser= rhost=server-46.45.148.197.as42926.net 
 user=root
Dec 17 00:46:23 li572-116 sshd[16900]: Failed password for root from 46.45.148.1
97 port 54823 ssh2
Dec 17 00:46:23 li572-116 sshd[16900]: Received disconnect from 46.45.148.197: 1
1: Bye Bye [preauth]
Dec 17 00:46:24 li572-116 sshd[16902]: pam_unix(sshd:auth): authentication failu
re; logname= uid=0 euid=0 tty=ssh ruser= rhost=server-46.45.148.197.as42926.net 
 user=root
Dec 17 00:46:27 li572-116 sshd[16902]: Failed password for root from 46.45.148.1
97 port 57797 ssh2
Dec 17 00:46:27 li572-116 sshd[16902]: Received disconnect from 46.45.148.197: 1
1: Bye Bye [preauth]
...
Feb 16 17:20:23 li572-116 sshd[11078]: Invalid user kevin from 209.6.232.207
Feb 16 17:20:23 li572-116 sshd[11078]: input_userauth_request: invalid user kevi
n [preauth]
Feb 16 17:20:23 li572-116 sshd[11078]: Connection closed by 209.6.232.207 [preau
th]
Feb 16 17:20:28 li572-116 sshd[11080]: Invalid user kevin from 209.6.232.207
Feb 16 17:20:28 li572-116 sshd[11080]: input_userauth_request: invalid user kevi
n [preauth]
Feb 16 17:20:28 li572-116 sshd[11080]: Connection closed by 209.6.232.207 [preau
th]
Feb 16 17:20:30 li572-116 sshd[11082]: Invalid user kevin from 209.6.232.207
Feb 16 17:20:30 li572-116 sshd[11082]: input_userauth_request: invalid user kevi
n [preauth]
Feb 16 17:20:30 li572-116 sshd[11082]: Connection closed by 209.6.232.207 [preau
th]
Feb 16 17:20:30 li572-116 sshd[11084]: Invalid user kevin from 209.6.232.207
Feb 16 17:20:30 li572-116 sshd[11084]: input_userauth_request: invalid user kevi
n [preauth]
Feb 16 17:20:30 li572-116 sshd[11084]: Connection closed by 209.6.232.207 [preau
th]
Feb 16 17:20:31 li572-116 sshd[11086]: Invalid user kevin from 209.6.232.207
Feb 16 17:20:31 li572-116 sshd[11086]: input_userauth_request: invalid user kevi
n [preauth]
Feb 16 17:20:31 li572-116 sshd[11086]: Connection closed by 209.6.232.207 [preau
th]

Running `python2 fail2ban-regex -m ALL systemd-journal /etc/fail2ban/filter.d/sshd.conf`` as root results in some sort of encoding error:

Traceback (most recent call last):
  File "fail2ban-regex", line 397, in <module>
    fail2banRegex.testRegex(line)
  File "fail2ban-regex", line 241, in testRegex
    ret = self.__filter.processLine(line)
  File "/tmp/fail2ban/server/filter.py", line 294, in processLine
    l = line.decode('utf-8')
  File "/usr/lib/python2.7/encodings/utf_8.py", line 16, in decode
    return codecs.utf_8_decode(input, errors, True)
UnicodeEncodeError: 'ascii' codec can't encode character u'\u2018' in position 80: ordinal not in range(128)
@wilbowma

Thanks for the gamin bug fix, by the way!

@yarikoptic
Member

On Sat, 16 Feb 2013, William J. Bowman wrote:

Log of fail2ban-regex: [1]http://sprunge.us/ZVSJ

Output not captured in log despite redirects:

...
Correcting deduced year from 2013 to 2012 since 1388172574.000000 > 1361053503.470622

unicode strikes back... not sure why have I made those log messages
unicode strings ...

Traceback (most recent call last):
File "fail2ban-regex", line 397, in
fail2banRegex.testRegex(line)
File "fail2ban-regex", line 241, in testRegex
ret = self.__filter.processLine(line)
File "/tmp/fail2ban/server/filter.py", line 294, in processLine
l = line.decode('utf-8')
File "/usr/lib/python2.7/encodings/utf_8.py", line 16, in decode
return codecs.utf_8_decode(input, errors, True)
UnicodeEncodeError: 'ascii' codec can't encode character u'\u2018' in position 80: ordinal not in range(128)

d'oh -- we are catching UnicodeDecodeError error there, not
UnicodeEncodeError

I think I should watch
http://pyvideo.org/video/948/pragmatic-unicode-or-how-do-i-stop-the-pain
again to get my grasp of this together

Yaroslav O. Halchenko
http://neuro.debian.net http://www.pymvpa.org http://www.fail2ban.org
Postdoctoral Fellow, Department of Psychological and Brain Sciences
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@yarikoptic FilterPyjournalctl is passing unicode to processLine, which is then trying to convert to unicode again. Should it pass plain string to processLine, or should processLine not attempt conversion if line is already unicode?

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@bluephoenix47 Thanks again for testing. In order to access the journal, your must be in the adm group, or root, which may explain the issue. It may also explain why the testcases are failing, as your user running the test cannot access it?

@wilbowma

@kwirk I've run the test as an unprivledged user (i.e. without adm group), with sudo, and as root. The results seem to be the same (at least for the journald tests; gamin tests also fail without sudo or root).

It's interesting that even as an unprivledged user, test entries still appear in journalctl. I suppose root/adm is only needed to read the entries?

@yarikoptic
Member

On Sat, 16 Feb 2013, Steven Hiscocks wrote:

[1]@yarikoptic FilterPyjournalctl is passing unicode to processLine, which
is then trying to convert to unicode again. Should it pass plain string to
processLine, or should processLine not attempt conversion if line is
already unicode?

yeah... I guess, and also change imho confusing comment ;-) ... e.g.

diff --git a/server/filter.py b/server/filter.py
index 992d8dc..9dc0103 100644
--- a/server/filter.py
+++ b/server/filter.py
@@ -290,8 +290,10 @@ class Filter(JailThread):
                """Split the time portion from log msg and return findFailures on them
                """
                try:
-                   # Decode line to UTF-8
-                   l = line.decode('utf-8')
+                 # Line might be already unicode
+                 if isinstance(line, str):
+                         # Decode line from UTF-8
+                         l = line.decode('utf-8')
                except UnicodeDecodeError:
                        l = line
                timeMatch = self.dateDetector.matchTime(l)

BTW -- not sure if we will keep supporting 2.4, but since it seems to be
avoidable (journal-specific, and possibly would not be NA on systems with 2.4)
-- might be worth making it optional/imported late/when needed

Testing using /usr/bin/python2.4
Traceback (most recent call last):
  File "./fail2ban-testcases", line 34, in ?
    from testcases import filtertestcase
  File "/home/yoh/deb/gits/fail2ban/testcases/filtertestcase.py", line 30, in ?
    import uuid
ImportError: No module named uuid

Yaroslav O. Halchenko
http://neuro.debian.net http://www.pymvpa.org http://www.fail2ban.org
Postdoctoral Fellow, Department of Psychological and Brain Sciences
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@bluephoenix47 Your right, anyone can write to the journal, but only root user, or members of adm group can read the journal. It seems strange that the gamin tests also fail as non-root user...

Looking back at the fail2ban-regex log file, it appears that there are lines from 2013 (might of missed them as they are not at the bottom):

    124.160.68.195 (Thu Feb 14 22:30:11 2013)
    124.160.68.195 (Thu Feb 14 22:30:14 2013)
    91.153.195.36 (Fri Feb 15 11:42:16 2013)
    91.153.195.36 (Fri Feb 15 11:42:19 2013)
    42.96.132.217 (Fri Feb 15 11:52:33 2013)
    42.96.132.217 (Fri Feb 15 11:52:40 2013)
    119.60.29.230 (Fri Feb 15 23:32:24 2013)
    209.6.232.207 (Sat Feb 16 17:20:23 2013)
    209.6.232.207 (Sat Feb 16 17:20:28 2013)
    209.6.232.207 (Sat Feb 16 17:20:30 2013)
    209.6.232.207 (Sat Feb 16 17:20:30 2013)
    209.6.232.207 (Sat Feb 16 17:20:31 2013)

It's still not clear to me why the testcases are failing, as there are no errors in the logs...

@wilbowma

@kwirk Oh I did miss those. So the regex clearly isnt to blame.

I'm reading through the code now, trying to get a sense of it and what might cause it to fail. Can you explain this seemingly redundent nested loop?

    def run(self):
        self.setActive(True)
        while self._isActive():
            if not self.getIdle():
                while self._isActive():
...

I also notice in the debug log the tests reports

 2013-02-16 17:49:15,707 140465606760192 jailless filter terminated

However, if I manually add some print statements to the test suite, the getName() method of DummyJail is called properly. Why doesn't FilterPyjournalctl print the dummy jail and instead prints `jailless'?

In fact, if I replace

logSys.debug((self.jail and self.jail.getName() or "jailless") + " filter terminated")

in the main loop with

logSys.debug(self.jail.getName() + " filter terminated")

The dummy filter is printed as expected.

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@bluephoenix47 Thanks for trying more in-depth debugging

The nested loop was a copy from filterpoll.py. This loops without doing anything if the jail is set to be idle, and the second loop keeps trying to process lines until no more are able to read and then breaks. Poll backend does something similar with a while True statement in getFailures, which was what I was basing it off, but couldn't utilise getFailures as it handles files only.

For comparison here is my testcases output: http://sprunge.us/WeSA

I wonder if this is related to #103 , any maybe worth trying to increase isFilled and isEmpty delay argument to a high value (e.g. 60), just to keep sure? Looking at my testcases run, it took around 3 seconds...

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@bluephoenix47 Reference jailless, I believe a jail is created when a match is found, which would explain why it's jailless

EDIT: or maybe not...

@kwirk
Collaborator
kwirk commented Feb 17, 2013

http://docs.python.org/2/library/stdtypes.html?highlight=class#truth-value-testing

instances of user-defined classes, if the class defines a __nonzero__() or __len__() method, when that method returns the integer zero or bool value False. [1]

The jail has a __len__ function, which returns 0 when empty, which means the debug message wrongly assumes there jail doesn't exist.

@wilbowma

Thanks for the feedback. Even with a 60 second wait, the tests fail, so I doubt my issue is related to #103.

Traceback (most recent call last):
  File "/tmp/fail2ban/testcases/filtertestcase.py", line 620, in test_delJournalMatch
    self.assert_correct_ban("193.168.0.128", 3)
  File "/tmp/fail2ban/testcases/filtertestcase.py", line 575, in assert_correct_ban
    self.assertTrue(self.isFilled(60)) # give Filter a chance to react
AssertionError: False is not true

======================================================================
FAIL: MonitorJournalFailures<class 'server.filterpyjournalctl.FilterPyjournalctl'>(monitorjournalfailures-84a09507-7731-4a41-aedc-bfdfa36c7442)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/fail2ban/testcases/filtertestcase.py", line 598, in test_grow_file
    self.assertTrue(self.isFilled(60))
AssertionError: False is not true

----------------------------------------------------------------------
Ran 2 tests in 120.519s

You've run these on an Arch system as well, right? Any thoughts on differences between our setups? I'm not sure what stack of libraries fail2ban + journald requires, or which parts of it would be relevant.

@kwirk
Collaborator
kwirk commented Feb 17, 2013

@bluephoenix47 Thanks again. Yes, I'm on Arch as well. I've also tested on a fresh Fedora in Virtual Box, and all seems well.
I also just run tests on my Arch server, which has a much more minimalistic package setup, and all has passed okay there too.

One common theme is Europe/London timezone, but I'm not sure if that would make a difference...?

@wilbowma

Despite not changing anything, despite tests still failing, inexplicably, the journald feature seems to work in production. I just noticed this in my fail2ban.log

2013-02-18 21:59:01,838 fail2ban.actions: WARNING [nginx-scanners-ufw] Unban 129.10.110.48
2013-02-19 07:43:12,161 fail2ban.actions: WARNING [ssh-journal-ufw] Ban 220.246.27.234
2013-02-19 07:44:12,851 fail2ban.actions: WARNING [ssh-journal-ufw] Unban 220.246.27.234
2013-02-20 04:28:54,531 fail2ban.actions: WARNING [ssh-journal-ufw] Ban 218.104.48.162
2013-02-20 04:29:55,310 fail2ban.actions: WARNING [ssh-journal-ufw] Unban 218.104.48.162
2013-02-20 17:14:06,535 fail2ban.actions: WARNING [ssh-journal-ufw] Ban 96.239.20.163
2013-02-20 17:15:07,059 fail2ban.actions: WARNING [ssh-journal-ufw] Unban 96.239.20.163

Computers are magic.

@kwirk
Collaborator
kwirk commented Mar 9, 2013

This should now work for systemd with systemd version 198 or greater, with the systemd python module installed (for python2).

@pedrosland

I have tried to work out what was wrong with my systemd/logwatch that it stopped after working. I don't know what was up. I re-enabled the SSH service and rebooted the other day and it works again. Same version. I have a feeling that it might be to do with updating systemd while logwatch was running but I've not checked that out. I expect systemd will make its way to core on Arch soon and I can see if it works after upgrading.

@kwirk I'm pleased to see your work on the python journald lib was accepted. Thanks for this logwatch feature too.

@kwirk
Collaborator
kwirk commented Mar 11, 2013

@pedrosland Thanks for the update. Hopefully systemd198 will be available soon. Just a heads up that systemd comes with python3 bindings on Arch Linux now, but I've created a package for the python2 bindings that can be installed alongside 1

@yarikoptic yarikoptic referenced this pull request Mar 15, 2013
Merged

systemd support #142

@sitedyno

To start I used the AUR package here: https://aur.archlinux.org/packages/fail2ban-systemd-journal-git/

I'm not sure why I don't have /var/log/messages, but I had to ln -s /var/log/messages.log /var/log/messages before fail2ban would even start (I didn't find any reference to /var/log/messages in the conf).

I also did mkdir /var/run/fail2ban.

I'm using this fail2ban.service file:

[Unit]
Description=Fail2ban Service
After=network.target

[Service]
Type=forking
ExecStart=/usr/bin/fail2ban-client -x start
ExecStop=/usr/bin/fail2ban-client stop
ExecReload=/usr/bin/fail2ban-client reload
PIDFile=/var/run/fail2ban/fail2ban.pid
Restart=always

[Install]
WantedBy=multi-user.target

So with those 3 things fail2ban will start but I get this on status:

fail2ban.service - Fail2ban Service
          Loaded: loaded (/etc/systemd/system/fail2ban.service; enabled)
          Active: active (running) since Sun 2013-03-24 15:10:38 EDT; 22s ago
         Process: 9542 ExecStop=/usr/bin/fail2ban-client stop (code=exited, status=0/SUCCESS)
         Process: 9603 ExecStart=/usr/bin/fail2ban-client -x start (code=exited, status=0/SUCCESS)
        Main PID: 9606 (fail2ban-server)
          CGroup: name=systemd:/system/fail2ban.service
                  └─9606 /usr/bin/python2 /usr/bin/fail2ban-server -b -s /var/run/fail2ban/fail2ban.sock -x

Mar 24 15:10:37 cb-l fail2ban-client[9603]: WARNING 'action' not defined in 'php-url-fopen'. Using default value
Mar 24 15:10:38 cb-l fail2ban-client[9603]: WARNING 'action' not defined in 'lighttpd-fastcgi'. Using default value
Mar 24 15:10:38 cb-l fail2ban-client[9603]: WARNING 'action' not defined in 'lighttpd-auth'. Using default value
Mar 24 15:10:38 cb-l fail2ban-client[9603]: WARNING 'logpath' not defined in 'ssh-journal-iptables'. Using default value
Mar 24 15:10:38 cb-l fail2ban-client[9603]: WARNING 'logpath' not defined in 'postfix-journal-iptables'. Using default value
Mar 24 15:10:38 cb-l fail2ban-client[9603]: 2013-03-24 15:10:38,141 fail2ban.server : INFO   Starting Fail2ban v0.8.8
Mar 24 15:10:38 cb-l fail2ban-client[9603]: 2013-03-24 15:10:38,142 fail2ban.server : INFO   Starting in daemon mode
Mar 24 15:10:38 cb-l fail2ban-client[9603]: Failed to initialize any backend for Jail 'ssh-journal-iptables'
Mar 24 15:10:38 cb-l systemd[1]: Started Fail2ban Service.

I have no clue as to why the backend isn't initializing. I will try to poke a bit but I'm not that familiar with fail2ban or python in general, so don't expect much from me :p

@kwirk
Collaborator
kwirk commented Mar 24, 2013

@sitedyno Thanks for giving this a go.

The file /var/log/messages is the default log file fail2ban will try to load if a log file isn't present. This is set in the software, so that'll explain why you couldn't find it in the config.
It looks like no backend is starting for your jail. Note that the standard systemd package on Arch Linux only has the python3 bindings, so you'll need to install: https://aur.archlinux.org/packages/python2-systemd/
This package just installed the python2 bindings along side the current systemd ones.
This should stop the jail trying to fall back to a file based jail and hunting around for the /var/log/messages file which doesn't exist.

Any feedback you can provide is greatly appreciated.

@sitedyno

Ok installed the python2 bindings and it initializes the journal backend, but fail2ban would not trigger. After rebooting fail2ban will trigger, but then stops triggering after a restart of fail2ban (no configuration changes).

@kwirk
Collaborator
kwirk commented Mar 24, 2013

Thanks @sitedyno. Could you try running the testcases. If you've built with AUR, you should just find them in the src directory. Can be run with python2 ./fail2ban-testcases.
Also, is there anything in the fail2ban log file (default: /var/log/fail2ban.log) running with DEBUG loglevel (setting loglevel = 4 in /etc/fail2ban/fail2ban.conf)

@sitedyno
$ python2 ./fail2ban-testcases
Fail2ban 0.8.8 test suite. Python 2.7.3 (default, Dec 22 2012, 21:27:36) [GCC 4.7.2]. Please wait...
I: Skipping pyinotify backend testing. Got exception 'No module named pyinotify'
...........E.............................
======================================================================
ERROR: testIgnoreIPNOK (testcases.filtertestcase.IgnoreIP)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/testcases/filtertestcase.py", line 182, in testIgnoreIPNOK
    self.assertFalse(self.filter.inIgnoreIPList(ip))
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/server/filter.py", line 279, in inIgnoreIPList
    ips = DNSUtils.dnsToIp(i)
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/server/filter.py", line 611, in dnsToIp
    return socket.gethostbyname_ex(dns)[2]
error: [Errno 11] Resource temporarily unavailable

----------------------------------------------------------------------
Ran 41 tests in 58.751s

FAILED (errors=1)
Please wait...
FF
======================================================================
FAIL: MonitorJournalFailures<class 'server.filtersystemd.FilterSystemd'>(monitorjournalfailures-8661e961-1c0a-4999-b209-186c56038459)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/testcases/filtertestcase.py", line 620, in test_delJournalMatch
    self.assert_correct_ban("193.168.0.128", 3)
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/testcases/filtertestcase.py", line 575, in assert_correct_ban
    self.assertTrue(self.isFilled(10)) # give Filter a chance to react
AssertionError: False is not true

======================================================================
FAIL: MonitorJournalFailures<class 'server.filtersystemd.FilterSystemd'>(monitorjournalfailures-2c591187-058b-4e4c-a00a-2dc73f0d2f19)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/yaourt-tmp-candybar/aur-fail2ban-systemd-journal-git/src/fail2ban/testcases/filtertestcase.py", line 598, in test_grow_file
    self.assertTrue(self.isFilled(6))
AssertionError: False is not true

----------------------------------------------------------------------
Ran 2 tests in 16.817s

FAILED (failures=2)

fail2ban.log: http://sprunge.us/LCEW
journalctl log: http://sprunge.us/XEPQ

@kwirk
Collaborator
kwirk commented Mar 24, 2013

@sitedyno Thanks again. I still can't quite work out why it just seems to work on my systems, and having so much trouble elsewhere. It seems that system journal converts the datetime to the local timezone, which is making suspect this maybe the issue, as my systems are all conveniently at europe/london timezone, i.e. currently UTC

@sitedyno

@kwirk This definitely seems to be the case: https://gist.github.com/sitedyno/5233759

@kwirk
Collaborator
kwirk commented Mar 24, 2013

Thanks @sitedyno. I still can't work out why it worked initialy, but then didn't when you restarted. I've added a commit that will now log what log lines are being generated from the journal when in log level debug. I'm hoping it will be apparent that the times look wrong when you run it 😄

@sitedyno

The time where I rebooted and it worked, my bios clock was set to local
time and apparently it worked before ntp fired up and fixed the time. After
fixing the bios time to be utc it never works on boot. Apologies for any
miscommunication.

On Sun, Mar 24, 2013 at 6:40 PM, Steven Hiscocks
notifications@github.comwrote:

Thanks @sitedyno https://github.com/sitedyno. I still can't work out
why it worked initialy, but then didn't when you restarted. I've added a
commit that will now log what log lines are being generated from the
journal when in log level debug. I'm hoping it will be apparent that the
times look wrong when you run it [image: 😄]


Reply to this email directly or view it on GitHubhttps://github.com/fail2ban/fail2ban/pull/82#issuecomment-15371166
.

@kwirk
Collaborator
kwirk commented Mar 24, 2013

@sitedyno Thanks for the update. Looks like the time is the issue then. 😄

@kwirk
Collaborator
kwirk commented Mar 24, 2013

I think some issues were be caused by attempting to seek to the right place in the journal to begin reading. Last commit should fix that by removing utcnow, so hopefully testcases should pass in local timezone. I'm hoping this should fix it overall, as I currently believe the times are being read from the journal correctly.

When I have some time, I'll look at setting up a test VM with a different timezones to make sure. If anyone else gets a chance to test that would be great.

@kwirk
Collaborator
kwirk commented Mar 24, 2013

Looks like the start time seeking was quite broken. It seems that when seeking to a time in the journal which is beyond the end (which can easily happen when TZ is negative hours relative to UTC (fixed in 52cac45)), you are unable to read any subsequent entries until it has caught up. This shouldn't generally be an issue, but just in case I've added a seek one entry backwards, such that the if you do go beyond the end of the journal, you just jump back to the last entry.

@sitedyno

Working for me now :)

Offtopic: If I unban from iptables and restart fail2ban, it will reinstate the ban. Does fail2ban keep state data somewhere?

@kwirk
Collaborator
kwirk commented Mar 27, 2013

@bluephoenix47 @pedrosland If you have time, it would be great if you could give this another go, as hopefully the timezone fix has resolved everything.

@sitedyno Thanks for your assistance. Reference off-topic, fail2ban does not store state data, but when you restart, it reads the log files again, and if it picks up enough failures within the find time it will ban again.

@wilbowma

I'll happily give it a go sometime next week; big deadline Friday at 6am
so I'm doing nothing until then... and nothing for the first couple days
after that :)

William Bowman

On Wed, Mar 27, 2013 at 02:25:29PM -0700, Steven Hiscocks wrote:

@bluephoenix47 @pedrosland If you have time, it would be great if you could give this another go, as hopefully the timezone fix has resolved everything.

@sitedyno Thanks for your assistance. Reference off-topic, fail2ban does not store state data, but when you restart, it reads the log files again, and if it picks up enough failures within the find time it will ban again.


Reply to this email directly or view it on GitHub:
#82 (comment)

@pedrosland

I've been using the same version that worked and then stopped working all this time and it is working well.

Try 1: I've updated to this new version. I attempted to break in with ssh from another machine and I was not banned. The startup section of the log has 100s of lines of noise.

Try 2: I have now disabled my other ban rules to make the logs clearer. When I restarted fail2ban after checking config and renaming "[ssh-systemd-iptables]" back to "[ssh-journal-iptables]" it detected the previous attempts and has banned the IP. There were no lines starting up like Try 3. I had bantime way too long to wait for it to expire and try to ban myself again.

I ran the fail2ban-testcases and here is the result http://sprunge.us/Vebh.

Try 3: I shortened findtime and bantime to 60. I restarted again and the log has several sets of lines from startup like my first try:

2013-03-28 10:56:50,671 fail2ban.filter : DEBUG  Read systemd journal entry: u'Mar 28 10:36:56 HOST sshd[20225]: Failed password for user from IP port 34097 ssh2\n'
2013-03-28 10:56:50,671 fail2ban.filter : DEBUG  Processing line with time:1364467016.0 and ip:IP
2013-03-28 10:56:50,671 fail2ban.filter : DEBUG  Ignore line since time 1364467016.0 < 1364468210.67 - 60

I wouldn't have expected lines like this since I think it only seeks back findtime and it wasn't findtime - 1 line since there were several of these and I only have this one rule enabled. Some of them included the IP of the machine I was trying from so they were certainly not from the test.

Try 3 and a few more tries correctly detected a failed attempt and banned me.

I haven't changed my timezone on this machine while I've been trying your fail2ban fork and I use Europe/London.

systemctl --version
systemd 198

Conclusion: I have no idea what is going on!

Let me know what I can do to help.

@kwirk kwirk BF: Initial systemd-journal seek now called with correct find time
This bug was caused by the seek in the journal as part of filter init,
were the find time was still the default. This is now called when the
filter is run, such that the find time should be set correctly.
62bab70
@kwirk
Collaborator
kwirk commented Mar 28, 2013

@pedrosland Thanks for your help.

The find time default search was being used (6000 seconds), which is why it was picking up log lines early that the value you had set. Commit 62bab70 should fix this, as seek is now done when jail is started.

Just wanted to double check with the fail2ban-testcases: with systemd>=198, you now must be in group systemd-journal in order to read the journal. Previously it had been adm group. Easiest way to check is execute journalctl and it will print a warning to STDERR if your not a member of the correct group.

Not clear what happened in try 1, but you seem to say that in try 2 and try3 that it was functioning as expected.

@pedrosland

I'll git pull, rebuild and test when I have more time.

I wasn't in the group and journalctl gave me an error. I added myself to the systemd-journal group and reran the tests with the version I have. Now only testIgnoreIPNOK fails which is great.

@kwirk
Collaborator
kwirk commented Apr 6, 2013

Just a heads up to anyone testing with systemd 199/200. I've noticed a bug in the systemd python interface which causes wait function to be too short1, and gets fail2ban maxing at 100% CPU. For those using AUR python2-systemd package2, I've put on an unoffical patch to resolve the issue.

@kwirk
Collaborator
kwirk commented Apr 12, 2013

Currently this is broken in systemd 199-201 due to the wait issue mentioned earlier and some changes meaning the expected timestamps for the log messages aren't returned. These all appear to be bugs and unintended consequences of some changes make the python backend interface align with the backend C API.

I've posted on the systemd mailing list with suggested changes. I'm hoping from systemd 202+ that the python system interface will have stabilised such that this pull request can be finalised.

TODO: Add minimum version specification for systemd-journal in README

@wilbowma

@kirwk, I just ran the tests and almost everything passed! The one that failed looks unrelated to the systemd/journald, and has been failing since I started testing.

http://sprunge.us/bGfF

@kwirk
Collaborator
kwirk commented Apr 23, 2013

@bluephoenix47 Thanks very much for testing. I believe the error you are still having should be fixed in the 0.9 branch as well now.

I've just sent a patch to systemd devel mailing list to add a version number to the systemd. Hopefully, if this is accepted, it will make it easier to ensure that a correct version is installed (similar to pyinotify backend). Can then declare this is compatible from version 203+ (although it will work with 198, 202, or patched versions of the 199-201, but there's no way to check the version number, or patches have been applied 😦 ).

I was also thinking the journalmatch option can be added to the new [Init] section which you can define in filter configs. (see #180)?

@yarikoptic Once this is done, I'm guessing it would be best to merge 0.9 into the branch, and then "squash" the commits into a single commit to merge? Should make it a lot cleaner 😁

@kwirk kwirk referenced this pull request May 10, 2013
Merged

systemd journal backend #224

@kwirk
Collaborator
kwirk commented May 10, 2013

Please see #224 which has squashed these commits for merge into 0.9 branch.

@kwirk kwirk closed this May 10, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment