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

@@ -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 += repr(logging.getLevelName(response) if isinstance(response, int) else response)
-					msg += "ERROR"
-				elif response == 2:
-					msg += "WARN"
-				elif response == 3:
-					msg += "INFO"
-				elif response == 4:
-					msg += "DEBUG"
-				else:
-					msg += repr(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 "
+			logSys.error("Beautify %r with %r failed", response, self.__inputCmd)
-				+ repr(self.__inputCmd) + " failed")
+			msg = repr(msg) + repr(response)
-			msg += repr(response)
 		return msg
 
 	def beautifyError(self, response):
-		logSys.debug("Beautify (error) " + repr(response) + " with "
+		logSys.debug("Beautify (error) %r with %r", response, self.__inputCmd)
-					 + repr(self.__inputCmd))
 		msg = response
 		if isinstance(response, UnknownJailException):
 			msg = "Sorry but the jail '" + response.args[0] + "' does not exist"

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

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)

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

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.error("Unable to log to %r", target)
-					logSys.info("Logging to previous target " + self.__logTarget)
+					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:

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 '[<name>] %s: -- unban <ip>'" % actname, unban,
 				"actionstop =   echo '[<name>] %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",

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"
+	llev = None
-	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
-
 	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
+	fmt = getVerbosityFormat(verbosity, fmt)
-		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
 
 	#
 	stdout.setFormatter(Formatter(fmt))