Merge pull request #3053 from db48x/fix-grammar-of-timestamp-warnings

Improve grammar and readability of timestamp warnings

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 []
 

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 <ADDR>$')
 			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()