From 2cfaf845ca9cb275cc8c6e8ca6a6c1c8b48a900d Mon Sep 17 00:00:00 2001 From: sebres Date: Thu, 29 Sep 2016 21:23:37 +0200 Subject: [PATCH] standardize and normalize logging and verbosity formats, logging level etc between command lines (server, client, test-cases); test cases could pass (so increase) verbosity to the client (and furthermore client to the server also), usable for debug purposes resp. simplifying read of the log-file; custom and precise numeric log-levels can be given in test cases now; --- fail2ban/client/beautifier.py | 21 +++--------- fail2ban/client/fail2bancmdline.py | 12 ++++--- fail2ban/client/fail2banserver.py | 2 ++ fail2ban/helpers.py | 14 +++++++- fail2ban/server/server.py | 19 +++++++---- fail2ban/tests/fail2banclienttestcase.py | 22 +++++++----- fail2ban/tests/utils.py | 43 +++++++++++------------- 7 files changed, 74 insertions(+), 59 deletions(-) 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/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/fail2banserver.py b/fail2ban/client/fail2banserver.py index faf1732a..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) 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/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/tests/fail2banclienttestcase.py b/fail2ban/tests/fail2banclienttestcase.py index 82164a80..d8fc156b 100644 --- a/fail2ban/tests/fail2banclienttestcase.py +++ b/fail2ban/tests/fail2banclienttestcase.py @@ -174,13 +174,19 @@ 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), ) @@ -726,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=()): @@ -754,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: @@ -768,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( @@ -786,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) @@ -848,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( @@ -947,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/utils.py b/fail2ban/tests/utils.py index 3c044951..77210088 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,9 +82,8 @@ 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", @@ -122,22 +121,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 +133,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 +158,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))