diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index e9000447..a13b1fb5 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,30 +655,38 @@ 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: + 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): - if (date is None or date < MyTime.time() - 60 or date > MyTime.time() + 60): - # 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", - ("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", - line)) + ("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", - ("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", - line)) + ("Ignoring all log entries older than %ss; these are probably" + + " messages generated while fail2ban was not running.", + self.getFindTime()), + ("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 5166bc43..be874697 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) @@ -457,15 +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( - "Simulate NOW in operation since found time has too large deviation", - "Please check jail has possibly a timezone issue.", + "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") @@ -478,6 +481,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) + # + 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=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")], all=True) + else: + self.assertNotLogged("timezone problem", "latency problem", all=True) finally: tearDownMyTime()