From 4ec70d7851bb4ff8a103ac335fc446592401f1f8 Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 Feb 2016 19:19:31 +0100 Subject: [PATCH] code review, timeout fix, better tracing (and test coverage) by start of server/client (with or without fork) --- fail2ban/client/fail2banclient.py | 21 ++-- fail2ban/client/fail2bancmdline.py | 22 +++-- fail2ban/client/fail2banserver.py | 21 ++-- fail2ban/server/utils.py | 12 ++- fail2ban/tests/actiontestcase.py | 4 +- fail2ban/tests/fail2banclienttestcase.py | 116 ++++++++++++++++++----- 6 files changed, 139 insertions(+), 57 deletions(-) diff --git a/fail2ban/client/fail2banclient.py b/fail2ban/client/fail2banclient.py index ad5cc57e..23d31dc5 100644 --- a/fail2ban/client/fail2banclient.py +++ b/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)) diff --git a/fail2ban/client/fail2bancmdline.py b/fail2ban/client/fail2bancmdline.py index 58fd47c2..a7754bc3 100644 --- a/fail2ban/client/fail2bancmdline.py +++ b/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) diff --git a/fail2ban/client/fail2banserver.py b/fail2ban/client/fail2banserver.py index 73e528ca..a6c8a7c5 100644 --- a/fail2ban/client/fail2banserver.py +++ b/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) - except OSError as e: + ret = os.spawnv(os.P_WAIT, exe, args) + 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: - Utils.wait_for(lambda: phase.get('ready', None) is not None, MAX_WAITTIME) + # wait, do not continue if configuration is not 100% valid: + 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() diff --git a/fail2ban/server/utils.py b/fail2ban/server/utils.py index a8496f8e..fcf54d5f 100644 --- a/fail2ban/server/utils.py +++ b/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 != '': - logSys.log(std_level, "%s -- stdout: %r", realCmd, stdout) + if stdout is not None and stdout != '' and std_level >= logSys.getEffectiveLevel(): + 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 != '': - logSys.log(std_level, "%s -- stderr: %r", realCmd, stderr) + if stderr is not None and stderr != '' and std_level >= logSys.getEffectiveLevel(): + 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: diff --git a/fail2ban/tests/actiontestcase.py b/fail2ban/tests/actiontestcase.py index 6d8fcc82..1872eb1f 100644 --- a/fail2ban/tests/actiontestcase.py +++ b/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'), diff --git a/fail2ban/tests/fail2banclienttestcase.py b/fail2ban/tests/fail2banclienttestcase.py index 6fee732b..aa507fe6 100644 --- a/fail2ban/tests/fail2banclienttestcase.py +++ b/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 = \ -fail2banserver.MAX_WAITTIME = MAX_WAITTIME - +fail2bancmdline.MAX_WAITTIME = MAX_WAITTIME-1 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" - # wait for server (socket): - ret = Utils.wait_for(lambda: os.path.exists(sock), MAX_WAITTIME) - if not ret: - 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) + try: + sock = tmp+"/f2b.sock" + # wait for server (socket): + ret = Utils.wait_for(lambda: os.path.exists(sock), 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",) - Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True) + 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") @@ -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)