diff --git a/fail2ban/client/beautifier.py b/fail2ban/client/beautifier.py index bd803a6a..2d2c0caf 100644 --- a/fail2ban/client/beautifier.py +++ b/fail2ban/client/beautifier.py @@ -46,7 +46,7 @@ class Beautifier: return self.__inputCmd def beautify(self, response): - logSys.debug( + logSys.log(5, "Beautify " + repr(response) + " with " + repr(self.__inputCmd)) inC = self.__inputCmd msg = response diff --git a/fail2ban/client/fail2banclient.py b/fail2ban/client/fail2banclient.py index 788906aa..9bc1525e 100755 --- a/fail2ban/client/fail2banclient.py +++ b/fail2ban/client/fail2banclient.py @@ -91,7 +91,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): client = CSocket(self._conf["socket"]) ret = client.send(c) if ret[0] == 0: - logSys.debug("OK : %r", ret[1]) + logSys.log(5, "OK : %r", ret[1]) if showRet or c[0] == 'echo': output(beautifier.beautify(ret[1])) else: @@ -104,7 +104,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): if showRet or c != ["ping"]: self.__logSocketError() else: - logSys.debug(" -- ping failed -- %r", e) + logSys.log(5, " -- ping failed -- %r", e) return False except Exception as e: # pragma: no cover if showRet or self._conf["verbose"] > 1: @@ -226,11 +226,11 @@ class Fail2banClient(Fail2banCmdLine, Thread): # prepare: read config, check configuration is valid, etc.: if phase is not None: phase['start'] = True - logSys.debug(' client phase %s', phase) + logSys.log(5, ' client phase %s', phase) stream = self.__prepareStartServer() if phase is not None: phase['ready'] = phase['start'] = (True if stream else False) - logSys.debug(' client phase %s', phase) + logSys.log(5, ' client phase %s', phase) if not stream: return False # configure server with config stream: @@ -246,6 +246,10 @@ class Fail2banClient(Fail2banCmdLine, Thread): # @param cmd the command line def __processCommand(self, cmd): + # wrap tuple to list (because could be modified here): + if not isinstance(cmd, list): + cmd = list(cmd) + # process: if len(cmd) == 1 and cmd[0] == "start": ret = self.__startServer(self._conf["background"]) @@ -253,8 +257,12 @@ class Fail2banClient(Fail2banCmdLine, Thread): return False return ret - elif len(cmd) == 1 and cmd[0] == "restart": - + elif len(cmd) >= 1 and cmd[0] == "restart": + # if restart jail - re-operate via "reload --restart ...": + if len(cmd) > 1: + cmd[0:1] = ["reload", "--restart"] + return self.__processCommand(cmd) + # restart server: if self._conf.get("interactive", False): output(' ## stop ... ') self.__processCommand(['stop']) @@ -273,9 +281,21 @@ class Fail2banClient(Fail2banCmdLine, Thread): return self.__processCommand(['start']) elif len(cmd) >= 1 and cmd[0] == "reload": + # reload options: + opts = [] + while len(cmd) >= 2: + if cmd[1] in ('--restart', "--unban", "--if-exists"): + opts.append(cmd[1]) + del cmd[1] + else: + if len(cmd) > 2: + logSys.error("Unexpected argument(s) for reload: %r", cmd[1:]) + return False + # stop options - jail name or --all + break if self.__ping(): if len(cmd) == 1: - jail = 'all' + jail = '--all' ret, stream = self.readConfig() else: jail = cmd[1] @@ -283,9 +303,10 @@ class Fail2banClient(Fail2banCmdLine, Thread): # Do not continue if configuration is not 100% valid if not ret: return False - self.__processCmd([['stop', jail]], False) - # Configure the server - return self.__processCmd(stream, True) + if self._conf.get("interactive", False): + output(' ## reload ... ') + # Reconfigure the server + return self.__processCmd([['reload', jail, opts, stream]], True) else: logSys.error("Could not find server") return False @@ -320,7 +341,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): maxtime = self._conf["timeout"] # Wait for the server to start (the server has 30 seconds to answer ping) starttime = time.time() - logSys.debug("__waitOnServer: %r", (alive, maxtime)) + logSys.log(5, "__waitOnServer: %r", (alive, maxtime)) test = lambda: os.path.exists(self._conf["socket"]) and self.__ping() with VisualWait(self._conf["verbose"]) as vis: sltime = 0.0125 / 2 diff --git a/fail2ban/protocol.py b/fail2ban/protocol.py index d671f3c3..147cd38d 100644 --- a/fail2ban/protocol.py +++ b/fail2ban/protocol.py @@ -49,8 +49,11 @@ protocol = [ ['', "BASIC", ""], ["start", "starts the server and the jails"], ["restart", "restarts the server"], -["reload", "reloads the configuration without restart"], -["reload ", "reloads the jail "], +["restart [--unban] [--if-exists] ", "restarts the jail (alias for 'reload --restart ... ')"], +["reload [--restart] [--unban] [--all]", "reloads the configuration without restarting of the server, the option '--restart' activates completely restarting of affected jails, thereby unbans IP addresses (if option '--unban' specified)"], +["reload [--restart] [--unban] [--if-exists] ", "reloads the jail , or restarts it (if option '--restart' specified)"], +["unban --all", "unbans all IP addresses (in all jails)"], +["unban ... ", "unbans (in all jails)"], ["stop", "stops all jails and terminate the server"], ["status", "gets the current status of the server"], ["ping", "tests if the server is alive"], diff --git a/fail2ban/server/actions.py b/fail2ban/server/actions.py index 050c12e6..2fab02cd 100644 --- a/fail2ban/server/actions.py +++ b/fail2ban/server/actions.py @@ -180,7 +180,7 @@ class Actions(JailThread, Mapping): def getBanTime(self): return self.__banManager.getBanTime() - def removeBannedIP(self, ip): + def removeBannedIP(self, ip=None, db=True, ifexists=False): """Removes banned IP calling actions' unban method Remove a banned IP now, rather than waiting for it to expire, @@ -188,16 +188,20 @@ class Actions(JailThread, Mapping): Parameters ---------- - ip : str or IPAddr - The IP address to unban + ip : str or IPAddr or None + The IP address to unban or all IPs if None Raises ------ ValueError If `ip` is not banned """ + # Unban all? + if ip is None: + return self.__flushBan(db) + # Single IP: # Always delete ip from database (also if currently not banned) - if self._jail.database is not None: + if db and self._jail.database is not None: self._jail.database.delBan(self._jail, ip) # Find the ticket with the IP. ticket = self.__banManager.getTicketByIP(ip) @@ -205,7 +209,11 @@ class Actions(JailThread, Mapping): # Unban the IP. self.__unBan(ticket) else: - raise ValueError("IP %s is not banned" % ip) + if ifexists: + return 0 + raise ValueError("%s is not banned" % ip) + return 1 + def run(self): """Main loop for Threading. @@ -336,14 +344,21 @@ class Actions(JailThread, Mapping): for ticket in self.__banManager.unBanList(MyTime.time()): self.__unBan(ticket) - def __flushBan(self): + def __flushBan(self, db=False): """Flush the ban list. Unban all IP address which are still in the banning list. """ logSys.debug("Flush ban list") - for ticket in self.__banManager.flushBanList(): + lst = self.__banManager.flushBanList() + for ticket in lst: + # delete ip from database also: + if db and self._jail.database is not None: + ip = str(ticket.getIP()) + self._jail.database.delBan(self._jail, ip) + # unban ip: self.__unBan(ticket) + return len(lst) def __unBan(self, ticket): """Unbans host corresponding to the ticket. diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index e689ff00..4c67470e 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -88,8 +88,9 @@ class Filter(JailThread): self.__ignoreCommand = False ## Default or preferred encoding (to decode bytes from file or journal): self.__encoding = locale.getpreferredencoding() - ## Error counter - self.__errors = 0 + ## Error counter (protected, so can be used in filter implementations) + ## if it reached 100 (at once), run-cycle will go idle + self._errors = 0 ## Ticks counter self.ticks = 0 @@ -100,6 +101,30 @@ class Filter(JailThread): def __repr__(self): return "%s(%r)" % (self.__class__.__name__, self.jail) + def clearAllParams(self): + """ Clear all lists/dicts parameters (used by reloading) + """ + self.delFailRegex() + self.delIgnoreRegex() + self.delIgnoreIP() + + def reload(self, begin=True): + """ Begin or end of reloading resp. refreshing of all parameters + """ + if begin: + self.clearAllParams() + if hasattr(self, 'getLogPaths'): + self._reload_logs = dict((k, 1) for k in self.getLogPaths()) + else: + if hasattr(self, '_reload_logs'): + dellogs = dict() + # if it was not reloaded - remove obsolete log file: + for path in self._reload_logs: + self.delLogPath(path) + delattr(self, '_reload_logs') + + + ## # Add a regular expression which matches the failure. # @@ -119,8 +144,13 @@ class Filter(JailThread): logSys.error(e) raise e - def delFailRegex(self, index): + def delFailRegex(self, index=None): try: + # clear all: + if index is None: + del self.__failRegex[:] + return + # delete by index: del self.__failRegex[index] except IndexError: logSys.error("Cannot remove regular expression. Index %d is not " @@ -152,8 +182,13 @@ class Filter(JailThread): logSys.error(e) raise e - def delIgnoreRegex(self, index): + def delIgnoreRegex(self, index=None): try: + # clear all: + if index is None: + del self.__ignoreRegex[:] + return + # delete by index: del self.__ignoreRegex[index] except IndexError: logSys.error("Cannot remove regular expression. Index %d is not " @@ -203,7 +238,7 @@ class Filter(JailThread): value = MyTime.str2seconds(value) self.__findTime = value self.failManager.setMaxTime(value) - logSys.info("Set findtime = %s" % value) + logSys.info(" findtime: %s", value) ## # Get the time needed to find a failure. @@ -232,10 +267,10 @@ class Filter(JailThread): template = DatePatternRegex(pattern) self.dateDetector = DateDetector() self.dateDetector.appendTemplate(template) - logSys.info("Date pattern set to `%r`: `%s`" % - (pattern, template.name)) - logSys.debug("Date pattern regex for %r: %s" % - (pattern, template.regex)) + logSys.info(" date pattern `%r`: `%s`", + pattern, template.name) + logSys.debug(" date pattern regex for %r: %s", + pattern, template.regex) ## # Get the date detector pattern, or Default Detectors if not changed @@ -261,7 +296,7 @@ class Filter(JailThread): def setMaxRetry(self, value): self.failManager.setMaxRetry(value) - logSys.info("Set maxRetry = %s" % value) + logSys.info(" maxRetry: %s", value) ## # Get the maximum retry value. @@ -280,7 +315,7 @@ class Filter(JailThread): if int(value) <= 0: raise ValueError("maxlines must be integer greater than zero") self.__lineBufferSize = int(value) - logSys.info("Set maxlines = %i" % self.__lineBufferSize) + logSys.info(" maxLines: %i", self.__lineBufferSize) ## # Get the maximum line buffer size. @@ -300,7 +335,7 @@ class Filter(JailThread): encoding = locale.getpreferredencoding() codecs.lookup(encoding) # Raise LookupError if invalid codec self.__encoding = encoding - logSys.info("Set jail log file encoding to %s" % encoding) + logSys.info(" encoding: %s" % encoding) return encoding ## @@ -375,11 +410,16 @@ class Filter(JailThread): ip = IPAddr(ipstr) # log and append to ignore list - logSys.debug("Add %r to ignore list (%r)", ip, ipstr) + logSys.debug(" Add %r to ignore list (%r)", ip, ipstr) self.__ignoreIpList.append(ip) - def delIgnoreIP(self, ip): - logSys.debug("Remove %r from ignore list", ip) + def delIgnoreIP(self, ip=None): + # clear all: + if ip is None: + del self.__ignoreIpList[:] + return + # delete by ip: + logSys.debug(" Remove %r from ignore list", ip) self.__ignoreIpList.remove(ip) def logIgnoreIp(self, ip, log_ignore, ignore_source="unknown source"): @@ -483,18 +523,18 @@ class Filter(JailThread): tick = FailTicket(ip, unixTime, lines, data=fail) self.failManager.addFailure(tick) # reset (halve) error counter (successfully processed line): - if self.__errors: - self.__errors //= 2 + if self._errors: + self._errors //= 2 except Exception as e: logSys.error("Failed to process line: %r, caught exception: %r", line, e, exc_info=logSys.getEffectiveLevel()<=logging.DEBUG) # incr error counter, stop processing (going idle) after 100th error : - self.__errors += 1 + self._errors += 1 # sleep a little bit (to get around time-related errors): time.sleep(self.sleeptime) - if self.__errors >= 100: - logSys.error("Too many errors at once (%s), going idle", self.__errors) - self.__errors //= 2 + if self._errors >= 100: + logSys.error("Too many errors at once (%s), going idle", self._errors) + self._errors //= 2 self.idle = True ## @@ -657,7 +697,10 @@ class FileFilter(Filter): def addLogPath(self, path, tail=False, autoSeek=True): if path in self.__logs: - logSys.error(path + " already exists") + if hasattr(self, '_reload_logs') and path in self._reload_logs: + del self._reload_logs[path] + else: + logSys.error(path + " already exists") else: log = FileContainer(path, self.getLogEncoding(), tail) db = self.jail.database @@ -666,7 +709,7 @@ class FileFilter(Filter): if lastpos and not tail: log.setPos(lastpos) self.__logs[path] = log - logSys.info("Added logfile = %s (pos = %s, hash = %s)" , path, log.getPos(), log.getHash()) + logSys.info("Added logfile: %r (pos = %s, hash = %s)" , path, log.getPos(), log.getHash()) if autoSeek: # if default, seek to "current time" - "find time": if isinstance(autoSeek, bool): @@ -692,7 +735,7 @@ class FileFilter(Filter): db = self.jail.database if db is not None: db.updateLog(self.jail, log) - logSys.info("Removed logfile = %s" % path) + logSys.info("Removed logfile: %r" % path) self._delLogPath(path) return @@ -1055,10 +1098,14 @@ _decode_line_warn = {} class JournalFilter(Filter): # pragma: systemd no cover + def clearAllParams(self): + super(JournalFilter, self).clearAllParams() + self.delJournalMatch() + def addJournalMatch(self, match): # pragma: no cover - Base class, not used pass - def delJournalMatch(self, match): # pragma: no cover - Base class, not used + def delJournalMatch(self, match=None): # pragma: no cover - Base class, not used pass def getJournalMatch(self, match): # pragma: no cover - Base class, not used diff --git a/fail2ban/server/filterpoll.py b/fail2ban/server/filterpoll.py index 336807d4..f66be42b 100644 --- a/fail2ban/server/filterpoll.py +++ b/fail2ban/server/filterpoll.py @@ -31,7 +31,7 @@ from .failmanager import FailManagerEmpty from .filter import FileFilter from .mytime import MyTime from .utils import Utils -from ..helpers import getLogger +from ..helpers import getLogger, logging # Gets the instance of the logger. @@ -137,28 +137,34 @@ class FilterPoll(FileFilter): try: logStats = os.stat(filename) stats = logStats.st_mtime, logStats.st_ino, logStats.st_size - pstats = self.__prevStats.get(filename, ()) - self.__file404Cnt[filename] = 0 + pstats = self.__prevStats.get(filename, (0)) if logSys.getEffectiveLevel() <= 7: # we do not want to waste time on strftime etc if not necessary dt = logStats.st_mtime - pstats[0] logSys.log(7, "Checking %s for being modified. Previous/current stats: %s / %s. dt: %s", filename, pstats, stats, dt) # os.system("stat %s | grep Modify" % filename) + self.__file404Cnt[filename] = 0 if pstats == stats: return False logSys.debug("%s has been modified", filename) self.__prevStats[filename] = stats return True - except OSError as e: - logSys.error("Unable to get stat on %s because of: %s" - % (filename, e)) + except Exception as e: + # stil alive (may be deleted because multi-threaded): + if not self.getLog(filename): + logSys.warning("Log %r seems to be down: %s", filename, e) + return + # log error: + if self.__file404Cnt[filename] < 2: + logSys.error("Unable to get stat on %s because of: %s", + filename, e, + exc_info=logSys.getEffectiveLevel()<=logging.DEBUG) + # increase file and common error counters: self.__file404Cnt[filename] += 1 - if self.__file404Cnt[filename] > 2: - logSys.warning("Too many errors. Setting the jail idle") - if self.jail is not None: - self.jail.idle = True - else: - logSys.warning("No jail is assigned to %s" % self) + self._errors += 1 + if self.__file404Cnt[filename] > 50: + logSys.warning("Too many errors. Remove file %r from monitoring process", filename) self.__file404Cnt[filename] = 0 + self.delLogPath(filename) return False diff --git a/fail2ban/server/filtersystemd.py b/fail2ban/server/filtersystemd.py index 487af793..0b6c4074 100644 --- a/fail2ban/server/filtersystemd.py +++ b/fail2ban/server/filtersystemd.py @@ -154,12 +154,16 @@ class FilterSystemd(JournalFilter): # pragma: systemd no cover # # @param match journalctl syntax matches - def delJournalMatch(self, match): - if match in self.__matches: + def delJournalMatch(self, match=None): + # clear all: + if match is None: + del self.__matches[:] + # delete by index: + elif match in self.__matches: del self.__matches[self.__matches.index(match)] - self.resetJournalMatches() else: raise ValueError("Match not found") + self.resetJournalMatches() logSys.info("Removed journal match for: %r" % " ".join(match)) ## diff --git a/fail2ban/server/jail.py b/fail2ban/server/jail.py index 92f8190e..a5dc1119 100644 --- a/fail2ban/server/jail.py +++ b/fail2ban/server/jail.py @@ -79,6 +79,7 @@ class Jail(object): logSys.info("Creating new jail '%s'" % self.name) if backend is not None: self._setBackend(backend) + self.backend = backend def __repr__(self): return "%s(%r)" % (self.__class__.__name__, self.name) @@ -220,7 +221,7 @@ class Jail(object): jail=self, bantime=self.actions.getBanTime()): if not self.filter.inIgnoreIPList(ticket.getIP(), log_ignore=True): self.__queue.put(ticket) - logSys.info("Jail '%s' started" % self.name) + logSys.info("Jail %r started", self.name) def stop(self): """Stop the jail, by stopping filter and actions threads. diff --git a/fail2ban/server/jails.py b/fail2ban/server/jails.py index 675b6276..972a8c4b 100644 --- a/fail2ban/server/jails.py +++ b/fail2ban/server/jails.py @@ -62,14 +62,15 @@ class Jails(Mapping): DuplicateJailException If jail name is already present. """ - try: - self.__lock.acquire() + with self.__lock: if name in self._jails: - raise DuplicateJailException(name) + if noduplicates: + raise DuplicateJailException(name) else: self._jails[name] = Jail(name, backend, db) - finally: - self.__lock.release() + + def exists(self, name): + return name in self._jails def __getitem__(self, name): try: diff --git a/fail2ban/server/server.py b/fail2ban/server/server.py index 51487ed7..041b0983 100644 --- a/fail2ban/server/server.py +++ b/fail2ban/server/server.py @@ -67,6 +67,7 @@ class Server: self.__db = None self.__daemon = daemon self.__transm = Transmitter(self) + self.__reload_state = {} #self.__asyncServer = AsyncServer(self.__transm) self.__asyncServer = None self.__logLevel = None @@ -184,41 +185,105 @@ class Server: self.quit = lambda: False def addJail(self, name, backend): - self.__jails.add(name, backend, self.__db) + addflg = True + if self.__reload_state.get(name) and self.__jails.exists(name): + jail = self.__jails[name] + # if backend switch - restart instead of reload: + if jail.backend == backend: + addflg = False + logSys.info("Reload jail %r", name) + # prevent to reload the same jail twice (temporary keep it in state, needed to commit reload): + self.__reload_state[name] = None + else: + logSys.info("Restart jail %r (reason: %r != %r)", name, jail.backend, backend) + self.delJail(name, stop=True) + # prevent to start the same jail twice (no reload more - restart): + del self.__reload_state[name] + if addflg: + self.__jails.add(name, backend, self.__db) if self.__db is not None: self.__db.addJail(self.__jails[name]) - def delJail(self, name): + def delJail(self, name, stop=True): + jail = self.__jails[name] + if stop and jail.isAlive(): + logSys.debug("Stopping jail %r" % name) + jail.stop() if self.__db is not None: - self.__db.delJail(self.__jails[name]) + self.__db.delJail(jail) del self.__jails[name] def startJail(self, name): - try: - self.__lock.acquire() - if not self.__jails[name].isAlive(): - self.__jails[name].start() - finally: - self.__lock.release() + with self.__lock: + jail = self.__jails[name] + if not jail.isAlive(): + jail.start() + elif name in self.__reload_state: + logSys.info("Jail %r reloaded", name) + del self.__reload_state[name] + if jail.idle: + jail.idle = False def stopJail(self, name): - logSys.debug("Stopping jail %s" % name) - try: - self.__lock.acquire() - if self.__jails[name].isAlive(): - self.__jails[name].stop() - self.delJail(name) - finally: - self.__lock.release() + with self.__lock: + self.delJail(name, stop=True) def stopAllJail(self): logSys.info("Stopping all jails") - try: - self.__lock.acquire() - for jail in self.__jails.keys(): - self.stopJail(jail) - finally: - self.__lock.release() + with self.__lock: + for name in self.__jails.keys(): + self.delJail(name, stop=True) + + def reloadJails(self, name, opts, begin): + if begin: + # begin reload: + if self.__reload_state and (name == '--all' or self.__reload_state.get(name)): + raise ValueError('Reload already in progress') + logSys.info("Reload " + (("jail %s" % name) if name != '--all' else "all jails")) + with self.__lock: + # if single jail: + if name != '--all': + jail = None + # test jail exists (throws exception if not): + if "--if-exists" not in opts or self.__jails.exists(name): + jail = self.__jails[name] + if jail: + # first unban all ips (will be not restored after (re)start): + if "--unban" in opts: + self.setUnbanIP(name) + # stop if expected: + if "--restart" in opts: + self.stopJail(name) + else: + # first unban all ips (will be not restored after (re)start): + if "--unban" in opts: + self.setUnbanIP() + # stop if expected: + if "--restart" in opts: + self.stopAllJail() + # first set all affected jail(s) to idle and reset filter regex and other lists/dicts: + for jn, jail in self.__jails.iteritems(): + if name == '--all' or jn == name: + jail.idle = True + self.__reload_state[jn] = jail + jail.filter.reload(begin=True) + pass + else: + # end reload, all affected (or new) jails have already all new parameters (via stream) and (re)started: + with self.__lock: + deljails = [] + for jn, jail in self.__jails.iteritems(): + # still in reload state: + if jn in self.__reload_state: + # remove jails that are not reloaded (untouched, so not in new configuration) + deljails.append(jn) + else: + # commit (reload was finished): + jail.filter.reload(begin=False) + for jn in deljails: + self.delJail(jn) + self.__reload_state = {} + logSys.info("Reload finished.") def setIdleJail(self, name, value): self.__jails[name].idle = value @@ -309,7 +374,7 @@ class Server: logSys.debug(" failregex: %r", value) flt.addFailRegex(value) - def delFailRegex(self, name, index): + def delFailRegex(self, name, index=None): self.__jails[name].filter.delFailRegex(index) def getFailRegex(self, name): @@ -368,8 +433,20 @@ class Server: def setBanIP(self, name, value): return self.__jails[name].filter.addBannedIP(value) - def setUnbanIP(self, name, value): - self.__jails[name].actions.removeBannedIP(value) + def setUnbanIP(self, name=None, value=None): + if name is not None: + # in all jails: + jails = [self.__jails[name]] + else: + # single jail: + jails = self.__jails.values() + # unban given or all (if value is None): + cnt = 0 + for jail in jails: + cnt += jail.actions.removeBannedIP(value, ifexists=(name is None)) + if value and not cnt: + logSys.info("%s is not banned", value) + return cnt def getBanTime(self, name): return self.__jails[name].actions.getBanTime() @@ -420,7 +497,10 @@ class Server: if self.__logLevel == value: return try: - getLogger("fail2ban").setLevel(getattr(logging, value)) + ll = getattr(logging, value) + # don't change real log-level if running from the test cases: + getLogger("fail2ban").setLevel( + ll if DEF_LOGTARGET != "INHERITED" or ll < logging.DEBUG else DEF_LOGLEVEL) self.__logLevel = value except AttributeError: raise ValueError("Invalid log level %r" % value) diff --git a/fail2ban/server/transmitter.py b/fail2ban/server/transmitter.py index 698dad34..19cf51ef 100644 --- a/fail2ban/server/transmitter.py +++ b/fail2ban/server/transmitter.py @@ -27,7 +27,7 @@ __license__ = "GPL" import time import json -from ..helpers import getLogger +from ..helpers import getLogger, logging from .. import version # Gets the instance of the logger. @@ -52,13 +52,14 @@ class Transmitter: def proceed(self, command): # Deserialize object - logSys.debug("Command: %r", command) + logSys.log(5, "Command: %r", command) try: ret = self.__commandHandler(command) ack = 0, ret except Exception as e: - logSys.warning("Command %r has failed. Received %r" - % (command, e)) + logSys.warning("Command %r has failed. Received %r", + command, e, + exc_info=logSys.getEffectiveLevel()<=logging.DEBUG) ack = 1, e return ack @@ -72,8 +73,8 @@ class Transmitter: return "pong" elif command[0] == "add": name = command[1] - if name == "all": - raise Exception("Reserved name") + if name == "--all": + raise Exception("Reserved name %r" % (name,)) try: backend = command[2] except IndexError: @@ -87,12 +88,31 @@ class Transmitter: elif command[0] == "stop": if len(command) == 1: self.__server.quit() - elif command[1] == "all": + elif command[1] == "--all": self.__server.stopAllJail() else: name = command[1] self.__server.stopJail(name) return None + elif command[0] == "reload": + opts = command[1:3] + try: + self.__server.reloadJails(*opts, begin=True) + for cmd in command[3]: + self.__commandHandler(cmd) + finally: + self.__server.reloadJails(*opts, begin=False) + return None + elif len(command) >= 2 and command[0] == "unban": + # unban in all jails: + value = command[1:] + # if all ips: + if len(value) == 1 and value[0] == "--all": + self.__server.setUnbanIP() + return + for value in value: + self.__server.setUnbanIP(None, value) + return None elif command[0] == "echo": return command[1:] elif command[0] == "sleep": @@ -265,7 +285,7 @@ class Transmitter: action = self.__server.getAction(name, actionname) if multiple: for cmd in command[3]: - logSys.debug(" %r", cmd) + logSys.log(5, " %r", cmd) actionkey = cmd[0] if callable(getattr(action, actionkey, None)): actionvalue = json.loads(cmd[1]) if len(cmd)>1 else {} diff --git a/fail2ban/tests/fail2banclienttestcase.py b/fail2ban/tests/fail2banclienttestcase.py index 6d4691fe..557f0ada 100644 --- a/fail2ban/tests/fail2banclienttestcase.py +++ b/fail2ban/tests/fail2banclienttestcase.py @@ -43,7 +43,7 @@ from .. import protocol from ..server import server from ..server.mytime import MyTime from ..server.utils import Utils -from .utils import LogCaptureTestCase, with_tmpdir, shutil, logging +from .utils import LogCaptureTestCase, logSys as DefLogSys, with_tmpdir, shutil, logging from ..helpers import getLogger @@ -69,7 +69,8 @@ fail2bancmdline.logSys = \ fail2banclient.logSys = \ fail2banserver.logSys = logSys -server.DEF_LOGTARGET = "/dev/null" +SRV_DEF_LOGTARGET = server.DEF_LOGTARGET +SRV_DEF_LOGLEVEL = server.DEF_LOGLEVEL def _test_output(*args): logSys.info(args[0]) @@ -111,17 +112,25 @@ fail2bancmdline.PRODUCTION = \ fail2banserver.PRODUCTION = False -def _out_file(fn): +def _out_file(fn, handle=logSys.debug): """Helper which outputs content of the file at HEAVYDEBUG loglevels""" - logSys.debug('---- ' + fn + ' ----') + handle('---- ' + fn + ' ----') for line in fileinput.input(fn): line = line.rstrip('\n') - logSys.debug(line) - logSys.debug('-'*30) + handle(line) + handle('-'*30) -def _start_params(tmp, use_stock=False, logtarget="/dev/null"): +def _write_file(fn, mode, *lines): + f = open(fn, mode) + f.write('\n'.join(lines)) + f.close() + + +def _start_params(tmp, use_stock=False, logtarget="/dev/null", db=":memory:"): cfg = pjoin(tmp, "config") + if db == 'auto': + db = pjoin(tmp, "f2b-db.sqlite3") if use_stock and STOCK: # copy config (sub-directories as alias): def ig_dirs(dir, files): @@ -147,8 +156,7 @@ def _start_params(tmp, use_stock=False, logtarget="/dev/null"): else: # just empty config directory without anything (only fail2ban.conf/jail.conf): os.mkdir(cfg) - f = open(pjoin(cfg, "fail2ban.conf"), "w") - f.write('\n'.join(( + _write_file(pjoin(cfg, "fail2ban.conf"), "w", "[Definition]", "loglevel = INFO", "logtarget = " + logtarget, @@ -156,19 +164,16 @@ def _start_params(tmp, use_stock=False, logtarget="/dev/null"): "socket = " + pjoin(tmp, "f2b.sock"), "pidfile = " + pjoin(tmp, "f2b.pid"), "backend = polling", - "dbfile = :memory:", + "dbfile = " + db, "dbpurgeage = 1d", "", - ))) - f.close() - f = open(pjoin(cfg, "jail.conf"), "w") - f.write('\n'.join(( + ) + _write_file(pjoin(cfg, "jail.conf"), "w", "[INCLUDES]", "", "[DEFAULT]", "", "", - ))) - f.close() - if logSys.level < logging.DEBUG: # if HEAVYDEBUG + ) + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG _out_file(pjoin(cfg, "fail2ban.conf")) _out_file(pjoin(cfg, "jail.conf")) # parameters (sock/pid and config, increase verbosity, set log, etc.): @@ -238,19 +243,78 @@ def with_kill_srv(f): _kill_srv(pidfile) return wrapper +def with_foreground_server_thread(startextra={}): + """Helper to decorate tests uses foreground server (as thread), started directly in test-cases + + To be used only in subclasses + """ + def _deco_wrapper(f): + @with_tmpdir + @wraps(f) + def wrapper(self, tmp, *args, **kwargs): + th = None + phase = dict() + try: + # started directly here, so prevent overwrite test cases logger with "INHERITED" + startparams = _start_params(tmp, logtarget="INHERITED", **startextra) + # because foreground block execution - start it in thread: + th = Thread( + name="_TestCaseWorker", + target=self._testStartForeground, + args=(tmp, startparams, phase) + ) + th.daemon = True + th.start() + try: + # wait for start thread: + Utils.wait_for(lambda: phase.get('start', None) is not None, MAX_WAITTIME) + self.assertTrue(phase.get('start', None)) + # wait for server (socket and ready): + self._wait_for_srv(tmp, True, startparams=startparams) + DefLogSys.info('=== within server: begin ===') + self.pruneLog() + # several commands to server in body of decorated function: + return f(self, tmp, startparams, *args, **kwargs) + finally: + DefLogSys.info('=== within server: end. ===') + self.pruneLog() + # stop: + self.execSuccess(startparams, "stop") + # wait for end: + Utils.wait_for(lambda: phase.get('end', None) is not None, MAX_WAITTIME) + self.assertTrue(phase.get('end', None)) + self.assertLogged("Shutdown successful", "Exiting Fail2ban") + finally: + if th: + # we start client/server directly in current process (new thread), + # so don't kill (same process) - if success, just wait for end of worker: + if phase.get('end', None): + th.join() + return wrapper + return _deco_wrapper + class Fail2banClientServerBase(LogCaptureTestCase): _orig_exit = Fail2banCmdLine._exit + def _setLogLevel(self, *args, **kwargs): + pass + def setUp(self): """Call before every test case.""" LogCaptureTestCase.setUp(self) + # prevent to switch the logging in the test cases (use inherited one): + server.DEF_LOGTARGET = "INHERITED" + server.DEF_LOGLEVEL = DefLogSys.level Fail2banCmdLine._exit = staticmethod(self._test_exit) def tearDown(self): """Call after every test case.""" Fail2banCmdLine._exit = self._orig_exit + # restore server log target: + server.DEF_LOGTARGET = SRV_DEF_LOGTARGET + server.DEF_LOGLEVEL = SRV_DEF_LOGLEVEL LogCaptureTestCase.tearDown(self) @staticmethod @@ -304,54 +368,6 @@ class Fail2banClientServerBase(LogCaptureTestCase): phase['end'] = True logSys.debug("end of test worker") - def with_foreground_server_thread(startextra={}): - """Helper to decorate tests uses foreground server (as thread), started directly in test-cases - - To be used only in subclasses - """ - def _deco_wrapper(f): - @with_tmpdir - @wraps(f) - def wrapper(self, tmp, *args, **kwargs): - th = None - phase = dict() - try: - # started directly here, so prevent overwrite test cases logger with "INHERITED" - startparams = _start_params(tmp, logtarget="INHERITED", **startextra) - # because foreground block execution - start it in thread: - th = Thread( - name="_TestCaseWorker", - target=self._testStartForeground, - args=(tmp, startparams, phase) - ) - th.daemon = True - th.start() - try: - # wait for start thread: - Utils.wait_for(lambda: phase.get('start', None) is not None, MAX_WAITTIME) - self.assertTrue(phase.get('start', None)) - # wait for server (socket and ready): - self._wait_for_srv(tmp, True, startparams=startparams) - self.pruneLog() - # several commands to server in body of decorated function: - return f(self, tmp, startparams, *args, **kwargs) - finally: - self.pruneLog() - # stop: - self.execSuccess(startparams, "stop") - # wait for end: - Utils.wait_for(lambda: phase.get('end', None) is not None, MAX_WAITTIME) - self.assertTrue(phase.get('end', None)) - self.assertLogged("Shutdown successful", "Exiting Fail2ban") - finally: - if th: - # we start client/server directly in current process (new thread), - # so don't kill (same process) - if success, just wait for end of worker: - if phase.get('end', None): - th.join() - return wrapper - return _deco_wrapper - @with_foreground_server_thread() def testStartForeground(self, tmp, startparams): # several commands to server: @@ -522,6 +538,24 @@ class Fail2banClientTest(Fail2banClientServerBase): self.assertLogged("Usage: ") self.pruneLog() + @with_tmpdir + def testClientFailCommands(self, tmp): + # started directly here, so prevent overwrite test cases logger with "INHERITED" + startparams = _start_params(tmp, logtarget="INHERITED") + + # not started: + self.execFailed(startparams, + "reload", "jail") + self.assertLogged("Could not find server") + self.pruneLog() + + # unexpected arg: + self.execFailed(startparams, + "--async", "reload", "--xxx", "jail") + self.assertLogged("Unexpected argument(s) for reload:") + self.pruneLog() + + def testVisualWait(self): sleeptime = 0.035 for verbose in (2, 0): @@ -626,3 +660,242 @@ class Fail2banServerTest(Fail2banClientServerBase): # again: self.assertTrue(_kill_srv(tmp)) self.assertLogged("cleanup: no pidfile for") + + @with_foreground_server_thread(startextra={'db': 'auto'}) + def testServerReloadTest(self, tmp, startparams): + """Very complicated test-case, that expected running server (foreground in thread). + + In this test-case, each phase is related from previous one, + so it cannot be splitted in multiple test cases. + + It uses file database (instead of :memory:), to restore bans and log-file positions, + after restart/reload between phases. + """ + cfg = pjoin(tmp, "config") + test1log = pjoin(tmp, "test1.log") + test2log = pjoin(tmp, "test2.log") + test3log = pjoin(tmp, "test3.log") + + def _write_jail_cfg(enabled=[1, 2]): + _write_file(pjoin(cfg, "jail.conf"), "w", + "[INCLUDES]", "", + "[DEFAULT]", "", + "maxretry = 3", + "findtime = 10m", + "failregex = ^\s*failure (401|403) from ", + "", + "[test-jail1]", "backend = polling", "filter =", "action =", + "logpath = " + test1log, + " " + test2log if 2 in enabled else "", + " " + test3log if 2 in enabled else "", + "failregex = ^\s*failure (401|403) from ", + " ^\s*error (401|403) from " if 2 in enabled else "", + "enabled = true" if 1 in enabled else "", + "", + "[test-jail2]", "backend = polling", "filter =", "action =", + "logpath = " + test2log, + "enabled = true" if 2 in enabled else "", + ) + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + _out_file(pjoin(cfg, "jail.conf")) + + _write_jail_cfg(enabled=[1]) + _write_file(test1log, "w", *((str(int(MyTime.time())) + " failure 401 from 192.0.2.1: test 1",) * 3)) + _write_file(test2log, "w") + _write_file(test3log, "w") + + # reload and wait for ban: + self.pruneLog("[test-phase 1]") + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + _out_file(test1log) + self.execSuccess(startparams, "reload") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("[test-jail1] Ban 192.0.2.1"), MAX_WAITTIME / 5.0)) + self.assertLogged("Added logfile: %r" % test1log) + + # enable both jails, 3 logs for jail1, etc... + # truncate test-log - we should not find unban/ban again by reload: + self.pruneLog("[test-phase 2a]") + _write_jail_cfg() + _write_file(test1log, "w+") + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + _out_file(test1log) + self.execSuccess(startparams, "reload") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("Reload finished."), MAX_WAITTIME / 5.0)) + # test not unbanned / banned again: + self.assertNotLogged( + "[test-jail1] Unban 192.0.2.1", + "[test-jail1] Ban 192.0.2.1", all=True) + # test 2 new log files: + self.assertLogged( + "Added logfile: %r" % test2log, + "Added logfile: %r" % test3log, all=True) + # test 1 new jail: + self.assertLogged( + "Creating new jail 'test-jail2'", + "Jail 'test-jail2' started", all=True) + + # write new failures: + self.pruneLog("[test-phase 2b]") + _write_file(test2log, "w+", *( + (str(int(MyTime.time())) + " error 403 from 192.0.2.2: test 2",) * 3 + + (str(int(MyTime.time())) + " error 403 from 192.0.2.3: test 2",) * 3 + + (str(int(MyTime.time())) + " failure 401 from 192.0.2.4: test 2",) * 3 + )) + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + _out_file(test2log) + # test all will be found in jail1 and one in jail2: + self.assertTrue( + Utils.wait_for(lambda: \ + self._is_logged("[test-jail1] Ban 192.0.2.2") and + self._is_logged("[test-jail1] Ban 192.0.2.3") and + self._is_logged("[test-jail1] Ban 192.0.2.4") and + self._is_logged("[test-jail2] Ban 192.0.2.4") + , MAX_WAITTIME / 5.0)) + # test ips at all not visible for jail2: + self.assertNotLogged( + "[test-jail2] Found 192.0.2.2", + "[test-jail2] Ban 192.0.2.2", + "[test-jail2] Found 192.0.2.3", + "[test-jail2] Ban 192.0.2.3", all=True) + + # rotate logs: + _write_file(test1log, "w+") + _write_file(test2log, "w+") + + # restart jail without unban all: + self.pruneLog("[test-phase 2c]") + self.execSuccess(startparams, + "restart", "test-jail2") + self.assertTrue( + Utils.wait_for(lambda: \ + self._is_logged("Jail 'test-jail2' started") and + self._is_logged("[test-jail2] Ban 192.0.2.4") + , MAX_WAITTIME / 5.0)) + # stop/start and ban/unban: + self.assertLogged( + "Jail 'test-jail2' stopped", + "Jail 'test-jail2' started", + "[test-jail2] Unban 192.0.2.4", + "[test-jail2] Ban 192.0.2.4", all=True + ) + + # restart jail with unban all: + self.pruneLog("[test-phase 2d]") + self.execSuccess(startparams, + "restart", "--unban", "test-jail2") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("Jail 'test-jail2' started"), + MAX_WAITTIME / 5.0)) + self.assertLogged( + "Jail 'test-jail2' stopped", + "Jail 'test-jail2' started", + "[test-jail2] Unban 192.0.2.4", all=True + ) + # no more ban (unbanned all): + self.assertNotLogged( + "[test-jail2] Ban 192.0.2.4", all=True + ) + + # reload jail1 without restart (without ban/unban): + self.pruneLog("[test-phase 3]") + self.execSuccess(startparams, "reload", "test-jail1") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("Reload finished."), MAX_WAITTIME / 5.0)) + self.assertLogged( + "Reload jail 'test-jail1'", + "Jail 'test-jail1' reloaded", all=True) + self.assertNotLogged( + "Reload jail 'test-jail2'", + "Jail 'test-jail2' reloaded", + "Jail 'test-jail1' started", all=True + ) + + # whole reload, but this time with jail1 only (jail2 should be stopped via configuration): + self.pruneLog("[test-phase 4]") + _write_jail_cfg(enabled=[1]) + self.execSuccess(startparams, "reload") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("Reload finished."), MAX_WAITTIME / 5.0)) + # test both jails should be reloaded: + self.assertLogged( + "Reload jail 'test-jail1'") + # test jail2 goes down: + self.assertLogged( + "Stopping jail 'test-jail2'", + "Jail 'test-jail2' stopped", all=True) + # test 2 log files removed: + self.assertLogged( + "Removed logfile: %r" % test2log, + "Removed logfile: %r" % test3log, all=True) + + # now write failures again and check already banned (jail1 was alive the whole time) and new bans occurred (jail1 was alive the whole time): + self.pruneLog("[test-phase 5]") + _write_file(test1log, "w+", *( + (str(int(MyTime.time())) + " failure 401 from 192.0.2.1: test 5",) * 3 + + (str(int(MyTime.time())) + " error 403 from 192.0.2.5: test 5",) * 3 + + (str(int(MyTime.time())) + " failure 401 from 192.0.2.6: test 5",) * 3 + )) + if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + _out_file(test1log) + # test "failure" regexp still available: + self.assertTrue( + Utils.wait_for(lambda: \ + self._is_logged("[test-jail1] 192.0.2.1 already banned") and + self._is_logged("[test-jail1] Ban 192.0.2.6") + , MAX_WAITTIME / 5.0)) + self.assertLogged( + "[test-jail1] Found 192.0.2.1", + "[test-jail1] Found 192.0.2.6", all=True + ) + # test "error" regexp no more available: + self.assertNotLogged("[test-jail1] Found 192.0.2.5") + + # unban single ips: + self.pruneLog("[test-phase 6]") + self.execSuccess(startparams, + "--async", "unban", "192.0.2.5", "192.0.2.6") + self.assertLogged( + "192.0.2.5 is not banned", + "[test-jail1] Unban 192.0.2.6", all=True + ) + + # reload all (one jail) with unban all: + self.pruneLog("[test-phase 7]") + self.execSuccess(startparams, + "reload", "--unban") + self.assertTrue( + Utils.wait_for(lambda: self._is_logged("Reload finished."), MAX_WAITTIME / 5.0)) + # reloads unbanned all: + self.assertLogged( + "Jail 'test-jail1' reloaded", + "[test-jail1] Unban 192.0.2.1", + "[test-jail1] Unban 192.0.2.2", + "[test-jail1] Unban 192.0.2.3", + "[test-jail1] Unban 192.0.2.4", all=True + ) + # no restart occurred, no more ban (unbanned all using option "--unban"): + self.assertNotLogged( + "Jail 'test-jail1' stopped", + "Jail 'test-jail1' started", + "[test-jail1] Ban 192.0.2.1", + "[test-jail1] Ban 192.0.2.2", + "[test-jail1] Ban 192.0.2.3", + "[test-jail1] Ban 192.0.2.4", all=True + ) + + # several small cases: + self.pruneLog("[test-phase end-1]") + # wrong jail (not-started): + self.execFailed(startparams, + "--async", "reload", "test-jail2") + self.assertLogged("the jail 'test-jail2' does not exist") + self.pruneLog() + # unavailable jail (but exit 0), using --if-exists option: + self.execSuccess(startparams, + "--async", "reload", "--if-exists", "test-jail2") + self.assertNotLogged( + "Creating new jail 'test-jail2'", + "Jail 'test-jail2' started", all=True) + self.pruneLog() diff --git a/fail2ban/tests/servertestcase.py b/fail2ban/tests/servertestcase.py index 12bbb2f7..3ca8049b 100644 --- a/fail2ban/tests/servertestcase.py +++ b/fail2ban/tests/servertestcase.py @@ -240,7 +240,7 @@ class Transmitter(TransmitterBase): self.transm.proceed(["add", self.jailName, "polling"])[0], 1) # All name is reserved self.assertEqual( - self.transm.proceed(["add", "all", "polling"])[0], 1) + self.transm.proceed(["add", "--all", "polling"])[0], 1) def testStartStopJail(self): self.assertEqual( @@ -267,7 +267,7 @@ class Transmitter(TransmitterBase): self.assertTrue( Utils.wait_for( lambda: self.server.isAlive(2) and not isinstance(self.transm.proceed(["status", self.jailName]), RuntimeError), 3) ) - self.assertEqual(self.transm.proceed(["stop", "all"]), (0, None)) + self.assertEqual(self.transm.proceed(["stop", "--all"]), (0, None)) self.assertTrue( Utils.wait_for( lambda: not len(self.server._Server__jails), 3) ) self.assertNotIn(self.jailName, self.server._Server__jails) self.assertNotIn("TestJail2", self.server._Server__jails) diff --git a/fail2ban/tests/utils.py b/fail2ban/tests/utils.py index bdc1c189..6eaf560b 100644 --- a/fail2ban/tests/utils.py +++ b/fail2ban/tests/utils.py @@ -119,6 +119,7 @@ def getOptParser(doc=""): def initProcess(opts): # Logger: + global logSys logSys = getLogger("fail2ban") # Numerical level of verbosity corresponding to a log "level" @@ -577,7 +578,8 @@ class LogCaptureTestCase(unittest.TestCase): print("") logSys.handlers += self._old_handlers logSys.debug('='*10 + ' %s ' + '='*20, self.id()) - logSys.setLevel(logging.DEBUG) + else: + logSys.setLevel(logging.DEBUG) def tearDown(self): """Call after every test case.""" @@ -638,8 +640,10 @@ class LogCaptureTestCase(unittest.TestCase): if s_ in logged: # pragma: no cover self.fail("%r was found in the log: ===\n%s===" % (s_, logged)) - def pruneLog(self): + def pruneLog(self, logphase=None): self._log.truncate(0) + if logphase: + logSys.debug('='*5 + ' %s ' + '='*5, logphase) def getLog(self): return self._log.getvalue()