code review, timeout fix, better tracing (and test coverage) by start of server/client (with or without fork)

fail2ban/client/fail2banclient.py

@@ -37,14 +37,13 @@ from .beautifier import Beautifier
 from .fail2bancmdline import Fail2banCmdLine, ServerExecutionException, ExitException, \
 	logSys, PRODUCTION, exit, output
 
-MAX_WAITTIME = 30
 PROMPT = "fail2ban> "
 
 
 def _thread_name():
 	return threading.current_thread().__class__.__name__
 
-def input_command():
+def input_command(): # pragma: no cover
 	return raw_input(PROMPT)
 
 ##
@@ -101,13 +100,19 @@ class Fail2banClient(Fail2banCmdLine, Thread):
 						if showRet:
 							output(beautifier.beautifyError(ret[1]))
 						streamRet = False
-				except socket.error:
+				except socket.error as e:
 					if showRet or self._conf["verbose"] > 1:
-						self.__logSocketError()
+						if showRet or c != ["ping"]:
+							self.__logSocketError()
+						else:
+							logSys.debug(" -- ping failed -- %r", e)
 					return False
-				except Exception, e:
+				except Exception as e: # pragma: no cover
 					if showRet or self._conf["verbose"] > 1:
-						logSys.error(e)
+						if self._conf["verbose"] > 1:
+							logSys.exception(e)
+						else:
+							logSys.error(e)
 					return False
 		finally:
 			# prevent errors by close during shutdown (on exit command):
@@ -123,7 +128,7 @@ class Fail2banClient(Fail2banCmdLine, Thread):
 
 	def __logSocketError(self):
 		try:
-			if os.access(self._conf["socket"], os.F_OK):
+			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):
@@ -313,7 +318,7 @@ class Fail2banClient(Fail2banCmdLine, Thread):
 
 	def __waitOnServer(self, alive=True, maxtime=None):
 		if maxtime is None:
-			maxtime = MAX_WAITTIME
+			maxtime = self._conf["timeout"]
 		# Wait for the server to start (the server has 30 seconds to answer ping)
 		starttime = time.time()
 		logSys.debug("__waitOnServer: %r", (alive, maxtime))

fail2ban/client/fail2bancmdline.py

@@ -33,13 +33,14 @@ from ..helpers import getLogger
 # Gets the instance of the logger.
 logSys = getLogger("fail2ban")
 
-def output(s):
+def output(s): # pragma: no cover
 	print(s)
 
 CONFIG_PARAMS = ("socket", "pidfile", "logtarget", "loglevel", "syslogsocket",)
 # Used to signal - we are in test cases (ex: prevents change logging params, log capturing, etc)
 PRODUCTION = True
 
+MAX_WAITTIME = 30
 
 class Fail2banCmdLine():
 
@@ -56,7 +57,8 @@ class Fail2banCmdLine():
 			"background": True,
 			"verbose": 1,
 			"socket": None,
-			"pidfile": None
+			"pidfile": None,
+			"timeout": MAX_WAITTIME
 		}
 
 	@property
@@ -109,6 +111,7 @@ class Fail2banCmdLine():
 		output("    -b                      start server in background (default)")
 		output("    -f                      start server in foreground")
 		output("    --async                 start server in async mode (for internal usage only, don't read configuration)")
+		output("    --timeout               timeout to wait for the server (for internal usage only, don't read configuration)")
 		output("    -h, --help              display this help message")
 		output("    -V, --version           print the version")
 		
