diff --git a/config/action.d/badips.py b/config/action.d/badips.py index 4bc879a1..473fbf33 100644 --- a/config/action.d/badips.py +++ b/config/action.d/badips.py @@ -34,7 +34,7 @@ else: from fail2ban.server.actions import ActionBase -class BadIPsAction(ActionBase): +class BadIPsAction(ActionBase): # pragma: no cover - may be unavailable """Fail2Ban action which reports bans to badips.com, and also blacklist bad IPs listed on badips.com by using another action's ban method. @@ -105,6 +105,16 @@ class BadIPsAction(ActionBase): # Used later for threading.Timer for updating badips self._timer = None + @staticmethod + def isAvailable(timeout=1): + try: + response = urlopen(Request("/".join([BadIPsAction._badips]), + headers={'User-Agent': "Fail2Ban"}), timeout=timeout) + return True, '' + except Exception as e: # pragma: no cover + return False, e + + def getCategories(self, incParents=False): """Get badips.com categories. diff --git a/fail2ban/client/beautifier.py b/fail2ban/client/beautifier.py index 2d2c0caf..df44afbb 100644 --- a/fail2ban/client/beautifier.py +++ b/fail2ban/client/beautifier.py @@ -22,7 +22,7 @@ __copyright__ = "Copyright (c) 2004 Cyril Jaquier, 2013- Yaroslav Halchenko" __license__ = "GPL" from ..exceptions import UnknownJailException, DuplicateJailException -from ..helpers import getLogger +from ..helpers import getLogger, logging # Gets the instance of the logger. logSys = getLogger(__name__) @@ -97,16 +97,7 @@ class Beautifier: msg += "`- " + response elif inC[1:2] == ['loglevel']: msg = "Current logging level is " - if response == 1: - msg += "ERROR" - elif response == 2: - msg += "WARN" - elif response == 3: - msg += "INFO" - elif response == 4: - msg += "DEBUG" - else: - msg += repr(response) + msg += repr(logging.getLevelName(response) if isinstance(response, int) else response) elif inC[1] == "dbfile": if response is None: msg = "Database currently disabled" @@ -187,14 +178,12 @@ class Beautifier: msg += ", ".join(response) except Exception: logSys.warning("Beautifier error. Please report the error") - logSys.error("Beautify " + repr(response) + " with " - + repr(self.__inputCmd) + " failed") - msg += repr(response) + logSys.error("Beautify %r with %r failed", response, self.__inputCmd) + msg = repr(msg) + repr(response) return msg def beautifyError(self, response): - logSys.debug("Beautify (error) " + repr(response) + " with " - + repr(self.__inputCmd)) + logSys.debug("Beautify (error) %r with %r", response, self.__inputCmd) msg = response if isinstance(response, UnknownJailException): msg = "Sorry but the jail '" + response.args[0] + "' does not exist" diff --git a/fail2ban/client/csocket.py b/fail2ban/client/csocket.py index 45d58cc6..6b478460 100644 --- a/fail2ban/client/csocket.py +++ b/fail2ban/client/csocket.py @@ -32,10 +32,13 @@ import sys class CSocket: - def __init__(self, sock="/var/run/fail2ban/fail2ban.sock"): + def __init__(self, sock="/var/run/fail2ban/fail2ban.sock", timeout=-1): # Create an INET, STREAMing socket #self.csock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) self.__csock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) + self.__deftout = self.__csock.gettimeout() + if timeout != -1: + self.settimeout(timeout) #self.csock.connect(("localhost", 2222)) self.__csock.connect(sock) @@ -50,6 +53,9 @@ class CSocket: self.__csock.send(obj + CSPROTO.END) return self.receive(self.__csock) + def settimeout(self, timeout): + self.__csock.settimeout(timeout if timeout != -1 else self.__deftout) + def close(self, sendEnd=True): if not self.__csock: return diff --git a/fail2ban/client/fail2banclient.py b/fail2ban/client/fail2banclient.py index 9bc1525e..331c5f34 100755 --- a/fail2ban/client/fail2banclient.py +++ b/fail2ban/client/fail2banclient.py @@ -36,6 +36,8 @@ from .beautifier import Beautifier from .fail2bancmdline import Fail2banCmdLine, ServerExecutionException, ExitException, \ logSys, exit, output +from ..server.utils import Utils + PROMPT = "fail2ban> " @@ -69,8 +71,9 @@ class Fail2banClient(Fail2banCmdLine, Thread): logSys.warning("Caught signal %d. Exiting" % signum) exit(-1) - def __ping(self): - return self.__processCmd([["ping"]], False) + def __ping(self, timeout=0.1): + return self.__processCmd([["ping"] + ([timeout] if timeout != -1 else [])], + False, timeout=timeout) @property def beautifier(self): @@ -79,7 +82,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): self._beautifier = Beautifier() return self._beautifier - def __processCmd(self, cmd, showRet=True): + def __processCmd(self, cmd, showRet=True, timeout=-1): client = None try: beautifier = self.beautifier @@ -88,7 +91,11 @@ class Fail2banClient(Fail2banCmdLine, Thread): beautifier.setInputCmd(c) try: if not client: - client = CSocket(self._conf["socket"]) + client = CSocket(self._conf["socket"], timeout=timeout) + elif timeout != -1: + client.settimeout(timeout) + if self._conf["verbose"] > 2: + logSys.log(5, "CMD: %r", c) ret = client.send(c) if ret[0] == 0: logSys.log(5, "OK : %r", ret[1]) @@ -101,10 +108,10 @@ class Fail2banClient(Fail2banCmdLine, Thread): streamRet = False except socket.error as e: if showRet or self._conf["verbose"] > 1: - if showRet or c != ["ping"]: - self.__logSocketError() + if showRet or c[0] != "ping": + self.__logSocketError(e, c[0] == "ping") else: - logSys.log(5, " -- ping failed -- %r", e) + logSys.log(5, " -- %s failed -- %r", c, e) return False except Exception as e: # pragma: no cover if showRet or self._conf["verbose"] > 1: @@ -125,14 +132,18 @@ class Fail2banClient(Fail2banCmdLine, Thread): sys.stdout.flush() return streamRet - def __logSocketError(self): + def __logSocketError(self, prevError="", errorOnly=False): try: if os.access(self._conf["socket"], os.F_OK): # pragma: no cover # This doesn't check if path is a socket, # but socket.error should be raised if os.access(self._conf["socket"], os.W_OK): # Permissions look good, but socket.error was raised - logSys.error("Unable to contact server. Is it running?") + if errorOnly: + logSys.error(prevError) + else: + logSys.error("%sUnable to contact server. Is it running?", + ("[%s] " % prevError) if prevError else '') else: logSys.error("Permission denied to socket: %s," " (you must be root)", self._conf["socket"]) @@ -188,7 +199,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): # Start the server or just initialize started one: try: if background: - # Start server daemon as fork of client process: + # Start server daemon as fork of client process (or new process): Fail2banServer.startServerAsync(self._conf) # Send config stream to server: if not self.__processStartStreamAfterWait(stream, False): @@ -233,6 +244,11 @@ class Fail2banClient(Fail2banCmdLine, Thread): logSys.log(5, ' client phase %s', phase) if not stream: return False + # wait a litle bit for phase "start-ready" before enter active waiting: + if phase is not None: + Utils.wait_for(lambda: phase.get('start-ready', None) is not None, 0.5, 0.001) + phase['configure'] = (True if stream else False) + logSys.log(5, ' client phase %s', phase) # configure server with config stream: ret = self.__processStartStreamAfterWait(stream, False) if phase is not None: @@ -293,7 +309,7 @@ class Fail2banClient(Fail2banCmdLine, Thread): return False # stop options - jail name or --all break - if self.__ping(): + if self.__ping(timeout=-1): if len(cmd) == 1: jail = '--all' ret, stream = self.readConfig() @@ -311,6 +327,9 @@ class Fail2banClient(Fail2banCmdLine, Thread): logSys.error("Could not find server") return False + elif len(cmd) > 1 and cmd[0] == "ping": + return self.__processCmd([cmd], timeout=float(cmd[1])) + else: return self.__processCmd([cmd]) @@ -342,21 +361,23 @@ class Fail2banClient(Fail2banCmdLine, Thread): # Wait for the server to start (the server has 30 seconds to answer ping) starttime = time.time() logSys.log(5, "__waitOnServer: %r", (alive, maxtime)) - test = lambda: os.path.exists(self._conf["socket"]) and self.__ping() + sltime = 0.0125 / 2 + test = lambda: os.path.exists(self._conf["socket"]) and self.__ping(timeout=sltime) with VisualWait(self._conf["verbose"]) as vis: - sltime = 0.0125 / 2 while self._alive: runf = test() if runf == alive: return True - now = time.time() + waittime = time.time() - starttime + logSys.log(5, " wait-time: %s", waittime) # Wonderful visual :) - if now > starttime + 1: + if waittime > 1: vis.heartbeat() # f end time reached: - if now - starttime >= maxtime: + if waittime >= maxtime: raise ServerExecutionException("Failed to start server") - sltime = min(sltime * 2, 0.5) + # first 200ms faster: + sltime = min(sltime * 2, 0.5 if waittime > 0.2 else 0.1) time.sleep(sltime) return False diff --git a/fail2ban/client/fail2bancmdline.py b/fail2ban/client/fail2bancmdline.py index e1bc5f1e..74236ab1 100644 --- a/fail2ban/client/fail2bancmdline.py +++ b/fail2ban/client/fail2bancmdline.py @@ -27,7 +27,7 @@ import sys from ..version import version from ..protocol import printFormatted -from ..helpers import getLogger +from ..helpers import getLogger, str2LogLevel, getVerbosityFormat # Gets the instance of the logger. logSys = getLogger("fail2ban") @@ -200,8 +200,10 @@ class Fail2banCmdLine(): logSys.setLevel(logging.HEAVYDEBUG) # Add the default logging handler to dump to stderr logout = logging.StreamHandler(sys.stderr) - # set a format which is simpler for console use - formatter = logging.Formatter('%(levelname)-6s %(message)s') + + # Custom log format for the verbose run (-1, because default verbosity here is 1): + fmt = getVerbosityFormat(verbose-1) + formatter = logging.Formatter(fmt) # tell the handler to use this format logout.setFormatter(formatter) logSys.addHandler(logout) @@ -218,8 +220,10 @@ class Fail2banCmdLine(): logSys.info("Using socket file %s", self._conf["socket"]) + # Check log-level before start (or transmit to server), to prevent error in background: + llev = str2LogLevel(self._conf["loglevel"]) logSys.info("Using pid file %s, [%s] logging to %s", - self._conf["pidfile"], self._conf["loglevel"], self._conf["logtarget"]) + self._conf["pidfile"], logging.getLevelName(llev), self._conf["logtarget"]) if self._conf.get("dump", False): ret, stream = self.readConfig() diff --git a/fail2ban/client/fail2banregex.py b/fail2ban/client/fail2banregex.py index f99f9f01..c05006f7 100644 --- a/fail2ban/client/fail2banregex.py +++ b/fail2ban/client/fail2banregex.py @@ -51,7 +51,7 @@ from .filterreader import FilterReader from ..server.filter import Filter, FileContainer from ..server.failregex import RegexException -from ..helpers import FormatterWithTraceBack, getLogger, PREFER_ENC +from ..helpers import str2LogLevel, getVerbosityFormat, FormatterWithTraceBack, getLogger, PREFER_ENC # Gets the instance of the logger. logSys = getLogger("fail2ban") @@ -134,13 +134,16 @@ Report bugs to https://github.com/fail2ban/fail2ban/issues Option("-m", "--journalmatch", help="journalctl style matches overriding filter file. " "\"systemd-journal\" only"), - Option('-l', "--log-level", type="choice", + Option('-l', "--log-level", dest="log_level", - choices=('heavydebug', 'debug', 'info', 'notice', 'warning', 'error', 'critical'), default=None, help="Log level for the Fail2Ban logger to use"), - Option("-v", "--verbose", action='store_true', - help="Be verbose in output"), + Option('-v', '--verbose', action="count", dest="verbose", + default=None, + help="Increase verbosity"), + Option("--verbosity", action="store", dest="verbose", type=int, + default=None, + help="Set numerical level of verbosity (0..4)"), Option("-D", "--debuggex", action='store_true', help="Produce debuggex.com urls for debugging there"), Option("--print-no-missed", action='store_true', @@ -579,17 +582,17 @@ def exec_command_line(): # TODO: taken from -testcases -- move common functionality somewhere if opts.log_level is not None: # so we had explicit settings - logSys.setLevel(getattr(logging, opts.log_level.upper())) + logSys.setLevel(str2LogLevel(opts.log_level)) else: # suppress the logging but it would leave unittests' progress dots # ticking, unless like with '-l critical' which would be silent # unless error occurs - logSys.setLevel(getattr(logging, 'CRITICAL')) + logSys.setLevel(logging.CRITICAL) # Add the default logging handler stdout = logging.StreamHandler(sys.stdout) - fmt = 'D: %(message)s' + fmt = '%(levelname)-1.1s: %(message)s' if opts.verbose <= 1 else '%(message)s' if opts.log_traceback: Formatter = FormatterWithTraceBack @@ -598,11 +601,7 @@ def exec_command_line(): Formatter = logging.Formatter # Custom log format for the verbose tests runs - if opts.verbose: - stdout.setFormatter(Formatter(' %(asctime)-15s %(thread)s' + fmt)) - else: - # just prefix with the space - stdout.setFormatter(Formatter(fmt)) + stdout.setFormatter(Formatter(getVerbosityFormat(opts.verbose, fmt))) logSys.addHandler(stdout) fail2banRegex = Fail2banRegex(opts) diff --git a/fail2ban/client/fail2banserver.py b/fail2ban/client/fail2banserver.py index 85259e79..aba8f8ca 100644 --- a/fail2ban/client/fail2banserver.py +++ b/fail2ban/client/fail2banserver.py @@ -94,6 +94,8 @@ class Fail2banServer(Fail2banCmdLine): # Force the execution if needed. if conf["force"]: args.append("-x") + if conf["verbose"] > 1: + args.append("-" + "v"*(conf["verbose"]-1)) # Logging parameters: for o in ('loglevel', 'logtarget', 'syslogsocket'): args.append("--"+o) @@ -178,13 +180,17 @@ class Fail2banServer(Fail2banCmdLine): logSys.debug('Configure via async client thread') cli.configureServer(async=True, phase=phase) # wait, do not continue if configuration is not 100% valid: - Utils.wait_for(lambda: phase.get('ready', None) is not None, self._conf["timeout"]) + Utils.wait_for(lambda: phase.get('ready', None) is not None, self._conf["timeout"], 0.001) + logSys.log(5, ' server phase %s', phase) if not phase.get('start', False): raise ServerExecutionException('Async configuration of server failed') # Start server, daemonize it, etc. pid = os.getpid() server = Fail2banServer.startServerDirect(self._conf, background) + if not async: + phase['start-ready'] = True + logSys.log(5, ' server phase %s', phase) # If forked - just exit other processes if pid != os.getpid(): # pragma: no cover os._exit(0) @@ -193,7 +199,7 @@ class Fail2banServer(Fail2banCmdLine): # wait for client answer "done": if not async and cli: - Utils.wait_for(lambda: phase.get('done', None) is not None, self._conf["timeout"]) + Utils.wait_for(lambda: phase.get('done', None) is not None, self._conf["timeout"], 0.001) if not phase.get('done', False): if server: # pragma: no cover server.quit() diff --git a/fail2ban/helpers.py b/fail2ban/helpers.py index bbed61cf..4f4426b0 100644 --- a/fail2ban/helpers.py +++ b/fail2ban/helpers.py @@ -134,11 +134,23 @@ def str2LogLevel(value): if isinstance(value, int) or value.isdigit(): ll = int(value) else: - ll = getattr(logging, value) + ll = getattr(logging, value.upper()) except AttributeError: raise ValueError("Invalid log level %r" % value) return ll +def getVerbosityFormat(verbosity, fmt=' %(message)s'): + """Custom log format for the verbose runs + """ + if verbosity > 1: # pragma: no cover + if verbosity > 3: + fmt = ' | %(module)15.15s-%(levelno)-2d: %(funcName)-20.20s |' + fmt + if verbosity > 2: + fmt = ' +%(relativeCreated)5d %(thread)X %(name)-25.25s %(levelname)-5.5s' + fmt + else: + fmt = ' %(asctime)-15s %(thread)X %(levelname)-5.5s' + fmt + return fmt + def excepthook(exctype, value, traceback): """Except hook used to log unhandled exceptions to Fail2Ban log diff --git a/fail2ban/server/actions.py b/fail2ban/server/actions.py index eed481d7..782cd3de 100644 --- a/fail2ban/server/actions.py +++ b/fail2ban/server/actions.py @@ -85,6 +85,26 @@ class Actions(JailThread, Mapping): ## The ban manager. self.__banManager = BanManager() + @staticmethod + def _load_python_module(pythonModule): + pythonModuleName = os.path.splitext( + os.path.basename(pythonModule))[0] + if sys.version_info >= (3, 3): + mod = importlib.machinery.SourceFileLoader( + pythonModuleName, pythonModule).load_module() + else: + mod = imp.load_source( + pythonModuleName, pythonModule) + if not hasattr(mod, "Action"): + raise RuntimeError( + "%s module does not have 'Action' class" % pythonModule) + elif not issubclass(mod.Action, ActionBase): + raise RuntimeError( + "%s module %s does not implement required methods" % ( + pythonModule, mod.Action.__name__)) + return mod + + def add(self, name, pythonModule=None, initOpts=None, reload=False): """Adds a new action. @@ -127,21 +147,7 @@ class Actions(JailThread, Mapping): if pythonModule is None: action = CommandAction(self._jail, name) else: - pythonModuleName = os.path.splitext( - os.path.basename(pythonModule))[0] - if sys.version_info >= (3, 3): - customActionModule = importlib.machinery.SourceFileLoader( - pythonModuleName, pythonModule).load_module() - else: - customActionModule = imp.load_source( - pythonModuleName, pythonModule) - if not hasattr(customActionModule, "Action"): - raise RuntimeError( - "%s module does not have 'Action' class" % pythonModule) - elif not issubclass(customActionModule.Action, ActionBase): - raise RuntimeError( - "%s module %s does not implement required methods" % ( - pythonModule, customActionModule.Action.__name__)) + customActionModule = self._load_python_module(pythonModule) action = customActionModule.Action(self._jail, name, **initOpts) self._actions[name] = action diff --git a/fail2ban/server/server.py b/fail2ban/server/server.py index 2ae96e15..501083ed 100644 --- a/fail2ban/server/server.py +++ b/fail2ban/server/server.py @@ -38,7 +38,7 @@ from .filter import FileFilter, JournalFilter from .transmitter import Transmitter from .asyncserver import AsyncServer, AsyncServerException from .. import version -from ..helpers import getLogger, str2LogLevel, excepthook +from ..helpers import getLogger, str2LogLevel, getVerbosityFormat, excepthook # Gets the instance of the logger. logSys = getLogger(__name__) @@ -72,6 +72,7 @@ class Server: self.__asyncServer = None self.__logLevel = None self.__logTarget = None + self.__verbose = None self.__syslogSocket = None self.__autoSyslogSocketPaths = { 'Darwin': '/var/run/syslog', @@ -111,6 +112,7 @@ class Server: # We are daemon. # Set all logging parameters (or use default if not specified): + self.__verbose = conf.get("verbose", None) self.setSyslogSocket(conf.get("syslogsocket", self.__syslogSocket if self.__syslogSocket is not None else DEF_SYSLOGSOCKET)) self.setLogLevel(conf.get("loglevel", @@ -542,10 +544,10 @@ class Server: self.__logTarget = target return True # set a format which is simpler for console use - formatter = logging.Formatter("%(asctime)s %(name)-24s[%(process)d]: %(levelname)-7s %(message)s") + fmt = "%(asctime)s %(name)-24s[%(process)d]: %(levelname)-7s %(message)s" if target == "SYSLOG": # Syslog daemons already add date to the message. - formatter = logging.Formatter("%(name)s[%(process)d]: %(levelname)s %(message)s") + fmt = "%(name)s[%(process)d]: %(levelname)s %(message)s" facility = logging.handlers.SysLogHandler.LOG_DAEMON if self.__syslogSocket == "auto": import platform @@ -572,8 +574,8 @@ class Server: open(target, "a").close() hdlr = logging.handlers.RotatingFileHandler(target) except IOError: - logSys.error("Unable to log to " + target) - logSys.info("Logging to previous target " + self.__logTarget) + logSys.error("Unable to log to %r", target) + logSys.info("Logging to previous target %r", self.__logTarget) return False # Removes previous handlers -- in reverse order since removeHandler # alter the list in-place and that can confuses the iterable @@ -592,8 +594,13 @@ class Server: if (2, 6, 3) <= sys.version_info < (3,) or \ (3, 2) <= sys.version_info: raise + # detailed format by deep log levels (as DEBUG=10): + if logger.getEffectiveLevel() <= logging.DEBUG: # pragma: no cover + if self.__verbose is None: + self.__verbose = logging.DEBUG - logger.getEffectiveLevel() + 1 + fmt = getVerbosityFormat(self.__verbose-1) # tell the handler to use this format - hdlr.setFormatter(formatter) + hdlr.setFormatter(logging.Formatter(fmt)) logger.addHandler(hdlr) # Does not display this message at startup. if self.__logTarget is not None: diff --git a/fail2ban/server/utils.py b/fail2ban/server/utils.py index 74406363..7c13631e 100644 --- a/fail2ban/server/utils.py +++ b/fail2ban/server/utils.py @@ -54,6 +54,7 @@ class Utils(): DEFAULT_SLEEP_TIME = 2 DEFAULT_SLEEP_INTERVAL = 0.2 + DEFAULT_SHORT_INTERVAL = 0.001 class Cache(object): @@ -134,21 +135,22 @@ class Utils(): """ stdout = stderr = None retcode = None - if not callable(timeout): - stime = time.time() - timeout_expr = lambda: time.time() - stime <= timeout - else: - timeout_expr = timeout popen = None try: popen = subprocess.Popen( realCmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=shell, preexec_fn=os.setsid # so that killpg does not kill our process ) + # wait with timeout for process has terminated: retcode = popen.poll() - while retcode is None and timeout_expr(): - time.sleep(Utils.DEFAULT_SLEEP_INTERVAL) - retcode = popen.poll() + if retcode is None: + def _popen_wait_end(): + retcode = popen.poll() + return (True, retcode) if retcode is not None else None + retcode = Utils.wait_for(_popen_wait_end, timeout, Utils.DEFAULT_SHORT_INTERVAL) + if retcode: + retcode = retcode[1] + # if timeout: if retcode is None: logSys.error("%s -- timed out after %s seconds." % (realCmd, timeout)) @@ -202,18 +204,18 @@ class Utils(): success = False if retcode == 0: - logSys.debug("%s -- returned successfully", realCmd) + logSys.debug("%-.40s -- returned successfully", realCmd) success = True elif retcode is None: - logSys.error("%s -- unable to kill PID %i" % (realCmd, popen.pid)) + logSys.error("%-.40s -- unable to kill PID %i", realCmd, popen.pid) elif retcode < 0 or retcode > 128: # dash would return negative while bash 128 + n sigcode = -retcode if retcode < 0 else retcode - 128 - logSys.error("%s -- killed with %s (return code: %s)" % - (realCmd, signame.get(sigcode, "signal %i" % sigcode), retcode)) + logSys.error("%-.40s -- killed with %s (return code: %s)", + realCmd, signame.get(sigcode, "signal %i" % sigcode), retcode) else: msg = _RETCODE_HINTS.get(retcode, None) - logSys.error("%s -- returned %i" % (realCmd, retcode)) + logSys.error("%-.40s -- returned %i", realCmd, retcode) if msg: logSys.info("HINT on %i: %s", retcode, msg % locals()) return success if not output else (success, stdout, stderr, retcode) @@ -221,7 +223,25 @@ class Utils(): @staticmethod def wait_for(cond, timeout, interval=None): """Wait until condition expression `cond` is True, up to `timeout` sec + + Parameters + ---------- + cond : callable + The expression to check condition + (should return equivalent to bool True if wait successful). + timeout : float or callable + The time out for end of wait + (in seconds or callable that returns True if timeout occurred). + interval : float (optional) + Polling start interval for wait cycle in seconds. + + Returns + ------- + variable + The return value of the last call of `cond`, + logical False (or None, 0, etc) if timeout occurred. """ + #logSys.log(5, " wait for %r, tout: %r / %r", cond, timeout, interval) ini = 1 # to delay initializations until/when necessary while True: ret = cond() @@ -229,10 +249,14 @@ class Utils(): return ret if ini: ini = stm = 0 - time0 = time.time() + timeout + if not callable(timeout): + time0 = time.time() + timeout + timeout_expr = lambda: time.time() > time0 + else: + timeout_expr = timeout if not interval: interval = Utils.DEFAULT_SLEEP_INTERVAL - if time.time() > time0: + if timeout_expr(): break stm = min(stm + interval, Utils.DEFAULT_SLEEP_TIME) time.sleep(stm) diff --git a/fail2ban/tests/action_d/test_badips.py b/fail2ban/tests/action_d/test_badips.py index 2b9090cc..64db44e7 100644 --- a/fail2ban/tests/action_d/test_badips.py +++ b/fail2ban/tests/action_d/test_badips.py @@ -24,9 +24,12 @@ import sys from ..dummyjail import DummyJail from ..utils import CONFIG_DIR -if sys.version_info >= (2,7): +if sys.version_info >= (2,7): # pragma: no cover - may be unavailable class BadIPsActionTest(unittest.TestCase): + available = True, None + modAction = None + def setUp(self): """Call before every test case.""" unittest.F2B.SkipIfNoNetwork() @@ -36,6 +39,15 @@ if sys.version_info >= (2,7): self.jail.actions.add("test") pythonModule = os.path.join(CONFIG_DIR, "action.d", "badips.py") + + # check availability (once if not alive, used shorter timeout as in test cases): + if BadIPsActionTest.available[0]: + if not BadIPsActionTest.modAction: + BadIPsActionTest.modAction = self.jail.actions._load_python_module(pythonModule).Action + BadIPsActionTest.available = BadIPsActionTest.modAction.isAvailable(timeout=2 if unittest.F2B.fast else 10) + if not BadIPsActionTest.available[0]: + raise unittest.SkipTest('Skip test because service is not available: %s' % BadIPsActionTest.available[1]) + self.jail.actions.add("badips", pythonModule, initOpts={ 'category': "ssh", 'banaction': "test", diff --git a/fail2ban/tests/actiontestcase.py b/fail2ban/tests/actiontestcase.py index cacb5e17..403f7ea6 100644 --- a/fail2ban/tests/actiontestcase.py +++ b/fail2ban/tests/actiontestcase.py @@ -324,16 +324,13 @@ class CommandActionTest(LogCaptureTestCase): self.assertLogged('HINT on 127: "Command not found"') def testExecuteTimeout(self): - unittest.F2B.SkipIfFast() stime = time.time() - # Should take a minute - self.assertFalse(CommandAction.executeCmd('sleep 30', timeout=1)) + timeout = 1 if not unittest.F2B.fast else 0.01 + # Should take a 30 seconds (so timeout will occur) + self.assertFalse(CommandAction.executeCmd('sleep 30', timeout=timeout)) # give a test still 1 second, because system could be too busy - self.assertTrue(time.time() >= stime + 1 and time.time() <= stime + 2) - self.assertLogged( - 'sleep 30 -- timed out after 1 seconds', - 'sleep 30 -- timed out after 2 seconds' - ) + self.assertTrue(time.time() >= stime + timeout and time.time() <= stime + timeout + 1) + self.assertLogged('sleep 30 -- timed out after') self.assertLogged('sleep 30 -- killed with SIGTERM') def testExecuteTimeoutWithNastyChildren(self): @@ -353,8 +350,8 @@ class CommandActionTest(LogCaptureTestCase): # timeout as long as pid-file was not created, but max 5 seconds def getnasty_tout(): return ( - getnastypid() is None - and time.time() - stime <= 5 + getnastypid() is not None + or time.time() - stime > 5 ) def getnastypid(): diff --git a/fail2ban/tests/fail2banclienttestcase.py b/fail2ban/tests/fail2banclienttestcase.py index 8159a9f6..d8fc156b 100644 --- a/fail2ban/tests/fail2banclienttestcase.py +++ b/fail2ban/tests/fail2banclienttestcase.py @@ -174,16 +174,35 @@ def _start_params(tmp, use_stock=False, logtarget="/dev/null", db=":memory:"): "[DEFAULT]", "", "", ) - if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover _out_file(pjoin(cfg, "fail2ban.conf")) _out_file(pjoin(cfg, "jail.conf")) # parameters (sock/pid and config, increase verbosity, set log, etc.): + vvv, llev = (), "INFO" + if unittest.F2B.log_level < logging.INFO: # pragma: no cover + llev = str(unittest.F2B.log_level) + if unittest.F2B.verbosity > 1: + vvv = ("-" + "v"*unittest.F2B.verbosity,) + llev = vvv + ("--loglevel", llev) return ( "-c", cfg, "-s", pjoin(tmp, "f2b.sock"), "-p", pjoin(tmp, "f2b.pid"), - "-vv", "--logtarget", logtarget, "--loglevel", "DEBUG", "--syslogsocket", "auto", + "--logtarget", logtarget,) + llev + ("--syslogsocket", "auto", "--timeout", str(fail2bancmdline.MAX_WAITTIME), ) +def _get_pid_from_file(pidfile): + f = pid = None + try: + f = open(pidfile) + pid = f.read() + pid = re.match(r'\S+', pid).group() + return int(pid) + except Exception as e: # pragma: no cover + logSys.debug(e) + finally: + if f is not None: + f.close() + return pid def _kill_srv(pidfile): logSys.debug("cleanup: %r", (pidfile, isdir(pidfile))) @@ -193,23 +212,22 @@ def _kill_srv(pidfile): if not isfile(pidfile): # pragma: no cover pidfile = pjoin(piddir, "fail2ban.pid") + # output log in heavydebug (to see possible start errors): + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover + logfile = pjoin(piddir, "f2b.log") + if isfile(logfile): + _out_file(logfile) + else: + logSys.log(5, 'no logfile %r', logfile) + if not isfile(pidfile): logSys.debug("cleanup: no pidfile for %r", piddir) return True - f = pid = None - try: - logSys.debug("cleanup pidfile: %r", pidfile) - f = open(pidfile) - pid = f.read() - pid = re.match(r'\S+', pid).group() - pid = int(pid) - except Exception as e: # pragma: no cover - logSys.debug(e) + logSys.debug("cleanup pidfile: %r", pidfile) + pid = _get_pid_from_file(pidfile) + if pid is None: # pragma: no cover return False - finally: - if f is not None: - f.close() try: logSys.debug("cleanup pid: %r", pid) @@ -443,14 +461,18 @@ class Fail2banClientTest(Fail2banClientServerBase): def testClientStartBackgroundCall(self, tmp): global INTERACT startparams = _start_params(tmp, logtarget=pjoin(tmp, "f2b.log")) - # start (in new process, using the same python version): - cmd = (sys.executable, pjoin(BIN, CLIENT)) - logSys.debug('Start %s ...', cmd) - cmd = cmd + startparams + ("--async", "start",) - ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True) - self.assertTrue(len(ret) and ret[0]) - # wait for server (socket and ready): - self._wait_for_srv(tmp, True, startparams=cmd) + # if fast, start server process from client started direct here: + if unittest.F2B.fast: # pragma: no cover + self.execSuccess(startparams + ("start",)) + else: + # start (in new process, using the same python version): + cmd = (sys.executable, pjoin(BIN, CLIENT)) + logSys.debug('Start %s ...', cmd) + cmd = cmd + startparams + ("--async", "start",) + ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True) + self.assertTrue(len(ret) and ret[0]) + # wait for server (socket and ready): + self._wait_for_srv(tmp, True, startparams=cmd) self.assertLogged("Server ready") self.pruneLog() try: @@ -459,6 +481,24 @@ class Fail2banClientTest(Fail2banClientServerBase): self.assertLogged("TEST-ECHO") self.assertLogged("Exit with code 0") self.pruneLog() + # test ping timeout: + self.execSuccess(startparams, "ping", "0.1") + self.assertLogged("Server replied: pong") + self.pruneLog() + # python 3 seems to bypass such short timeouts also, + # so suspend/resume server process and test between it... + pid = _get_pid_from_file(pjoin(tmp, "f2b.pid")) + try: + # suspend: + os.kill(pid, signal.SIGSTOP); # or SIGTSTP? + time.sleep(Utils.DEFAULT_SHORT_INTERVAL) + # test ping with short timeout: + self.execFailed(startparams, "ping", "1e-10") + finally: + # resume: + os.kill(pid, signal.SIGCONT) + self.assertLogged("timed out") + self.pruneLog() # interactive client chat with started server: INTERACT += [ "echo INTERACT-ECHO", @@ -692,7 +732,7 @@ class Fail2banServerTest(Fail2banClientServerBase): "actionunban = echo '[] %s: -- unban '" % actname, unban, "actionstop = echo '[] %s: __ stop'" % actname, stop, ) - if DefLogSys.level <= logging.DEBUG: # if DEBUG + if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover _out_file(fn) def _write_jail_cfg(enabled=(1, 2), actions=()): @@ -720,7 +760,7 @@ class Fail2banServerTest(Fail2banClientServerBase): "logpath = " + test2log, "enabled = true" if 2 in enabled else "", ) - if DefLogSys.level <= logging.DEBUG: # if DEBUG + if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover _out_file(pjoin(cfg, "jail.conf")) # create default test actions: @@ -734,7 +774,7 @@ class Fail2banServerTest(Fail2banClientServerBase): # reload and wait for ban: self.pruneLog("[test-phase 1a]") - if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover _out_file(test1log) self.execSuccess(startparams, "reload") self.assertLogged( @@ -752,7 +792,7 @@ class Fail2banServerTest(Fail2banClientServerBase): self.pruneLog("[test-phase 1b]") _write_jail_cfg(actions=[1,2]) _write_file(test1log, "w+") - if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover _out_file(test1log) self.execSuccess(startparams, "reload") self.assertLogged("Reload finished.", all=True, wait=MID_WAITTIME) @@ -814,7 +854,7 @@ class Fail2banServerTest(Fail2banClientServerBase): (str(int(MyTime.time())) + " failure 401 from 192.0.2.4: test 2",) * 3 + (str(int(MyTime.time())) + " failure 401 from 192.0.2.8: test 2",) * 3 )) - if DefLogSys.level < logging.DEBUG: # if HEAVYDEBUG + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover _out_file(test2log) # test all will be found in jail1 and one in jail2: self.assertLogged( @@ -913,7 +953,7 @@ class Fail2banServerTest(Fail2banClientServerBase): (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 + if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover _out_file(test1log) self.assertLogged( "6 ticket(s) in 'test-jail1", diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index 15495655..8e62531a 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -225,7 +225,7 @@ def _copy_lines_between_files(in_, fout, n=None, skip=0, mode='a', terminal_line # Opened earlier, therefore must close it fin.close() # to give other threads possibly some time to crunch - time.sleep(Utils.DEFAULT_SLEEP_INTERVAL) + time.sleep(Utils.DEFAULT_SHORT_INTERVAL) return fout @@ -909,7 +909,7 @@ def get_monitor_failures_testcase(Filter_): if interim_kill: _killfile(None, self.name) - time.sleep(Utils.DEFAULT_SLEEP_INTERVAL) # let them know + time.sleep(Utils.DEFAULT_SHORT_INTERVAL) # let them know # now create a new one to override old one _copy_lines_between_files(GetFailures.FILENAME_01, self.name + '.new', diff --git a/fail2ban/tests/utils.py b/fail2ban/tests/utils.py index eecb94b8..ea051872 100644 --- a/fail2ban/tests/utils.py +++ b/fail2ban/tests/utils.py @@ -37,7 +37,7 @@ import unittest from cStringIO import StringIO from functools import wraps -from ..helpers import getLogger +from ..helpers import getLogger, str2LogLevel, getVerbosityFormat from ..server.ipdns import DNSUtils from ..server.mytime import MyTime from ..server.utils import Utils @@ -82,13 +82,14 @@ def getOptParser(doc=""): version="%prog " + version) p.add_options([ - Option('-l', "--log-level", type="choice", + Option('-l', "--log-level", dest="log_level", - choices=('heavydebug', 'debug', 'info', 'notice', 'warning', 'error', 'critical'), default=None, help="Log level for the logger to use during running tests"), - Option('-v', "--verbosity", action="store", - dest="verbosity", type=int, + Option('-v', action="count", dest="verbosity", + default=None, + help="Increase verbosity"), + Option("--verbosity", action="store", dest="verbosity", type=int, default=None, help="Set numerical level of verbosity (0..4)"), Option("--log-direct", action="store_false", @@ -122,22 +123,11 @@ def initProcess(opts): global logSys logSys = getLogger("fail2ban") - # Numerical level of verbosity corresponding to a log "level" - verbosity = opts.verbosity - if verbosity is None: - verbosity = {'heavydebug': 4, - 'debug': 3, - 'info': 2, - 'notice': 2, - 'warning': 1, - 'error': 1, - 'critical': 0, - None: 1}[opts.log_level] - opts.verbosity = verbosity - + llev = None if opts.log_level is not None: # pragma: no cover # so we had explicit settings - logSys.setLevel(getattr(logging, opts.log_level.upper())) + llev = str2LogLevel(opts.log_level) + logSys.setLevel(llev) else: # pragma: no cover # suppress the logging but it would leave unittests' progress dots # ticking, unless like with '-l critical' which would be silent @@ -145,6 +135,19 @@ def initProcess(opts): logSys.setLevel(logging.CRITICAL) opts.log_level = logSys.level + # Numerical level of verbosity corresponding to a given log "level" + verbosity = opts.verbosity + if verbosity is None: + verbosity = ( + 1 if llev is None else \ + 4 if llev <= logging.HEAVYDEBUG else \ + 3 if llev <= logging.DEBUG else \ + 2 if llev <= min(logging.INFO, logging.NOTICE) else \ + 1 if llev <= min(logging.WARNING, logging.ERROR) else \ + 0 # if llev <= logging.CRITICAL + ) + opts.verbosity = verbosity + # Add the default logging handler stdout = logging.StreamHandler(sys.stdout) @@ -157,13 +160,7 @@ def initProcess(opts): Formatter = logging.Formatter # Custom log format for the verbose tests runs - if verbosity > 1: # pragma: no cover - if verbosity > 3: - fmt = ' | %(module)15.15s-%(levelno)-2d: %(funcName)-20.20s |' + fmt - if verbosity > 2: - fmt = ' +%(relativeCreated)5d %(thread)X %(name)-25.25s %(levelname)-5.5s' + fmt - else: - fmt = ' %(asctime)-15s %(thread)X %(levelname)-5.5s' + fmt + fmt = getVerbosityFormat(verbosity, fmt) # stdout.setFormatter(Formatter(fmt)) @@ -239,6 +236,7 @@ def initTests(opts): # (prevent long sleeping during test cases ... less time goes to sleep): Utils.DEFAULT_SLEEP_TIME = 0.0025 Utils.DEFAULT_SLEEP_INTERVAL = 0.0005 + Utils.DEFAULT_SHORT_INTERVAL = 0.0001 def F2B_SkipIfFast(): raise unittest.SkipTest('Skip test because of "--fast"') unittest.F2B.SkipIfFast = F2B_SkipIfFast @@ -246,6 +244,7 @@ def initTests(opts): # smaller inertance inside test-cases (litle speedup): Utils.DEFAULT_SLEEP_TIME = 0.25 Utils.DEFAULT_SLEEP_INTERVAL = 0.025 + Utils.DEFAULT_SHORT_INTERVAL = 0.0005 # sleep intervals are large - use replacement for sleep to check time to sleep: _org_sleep = time.sleep def _new_sleep(v): @@ -331,6 +330,11 @@ def gatherTests(regexps=None, opts=None): def addTest(self, suite): matched = [] for test in suite: + # test of suite loaded with loadTestsFromName may be a suite self: + if isinstance(test, unittest.TestSuite): # pragma: no cover + self.addTest(test) + continue + # filter by regexp: s = str(test) for r in self._regexps: m = r.search(s)