From a98cc08b31b41e9d344e26c6eb0d63d54b5f1242 Mon Sep 17 00:00:00 2001 From: Daniel Brooks Date: Sat, 10 Jul 2021 21:34:46 -0700 Subject: [PATCH 1/8] 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 2/8] 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 3/8] 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 4/8] 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 5/8] 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 6/8] 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 7/8] 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 8/8] 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. "