Merge branch '0.11'

.github/workflows/main.yml

@@ -34,6 +34,9 @@ jobs:
         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)")

config/action.d/firewallcmd-ipset.conf

@@ -102,7 +102,7 @@ allports = -p <protocol>
 # Option: multiport
 # Notes.: addition to block access only to specific ports
 # Usage.: use in jail config:  banaction = firewallcmd-ipset[actiontype=<multiport>]
-multiport = -p <protocol> -m multiport --dports "$(echo '<port>' | sed s/:/-/g)"
+multiport = -p <protocol> -m multiport --dports <port>
 
 ipmset = f2b-<name>
 familyopt =

config/action.d/firewallcmd-multiport.conf

@@ -11,9 +11,9 @@ before = firewallcmd-common.conf
 
 actionstart = firewall-cmd --direct --add-chain <family> filter f2b-<name>
               firewall-cmd --direct --add-rule <family> filter f2b-<name> 1000 -j RETURN
-              firewall-cmd --direct --add-rule <family> filter <chain> 0 -m conntrack --ctstate NEW -p <protocol> -m multiport --dports "$(echo '<port>' | sed s/:/-/g)" -j f2b-<name>
+              firewall-cmd --direct --add-rule <family> filter <chain> 0 -m conntrack --ctstate NEW -p <protocol> -m multiport --dports <port> -j f2b-<name>
 
-actionstop = firewall-cmd --direct --remove-rule <family> filter <chain> 0 -m conntrack --ctstate NEW -p <protocol> -m multiport --dports "$(echo '<port>' | sed s/:/-/g)" -j f2b-<name>
+actionstop = firewall-cmd --direct --remove-rule <family> filter <chain> 0 -m conntrack --ctstate NEW -p <protocol> -m multiport --dports <port> -j f2b-<name>
              firewall-cmd --direct --remove-rules <family> filter f2b-<name>
              firewall-cmd --direct --remove-chain <family> filter f2b-<name>
 

config/action.d/firewallcmd-new.conf

@@ -10,9 +10,9 @@ before = firewallcmd-common.conf
 
 actionstart = firewall-cmd --direct --add-chain <family> filter f2b-<name>
               firewall-cmd --direct --add-rule <family> filter f2b-<name> 1000 -j RETURN
-              firewall-cmd --direct --add-rule <family> filter <chain> 0 -m state --state NEW -p <protocol> -m multiport --dports "$(echo '<port>' | sed s/:/-/g)" -j f2b-<name>
+              firewall-cmd --direct --add-rule <family> filter <chain> 0 -m state --state NEW -p <protocol> -m multiport --dports <port> -j f2b-<name>
 
-actionstop = firewall-cmd --direct --remove-rule <family> filter <chain> 0 -m state --state NEW -p <protocol> -m multiport --dports "$(echo '<port>' | sed s/:/-/g)" -j f2b-<name>
+actionstop = firewall-cmd --direct --remove-rule <family> filter <chain> 0 -m state --state NEW -p <protocol> -m multiport --dports <port> -j f2b-<name>
              firewall-cmd --direct --remove-rules <family> filter f2b-<name>
              firewall-cmd --direct --remove-chain <family> filter f2b-<name>
 

config/action.d/firewallcmd-rich-rules.conf

@@ -37,8 +37,8 @@ actioncheck =
 
 fwcmd_rich_rule = rule family='<family>' source address='<ip>' port port='$p' protocol='<protocol>' %(rich-suffix)s
 
-actionban = ports="$(echo '<port>' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="%(fwcmd_rich_rule)s"; done
+actionban = ports="<port>"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --add-rich-rule="%(fwcmd_rich_rule)s"; done
 	   
-actionunban = ports="$(echo '<port>' | sed s/:/-/g)"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="%(fwcmd_rich_rule)s"; done
+actionunban = ports="<port>"; for p in $(echo $ports | tr ", " " "); do firewall-cmd --remove-rich-rule="%(fwcmd_rich_rule)s"; done
 
 rich-suffix = <rich-blocktype>

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: <HOST>\s*$
+failregex = ^\s*(?:: )?\(?(?:http|mod)_auth\.c\.\d+\) (?:password doesn\'t match for (?:\S+|.*?) username:\s+<F-USER>(?:\S+|.*?)</F-USER>\s*|digest: auth failed(?: for\s+<F-ALT_USER>(?:\S+|.*?)</F-ALT_USER>\s*)?: (?:wrong password|uri mismatch \([^\)]*\))|get_password failed),? IP: <HOST>\s*$
 
 ignoreregex = 
 

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

fail2ban/server/filter.py

@@ -105,6 +105,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):
@@ -619,6 +623,7 @@ class Filter(JailThread):
 		noDate = False
 		if date:
 			tupleLine = line
+			line = "".join(line)
 			self.__lastTimeText = tupleLine[1]
 			self.__lastDate = date
 		else:
@@ -655,29 +660,36 @@ 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):
+				delta = int(date - MyTime.time())
-					# log time zone issue as warning once per day:
+				if abs(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",
+						("Detected a log entry %s %s the current time in operation mode. "
-							date, MyTime.time(), 60),
+						 "This looks like a %s problem. Treating such entries as if they just happened.",
-						("Please check jail has possibly a timezone issue. Line with odd timestamp: %s", 
+						 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))
 					# 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",
+						("Ignoring all log entries older than %ss; these are probably" +
-							date, MyTime.time(), self.getFindTime()),
+						 " messages generated while fail2ban was not running.",
-						("Please check jail has possibly a timezone issue. Line with odd timestamp: %s", 
+							self.getFindTime()),
+						("Please check a jail for a timing issue. Line with odd timestamp: %s",
 						 line))
 					# ignore - too old (obsolete) entry:
 					return []
@@ -1019,9 +1031,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
@@ -1141,9 +1150,15 @@ class FileFilter(Filter):
 					self.processLineAndAdd(line)
 		finally:
 			log.close()
-		db = self.jail.database
+		if self.jail.database is not None:
-		if db is not None:
+			self._pendDBUpdates[log] = 1
-			db.updateLog(self.jail, log)
+			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
 
 	##
@@ -1245,12 +1260,33 @@ class FileFilter(Filter):
 		ret.append(("File list", path))
 		return ret
 
-	def stop(self):
+	def _updateDBPending(self):
-		"""Stop monitoring of log-file(s)
+		"""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()
 
@@ -1311,6 +1347,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
 

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")
 
@@ -92,8 +91,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):
+			# 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']):
+			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 +257,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 +271,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)
 
+		# Save current cursor position (to recognize in operation mode):
+		logentry = None
+		try:
+			self.__journal.seek_tail()
+			logentry = self.__journal.get_previous()
+			self.__journal.get_next()
+		except OSError:
+			logentry = None # Reading failure, so safe to ignore
+		if logentry:
 			# Try to obtain the last known time (position of journal)
-		start_time = 0
+			startTime = 0
 			if self.jail.database is not None:
-			start_time = self.jail.database.getJournalPos(self.jail, 'systemd-journal') or 0
+				startTime = 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()) )
+			startTime = max( startTime, MyTime.time() - int(self.getFindTime()) )
-		self.seekToTime(start_time)
+			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:
@@ -296,6 +320,7 @@ 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:
+				if not logentry:
 					Utils.wait_for(lambda: not self.active or \
 						self.__journal.wait(Utils.DEFAULT_SLEEP_INTERVAL) != journal.NOP,
 						self.sleeptime, 0.00001)
@@ -317,26 +342,43 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover
 							e, exc_info=logSys.getEffectiveLevel() <= logging.DEBUG)
 					self.ticks += 1
 					if logentry:
-						line = self.formatJournalEntry(logentry)
+						line, tm = self.formatJournalEntry(logentry)
-						self.processLineAndAdd(*line)
+						# 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:
 					self.performSvc()
 				# update position in log (time and iso string):
-				if (line and self.jail.database and (
+				if self.jail.database:
-				    self.ticks % 10 == 0
+					if line:
-				    or MyTime.time() >= self.__nextUpdateTM
+						self._pendDBUpdates['systemd-journal'] = (tm, line[1])
-				    or not self.active
-				  )
-				):
-					self.jail.database.updateJournal(self.jail, 'systemd-journal', line[1], line[0][1])
-					self.__nextUpdateTM = MyTime.time() + Utils.DEFAULT_SLEEP_TIME * 5
 						line = None
+					if self._pendDBUpdates and (
+				    self.ticks % 100 == 0
+				    or MyTime.time() >= self._nextUpdateTM
+				    or not self.active
+				  ):
+						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
@@ -363,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()
+

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.
 		"""

fail2ban/server/mytime.py

@@ -174,3 +174,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__()

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)),
+				logtime = (MyTime.seconds2str(btime), MyTime.time2str(bendtime))
-					MyTime.time2str(bendtime))
 				# check ban is not too old :
 				if bendtime < MyTime.time():
 					logSys.debug('Ignore old bantime %s', logtime[1])

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

fail2ban/tests/filtertestcase.py

@@ -445,11 +445,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)
@@ -458,15 +458,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",
+				"Detected a log entry 1h before the current time in operation mode. This looks like a timezone problem.",
-				"Please check jail has possibly a timezone issue.",
+				"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 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)
 			self.assertNotLogged("Found a match but no valid date/time found")
@@ -479,6 +482,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()
 
@@ -1386,7 +1412,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)
@@ -1527,9 +1553,33 @@ 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()
+			self.waitForTicks(1); # wait for start
 			# Smoke test for removing of match
 
 			# basic full test
@@ -1562,6 +1612,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)

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')

fail2ban/tests/servertestcase.py

@@ -1859,18 +1859,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`",
 				),
@@ -1938,21 +1938,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`",
 				),
@@ -2009,32 +2009,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`""",
 				),					
 			}),
 		)