@@ -126,8 +129,6 @@ class Fail2banCmdLine():
 		"""
 		for opt in optList:
 			o = opt[0]
-			if o == "--async":
-				self._conf["async"] = True
 			if o == "-c":
 				self._conf["conf"] = opt[1]
 			elif o == "-s":
@@ -150,6 +151,11 @@ class Fail2banCmdLine():
 				self._conf["background"] = True
 			elif o == "-f":
 				self._conf["background"] = False
+			elif o == "--async":
+				self._conf["async"] = True
+			elif o == "-timeout":
+				from ..mytime import MyTime
+				self._conf["timeout"] = MyTime.str2seconds(opt[1])
 			elif o in ["-h", "--help"]:
 				self.dispUsage()
 				return True
@@ -170,7 +176,7 @@ class Fail2banCmdLine():
 			# Reads the command line options.
 			try:
 				cmdOpts = 'hc:s:p:xfbdviqV'
-				cmdLongOpts = ['loglevel=', 'logtarget=', 'syslogsocket=', 'async', 'help', 'version']
+				cmdLongOpts = ['loglevel=', 'logtarget=', 'syslogsocket=', 'async', 'timeout=', 'help', 'version']
 				optList, self._args = getopt.getopt(self._argv[1:], cmdOpts, cmdLongOpts)
 			except getopt.GetoptError:
 				self.dispUsage()
@@ -180,6 +186,8 @@ class Fail2banCmdLine():
 			if ret is not None:
 				return ret
 
+			logSys.debug("-- conf: %r, args: %r", self._conf, self._args)
+
 			if initial and PRODUCTION: # pragma: no cover - can't test
 				verbose = self._conf["verbose"]
 				if verbose <= 0:
@@ -244,11 +252,11 @@ class Fail2banCmdLine():
 	@staticmethod
 	def dumpConfig(cmd):
 		for c in cmd:
-			print c
+			output(c)
 		return True
 
 	@staticmethod
-	def exit(code=0):
+	def exit(code=0): # pragma: no cover - can't test
 		logSys.debug("Exit with code %s", code)
 		if os._exit:
 			os._exit(code)

fail2ban/client/fail2banserver.py

@@ -27,8 +27,6 @@ import sys
 from .fail2bancmdline import Fail2banCmdLine, ServerExecutionException, \
 	logSys, PRODUCTION, exit
 
-MAX_WAITTIME = 30
-
 SERVER = "fail2ban-server"
 
 ##
@@ -114,16 +112,17 @@ class Fail2banServer(Fail2banCmdLine):
 					return os.execv(exe, args)
 				else:
 					# use P_WAIT instead of P_NOWAIT (to prevent defunct-zomby process), it startet as daemon, so parent exit fast after fork):
-					return os.spawnv(os.P_WAIT, exe, args)
+					ret = os.spawnv(os.P_WAIT, exe, args)
-			except OSError as e:
+					if ret != 0:
+						raise OSError(ret, "Unknown error by executing server %r with %r" % (args[1], exe))
+					return 0
+			except OSError as e: # pragma: no cover
+				if not frk: #not PRODUCTION:
+					raise
 				# Use the PATH env.
 				logSys.warning("Initial start attempt failed (%s). Starting %r with the same args", e, SERVER)
 				if frk:
 					return os.execvp(SERVER, args)
-				else:
-					del args[0]
-					args[0] = SERVER
-					return os.spawnvp(os.P_WAIT, SERVER, args)
 		return pid
 
 	@staticmethod
@@ -181,8 +180,8 @@ class Fail2banServer(Fail2banCmdLine):
 				phase = dict()
 				logSys.debug('Configure via async client thread')
 				cli.configureServer(async=True, phase=phase)
-				# wait up to MAX_WAITTIME, do not continue if configuration is not 100% valid:
+				# wait, do not continue if configuration is not 100% valid:
-				Utils.wait_for(lambda: phase.get('ready', None) is not None, MAX_WAITTIME)
+				Utils.wait_for(lambda: phase.get('ready', None) is not None, self._conf["timeout"])
 				if not phase.get('start', False):
 					raise ServerExecutionException('Async configuration of server failed')
 
@@ -197,7 +196,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, MAX_WAITTIME)
+				Utils.wait_for(lambda: phase.get('done', None) is not None, self._conf["timeout"])
 				if not phase.get('done', False):
 					if server:
 						server.quit()

fail2ban/server/utils.py

@@ -168,8 +168,10 @@ class Utils():
 					stdout = popen.stdout.read()
 				except IOError as e:
 					logSys.error(" ... -- failed to read stdout %s", e)
-				if stdout is not None and stdout != '':
+				if stdout is not None and stdout != '' and std_level >= logSys.getEffectiveLevel():
-					logSys.log(std_level, "%s -- stdout: %r", realCmd, stdout)
+					logSys.log(std_level, "%s -- stdout:", realCmd)
+					for l in stdout.splitlines():
+						logSys.log(std_level, " -- stdout: %r", l)
 				popen.stdout.close()
 			if popen.stderr:
 				try:
@@ -178,8 +180,10 @@ class Utils():
 					stderr = popen.stderr.read()
 				except IOError as e:
 					logSys.error(" ... -- failed to read stderr %s", e)
-				if stderr is not None and stderr != '':
+				if stderr is not None and stderr != '' and std_level >= logSys.getEffectiveLevel():
-					logSys.log(std_level, "%s -- stderr: %r", realCmd, stderr)
+					logSys.log(std_level, "%s -- stderr:", realCmd)
+					for l in stderr.splitlines():
+						logSys.log(std_level, " -- stderr: %r", l)
 				popen.stderr.close()
 
 		if retcode == 0:

fail2ban/tests/actiontestcase.py

@@ -271,11 +271,11 @@ class CommandActionTest(LogCaptureTestCase):
 
 	def testCaptureStdOutErr(self):
 		CommandAction.executeCmd('echo "How now brown cow"')
-		self.assertLogged("'How now brown cow\\n'")
+		self.assertLogged("stdout: 'How now brown cow'\n", "stdout: b'How now brown cow'\n")
 		CommandAction.executeCmd(
 			'echo "The rain in Spain stays mainly in the plain" 1>&2')
 		self.assertLogged(
-			"'The rain in Spain stays mainly in the plain\\n'")
+			"stderr: 'The rain in Spain stays mainly in the plain'\n", "stderr: b'The rain in Spain stays mainly in the plain'\n")
 
 	def testCallingMap(self):
 		mymap = CallingMap(callme=lambda: str(10), error=lambda: int('a'),

fail2ban/tests/fail2banclienttestcase.py

@@ -43,11 +43,6 @@ from .utils import LogCaptureTestCase, logSys, withtmpdir, shutil, logging
 
 STOCK_CONF_DIR = "config"
 STOCK = os.path.exists(os.path.join(STOCK_CONF_DIR,'fail2ban.conf'))
-TEST_CONF_DIR = os.path.join(os.path.dirname(__file__), "config")
-if STOCK:
-	CONF_DIR = STOCK_CONF_DIR
-else:
-	CONF_DIR = TEST_CONF_DIR
 
 CLIENT = "fail2ban-client"
 SERVER = "fail2ban-server"
@@ -59,9 +54,7 @@ MAX_WAITTIME = 30 if not unittest.F2B.fast else 5
 # Several wrappers and settings for proper testing:
 #
 
-fail2banclient.MAX_WAITTIME = \
+fail2bancmdline.MAX_WAITTIME = MAX_WAITTIME-1
-fail2banserver.MAX_WAITTIME = MAX_WAITTIME
-
 
 fail2bancmdline.logSys = \
 fail2banclient.logSys = \
@@ -167,6 +160,7 @@ def _start_params(tmp, use_stock=False, logtarget="/dev/null"):
 	# parameters (sock/pid and config, increase verbosity, set log, etc.):
 	return ("-c", cfg, "-s", tmp+"/f2b.sock", "-p", tmp+"/f2b.pid",
 					"-vv", "--logtarget", logtarget, "--loglevel", "DEBUG", "--syslogsocket", "auto",
+					"--timeout", str(fail2bancmdline.MAX_WAITTIME),
 	)
 
 def _kill_srv(pidfile): # pragma: no cover
@@ -199,7 +193,7 @@ def _kill_srv(pidfile): # pragma: no cover
 		## try to preper stop (have signal handler):
 		os.kill(pid, signal.SIGTERM)
 		## check still exists after small timeout:
-		if not Utils.wait_for(lambda: not _pid_exists(pid), MAX_WAITTIME / 3):
+		if not Utils.wait_for(lambda: not _pid_exists(pid), 1):
 			## try to kill hereafter:
 			os.kill(pid, signal.SIGKILL)
 		return not _pid_exists(pid)
@@ -222,25 +216,50 @@ class Fail2banClientServerBase(LogCaptureTestCase):
 		LogCaptureTestCase.tearDown(self)
 
 	def _wait_for_srv(self, tmp, ready=True, startparams=None):
-		sock = tmp+"/f2b.sock"
+		try:
-		# wait for server (socket):
+			sock = tmp+"/f2b.sock"
-		ret = Utils.wait_for(lambda: os.path.exists(sock), MAX_WAITTIME)
+			# wait for server (socket):
-		if not ret:
+			ret = Utils.wait_for(lambda: os.path.exists(sock), MAX_WAITTIME)
-			raise Exception('Unexpected: Socket file does not exists.\nStart failed: %r' % (startparams,))
-		if ready:
-			# wait for communication with worker ready:
-			ret = Utils.wait_for(lambda: "Server ready" in self.getLog(), MAX_WAITTIME)
 			if not ret:
-				raise Exception('Unexpected: Server ready was not found.\nStart failed: %r' % (startparams,))
+				raise Exception('Unexpected: Socket file does not exists.\nStart failed: %r' % (startparams,))
+			if ready:
+				# wait for communication with worker ready:
+				ret = Utils.wait_for(lambda: "Server ready" in self.getLog(), MAX_WAITTIME)
+				if not ret:
+					raise Exception('Unexpected: Server ready was not found.\nStart failed: %r' % (startparams,))
+		except: # pragma: no cover
+			log = tmp+"/f2b.log"
+			if os.path.isfile(log):
+				_out_file(log)
+			else:
+				logSys.debug("No log file %s to examine details of error", log)
+			raise
 
 
 class Fail2banClientTest(Fail2banClientServerBase):
 
+	def testConsistency(self):
+		self.assertTrue(os.path.isfile(os.path.join(os.path.join(BIN), CLIENT)))
+		self.assertTrue(os.path.isfile(os.path.join(os.path.join(BIN), SERVER)))
+
 	def testClientUsage(self):
 		self.assertRaises(ExitException, _exec_client, 
 			(CLIENT, "-h",))
 		self.assertLogged("Usage: " + CLIENT)
 		self.assertLogged("Report bugs to ")
+		self.pruneLog()
+		self.assertRaises(ExitException, _exec_client, 
+			(CLIENT, "-vq", "-V",))
+		self.assertLogged("Fail2Ban v" + fail2bancmdline.version)
+
+	@withtmpdir
+	def testClientDump(self, tmp):
+		# use here the stock configuration (if possible)
+		startparams = _start_params(tmp, True)
+		self.assertRaises(ExitException, _exec_client, 
+			((CLIENT,) + startparams + ("-vvd",)))
+		self.assertLogged("Loading files")
+		self.assertLogged("logtarget")
 
 	@withtmpdir
 	def testClientStartBackgroundInside(self, tmp):
@@ -271,6 +290,13 @@ class Fail2banClientTest(Fail2banClientServerBase):
 					(CLIENT,) + startparams + ("stop",))
 				self.assertLogged("Shutdown successful")
 				self.assertLogged("Exit with code 0")
+
+			self.pruneLog()
+			# stop again (should fail):
+			self.assertRaises(FailExitException, _exec_client, 
+				(CLIENT,) + startparams + ("stop",))
+			self.assertLogged("Failed to access socket path")
+			self.assertLogged("Is fail2ban running?")
 		finally:
 			_kill_srv(tmp)
 
@@ -278,12 +304,13 @@ class Fail2banClientTest(Fail2banClientServerBase):
 	def testClientStartBackgroundCall(self, tmp):
 		try:
 			global INTERACT
-			startparams = _start_params(tmp)
+			startparams = _start_params(tmp, logtarget=tmp+"/f2b.log")
 			# start (in new process, using the same python version):
 			cmd = (sys.executable, os.path.join(os.path.join(BIN), CLIENT))
 			logSys.debug('Start %s ...', cmd)
-			cmd = cmd + startparams + ("start",)
+			cmd = cmd + startparams + ("--async", "start",)
-			Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
+			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")
@@ -383,13 +410,35 @@ class Fail2banClientTest(Fail2banClientServerBase):
 	@withtmpdir
 	def testClientFailStart(self, tmp):
 		try:
+			# started directly here, so prevent overwrite test cases logger with "INHERITED"
+			startparams = _start_params(tmp, logtarget="INHERITED")
+
+			## wrong config directory
 			self.assertRaises(FailExitException, _exec_client, 
 				(CLIENT, "--async", "-c", tmp+"/miss", "start",))
 			self.assertLogged("Base configuration directory " + tmp+"/miss" + " does not exist")
+			self.pruneLog()
 
+			## wrong socket
 			self.assertRaises(FailExitException, _exec_client, 
-				(CLIENT, "--async", "-c", CONF_DIR, "-s", tmp+"/miss/f2b.sock", "start",))
+				(CLIENT, "--async", "-c", tmp+"/config", "-s", tmp+"/miss/f2b.sock", "start",))
 			self.assertLogged("There is no directory " + tmp+"/miss" + " to contain the socket file")
+			self.pruneLog()
+
+			## already exists:
+			open(tmp+"/f2b.sock", 'a').close()
+			self.assertRaises(FailExitException, _exec_client, 
+				(CLIENT, "--async", "-c", tmp+"/config", "-s", tmp+"/f2b.sock", "start",))
+			self.assertLogged("Fail2ban seems to be in unexpected state (not running but the socket exists)")
+			self.pruneLog()
+			os.remove(tmp+"/f2b.sock")
+
+			## wrong option:
+			self.assertRaises(FailExitException, _exec_client, 
+				(CLIENT, "-s",))
+			self.assertLogged("Usage: ")
+			self.pruneLog()
+
 		finally:
 			_kill_srv(tmp)
 
@@ -417,12 +466,13 @@ class Fail2banServerTest(Fail2banClientServerBase):
 	def testServerStartBackground(self, tmp):
 		try:
 			# to prevent fork of test-cases process, start server in background via command:
-			startparams = _start_params(tmp)
+			startparams = _start_params(tmp, logtarget=tmp+"/f2b.log")
 			# start (in new process, using the same python version):
 			cmd = (sys.executable, os.path.join(os.path.join(BIN), SERVER))
 			logSys.debug('Start %s ...', cmd)
 			cmd = cmd + startparams + ("-b",)
-			Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
+			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")
@@ -495,12 +545,28 @@ class Fail2banServerTest(Fail2banClientServerBase):
 	@withtmpdir
 	def testServerFailStart(self, tmp):
 		try:
+			# started directly here, so prevent overwrite test cases logger with "INHERITED"
+			startparams = _start_params(tmp, logtarget="INHERITED")
+
+			## wrong config directory
 			self.assertRaises(FailExitException, _exec_server, 
 				(SERVER, "-c", tmp+"/miss",))
 			self.assertLogged("Base configuration directory " + tmp+"/miss" + " does not exist")
+			self.pruneLog()
 
+			## wrong socket
 			self.assertRaises(FailExitException, _exec_server, 
-				(SERVER, "-c", CONF_DIR, "-s", tmp+"/miss/f2b.sock",))
+				(SERVER, "-c", tmp+"/config", "-x", "-s", tmp+"/miss/f2b.sock",))
 			self.assertLogged("There is no directory " + tmp+"/miss" + " to contain the socket file")
+			self.pruneLog()
+
+			## already exists:
+			open(tmp+"/f2b.sock", 'a').close()
+			self.assertRaises(FailExitException, _exec_server, 
+				(SERVER, "-c", tmp+"/config", "-s", tmp+"/f2b.sock",))
+			self.assertLogged("Fail2ban seems to be in unexpected state (not running but the socket exists)")
+			self.pruneLog()
+			os.remove(tmp+"/f2b.sock")
+
 		finally:
 			_kill_srv(tmp)