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/config/action.d/firewallcmd-ipset.conf b/config/action.d/firewallcmd-ipset.conf index e1cb67e7..eaebdb3a 100644 --- a/config/action.d/firewallcmd-ipset.conf +++ b/config/action.d/firewallcmd-ipset.conf @@ -102,7 +102,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/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 = 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 diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index 138b3f0f..6f1572ef 100644 --- a/fail2ban/server/filter.py +++ b/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,30 +660,37 @@ 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: + # 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 %s %s the current time in operation mode. " + "This looks like a %s problem. Treating such entries as if they just happened.", + 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", - 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 [] @@ -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 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 ## @@ -1245,12 +1260,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() @@ -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 diff --git a/fail2ban/server/filtersystemd.py b/fail2ban/server/filtersystemd.py index 88f8c292..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") @@ -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): - 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 +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) - # 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: @@ -296,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: @@ -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) - 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: 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', line[1], line[0][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 @@ -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() + 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. """ diff --git a/fail2ban/server/mytime.py b/fail2ban/server/mytime.py index e4b091a7..377fd821 100644 --- a/fail2ban/server/mytime.py +++ b/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__() diff --git a/fail2ban/server/observer.py b/fail2ban/server/observer.py index 996eec4a..241c677e 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]) 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 diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 183bc98e..61616225 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/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 $') 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", - "Please check jail has possibly a timezone issue.", + "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.", 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) @@ -1448,7 +1474,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 @@ -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) diff --git a/fail2ban/tests/misctestcase.py b/fail2ban/tests/misctestcase.py index 559a89f3..d6fdee65 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') diff --git a/fail2ban/tests/servertestcase.py b/fail2ban/tests/servertestcase.py index 1c80fab8..0ea1c757 100644 --- a/fail2ban/tests/servertestcase.py +++ b/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`""", ), }), )