Merge pull request #1562 from sebres/_0.10/fix-stability-and-speed

0.10/fix stability and speed optimization

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.
 

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/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

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):
+	def __ping(self, timeout=0.1):
-		return self.__processCmd([["ping"]], False)
+		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"]:
+						if showRet or c[0] != "ping":
-							self.__logSocketError()
+							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
 

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/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',
+		Option('-v', '--verbose', action="count", dest="verbose",
-			   help="Be verbose in output"),
+			   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(getVerbosityFormat(opts.verbose, fmt)))
-		stdout.setFormatter(Formatter(' %(asctime)-15s %(thread)s' + fmt))
-	else:
-		# just prefix with the space
-		stdout.setFormatter(Formatter(fmt))
 	logSys.addHandler(stdout)
 
 	fail2banRegex = Fail2banRegex(opts)

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

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/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(
+			customActionModule = self._load_python_module(pythonModule)
-				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__))
 			action = customActionModule.Action(self._jail, name, **initOpts)
 		self._actions[name] = action
 

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/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():
+			if retcode is None:
-				time.sleep(Utils.DEFAULT_SLEEP_INTERVAL)
+				def _popen_wait_end():
-				retcode = popen.poll()
+					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)" %
+			logSys.error("%-.40s -- killed with %s (return code: %s)",
-				(realCmd, signame.get(sigcode, "signal %i" % sigcode), retcode))
+				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)

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",

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
+		timeout = 1 if not unittest.F2B.fast else 0.01
-		self.assertFalse(CommandAction.executeCmd('sleep 30', timeout=1))
+		# 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.assertTrue(time.time() >= stime + timeout and time.time() <= stime + timeout + 1)
-		self.assertLogged(
+		self.assertLogged('sleep 30 -- timed out after')
-			'sleep 30 -- timed out after 1 seconds',
-			'sleep 30 -- timed out after 2 seconds'
-		)
 		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
+				getnastypid() is not None
-				and time.time() - stime <= 5
+				or time.time() - stime > 5
 			)
 
 		def getnastypid():

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
+	logSys.debug("cleanup pidfile: %r", pidfile)
-	try:
+	pid = _get_pid_from_file(pidfile)
-		logSys.debug("cleanup pidfile: %r", pidfile)
+	if pid is None: # pragma: no cover
-		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)
 		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):
+		# if fast, start server process from client started direct here:
-		cmd = (sys.executable, pjoin(BIN, CLIENT))
+		if unittest.F2B.fast: # pragma: no cover
-		logSys.debug('Start %s ...', cmd)
+			self.execSuccess(startparams + ("start",))
-		cmd = cmd + startparams + ("--async", "start",)
+		else:
-		ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
+			# start (in new process, using the same python version):
-		self.assertTrue(len(ret) and ret[0])
+			cmd = (sys.executable, pjoin(BIN, CLIENT))
-		# wait for server (socket and ready):
+			logSys.debug('Start %s ...', cmd)
-		self._wait_for_srv(tmp, True, startparams=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 '[<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=()):
@@ -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",

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',

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",
+		Option('-v', action="count", dest="verbosity",
-			   dest="verbosity", type=int,
+			   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"
+	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 +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
+	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))
@@ -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)