From a98cc08b31b41e9d344e26c6eb0d63d54b5f1242 Mon Sep 17 00:00:00 2001 From: Daniel Brooks Date: Sat, 10 Jul 2021 21:34:46 -0700 Subject: [PATCH 01/17] Updated the warning messages created when fail2ban sees unexpected timestamps to improve their grammar and to remove jargon. Partially fixes #2822 --- fail2ban/server/filter.py | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index e9000447..f9ea9025 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -662,9 +662,10 @@ class Filter(JailThread): if (date is None or date < MyTime.time() - 60 or date > MyTime.time() + 60): # log time zone issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", - ("Simulate NOW in operation since found time has too large deviation %s ~ %s +/- %s", - date, MyTime.time(), 60), - ("Please check jail has possibly a timezone issue. Line with odd timestamp: %s", + ("Found at least one log entry with a timestamp more" + + " than a minute from the current time. This is rarely a problem."), + ("Please check this jail and associated logs as" + + " there is potentially a timezone or latency problem: %s", line)) # simulate now as date: date = MyTime.time() @@ -674,9 +675,11 @@ class Filter(JailThread): if date is not None and date < MyTime.time() - self.getFindTime(): # log time zone issue as warning once per day: self._logWarnOnce("_next_ignByTimeWarn", - ("Ignore line since time %s < %s - %s", - date, MyTime.time(), self.getFindTime()), - ("Please check jail has possibly a timezone issue. Line with odd timestamp: %s", + ("Ignoring all log entries older than %s; these are probably" + + " messages generated while fail2ban was not running.", + self.getFindTime()), + ("Please check this jail and associated logs as" + + " there is potentially a timezone or latency problem: %s", line)) # ignore - too old (obsolete) entry: return [] From 320a3dcdd5a8b3019df3dfb21022dd4d80851f38 Mon Sep 17 00:00:00 2001 From: Daniel Brooks Date: Sat, 10 Jul 2021 21:48:32 -0700 Subject: [PATCH 02/17] remove old warnings from filtertestcase.py MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit assertLogged only checks that at least one listed message is found, so it isn’t necessary to repeat them in the test. --- fail2ban/tests/filtertestcase.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 5166bc43..9e81006b 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -457,8 +457,6 @@ class IgnoreIP(LogCaptureTestCase): for i in (1,2,3): self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); # +3 = 3 self.assertLogged( - "Simulate NOW in operation since found time has too large deviation", - "Please check jail has possibly a timezone issue.", "192.0.2.15:1", "192.0.2.15:2", "192.0.2.15:3", "Total # of detected failures: 3.", wait=True) # From 1929e7a76b03becbece228edd8c65204a7e83371 Mon Sep 17 00:00:00 2001 From: Daniel Brooks Date: Mon, 12 Jul 2021 09:21:00 -0700 Subject: [PATCH 03/17] include more specific information in the warning --- fail2ban/server/filter.py | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index f9ea9025..e327228e 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -659,14 +659,19 @@ class Filter(JailThread): # if in operation (modifications have been really found): if self.inOperation: # if weird date - we'd simulate now for timeing issue (too large deviation from now): - if (date is None or date < MyTime.time() - 60 or date > MyTime.time() + 60): + delta = date - MyTime.time() + if (date is None or abs(delta) > 60): + latency = "This could indicate a latency problem." + timezone = "This looks like a timezone problem." # log time zone issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", - ("Found at least one log entry with a timestamp more" + - " than a minute from the current time. This is rarely a problem."), - ("Please check this jail and associated logs as" + - " there is potentially a timezone or latency problem: %s", - line)) + ("Found a log entry with a timestamp %ss %s the current time. %s", + abs(delta), + "before" if delta <= 0 else "after", + latency if -15*60 <= delta <= 0 else timezone), + ("Please check this jail and associated logs as there" + + " is potentially a timezone or latency problem: %s", + line)) # simulate now as date: date = MyTime.time() self.__lastDate = date From d7afcde2e10fa61bb4adb6604862074461e19f16 Mon Sep 17 00:00:00 2001 From: Daniel Brooks Date: Mon, 12 Jul 2021 17:09:58 -0700 Subject: [PATCH 04/17] add a warning message for dates in the future and a test that checks which message was output for which time deltas. --- fail2ban/server/filter.py | 11 ++++++++++- fail2ban/tests/filtertestcase.py | 30 ++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+), 1 deletion(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index e327228e..16e7d2a6 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -662,13 +662,22 @@ class Filter(JailThread): delta = date - MyTime.time() if (date is None or abs(delta) > 60): latency = "This could indicate a latency problem." + synchronization = "This could be a clock synchronization" + \ + " problem; are you sure that NTP is set up?" timezone = "This looks like a timezone problem." + msg = "" + if -15*60 <= delta <= 0: + msg = latency + elif 0 < delta <= 15*60: + msg = synchronization + else: + msg = timezone # log time zone issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", ("Found a log entry with a timestamp %ss %s the current time. %s", abs(delta), "before" if delta <= 0 else "after", - latency if -15*60 <= delta <= 0 else timezone), + msg), ("Please check this jail and associated logs as there" + " is potentially a timezone or latency problem: %s", line)) diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 9e81006b..6b0218f0 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -479,6 +479,36 @@ class IgnoreIP(LogCaptureTestCase): finally: tearDownMyTime() + def testWrongTimeDelta(self): + try: + self.filter.addFailRegex('fail from $') + self.filter.setDatePattern(r'{^LN-BEG}%Y-%m-%d %H:%M:%S(?:\s*%Z)?\s') + self.filter.setMaxRetry(5); # don't ban here + self.filter.inOperation = True; # real processing (all messages are new) + expectable_messages = ["timezone problem.", "clock synchronization problem;", "latency problem."] + cases = [(-90*60, 0), + (-10*60, 1), + (-30, None), + (30, None), + (10*60, 2), + (90*60, 0)] + for idx, (delta, expect) in enumerate(cases): + MyTime.setTime(1572138000+delta) + setattr(self.filter, "_next_simByTimeWarn", -1) + self.pruneLog('[phase {phase}] log entries offset by {delta}s'.format(phase=idx+1, delta=delta)) + for i in (1,2,3): + self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); + for (idx, msg) in enumerate(expectable_messages): + if idx == expect: + self.assertLogged(expectable_messages[idx]) + else: + self.assertNotLogged(expectable_messages[idx]) + self.assertLogged( + "192.0.2.15:1", "192.0.2.15:2", "192.0.2.15:3", + "Total # of detected failures: 3.", wait=True) + finally: + tearDownMyTime() + def testAddAttempt(self): self.filter.setMaxRetry(3) for i in xrange(1, 1+3): From ec043cd2029fe52d56cf526fac31e79b79d73467 Mon Sep 17 00:00:00 2001 From: sebres Date: Sun, 19 Sep 2021 21:58:42 +0200 Subject: [PATCH 05/17] simplifying logic and shortening messages (delta in minutes; removed clock synchronization, because it is rarely an issue on fail2ban side, e. g. for remote logs only, etc) --- fail2ban/server/filter.py | 41 +++++++++--------------- fail2ban/tests/filtertestcase.py | 53 ++++++++++++++------------------ 2 files changed, 38 insertions(+), 56 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index 16e7d2a6..08bc2e59 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -655,46 +655,35 @@ class Filter(JailThread): tupleLine = ("", self.__lastTimeText, line) date = self.__lastDate - if self.checkFindTime: + if self.checkFindTime and date is not None: # if in operation (modifications have been really found): if self.inOperation: # if weird date - we'd simulate now for timeing issue (too large deviation from now): - delta = date - MyTime.time() - if (date is None or abs(delta) > 60): - latency = "This could indicate a latency problem." - synchronization = "This could be a clock synchronization" + \ - " problem; are you sure that NTP is set up?" - timezone = "This looks like a timezone problem." - msg = "" - if -15*60 <= delta <= 0: - msg = latency - elif 0 < delta <= 15*60: - msg = synchronization - else: - msg = timezone - # log time zone issue as warning once per day: + delta = int(date - MyTime.time()) + if abs(delta) > 60: + delta /= 60 + # log timing issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", - ("Found a log entry with a timestamp %ss %s the current time. %s", - abs(delta), - "before" if delta <= 0 else "after", - msg), - ("Please check this jail and associated logs as there" + - " is potentially a timezone or latency problem: %s", + ("Detected a log entry %sm %s the current time in operation mode. " + "This looks like a %s problem. Treating such entries as if they just happened.", + abs(delta), "before" if delta < 0 else "after", + "latency" if -55 <= delta < 0 else "timezone" + ), + ("Please check a jail for a timing issue. Line with odd timestamp: %s", line)) # simulate now as date: date = MyTime.time() self.__lastDate = date else: # in initialization (restore) phase, if too old - ignore: - if date is not None and date < MyTime.time() - self.getFindTime(): + if date < MyTime.time() - self.getFindTime(): # log time zone issue as warning once per day: self._logWarnOnce("_next_ignByTimeWarn", - ("Ignoring all log entries older than %s; these are probably" + + ("Ignoring all log entries older than %ss; these are probably" + " messages generated while fail2ban was not running.", self.getFindTime()), - ("Please check this jail and associated logs as" + - " there is potentially a timezone or latency problem: %s", - line)) + ("Please check a jail for a timing issue. Line with odd timestamp: %s", + line)) # ignore - too old (obsolete) entry: return [] diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 6b0218f0..8e151f77 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -444,11 +444,11 @@ class IgnoreIP(LogCaptureTestCase): def testTimeJump_InOperation(self): self._testTimeJump(inOperation=True) - def testWrongTimeZone(self): + def testWrongTimeOrTZ(self): try: self.filter.addFailRegex('fail from $') self.filter.setDatePattern(r'{^LN-BEG}%Y-%m-%d %H:%M:%S(?:\s*%Z)?\s') - self.filter.setMaxRetry(5); # don't ban here + self.filter.setMaxRetry(50); # don't ban here self.filter.inOperation = True; # real processing (all messages are new) # current time is 1h later than log-entries: MyTime.setTime(1572138000+3600) @@ -476,36 +476,29 @@ class IgnoreIP(LogCaptureTestCase): "Match without a timestamp:", "192.0.2.17:1", "192.0.2.17:2", "192.0.2.17:3", "Total # of detected failures: 9.", all=True, wait=True) - finally: - tearDownMyTime() - - def testWrongTimeDelta(self): - try: - self.filter.addFailRegex('fail from $') - self.filter.setDatePattern(r'{^LN-BEG}%Y-%m-%d %H:%M:%S(?:\s*%Z)?\s') - self.filter.setMaxRetry(5); # don't ban here - self.filter.inOperation = True; # real processing (all messages are new) - expectable_messages = ["timezone problem.", "clock synchronization problem;", "latency problem."] - cases = [(-90*60, 0), - (-10*60, 1), - (-30, None), - (30, None), - (10*60, 2), - (90*60, 0)] - for idx, (delta, expect) in enumerate(cases): + # + phase = 3 + for delta, expect in ( + (-90*60, "timezone"), #90 minutes after + (-60*60, "timezone"), #60 minutes after + (-10*60, "timezone"), #10 minutes after + (-59, None), #59 seconds after + (59, None), #59 seconds before + (61, "latency"), #>1 minute before + (55*60, "latency"), #55 minutes before + (90*60, "timezone") #90 minutes before + ): + phase += 1 MyTime.setTime(1572138000+delta) setattr(self.filter, "_next_simByTimeWarn", -1) - self.pruneLog('[phase {phase}] log entries offset by {delta}s'.format(phase=idx+1, delta=delta)) - for i in (1,2,3): - self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); - for (idx, msg) in enumerate(expectable_messages): - if idx == expect: - self.assertLogged(expectable_messages[idx]) - else: - self.assertNotLogged(expectable_messages[idx]) - self.assertLogged( - "192.0.2.15:1", "192.0.2.15:2", "192.0.2.15:3", - "Total # of detected failures: 3.", wait=True) + self.pruneLog('[phase {phase}] log entries offset by {delta}s'.format(phase=phase, delta=delta)) + self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); + self.assertLogged("Found 192.0.2.15", wait=True) + if expect: + self.assertLogged(("timezone problem", "latency problem")[int(expect == "latency")], all=True) + self.assertNotLogged(("timezone problem", "latency problem")[int(expect != "latency")]) + else: + self.assertNotLogged("timezone problem", "latency problem", all=True) finally: tearDownMyTime() From 621d8cae17f16cfea43a394149217963034d344b Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 20 Sep 2021 02:20:22 +0200 Subject: [PATCH 06/17] restore backwards compatibility for date None --- fail2ban/server/filter.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index 08bc2e59..f49fe198 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -618,6 +618,7 @@ class Filter(JailThread): noDate = False if date: tupleLine = line + line = "".join(line) self.__lastTimeText = tupleLine[1] self.__lastDate = date else: @@ -654,6 +655,8 @@ class Filter(JailThread): if self.__lastDate and self.__lastDate > MyTime.time() - 60: tupleLine = ("", self.__lastTimeText, line) date = self.__lastDate + elif self.checkFindTime and self.inOperation: + date = MyTime.time() if self.checkFindTime and date is not None: # if in operation (modifications have been really found): From 17eed32e03e86f6b42a0f0ad227345713b7c7cd7 Mon Sep 17 00:00:00 2001 From: "Sergey G. Brester" Date: Tue, 21 Sep 2021 16:00:37 +0200 Subject: [PATCH 07/17] Update filtertestcase.py --- fail2ban/tests/filtertestcase.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 8e151f77..be874697 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -457,13 +457,18 @@ class IgnoreIP(LogCaptureTestCase): for i in (1,2,3): self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); # +3 = 3 self.assertLogged( + "Detected a log entry 60m before the current time in operation mode. This looks like a timezone problem.", + "Please check a jail for a timing issue.", "192.0.2.15:1", "192.0.2.15:2", "192.0.2.15:3", - "Total # of detected failures: 3.", wait=True) + "Total # of detected failures: 3.", all=True, wait=True) # + setattr(self.filter, "_next_simByTimeWarn", -1) self.pruneLog("[phase 2] wrong TZ given in log") for i in (1,2,3): self.filter.processLineAndAdd('2019-10-27 04:00:00 GMT fail from 192.0.2.16'); # +3 = 6 self.assertLogged( + "Detected a log entry 120m after the current time in operation mode. This looks like a timezone problem.", + "Please check a jail for a timing issue.", "192.0.2.16:1", "192.0.2.16:2", "192.0.2.16:3", "Total # of detected failures: 6.", all=True, wait=True) self.assertNotLogged("Found a match but no valid date/time found") @@ -496,7 +501,7 @@ class IgnoreIP(LogCaptureTestCase): self.assertLogged("Found 192.0.2.15", wait=True) if expect: self.assertLogged(("timezone problem", "latency problem")[int(expect == "latency")], all=True) - self.assertNotLogged(("timezone problem", "latency problem")[int(expect != "latency")]) + self.assertNotLogged(("timezone problem", "latency problem")[int(expect != "latency")], all=True) else: self.assertNotLogged("timezone problem", "latency problem", all=True) finally: From d086317cc83ec7aa6e6772dc91525bce33ed7200 Mon Sep 17 00:00:00 2001 From: "Sergey G. Brester" Date: Tue, 21 Sep 2021 16:05:53 +0200 Subject: [PATCH 08/17] Update filter.py --- fail2ban/server/filter.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index f49fe198..a13b1fb5 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -664,7 +664,7 @@ class Filter(JailThread): # if weird date - we'd simulate now for timeing issue (too large deviation from now): delta = int(date - MyTime.time()) if abs(delta) > 60: - delta /= 60 + delta //= 60 # log timing issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", ("Detected a log entry %sm %s the current time in operation mode. " From f8f59dd31a46f6ad35b38df1f29a8f81c7e88960 Mon Sep 17 00:00:00 2001 From: "Sergey G. Brester" Date: Fri, 1 Oct 2021 14:58:25 +0200 Subject: [PATCH 09/17] added test cases covering different messages adjusted to new log-format (gh-3116) --- fail2ban/tests/files/logs/lighttpd-auth | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/fail2ban/tests/files/logs/lighttpd-auth b/fail2ban/tests/files/logs/lighttpd-auth index 184dba33..c8a922b5 100644 --- a/fail2ban/tests/files/logs/lighttpd-auth +++ b/fail2ban/tests/files/logs/lighttpd-auth @@ -1,4 +1,3 @@ -#authentification failure (mod_auth) # failJSON: { "time": "2011-12-25T17:09:20", "match": true , "host": "4.4.4.4" } 2011-12-25 17:09:20: (http_auth.c.875) password doesn't match for /gitweb/ username: francois, IP: 4.4.4.4 # failJSON: { "time": "2012-09-26T10:24:35", "match": true , "host": "4.4.4.4" } @@ -7,3 +6,9 @@ 2013-08-25 00:24:55: (http_auth.c.877) get_password failed, IP: 4.4.4.4 # failJSON: { "time": "2018-01-16T14:10:32", "match": true , "host": "192.0.2.1", "desc": "http_auth -> mod_auth, gh-2018" } 2018-01-16 14:10:32: (mod_auth.c.525) password doesn't match for /test-url username: test, IP: 192.0.2.1 +# failJSON: { "time": "2021-09-30T16:05:33", "match": true , "host": "192.0.2.2", "user":"test", "desc": "gh-3116" } +2021-09-30 16:05:33: mod_auth.c.828) password doesn't match for /secure/ username: test IP: 192.0.2.2 +# failJSON: { "time": "2021-09-30T17:44:37", "match": true , "host": "192.0.2.3", "user":"tester", "desc": "gh-3116" } +2021-09-30 17:44:37: (mod_auth.c.791) digest: auth failed for tester : wrong password, IP: 192.0.2.3 +# failJSON: { "time": "2021-09-30T17:44:37", "match": true , "host": "192.0.2.4", "desc": "gh-3116" } +2021-09-30 17:44:37: (mod_auth.c.791) digest: auth failed: uri mismatch (/uri1 != /uri2), IP: 192.0.2.4 From ba839af8ad594439002f468b71b4c6caafb5de03 Mon Sep 17 00:00:00 2001 From: "Sergey G. Brester" Date: Fri, 1 Oct 2021 15:03:24 +0200 Subject: [PATCH 10/17] filter.d/lighttpd-auth.conf: adjusted to the current source code + avoiding catch-all's, etc (gh-3116) --- config/filter.d/lighttpd-auth.conf | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/filter.d/lighttpd-auth.conf b/config/filter.d/lighttpd-auth.conf index a68f4f4d..dcf19d3e 100644 --- a/config/filter.d/lighttpd-auth.conf +++ b/config/filter.d/lighttpd-auth.conf @@ -3,7 +3,7 @@ [Definition] -failregex = ^: \((?:http|mod)_auth\.c\.\d+\) (?:password doesn\'t match .* username: .*|digest: auth failed for .*: wrong password|get_password failed), IP: \s*$ +failregex = ^\s*(?:: )?\(?(?:http|mod)_auth\.c\.\d+\) (?:password doesn\'t match for (?:\S+|.*?) username:\s+(?:\S+|.*?)\s*|digest: auth failed(?: for\s+(?:\S+|.*?)\s*)?: (?:wrong password|uri mismatch \([^\)]*\))|get_password failed),? IP: \s*$ ignoreregex = From d91d949e95d5fbf70ca8679319dac7c8c2ba7a61 Mon Sep 17 00:00:00 2001 From: Mike Gilbert Date: Tue, 8 Jun 2021 17:48:12 -0400 Subject: [PATCH 11/17] tests: improve detection of readable systemd journal Look for system.journal in journal sub-directory. Add -readable to the find command. Bug: https://bugs.gentoo.org/794931 --- fail2ban/tests/filtertestcase.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index be874697..2b3dd995 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -1396,7 +1396,7 @@ def get_monitor_failures_journal_testcase(Filter_): # pragma: systemd no cover # check one at at time until the first hit for systemd_var in 'system-runtime-logs', 'system-state-logs': tmp = Utils.executeCmd( - 'find "$(systemd-path %s)" -name system.journal' % systemd_var, + 'find "$(systemd-path %s)/journal" -name system.journal -readable' % systemd_var, timeout=10, shell=True, output=True ) self.assertTrue(tmp) From 3245b8018b2606a5278df42790fac06d5a455f00 Mon Sep 17 00:00:00 2001 From: Sylvestre Ledru Date: Sat, 23 Oct 2021 17:38:20 +0200 Subject: [PATCH 12/17] Add the Debian path to roundcube error logs --- config/paths-debian.conf | 2 ++ 1 file changed, 2 insertions(+) diff --git a/config/paths-debian.conf b/config/paths-debian.conf index e096f972..1f5ea37d 100644 --- a/config/paths-debian.conf +++ b/config/paths-debian.conf @@ -26,3 +26,5 @@ exim_main_log = /var/log/exim4/mainlog # was in debian squeezy but not in wheezy # /etc/proftpd/proftpd.conf (SystemLog) proftpd_log = /var/log/proftpd/proftpd.log + +roundcube_errors_log = /var/log/roundcube/errors.log From 4b54a07d71a6ce1c85a3eae92bace6c0dadcdcfb Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 1 Nov 2021 11:43:54 +0100 Subject: [PATCH 13/17] Revert "`action.d/firewallcmd-*.conf` (multiport only): fixed port range selector, replacing `:` with `-`;" This reverts the incompatibility #3047 introduced by commit a038fd5dfe8cb0714472833604735b83462a217d (#2821). --- config/action.d/firewallcmd-ipset.conf | 2 +- config/action.d/firewallcmd-multiport.conf | 4 +-- config/action.d/firewallcmd-new.conf | 4 +-- config/action.d/firewallcmd-rich-rules.conf | 4 +-- fail2ban/tests/servertestcase.py | 32 ++++++++++----------- 5 files changed, 23 insertions(+), 23 deletions(-) diff --git a/config/action.d/firewallcmd-ipset.conf b/config/action.d/firewallcmd-ipset.conf index 66358f23..42513933 100644 --- a/config/action.d/firewallcmd-ipset.conf +++ b/config/action.d/firewallcmd-ipset.conf @@ -69,7 +69,7 @@ allports = -p # Option: multiport # Notes.: addition to block access only to specific ports # Usage.: use in jail config: banaction = firewallcmd-ipset[actiontype=] -multiport = -p -m multiport --dports "$(echo '' | sed s/:/-/g)" +multiport = -p -m multiport --dports ipmset = f2b- familyopt = diff --git a/config/action.d/firewallcmd-multiport.conf b/config/action.d/firewallcmd-multiport.conf index 0c401f1b..81540e5b 100644 --- a/config/action.d/firewallcmd-multiport.conf +++ b/config/action.d/firewallcmd-multiport.conf @@ -11,9 +11,9 @@ before = firewallcmd-common.conf actionstart = firewall-cmd --direct --add-chain filter f2b- firewall-cmd --direct --add-rule filter f2b- 1000 -j RETURN - firewall-cmd --direct --add-rule filter 0 -m conntrack --ctstate NEW -p -m multiport --dports "$(echo '' | sed s/:/-/g)" -j f2b- + firewall-cmd --direct --add-rule filter 0 -m conntrack --ctstate NEW -p -m multiport --dports -j f2b- -actionstop = firewall-cmd --direct --remove-rule filter 0 -m conntrack --ctstate NEW -p -m multiport --dports "$(echo '' | sed s/:/-/g)" -j f2b- +actionstop = firewall-cmd --direct --remove-rule filter 0 -m conntrack --ctstate NEW -p -m multiport --dports -j f2b- firewall-cmd --direct --remove-rules filter f2b- firewall-cmd --direct --remove-chain filter f2b- diff --git a/config/action.d/firewallcmd-new.conf b/config/action.d/firewallcmd-new.conf index 7b08603c..b06f5ccd 100644 --- a/config/action.d/firewallcmd-new.conf +++ b/config/action.d/firewallcmd-new.conf @@ -10,9 +10,9 @@ before = firewallcmd-common.conf actionstart = firewall-cmd --direct --add-chain filter f2b- firewall-cmd --direct --add-rule filter f2b- 1000 -j RETURN - firewall-cmd --direct --add-rule filter 0 -m state --state NEW -p -m multiport --dports "$(echo '' | sed s/:/-/g)" -j f2b- + firewall-cmd --direct --add-rule filter 0 -m state --state NEW -p -m multiport --dports -j f2b- -actionstop = firewall-cmd --direct --remove-rule filter 0 -m state --state NEW -p -m multiport --dports "$(echo '' | sed s/:/-/g)" -j f2b- +actionstop = firewall-cmd --direct --remove-rule filter 0 -m state --state NEW -p -m multiport --dports -j f2b- firewall-cmd --direct --remove-rules filter f2b- firewall-cmd --direct --remove-chain filter f2b- diff --git a/config/action.d/firewallcmd-rich-rules.conf b/config/action.d/firewallcmd-rich-rules.conf index 803d7d12..75a27d88 100644 --- a/config/action.d/firewallcmd-rich-rules.conf +++ b/config/action.d/firewallcmd-rich-rules.conf @@ -37,8 +37,8 @@ actioncheck = fwcmd_rich_rule = rule family='' source address='' port port='$p' protocol='' %(rich-suffix)s -actionban = ports="$(echo '' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="%(fwcmd_rich_rule)s"; done +actionban = ports=""; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="%(fwcmd_rich_rule)s"; done -actionunban = ports="$(echo '' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="%(fwcmd_rich_rule)s"; done +actionunban = ports=""; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="%(fwcmd_rich_rule)s"; done rich-suffix = \ No newline at end of file diff --git a/fail2ban/tests/servertestcase.py b/fail2ban/tests/servertestcase.py index fc505552..6cf45f53 100644 --- a/fail2ban/tests/servertestcase.py +++ b/fail2ban/tests/servertestcase.py @@ -1793,18 +1793,18 @@ class ServerConfigReaderTests(LogCaptureTestCase): 'ip4-start': ( "`firewall-cmd --direct --add-chain ipv4 filter f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --add-rule ipv4 filter f2b-j-w-fwcmd-mp 1000 -j RETURN`", - """`firewall-cmd --direct --add-rule ipv4 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports "$(echo 'http,https' | sed s/:/-/g)" -j f2b-j-w-fwcmd-mp`""", + "`firewall-cmd --direct --add-rule ipv4 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports http,https -j f2b-j-w-fwcmd-mp`", ), 'ip6-start': ( "`firewall-cmd --direct --add-chain ipv6 filter f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --add-rule ipv6 filter f2b-j-w-fwcmd-mp 1000 -j RETURN`", - """`firewall-cmd --direct --add-rule ipv6 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports "$(echo 'http,https' | sed s/:/-/g)" -j f2b-j-w-fwcmd-mp`""", + "`firewall-cmd --direct --add-rule ipv6 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports http,https -j f2b-j-w-fwcmd-mp`", ), 'stop': ( - """`firewall-cmd --direct --remove-rule ipv4 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports "$(echo 'http,https' | sed s/:/-/g)" -j f2b-j-w-fwcmd-mp`""", + "`firewall-cmd --direct --remove-rule ipv4 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports http,https -j f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --remove-rules ipv4 filter f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --remove-chain ipv4 filter f2b-j-w-fwcmd-mp`", - """`firewall-cmd --direct --remove-rule ipv6 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports "$(echo 'http,https' | sed s/:/-/g)" -j f2b-j-w-fwcmd-mp`""", + "`firewall-cmd --direct --remove-rule ipv6 filter INPUT_direct 0 -m conntrack --ctstate NEW -p tcp -m multiport --dports http,https -j f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --remove-rules ipv6 filter f2b-j-w-fwcmd-mp`", "`firewall-cmd --direct --remove-chain ipv6 filter f2b-j-w-fwcmd-mp`", ), @@ -1872,21 +1872,21 @@ class ServerConfigReaderTests(LogCaptureTestCase): 'ip4': (' f2b-j-w-fwcmd-ipset ',), 'ip6': (' f2b-j-w-fwcmd-ipset6 ',), 'ip4-start': ( "`ipset create f2b-j-w-fwcmd-ipset hash:ip timeout 0 `", - """`firewall-cmd --direct --add-rule ipv4 filter INPUT_direct 0 -p tcp -m multiport --dports "$(echo 'http' | sed s/:/-/g)" -m set --match-set f2b-j-w-fwcmd-ipset src -j REJECT --reject-with icmp-port-unreachable`""", + "`firewall-cmd --direct --add-rule ipv4 filter INPUT_direct 0 -p tcp -m multiport --dports http -m set --match-set f2b-j-w-fwcmd-ipset src -j REJECT --reject-with icmp-port-unreachable`", ), 'ip6-start': ( "`ipset create f2b-j-w-fwcmd-ipset6 hash:ip timeout 0 family inet6`", - """`firewall-cmd --direct --add-rule ipv6 filter INPUT_direct 0 -p tcp -m multiport --dports "$(echo 'http' | sed s/:/-/g)" -m set --match-set f2b-j-w-fwcmd-ipset6 src -j REJECT --reject-with icmp6-port-unreachable`""", + "`firewall-cmd --direct --add-rule ipv6 filter INPUT_direct 0 -p tcp -m multiport --dports http -m set --match-set f2b-j-w-fwcmd-ipset6 src -j REJECT --reject-with icmp6-port-unreachable`", ), 'flush': ( "`ipset flush f2b-j-w-fwcmd-ipset`", "`ipset flush f2b-j-w-fwcmd-ipset6`", ), 'stop': ( - """`firewall-cmd --direct --remove-rule ipv4 filter INPUT_direct 0 -p tcp -m multiport --dports "$(echo 'http' | sed s/:/-/g)" -m set --match-set f2b-j-w-fwcmd-ipset src -j REJECT --reject-with icmp-port-unreachable`""", + "`firewall-cmd --direct --remove-rule ipv4 filter INPUT_direct 0 -p tcp -m multiport --dports http -m set --match-set f2b-j-w-fwcmd-ipset src -j REJECT --reject-with icmp-port-unreachable`", "`ipset flush f2b-j-w-fwcmd-ipset`", "`ipset destroy f2b-j-w-fwcmd-ipset`", - """`firewall-cmd --direct --remove-rule ipv6 filter INPUT_direct 0 -p tcp -m multiport --dports "$(echo 'http' | sed s/:/-/g)" -m set --match-set f2b-j-w-fwcmd-ipset6 src -j REJECT --reject-with icmp6-port-unreachable`""", + "`firewall-cmd --direct --remove-rule ipv6 filter INPUT_direct 0 -p tcp -m multiport --dports http -m set --match-set f2b-j-w-fwcmd-ipset6 src -j REJECT --reject-with icmp6-port-unreachable`", "`ipset flush f2b-j-w-fwcmd-ipset6`", "`ipset destroy f2b-j-w-fwcmd-ipset6`", ), @@ -1943,32 +1943,32 @@ class ServerConfigReaderTests(LogCaptureTestCase): ('j-fwcmd-rr', 'firewallcmd-rich-rules[port="22:24", protocol="tcp"]', { 'ip4': ("family='ipv4'", "icmp-port-unreachable",), 'ip6': ("family='ipv6'", 'icmp6-port-unreachable',), 'ip4-ban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' reject type='icmp-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' reject type='icmp-port-unreachable'"; done`""", ), 'ip4-unban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' reject type='icmp-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' reject type='icmp-port-unreachable'"; done`""", ), 'ip6-ban': ( - """ `ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' reject type='icmp6-port-unreachable'"; done`""", + """ `ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' reject type='icmp6-port-unreachable'"; done`""", ), 'ip6-unban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' reject type='icmp6-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' reject type='icmp6-port-unreachable'"; done`""", ), }), # firewallcmd-rich-logging -- ('j-fwcmd-rl', 'firewallcmd-rich-logging[port="22:24", protocol="tcp"]', { 'ip4': ("family='ipv4'", "icmp-port-unreachable",), 'ip6': ("family='ipv6'", 'icmp6-port-unreachable',), 'ip4-ban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp-port-unreachable'"; done`""", ), 'ip4-unban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv4' source address='192.0.2.1' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp-port-unreachable'"; done`""", ), 'ip6-ban': ( - """ `ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp6-port-unreachable'"; done`""", + """ `ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp6-port-unreachable'"; done`""", ), 'ip6-unban': ( - """`ports="$(echo '22:24' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp6-port-unreachable'"; done`""", + """`ports="22:24"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="rule family='ipv6' source address='2001:db8::' port port='$p' protocol='tcp' log prefix='f2b-j-fwcmd-rl' level='info' limit value='1/m' reject type='icmp6-port-unreachable'"; done`""", ), }), ) From 7678f5982733f1d20bbec8d04006ac78cded10db Mon Sep 17 00:00:00 2001 From: sebres Date: Tue, 21 Sep 2021 20:42:51 +0200 Subject: [PATCH 14/17] better format of time delta (using seconds2str); increase stability for systemd test-cases --- fail2ban/server/filter.py | 7 ++--- fail2ban/server/mytime.py | 48 ++++++++++++++++++++++++++++++++ fail2ban/tests/filtertestcase.py | 8 ++++-- fail2ban/tests/misctestcase.py | 12 ++++++++ 4 files changed, 68 insertions(+), 7 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index a13b1fb5..d2cd0ce9 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -664,13 +664,12 @@ class Filter(JailThread): # if weird date - we'd simulate now for timeing issue (too large deviation from now): delta = int(date - MyTime.time()) if abs(delta) > 60: - delta //= 60 # log timing issue as warning once per day: self._logWarnOnce("_next_simByTimeWarn", - ("Detected a log entry %sm %s the current time in operation mode. " + ("Detected a log entry %s %s the current time in operation mode. " "This looks like a %s problem. Treating such entries as if they just happened.", - abs(delta), "before" if delta < 0 else "after", - "latency" if -55 <= delta < 0 else "timezone" + MyTime.seconds2str(abs(delta)), "before" if delta < 0 else "after", + "latency" if -3300 <= delta < 0 else "timezone" ), ("Please check a jail for a timing issue. Line with odd timestamp: %s", line)) diff --git a/fail2ban/server/mytime.py b/fail2ban/server/mytime.py index 49199887..d09c9d41 100644 --- a/fail2ban/server/mytime.py +++ b/fail2ban/server/mytime.py @@ -161,3 +161,51 @@ class MyTime: val = rexp.sub(rpl, val) val = MyTime._str2sec_fini.sub(r"\1+\2", val) return eval(val) + + class seconds2str(): + """Converts seconds to string on demand (if string representation needed). + Ex: seconds2str(86400*390) = 1y 3w 4d + seconds2str(86400*368) = 1y 3d + seconds2str(86400*365.5) = 1y + seconds2str(86400*2+3600*7+60*15) = 2d 7h 15m + seconds2str(86400*2+3599) = 2d 1h + seconds2str(3600-5) = 1h + seconds2str(3600-10) = 59m 50s + seconds2str(59) = 59s + """ + def __init__(self, sec): + self.sec = sec + def __str__(self): + # s = str(datetime.timedelta(seconds=int(self.sec))) + # return s if s[-3:] != ":00" else s[:-3] + s = self.sec; r = ""; c = 3 + # automatic accuracy: round by large values (upto 1 minute, or 1 day by year): + if s >= 3570: + if s >= 31536000: + s = int(round(float(s)/86400)*86400) + elif s >= 86400: + s = int(round(float(s)/60)*60) + else: + s = int(round(float(s)/10)*10) + for n, m in ( + ('y', 31536000), # a year as 365*24*60*60 (don't need to consider leap year by this accuracy) + ('w', 604800), # a week as 24*60*60*7 + ('d', 86400), # a day as 24*60*60 + ('h', 3600), # a hour as 60*60 + ('m', 60), # a minute + ('s', 1) # a second + ): + if s >= m: + c -= 1 + r += ' ' + str(s//m) + n + s %= m + # stop if no remaining part or no repeat needed (too small granularity): + if not s or not c: break + elif c < 3: + # avoid too small granularity: + c -= 1 + if not c: break + # + return r[1:] + def __repr__(self): + return self.__str__() diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 2b3dd995..343cfe04 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -457,7 +457,7 @@ class IgnoreIP(LogCaptureTestCase): for i in (1,2,3): self.filter.processLineAndAdd('2019-10-27 02:00:00 fail from 192.0.2.15'); # +3 = 3 self.assertLogged( - "Detected a log entry 60m before the current time in operation mode. This looks like a timezone problem.", + "Detected a log entry 1h before the current time in operation mode. This looks like a timezone problem.", "Please check a jail for a timing issue.", "192.0.2.15:1", "192.0.2.15:2", "192.0.2.15:3", "Total # of detected failures: 3.", all=True, wait=True) @@ -467,7 +467,7 @@ class IgnoreIP(LogCaptureTestCase): for i in (1,2,3): self.filter.processLineAndAdd('2019-10-27 04:00:00 GMT fail from 192.0.2.16'); # +3 = 6 self.assertLogged( - "Detected a log entry 120m after the current time in operation mode. This looks like a timezone problem.", + "Detected a log entry 2h after the current time in operation mode. This looks like a timezone problem.", "Please check a jail for a timing issue.", "192.0.2.16:1", "192.0.2.16:2", "192.0.2.16:3", "Total # of detected failures: 6.", all=True, wait=True) @@ -1458,7 +1458,7 @@ def get_monitor_failures_journal_testcase(Filter_): # pragma: systemd no cover if idle: self.filter.sleeptime /= 100.0 self.filter.idle = True - self.waitForTicks(1) + self.waitForTicks(1) self.assertRaises(FailManagerEmpty, self.filter.failManager.toBan) # Now let's feed it with entries from the file @@ -1540,6 +1540,7 @@ def get_monitor_failures_journal_testcase(Filter_): # pragma: systemd no cover def test_delJournalMatch(self): self._initFilter() self.filter.start() + self.waitForTicks(1); # wait for start # Smoke test for removing of match # basic full test @@ -1572,6 +1573,7 @@ def get_monitor_failures_journal_testcase(Filter_): # pragma: systemd no cover def test_WrongChar(self): self._initFilter() self.filter.start() + self.waitForTicks(1); # wait for start # Now let's feed it with entries from the file _copy_lines_to_journal( self.test_file, self.journal_fields, skip=15, n=4) diff --git a/fail2ban/tests/misctestcase.py b/fail2ban/tests/misctestcase.py index 458e9a23..915ce7df 100644 --- a/fail2ban/tests/misctestcase.py +++ b/fail2ban/tests/misctestcase.py @@ -457,3 +457,15 @@ class MyTimeTest(unittest.TestCase): self.assertEqual(float(str2sec("1 month")) / 60 / 60 / 24, 30.4375) self.assertEqual(float(str2sec("1 year")) / 60 / 60 / 24, 365.25) + def testSec2Str(self): + sec2str = lambda s: str(MyTime.seconds2str(s)) + self.assertEqual(sec2str(86400*390), '1y 3w 4d') + self.assertEqual(sec2str(86400*368), '1y 3d') + self.assertEqual(sec2str(86400*365.49), '1y') + self.assertEqual(sec2str(86400*15), '2w 1d') + self.assertEqual(sec2str(86400*14-10), '2w') + self.assertEqual(sec2str(86400*2+3600*7+60*15), '2d 7h 15m') + self.assertEqual(sec2str(86400*2+3599), '2d 1h') + self.assertEqual(sec2str(3600-5), '1h') + self.assertEqual(sec2str(3600-10), '59m 50s') + self.assertEqual(sec2str(59), '59s') From 96661f25ab558b92b42d01c87d383664e69dd18b Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 20 Sep 2021 04:07:55 +0200 Subject: [PATCH 15/17] filtersystemd.py: fixes wrong time point of "in operation" mode todo: need more tests to cover any step of switch to inOperationMode (all branches) --- .github/workflows/main.yml | 5 ++- fail2ban/server/filtersystemd.py | 76 ++++++++++++++++++++++++-------- fail2ban/tests/filtertestcase.py | 23 ++++++++++ 3 files changed, 85 insertions(+), 19 deletions(-) diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index c60ab05c..e346635d 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -33,7 +33,10 @@ jobs: uses: actions/setup-python@v2 with: python-version: ${{ matrix.python-version }} - + + - name: Grant systemd-journal access + run: sudo usermod -a -G systemd-journal "$USER" || echo 'no systemd-journal access' + - name: Python version run: | F2B_PY=$(python -c "import sys; print(sys.version)") diff --git a/fail2ban/server/filtersystemd.py b/fail2ban/server/filtersystemd.py index 88f8c292..a305b6cf 100644 --- a/fail2ban/server/filtersystemd.py +++ b/fail2ban/server/filtersystemd.py @@ -92,8 +92,8 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover try: args['flags'] = int(kwargs.pop('journalflags')) except KeyError: - # be sure all journal types will be opened if files specified (don't set flags): - if 'files' not in args or not len(args['files']): + # be sure all journal types will be opened if files/path specified (don't set flags): + if ('files' not in args or not len(args['files'])) and ('path' not in args or not args['path']): args['flags'] = 4 try: @@ -258,6 +258,10 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover date = datetime.datetime.fromtimestamp(date) self.__journal.seek_realtime(date) + def inOperationMode(self): + self.inOperation = True + logSys.info("[%s] Jail is in operation now (process new journal entries)", self.jailName) + ## # Main loop. # @@ -268,23 +272,44 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover if not self.getJournalMatch(): logSys.notice( - "Jail started without 'journalmatch' set. " + "[%s] Jail started without 'journalmatch' set. " "Jail regexs will be checked against all journal entries, " - "which is not advised for performance reasons.") + "which is not advised for performance reasons.", self.jailName) - # Try to obtain the last known time (position of journal) - start_time = 0 - if self.jail.database is not None: - start_time = self.jail.database.getJournalPos(self.jail, 'systemd-journal') or 0 - # Seek to max(last_known_time, now - findtime) in journal - start_time = max( start_time, MyTime.time() - int(self.getFindTime()) ) - self.seekToTime(start_time) - # Move back one entry to ensure do not end up in dead space - # if start time beyond end of journal + # Save current cursor position (to recognize in operation mode): + logentry = None try: - self.__journal.get_previous() + self.__journal.seek_tail() + logentry = self.__journal.get_previous() + self.__journal.get_next() except OSError: - pass # Reading failure, so safe to ignore + logentry = None # Reading failure, so safe to ignore + if logentry: + # Try to obtain the last known time (position of journal) + startTime = 0 + if self.jail.database is not None: + startTime = self.jail.database.getJournalPos(self.jail, 'systemd-journal') or 0 + # Seek to max(last_known_time, now - findtime) in journal + startTime = max( startTime, MyTime.time() - int(self.getFindTime()) ) + self.seekToTime(startTime) + # Not in operation while we'll read old messages ... + self.inOperation = False + # Save current time in order to check time to switch "in operation" mode + startTime = (1, MyTime.time(), logentry.get('__CURSOR')) + # Move back one entry to ensure do not end up in dead space + # if start time beyond end of journal + try: + self.__journal.get_previous() + except OSError: + pass # Reading failure, so safe to ignore + else: + # empty journal or no entries for current filter: + self.inOperationMode() + # seek_tail() seems to have a bug by no entries (could bypass some entries hereafter), so seek to now instead: + startTime = MyTime.time() + self.seekToTime(startTime) + # for possible future switches of in-operation mode: + startTime = (0, startTime) line = None while self.active: @@ -317,12 +342,27 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover e, exc_info=logSys.getEffectiveLevel() <= logging.DEBUG) self.ticks += 1 if logentry: - line = self.formatJournalEntry(logentry) - self.processLineAndAdd(*line) + line, tm = self.formatJournalEntry(logentry) + # switch "in operation" mode if we'll find start entry (+ some delta): + if not self.inOperation: + if tm >= MyTime.time() - 1: # reached now (approximated): + self.inOperationMode() + elif startTime[0] == 1: + # if it reached start entry (or get read time larger than start time) + if logentry.get('__CURSOR') == startTime[2] or tm > startTime[1]: + # give the filter same time it needed to reach the start entry: + startTime = (0, MyTime.time()*2 - startTime[1]) + elif tm > startTime[1]: # reached start time (approximated): + self.inOperationMode() + # process line + self.processLineAndAdd(line, tm) self.__modified += 1 if self.__modified >= 100: # todo: should be configurable break else: + # "in operation" mode since we don't have messages anymore (reached end of journal): + if not self.inOperation: + self.inOperationMode() break self.__modified = 0 if self.ticks % 10 == 0: @@ -334,7 +374,7 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover or not self.active ) ): - self.jail.database.updateJournal(self.jail, 'systemd-journal', line[1], line[0][1]) + self.jail.database.updateJournal(self.jail, 'systemd-journal', tm, line[1]) self.__nextUpdateTM = MyTime.time() + Utils.DEFAULT_SLEEP_TIME * 5 line = None except Exception as e: # pragma: no cover diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 343cfe04..32dcca5c 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -1537,6 +1537,29 @@ def get_monitor_failures_journal_testcase(Filter_): # pragma: systemd no cover _gen_falure("192.0.2.6") self.assertFalse(self.jail.getFailTicket()) + # now reset DB, so we'd find all messages before filter entering in operation mode: + self.filter.stop() + self.filter.join() + self.jail.database.updateJournal(self.jail, 'systemd-journal', MyTime.time()-10000, 'TEST') + self._initFilter() + self.filter.setMaxRetry(1) + states = [] + def _state(*args): + self.assertNotIn("** in operation", states) + self.assertFalse(self.filter.inOperation) + states.append("** process line: %r" % (args,)) + self.filter.processLineAndAdd = _state + def _inoper(): + self.assertNotIn("** in operation", states) + self.assertEqual(len(states), 11) + states.append("** in operation") + self.filter.__class__.inOperationMode(self.filter) + self.filter.inOperationMode = _inoper + self.filter.start() + self.waitForTicks(12) + self.assertTrue(Utils.wait_for(lambda: len(states) == 12, _maxWaitTime(10))) + self.assertEqual(states[-1], "** in operation") + def test_delJournalMatch(self): self._initFilter() self.filter.start() From 3b020988172c4c38d9baae36344b0d3cfa50332e Mon Sep 17 00:00:00 2001 From: sebres Date: Wed, 3 Nov 2021 15:35:59 +0100 Subject: [PATCH 16/17] several backends optimizations (in file and journal filters): - don't need to wait if we still had log-entries from last iteration (which got interrupted for servicing) - rewritten update log/journal position, it is more stable and faster now (fewer DB access and surely up-to-date at end) --- fail2ban/server/filter.py | 53 +++++++++++++++++++++++++++----- fail2ban/server/filtersystemd.py | 45 +++++++++++++++++++-------- fail2ban/server/jailthread.py | 8 +++++ 3 files changed, 86 insertions(+), 20 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index d2cd0ce9..f8417d2d 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -104,6 +104,10 @@ class Filter(JailThread): ## Error counter (protected, so can be used in filter implementations) ## if it reached 100 (at once), run-cycle will go idle self._errors = 0 + ## Next time to update log or journal position in database: + self._nextUpdateTM = 0 + ## Pending updates (must be executed at next update time or during stop): + self._pendDBUpdates = {} ## return raw host (host is not dns): self.returnRawHost = False ## check each regex (used for test purposes): @@ -1023,9 +1027,6 @@ class FileFilter(Filter): log = self.__logs.pop(path) except KeyError: return - db = self.jail.database - if db is not None: - db.updateLog(self.jail, log) logSys.info("Removed logfile: %r", path) self._delLogPath(path) return @@ -1145,9 +1146,15 @@ class FileFilter(Filter): self.processLineAndAdd(line.rstrip('\r\n')) finally: log.close() - db = self.jail.database - if db is not None: - db.updateLog(self.jail, log) + if self.jail.database is not None: + self._pendDBUpdates[log] = 1 + if ( + self.ticks % 100 == 0 + or MyTime.time() >= self._nextUpdateTM + or not self.active + ): + self._updateDBPending() + self._nextUpdateTM = MyTime.time() + Utils.DEFAULT_SLEEP_TIME * 5 return True ## @@ -1247,12 +1254,33 @@ class FileFilter(Filter): ret.append(("File list", path)) return ret - def stop(self): - """Stop monitoring of log-file(s) + def _updateDBPending(self): + """Apply pending updates (log position) to database. """ + db = self.jail.database + while True: + try: + log, args = self._pendDBUpdates.popitem() + except KeyError: + break + db.updateLog(self.jail, log) + + def onStop(self): + """Stop monitoring of log-file(s). Invoked after run method. + """ + # ensure positions of pending logs are up-to-date: + if self._pendDBUpdates and self.jail.database: + self._updateDBPending() # stop files monitoring: for path in self.__logs.keys(): self.delLogPath(path) + + def stop(self): + """Stop filter + """ + # normally onStop will be called automatically in thread after its run ends, + # but for backwards compatibilities we'll invoke it in caller of stop method. + self.onStop() # stop thread: super(Filter, self).stop() @@ -1304,6 +1332,15 @@ class FileContainer: ## shows that log is in operation mode (expecting new messages only from here): self.inOperation = tail + def __hash__(self): + return hash(self.__filename) + def __eq__(self, other): + return (id(self) == id(other) or + self.__filename == (other.__filename if isinstance(other, FileContainer) else other) + ) + def __repr__(self): + return 'file-log:'+self.__filename + def getFileName(self): return self.__filename diff --git a/fail2ban/server/filtersystemd.py b/fail2ban/server/filtersystemd.py index a305b6cf..e2220105 100644 --- a/fail2ban/server/filtersystemd.py +++ b/fail2ban/server/filtersystemd.py @@ -61,7 +61,6 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover # Initialise systemd-journal connection self.__journal = journal.Reader(**jrnlargs) self.__matches = [] - self.__nextUpdateTM = 0 self.setDatePattern(None) logSys.debug("Created FilterSystemd") @@ -321,9 +320,10 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover #self.__journal.wait(self.sleeptime) != journal.NOP ## ## wait for entries without sleep in intervals, because "sleeping" in journal.wait: - Utils.wait_for(lambda: not self.active or \ - self.__journal.wait(Utils.DEFAULT_SLEEP_INTERVAL) != journal.NOP, - self.sleeptime, 0.00001) + if not logentry: + Utils.wait_for(lambda: not self.active or \ + self.__journal.wait(Utils.DEFAULT_SLEEP_INTERVAL) != journal.NOP, + self.sleeptime, 0.00001) if self.idle: # because journal.wait will returns immediatelly if we have records in journal, # just wait a little bit here for not idle, to prevent hi-load: @@ -368,15 +368,17 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover if self.ticks % 10 == 0: self.performSvc() # update position in log (time and iso string): - if (line and self.jail.database and ( - self.ticks % 10 == 0 - or MyTime.time() >= self.__nextUpdateTM + if self.jail.database: + if line: + self._pendDBUpdates['systemd-journal'] = (tm, line[1]) + line = None + if self._pendDBUpdates and ( + self.ticks % 100 == 0 + or MyTime.time() >= self._nextUpdateTM or not self.active - ) - ): - self.jail.database.updateJournal(self.jail, 'systemd-journal', tm, line[1]) - self.__nextUpdateTM = MyTime.time() + Utils.DEFAULT_SLEEP_TIME * 5 - line = None + ): + self._updateDBPending() + self._nextUpdateTM = MyTime.time() + Utils.DEFAULT_SLEEP_TIME * 5 except Exception as e: # pragma: no cover if not self.active: # if not active - error by stop... break @@ -403,3 +405,22 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover ret.append(("Journal matches", [" + ".join(" ".join(match) for match in self.__matches)])) return ret + + def _updateDBPending(self): + """Apply pending updates (jornal position) to database. + """ + db = self.jail.database + while True: + try: + log, args = self._pendDBUpdates.popitem() + except KeyError: + break + db.updateJournal(self.jail, log, *args) + + def onStop(self): + """Stop monitoring of journal. Invoked after run method. + """ + # ensure positions of pending logs are up-to-date: + if self._pendDBUpdates and self.jail.database: + self._updateDBPending() + diff --git a/fail2ban/server/jailthread.py b/fail2ban/server/jailthread.py index 94f34542..67955a06 100644 --- a/fail2ban/server/jailthread.py +++ b/fail2ban/server/jailthread.py @@ -67,6 +67,8 @@ class JailThread(Thread): def run_with_except_hook(*args, **kwargs): try: run(*args, **kwargs) + # call on stop callback to do some finalizations: + self.onStop() except Exception as e: # avoid very sporadic error "'NoneType' object has no attribute 'exc_info'" (https://bugs.python.org/issue7336) # only extremely fast systems are affected ATM (2.7 / 3.x), if thread ends nothing is available here. @@ -97,6 +99,12 @@ class JailThread(Thread): self.active = True super(JailThread, self).start() + @abstractmethod + def onStop(self): # pragma: no cover - absract + """Abstract - Called when thread ends (after run). + """ + pass + def stop(self): """Sets `active` property to False, to flag run method to return. """ From 4fe4ac8dde6ba14841da598ec37f8c6911fe0f64 Mon Sep 17 00:00:00 2001 From: sebres Date: Wed, 3 Nov 2021 15:58:57 +0100 Subject: [PATCH 17/17] amend to merge: replace timedelta string representation with new function seconds2str --- fail2ban/server/observer.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/fail2ban/server/observer.py b/fail2ban/server/observer.py index f5ba20d9..b585706f 100644 --- a/fail2ban/server/observer.py +++ b/fail2ban/server/observer.py @@ -462,7 +462,7 @@ class ObserverThread(JailThread): if ticket.getTime() > timeOfBan: logSys.info('[%s] IP %s is bad: %s # last %s - incr %s to %s' % (jail.name, ip, banCount, MyTime.time2str(timeOfBan), - datetime.timedelta(seconds=int(orgBanTime)), datetime.timedelta(seconds=int(banTime)))); + MyTime.seconds2str(orgBanTime), MyTime.seconds2str(banTime))) else: ticket.restored = True break @@ -491,8 +491,7 @@ class ObserverThread(JailThread): # if not permanent if btime != -1: bendtime = ticket.getTime() + btime - logtime = (datetime.timedelta(seconds=int(btime)), - MyTime.time2str(bendtime)) + logtime = (MyTime.seconds2str(btime), MyTime.time2str(bendtime)) # check ban is not too old : if bendtime < MyTime.time(): logSys.debug('Ignore old bantime %s', logtime[1])