"Fossies" - the Fresh Open Source Software Archive

Member "fail2ban-0.11.1/fail2ban/tests/fail2banclienttestcase.py" (11 Jan 2020, 56667 Bytes) of package /linux/misc/fail2ban-0.11.1.tar.gz:


As a special service "Fossies" has tried to format the requested source page into HTML format using (guessed) Python source code syntax highlighting (style: standard) with prefixed line numbers. Alternatively you can here view or download the uninterpreted source code file. See also the latest Fossies "Diffs" side-by-side code changes report for "fail2banclienttestcase.py": 0.10.5_vs_0.11.1.

    1 # emacs: -*- mode: python; py-indent-offset: 4; indent-tabs-mode: t -*-
    2 # vi: set ft=python sts=4 ts=4 sw=4 noet :
    3 
    4 # This file is part of Fail2Ban.
    5 #
    6 # Fail2Ban is free software; you can redistribute it and/or modify
    7 # it under the terms of the GNU General Public License as published by
    8 # the Free Software Foundation; either version 2 of the License, or
    9 # (at your option) any later version.
   10 #
   11 # Fail2Ban is distributed in the hope that it will be useful,
   12 # but WITHOUT ANY WARRANTY; without even the implied warranty of
   13 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
   14 # GNU General Public License for more details.
   15 #
   16 # You should have received a copy of the GNU General Public License
   17 # along with Fail2Ban; if not, write to the Free Software
   18 # Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
   19 
   20 # Fail2Ban developers
   21 
   22 __author__ = "Serg Brester"
   23 __copyright__ = "Copyright (c) 2014- Serg G. Brester (sebres), 2008- Fail2Ban Contributors"
   24 __license__ = "GPL"
   25 
   26 import fileinput
   27 import os
   28 import re
   29 import sys
   30 import time
   31 import signal
   32 import unittest
   33 
   34 from os.path import join as pjoin, isdir, isfile, exists, dirname
   35 from functools import wraps
   36 from threading import Thread
   37 
   38 from ..client import fail2banclient, fail2banserver, fail2bancmdline
   39 from ..client.fail2bancmdline import Fail2banCmdLine
   40 from ..client.fail2banclient import exec_command_line as _exec_client, VisualWait
   41 from ..client.fail2banserver import Fail2banServer, exec_command_line as _exec_server
   42 from .. import protocol
   43 from ..server import server
   44 from ..server.mytime import MyTime
   45 from ..server.utils import Utils
   46 from .utils import LogCaptureTestCase, logSys as DefLogSys, with_tmpdir, shutil, logging, \
   47     STOCK, CONFIG_DIR as STOCK_CONF_DIR, TEST_NOW, tearDownMyTime
   48 
   49 from ..helpers import getLogger
   50 
   51 # Gets the instance of the logger.
   52 logSys = getLogger(__name__)
   53 
   54 CLIENT = "fail2ban-client"
   55 SERVER = "fail2ban-server"
   56 BIN = dirname(Fail2banServer.getServerPath())
   57 
   58 MAX_WAITTIME = unittest.F2B.maxWaitTime(unittest.F2B.MAX_WAITTIME)
   59 MID_WAITTIME = unittest.F2B.maxWaitTime(unittest.F2B.MID_WAITTIME)
   60 
   61 ##
   62 # Several wrappers and settings for proper testing:
   63 #
   64 
   65 fail2bancmdline.MAX_WAITTIME = MAX_WAITTIME - 1
   66 
   67 fail2bancmdline.logSys = \
   68 fail2banclient.logSys = \
   69 fail2banserver.logSys = logSys
   70 
   71 SRV_DEF_LOGTARGET = server.DEF_LOGTARGET
   72 SRV_DEF_LOGLEVEL = server.DEF_LOGLEVEL
   73 
   74 def _test_output(*args):
   75     logSys.info(args[0])
   76 fail2bancmdline.output = \
   77 fail2banclient.output = \
   78 fail2banserver.output = \
   79 protocol.output = _test_output
   80 
   81 def _time_shift(shift):
   82     # jump to the future (+shift minutes):
   83     logSys.debug("===>>> time shift + %s min", shift)
   84     MyTime.setTime(MyTime.time() + shift*60)
   85 
   86 
   87 Observers = server.Observers
   88 
   89 def _observer_wait_idle():
   90     """Helper to wait observer becomes idle"""
   91     if Observers.Main is not None:
   92         Observers.Main.wait_empty(MID_WAITTIME)
   93         Observers.Main.wait_idle(MID_WAITTIME / 5)
   94 
   95 def _observer_wait_before_incrban(cond, timeout=MID_WAITTIME):
   96     """Helper to block observer before increase bantime until some condition gets true"""
   97     if Observers.Main is not None:
   98         # switch ban handler:
   99         _obs_banFound = Observers.Main.banFound
  100         def _banFound(*args, **kwargs):
  101             # restore original handler:
  102             Observers.Main.banFound = _obs_banFound
  103             # wait for:
  104             logSys.debug('  [Observer::banFound] *** observer blocked for test')
  105             Utils.wait_for(cond, timeout)
  106             logSys.debug('  [Observer::banFound] +++ observer runs again')
  107             # original banFound:
  108             _obs_banFound(*args, **kwargs)
  109         Observers.Main.banFound = _banFound
  110 
  111 #
  112 # Mocking .exit so we could test its correct operation.
  113 # Two custom exceptions will be assessed to be raised in the tests
  114 #
  115 
  116 class ExitException(fail2bancmdline.ExitException):
  117     """Exception upon a normal exit"""
  118     pass
  119 
  120 
  121 class FailExitException(fail2bancmdline.ExitException):
  122     """Exception upon abnormal exit"""
  123     pass
  124 
  125 
  126 SUCCESS = ExitException
  127 FAILED = FailExitException
  128 
  129 INTERACT = []
  130 
  131 
  132 def _test_input_command(*args):
  133     if len(INTERACT):
  134         #logSys.debug('--- interact command: %r', INTERACT[0])
  135         return INTERACT.pop(0)
  136     else:
  137         return "exit"
  138 
  139 fail2banclient.input_command = _test_input_command
  140 
  141 # prevents change logging params, log capturing, etc:
  142 fail2bancmdline.PRODUCTION = \
  143 fail2banserver.PRODUCTION = False
  144 
  145 _out_file = LogCaptureTestCase.dumpFile
  146 
  147 def _write_file(fn, mode, *lines):
  148     f = open(fn, mode)
  149     f.write('\n'.join(lines)+('\n' if lines else ''))
  150     f.close()
  151 
  152 def _read_file(fn):
  153     f = None
  154     try:
  155         f = open(fn)
  156         return f.read()
  157     finally:
  158         if f is not None:
  159             f.close()
  160 
  161 
  162 def _start_params(tmp, use_stock=False, use_stock_cfg=None, 
  163     logtarget="/dev/null", db=":memory:", f2b_local=(), jails=("",), 
  164     create_before_start=None,
  165 ):
  166     cfg = pjoin(tmp, "config")
  167     if db == 'auto':
  168         db = pjoin(tmp, "f2b-db.sqlite3")
  169     j_conf = 'jail.conf'
  170     if use_stock and STOCK:
  171         # copy config (sub-directories as alias):
  172         def ig_dirs(dir, files):
  173             """Filters list of 'files' to contain only directories (under dir)"""
  174             return [f for f in files if isdir(pjoin(dir, f))]
  175         shutil.copytree(STOCK_CONF_DIR, cfg, ignore=ig_dirs)
  176         if use_stock_cfg is None: use_stock_cfg = ('action.d', 'filter.d')
  177         # replace fail2ban params (database with memory):
  178         r = re.compile(r'^dbfile\s*=')
  179         for line in fileinput.input(pjoin(cfg, "fail2ban.conf"), inplace=True):
  180             line = line.rstrip('\n')
  181             if r.match(line):
  182                 line = "dbfile = :memory:"
  183             print(line)
  184         # replace jail params (polling as backend to be fast in initialize):
  185         r = re.compile(r'^backend\s*=')
  186         for line in fileinput.input(pjoin(cfg, "jail.conf"), inplace=True):
  187             line = line.rstrip('\n')
  188             if r.match(line):
  189                 line = "backend = polling"
  190             print(line)
  191         # jails to local:
  192         j_conf = 'jail.local' if jails else ''
  193     else:
  194         # just empty config directory without anything (only fail2ban.conf/jail.conf):
  195         os.mkdir(cfg)
  196         _write_file(pjoin(cfg, "fail2ban.conf"), "w",
  197             "[Definition]",
  198             "loglevel = INFO",
  199             "logtarget = " + logtarget.replace('%', '%%'),
  200             "syslogsocket = auto",
  201             "socket = " + pjoin(tmp, "f2b.sock"),
  202             "pidfile = " + pjoin(tmp, "f2b.pid"),
  203             "backend = polling",
  204             "dbfile = " + db,
  205             "dbmaxmatches = 100",
  206             "dbpurgeage = 1d",
  207             "",
  208         )
  209     # write jails (local or conf):
  210     if j_conf:
  211         _write_file(pjoin(cfg, j_conf), "w",
  212             *((
  213                 "[INCLUDES]", "",
  214               "[DEFAULT]", "tmp = " + tmp, "",
  215             )+jails)
  216         )
  217     if f2b_local:
  218         _write_file(pjoin(cfg, "fail2ban.local"), "w", *f2b_local)
  219     if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
  220         _out_file(pjoin(cfg, "fail2ban.conf"))
  221         _out_file(pjoin(cfg, "jail.conf"))
  222         if f2b_local:
  223             _out_file(pjoin(cfg, "fail2ban.local"))
  224         if j_conf and j_conf != "jail.conf":
  225             _out_file(pjoin(cfg, j_conf))
  226 
  227     # link stock actions and filters:
  228     if use_stock_cfg and STOCK:
  229         for n in use_stock_cfg:
  230             os.symlink(os.path.abspath(pjoin(STOCK_CONF_DIR, n)), pjoin(cfg, n))
  231     if create_before_start:
  232         for n in create_before_start:
  233             _write_file(n % {'tmp': tmp}, 'w', '')
  234     # parameters (sock/pid and config, increase verbosity, set log, etc.):
  235     vvv, llev = (), "INFO"
  236     if unittest.F2B.log_level < logging.INFO: # pragma: no cover
  237         llev = str(unittest.F2B.log_level)
  238         if unittest.F2B.verbosity > 1:
  239             vvv = ("-" + "v"*unittest.F2B.verbosity,)
  240     llev = vvv + ("--loglevel", llev)
  241     return (
  242         "-c", cfg, "-s", pjoin(tmp, "f2b.sock"), "-p", pjoin(tmp, "f2b.pid"),
  243         "--logtarget", logtarget,) + llev + ("--syslogsocket", "auto",
  244         "--timeout", str(fail2bancmdline.MAX_WAITTIME),
  245     )
  246 
  247 def _inherited_log(startparams):
  248     try:
  249         return startparams[startparams.index('--logtarget')+1] == 'INHERITED'
  250     except ValueError:
  251         return False
  252 
  253 def _get_pid_from_file(pidfile):
  254     pid = None
  255     try:
  256         pid = _read_file(pidfile)
  257         pid = re.match(r'\S+', pid).group()
  258         return int(pid)
  259     except Exception as e: # pragma: no cover
  260         logSys.debug(e)
  261     return pid
  262 
  263 def _kill_srv(pidfile):
  264     logSys.debug("cleanup: %r", (pidfile, isdir(pidfile)))
  265     if isdir(pidfile):
  266         piddir = pidfile
  267         pidfile = pjoin(piddir, "f2b.pid")
  268         if not isfile(pidfile): # pragma: no cover
  269             pidfile = pjoin(piddir, "fail2ban.pid")
  270 
  271     # output log in heavydebug (to see possible start errors):
  272     if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
  273         logfile = pjoin(piddir, "f2b.log")
  274         if isfile(logfile):
  275             _out_file(logfile)
  276         else:
  277             logSys.log(5, 'no logfile %r', logfile)
  278 
  279     if not isfile(pidfile):
  280         logSys.debug("cleanup: no pidfile for %r", piddir)
  281         return True
  282 
  283     logSys.debug("cleanup pidfile: %r", pidfile)
  284     pid = _get_pid_from_file(pidfile)
  285     if pid is None: # pragma: no cover
  286         return False
  287 
  288     try:
  289         logSys.debug("cleanup pid: %r", pid)
  290         if pid <= 0 or pid == os.getpid(): # pragma: no cover
  291             raise ValueError('pid %s of %s is invalid' % (pid, pidfile))
  292         if not Utils.pid_exists(pid):
  293             return True
  294         ## try to properly stop (have signal handler):
  295         os.kill(pid, signal.SIGTERM)
  296         ## check still exists after small timeout:
  297         if not Utils.wait_for(lambda: not Utils.pid_exists(pid), 1):
  298             ## try to kill hereafter:
  299             os.kill(pid, signal.SIGKILL)
  300         logSys.debug("cleanup: kill ready")
  301         return not Utils.pid_exists(pid)
  302     except Exception as e: # pragma: no cover
  303         logSys.exception(e)
  304     return True
  305 
  306 
  307 def with_kill_srv(f):
  308     """Helper to decorate tests which receive in the last argument tmpdir to pass to kill_srv
  309 
  310     To be used in tandem with @with_tmpdir
  311     """
  312     @wraps(f)
  313     def wrapper(self, *args):
  314         pidfile = args[-1]
  315         try:
  316             return f(self, *args)
  317         finally:
  318             _kill_srv(pidfile)
  319     return wrapper
  320 
  321 def with_foreground_server_thread(startextra={}):
  322     """Helper to decorate tests uses foreground server (as thread), started directly in test-cases
  323 
  324     To be used only in subclasses
  325     """
  326     def _deco_wrapper(f):
  327         @with_tmpdir
  328         @wraps(f)
  329         def wrapper(self, tmp, *args, **kwargs):
  330             th = None
  331             phase = dict()
  332             try:
  333                 # started directly here, so prevent overwrite test cases logger with "INHERITED"
  334                 startparams = _start_params(tmp, logtarget="INHERITED", **startextra)
  335                 # because foreground block execution - start it in thread:
  336                 th = Thread(
  337                     name="_TestCaseWorker",
  338                     target=self._testStartForeground,
  339                     args=(tmp, startparams, phase)
  340                 )
  341                 th.daemon = True
  342                 th.start()
  343                 # to wait for end of server, default accept any exit code, because multi-threaded, 
  344                 # thus server can exit in-between...
  345                 def _stopAndWaitForServerEnd(code=(SUCCESS, FAILED)):
  346                     # if seems to be down - try to catch end phase (wait a bit for end:True to recognize down state):
  347                     if not phase.get('end', None) and not os.path.exists(pjoin(tmp, "f2b.pid")):
  348                         Utils.wait_for(lambda: phase.get('end', None) is not None, MID_WAITTIME)
  349                     # stop (if still running):
  350                     if not phase.get('end', None):
  351                         self.execCmd(code, startparams, "stop")
  352                         # wait for end sign:
  353                         Utils.wait_for(lambda: phase.get('end', None) is not None, MAX_WAITTIME)
  354                         self.assertTrue(phase.get('end', None))
  355                         self.assertLogged("Shutdown successful", "Exiting Fail2ban", all=True, wait=MAX_WAITTIME)
  356                     # set to NOP: avoid dual call
  357                     self.stopAndWaitForServerEnd = lambda *args, **kwargs: None
  358                 self.stopAndWaitForServerEnd = _stopAndWaitForServerEnd
  359                 # wait for start thread:
  360                 Utils.wait_for(lambda: phase.get('start', None) is not None, MAX_WAITTIME)
  361                 self.assertTrue(phase.get('start', None))
  362                 # wait for server (socket and ready):
  363                 self._wait_for_srv(tmp, True, startparams=startparams, phase=phase)
  364                 DefLogSys.info('=== within server: begin ===')
  365                 self.pruneLog()
  366                 # several commands to server in body of decorated function:
  367                 return f(self, tmp, startparams, *args, **kwargs)
  368             except Exception as e: # pragma: no cover
  369                 print('=== Catch an exception: %s' % e)
  370                 log = self.getLog()
  371                 if log:
  372                     print('=== Error of server, log: ===\n%s===' % log)
  373                     self.pruneLog()
  374                 raise
  375             finally:
  376                 if th:
  377                     # wait for server end (if not yet already exited):
  378                     DefLogSys.info('=== within server: end.  ===')
  379                     self.pruneLog()
  380                     self.stopAndWaitForServerEnd()
  381                     # we start client/server directly in current process (new thread),
  382                     # so don't kill (same process) - if success, just wait for end of worker:
  383                     if phase.get('end', None):
  384                         th.join()
  385                 tearDownMyTime()
  386         return wrapper
  387     return _deco_wrapper
  388 
  389 
  390 class Fail2banClientServerBase(LogCaptureTestCase):
  391 
  392     _orig_exit = Fail2banCmdLine._exit
  393 
  394     def _setLogLevel(self, *args, **kwargs):
  395         pass
  396 
  397     def setUp(self):
  398         """Call before every test case."""
  399         LogCaptureTestCase.setUp(self)
  400         # prevent to switch the logging in the test cases (use inherited one):
  401         server.DEF_LOGTARGET = "INHERITED"
  402         server.DEF_LOGLEVEL = DefLogSys.level
  403         Fail2banCmdLine._exit = staticmethod(self._test_exit)
  404 
  405     def tearDown(self):
  406         """Call after every test case."""
  407         Fail2banCmdLine._exit = self._orig_exit
  408         # restore server log target:
  409         server.DEF_LOGTARGET = SRV_DEF_LOGTARGET
  410         server.DEF_LOGLEVEL = SRV_DEF_LOGLEVEL
  411         LogCaptureTestCase.tearDown(self)
  412         tearDownMyTime()
  413 
  414     @staticmethod
  415     def _test_exit(code=0):
  416         if code == 0:
  417             raise ExitException()
  418         else:
  419             raise FailExitException()
  420 
  421     def _wait_for_srv(self, tmp, ready=True, startparams=None, phase=None):
  422         if not phase: phase = {}
  423         try:
  424             sock = pjoin(tmp, "f2b.sock")
  425             # wait for server (socket):
  426             ret = Utils.wait_for(lambda: phase.get('end') or exists(sock), MAX_WAITTIME)
  427             if not ret or phase.get('end'): # pragma: no cover - test-failure case only
  428                 raise Exception(
  429                     'Unexpected: Socket file does not exists.\nStart failed: %r'
  430                     % (startparams,)
  431                 )
  432             if ready:
  433                 # wait for communication with worker ready:
  434                 ret = Utils.wait_for(lambda: "Server ready" in self.getLog(), MAX_WAITTIME)
  435                 if not ret: # pragma: no cover - test-failure case only
  436                     raise Exception(
  437                         'Unexpected: Server ready was not found, phase %r.\nStart failed: %r'
  438                         % (phase, startparams,)
  439                     )
  440         except:  # pragma: no cover
  441             if _inherited_log(startparams):
  442                 print('=== Error by wait fot server, log: ===\n%s===' % self.getLog())
  443                 self.pruneLog()
  444             log = pjoin(tmp, "f2b.log")
  445             if isfile(log):
  446                 _out_file(log)
  447             elif not _inherited_log(startparams):
  448                 logSys.debug("No log file %s to examine details of error", log)
  449             raise
  450 
  451     def execCmd(self, exitType, startparams, *args):
  452         self.assertRaises(exitType, self.exec_command_line[0],
  453             (self.exec_command_line[1:] + startparams + args))
  454 
  455     #
  456     # Common tests
  457     #
  458     def _testStartForeground(self, tmp, startparams, phase):
  459         # start and wait to end (foreground):
  460         logSys.debug("start of test worker")
  461         phase['start'] = True
  462         try:
  463             self.execCmd(SUCCESS, ("-f",) + startparams, "start")
  464         finally:
  465             # end :
  466             phase['start'] = False
  467             phase['end'] = True
  468             logSys.debug("end of test worker")
  469 
  470     @with_foreground_server_thread(startextra={'f2b_local':(
  471             "[Thread]",
  472             "stacksize = 32"
  473             "",
  474         )})
  475     def testStartForeground(self, tmp, startparams):
  476         # check thread options were set:
  477         self.pruneLog()
  478         self.execCmd(SUCCESS, startparams, "get", "thread")
  479         self.assertLogged("{'stacksize': 32}")
  480         # several commands to server:
  481         self.execCmd(SUCCESS, startparams, "ping")
  482         self.execCmd(FAILED, startparams, "~~unknown~cmd~failed~~")
  483         self.execCmd(SUCCESS, startparams, "echo", "TEST-ECHO")
  484 
  485 
  486 class Fail2banClientTest(Fail2banClientServerBase):
  487 
  488     exec_command_line = (_exec_client, CLIENT,)
  489 
  490     def testConsistency(self):
  491         self.assertTrue(isfile(pjoin(BIN, CLIENT)))
  492         self.assertTrue(isfile(pjoin(BIN, SERVER)))
  493 
  494     def testClientUsage(self):
  495         self.execCmd(SUCCESS, (), "-h")
  496         self.assertLogged("Usage: " + CLIENT)
  497         self.assertLogged("Report bugs to ")
  498         self.pruneLog()
  499         self.execCmd(SUCCESS, (), "-V")
  500         self.assertLogged(fail2bancmdline.normVersion())
  501         self.pruneLog()
  502         self.execCmd(SUCCESS, (), "-vq", "--version")
  503         self.assertLogged("Fail2Ban v" + fail2bancmdline.version)
  504         self.pruneLog()
  505         self.execCmd(SUCCESS, (), "--str2sec", "1d12h30m")
  506         self.assertLogged("131400")
  507 
  508     @with_tmpdir
  509     def testClientDump(self, tmp):
  510         # use here the stock configuration (if possible)
  511         startparams = _start_params(tmp, True)
  512         self.execCmd(SUCCESS, startparams, "-vvd")
  513         self.assertLogged("Loading files")
  514         self.assertLogged("['set', 'logtarget',")
  515         self.pruneLog()
  516         # pretty dump:
  517         self.execCmd(SUCCESS, startparams, "--dp")
  518         self.assertLogged("['set', 'logtarget',")
  519         
  520     @with_tmpdir
  521     @with_kill_srv
  522     def testClientStartBackgroundInside(self, tmp):
  523         # use once the stock configuration (to test starting also)
  524         startparams = _start_params(tmp, True)
  525         # start:
  526         self.execCmd(SUCCESS, ("-b",) + startparams, "start")
  527         # wait for server (socket and ready):
  528         self._wait_for_srv(tmp, True, startparams=startparams)
  529         self.assertLogged("Server ready")
  530         self.assertLogged("Exit with code 0")
  531         try:
  532             self.execCmd(SUCCESS, startparams, "echo", "TEST-ECHO")
  533             self.execCmd(FAILED, startparams, "~~unknown~cmd~failed~~")
  534             self.pruneLog()
  535             # start again (should fail):
  536             self.execCmd(FAILED, ("-b",) + startparams, "start")
  537             self.assertLogged("Server already running")
  538         finally:
  539             self.pruneLog()
  540             # stop:
  541             self.execCmd(SUCCESS, startparams, "stop")
  542             self.assertLogged("Shutdown successful")
  543             self.assertLogged("Exit with code 0")
  544 
  545         self.pruneLog()
  546         # stop again (should fail):
  547         self.execCmd(FAILED, startparams, "stop")
  548         self.assertLogged("Failed to access socket path")
  549         self.assertLogged("Is fail2ban running?")
  550 
  551     @with_tmpdir
  552     @with_kill_srv
  553     def testClientStartBackgroundCall(self, tmp):
  554         global INTERACT
  555         startparams = _start_params(tmp, logtarget=pjoin(tmp, "f2b.log"))
  556         # if fast, start server process from client started direct here:
  557         if unittest.F2B.fast: # pragma: no cover
  558             self.execCmd(SUCCESS, startparams + ("start",))
  559         else:
  560             # start (in new process, using the same python version):
  561             cmd = (sys.executable, pjoin(BIN, CLIENT))
  562             logSys.debug('Start %s ...', cmd)
  563             cmd = cmd + startparams + ("--async", "start",)
  564             ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
  565             self.assertTrue(len(ret) and ret[0])
  566             # wait for server (socket and ready):
  567             self._wait_for_srv(tmp, True, startparams=cmd)
  568         self.assertLogged("Server ready")
  569         self.pruneLog()
  570         try:
  571             # echo from client (inside):
  572             self.execCmd(SUCCESS, startparams, "echo", "TEST-ECHO")
  573             self.assertLogged("TEST-ECHO")
  574             self.assertLogged("Exit with code 0")
  575             self.pruneLog()
  576             # test ping timeout:
  577             self.execCmd(SUCCESS, startparams, "ping", "0.1")
  578             self.assertLogged("Server replied: pong")
  579             self.pruneLog()
  580             # python 3 seems to bypass such short timeouts also, 
  581             # so suspend/resume server process and test between it...
  582             pid = _get_pid_from_file(pjoin(tmp, "f2b.pid"))
  583             try:
  584                 # suspend:
  585                 os.kill(pid, signal.SIGSTOP); # or SIGTSTP?
  586                 time.sleep(Utils.DEFAULT_SHORT_INTERVAL)
  587                 # test ping with short timeout:
  588                 self.execCmd(FAILED, startparams, "ping", "1e-10")
  589             finally:
  590                 # resume:
  591                 os.kill(pid, signal.SIGCONT)
  592             self.assertLogged("timed out")
  593             self.pruneLog()
  594             # interactive client chat with started server:
  595             INTERACT += [
  596                 "echo INTERACT-ECHO",
  597                 "status",
  598                 "exit"
  599             ]
  600             self.execCmd(SUCCESS, startparams, "-i")
  601             self.assertLogged("INTERACT-ECHO")
  602             self.assertLogged("Status", "Number of jail:")
  603             self.assertLogged("Exit with code 0")
  604             self.pruneLog()
  605             # test reload and restart over interactive client:
  606             INTERACT += [
  607                 "reload",
  608                 "restart",
  609                 "exit"
  610             ]
  611             self.execCmd(SUCCESS, startparams, "-i")
  612             self.assertLogged("Reading config files:")
  613             self.assertLogged("Shutdown successful")
  614             self.assertLogged("Server ready")
  615             self.assertLogged("Exit with code 0")
  616             self.pruneLog()
  617             # test reload missing jail (interactive):
  618             INTERACT += [
  619                 "reload ~~unknown~jail~fail~~",
  620                 "exit"
  621             ]
  622             self.execCmd(SUCCESS, startparams, "-i")
  623             self.assertLogged("Failed during configuration: No section: '~~unknown~jail~fail~~'")
  624             self.pruneLog()
  625             # test reload missing jail (direct):
  626             self.execCmd(FAILED, startparams, "reload", "~~unknown~jail~fail~~")
  627             self.assertLogged("Failed during configuration: No section: '~~unknown~jail~fail~~'")
  628             self.assertLogged("Exit with code 255")
  629             self.pruneLog()
  630         finally:
  631             self.pruneLog()
  632             # stop:
  633             self.execCmd(SUCCESS, startparams, "stop")
  634             self.assertLogged("Shutdown successful")
  635             self.assertLogged("Exit with code 0")
  636 
  637     @with_tmpdir
  638     @with_kill_srv
  639     def testClientFailStart(self, tmp):
  640         # started directly here, so prevent overwrite test cases logger with "INHERITED"
  641         startparams = _start_params(tmp, logtarget="INHERITED")
  642 
  643         ## wrong config directory
  644         self.execCmd(FAILED, (),
  645             "--async", "-c", pjoin(tmp, "miss"), "start")
  646         self.assertLogged("Base configuration directory " + pjoin(tmp, "miss") + " does not exist")
  647         self.pruneLog()
  648 
  649         ## wrong socket
  650         self.execCmd(FAILED, (),
  651             "--async", "-c", pjoin(tmp, "config"), "-s", pjoin(tmp, "miss/f2b.sock"), "start")
  652         self.assertLogged("There is no directory " + pjoin(tmp, "miss") + " to contain the socket file")
  653         self.pruneLog()
  654 
  655         ## not running
  656         self.execCmd(FAILED, (),
  657             "-c", pjoin(tmp, "config"), "-s", pjoin(tmp, "f2b.sock"), "reload")
  658         self.assertLogged("Could not find server")
  659         self.pruneLog()
  660 
  661         ## already exists:
  662         open(pjoin(tmp, "f2b.sock"), 'a').close()
  663         self.execCmd(FAILED, (),
  664             "--async", "-c", pjoin(tmp, "config"), "-s", pjoin(tmp, "f2b.sock"), "start")
  665         self.assertLogged("Fail2ban seems to be in unexpected state (not running but the socket exists)")
  666         self.pruneLog()
  667         os.remove(pjoin(tmp, "f2b.sock"))
  668 
  669         ## wrong option:
  670         self.execCmd(FAILED, (), "-s")
  671         self.assertLogged("Usage: ")
  672         self.pruneLog()
  673 
  674     @with_tmpdir
  675     def testClientFailCommands(self, tmp):
  676         # started directly here, so prevent overwrite test cases logger with "INHERITED"
  677         startparams = _start_params(tmp, logtarget="INHERITED")
  678 
  679         # not started:
  680         self.execCmd(FAILED, startparams,
  681             "reload", "jail")
  682         self.assertLogged("Could not find server")
  683         self.pruneLog()
  684 
  685         # unexpected arg:
  686         self.execCmd(FAILED, startparams,
  687             "--async", "reload", "--xxx", "jail")
  688         self.assertLogged("Unexpected argument(s) for reload:")
  689         self.pruneLog()
  690 
  691 
  692     def testVisualWait(self):
  693         sleeptime = 0.035
  694         for verbose in (2, 0):
  695             cntr = 15
  696             with VisualWait(verbose, 5) as vis:
  697                 while cntr:
  698                     vis.heartbeat()
  699                     if verbose and not unittest.F2B.fast:
  700                         time.sleep(sleeptime)
  701                     cntr -= 1
  702 
  703 
  704 class Fail2banServerTest(Fail2banClientServerBase):
  705 
  706     exec_command_line = (_exec_server, SERVER,)
  707 
  708     def testServerUsage(self):
  709         self.execCmd(SUCCESS, (), "-h")
  710         self.assertLogged("Usage: " + SERVER)
  711         self.assertLogged("Report bugs to ")
  712 
  713     @with_tmpdir
  714     @with_kill_srv
  715     def testServerStartBackground(self, tmp):
  716         # to prevent fork of test-cases process, start server in background via command:
  717         startparams = _start_params(tmp, logtarget=pjoin(tmp, "f2b.log"))
  718         # start (in new process, using the same python version):
  719         cmd = (sys.executable, pjoin(BIN, SERVER))
  720         logSys.debug('Start %s ...', cmd)
  721         cmd = cmd + startparams + ("-b",)
  722         ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
  723         self.assertTrue(len(ret) and ret[0])
  724         # wait for server (socket and ready):
  725         self._wait_for_srv(tmp, True, startparams=cmd)
  726         self.assertLogged("Server ready")
  727         self.pruneLog()
  728         try:
  729             self.execCmd(SUCCESS, startparams, "echo", "TEST-ECHO")
  730             self.execCmd(FAILED, startparams, "~~unknown~cmd~failed~~")
  731         finally:
  732             self.pruneLog()
  733             # stop:
  734             self.execCmd(SUCCESS, startparams, "stop")
  735             self.assertLogged("Shutdown successful")
  736             self.assertLogged("Exit with code 0")
  737 
  738     @with_tmpdir
  739     @with_kill_srv
  740     def testServerFailStart(self, tmp):
  741         # started directly here, so prevent overwrite test cases logger with "INHERITED"
  742         startparams = _start_params(tmp, logtarget="INHERITED")
  743 
  744         ## wrong config directory
  745         self.execCmd(FAILED, (),
  746             "-c", pjoin(tmp, "miss"))
  747         self.assertLogged("Base configuration directory " + pjoin(tmp, "miss") + " does not exist")
  748         self.pruneLog()
  749 
  750         ## wrong socket
  751         self.execCmd(FAILED, (),
  752             "-c", pjoin(tmp, "config"), "-x", "-s", pjoin(tmp, "miss/f2b.sock"))
  753         self.assertLogged("There is no directory " + pjoin(tmp, "miss") + " to contain the socket file")
  754         self.pruneLog()
  755 
  756         ## already exists:
  757         open(pjoin(tmp, "f2b.sock"), 'a').close()
  758         self.execCmd(FAILED, (),
  759             "-c", pjoin(tmp, "config"), "-s", pjoin(tmp, "f2b.sock"))
  760         self.assertLogged("Fail2ban seems to be in unexpected state (not running but the socket exists)")
  761         self.pruneLog()
  762         os.remove(pjoin(tmp, "f2b.sock"))
  763 
  764     @with_tmpdir
  765     @with_kill_srv
  766     def testServerTestFailStart(self, tmp):
  767         # started directly here, so prevent overwrite test cases logger with "INHERITED"
  768         startparams = _start_params(tmp, logtarget="INHERITED")
  769         cfg = pjoin(tmp, "config")
  770 
  771         # test configuration is correct:
  772         self.pruneLog("[test-phase 0]")
  773         self.execCmd(SUCCESS, startparams, "--test")
  774         self.assertLogged("OK: configuration test is successful")
  775 
  776         # append one wrong configured jail:
  777         _write_file(pjoin(cfg, "jail.conf"), "a", "", "[broken-jail]", 
  778             "", "filter = broken-jail-filter", "enabled = true")
  779 
  780         # first try test config:
  781         self.pruneLog("[test-phase 0a]")
  782         self.execCmd(FAILED, startparams, "--test")
  783         self.assertLogged("Unable to read the filter 'broken-jail-filter'",
  784             "Errors in jail 'broken-jail'.",
  785             "ERROR: test configuration failed", all=True)
  786 
  787         # failed to start with test config:
  788         self.pruneLog("[test-phase 0b]")
  789         self.execCmd(FAILED, startparams, "-t", "start")
  790         self.assertLogged("Unable to read the filter 'broken-jail-filter'",
  791             "Errors in jail 'broken-jail'.",
  792             "ERROR: test configuration failed", all=True)
  793 
  794     @with_tmpdir
  795     def testKillAfterStart(self, tmp):
  796         try:
  797             # to prevent fork of test-cases process, start server in background via command:
  798             startparams = _start_params(tmp, logtarget=pjoin(tmp,
  799                 'f2b.log[format="SRV: %(relativeCreated)3d | %(message)s", datetime=off]'))
  800             # start (in new process, using the same python version):
  801             cmd = (sys.executable, pjoin(BIN, SERVER))
  802             logSys.debug('Start %s ...', cmd)
  803             cmd = cmd + startparams + ("-b",)
  804             ret = Utils.executeCmd(cmd, timeout=MAX_WAITTIME, shell=False, output=True)
  805             self.assertTrue(len(ret) and ret[0])
  806             # wait for server (socket and ready):
  807             self._wait_for_srv(tmp, True, startparams=cmd)
  808             self.assertLogged("Server ready")
  809             self.pruneLog()
  810             logSys.debug('Kill server ... %s', tmp)
  811         finally:
  812             self.assertTrue(_kill_srv(tmp))
  813         # wait for end (kill was successful):
  814         Utils.wait_for(lambda: not isfile(pjoin(tmp, "f2b.pid")), MAX_WAITTIME)
  815         self.assertFalse(isfile(pjoin(tmp, "f2b.pid")))
  816         self.assertLogged("cleanup: kill ready")
  817         self.pruneLog()
  818         # again:
  819         self.assertTrue(_kill_srv(tmp))
  820         self.assertLogged("cleanup: no pidfile for")
  821 
  822     @with_foreground_server_thread(startextra={'db': 'auto'})
  823     def testServerReloadTest(self, tmp, startparams):
  824         # Very complicated test-case, that expected running server (foreground in thread).
  825         #
  826         # In this test-case, each phase is related from previous one, 
  827         # so it cannot be splitted in multiple test cases.
  828         # Additionaly many log-messages used as ready-sign (to wait for end of phase).
  829         #
  830         # Used file database (instead of :memory:), to restore bans and log-file positions,
  831         # after restart/reload between phases.
  832         cfg = pjoin(tmp, "config")
  833         test1log = pjoin(tmp, "test1.log")
  834         test2log = pjoin(tmp, "test2.log")
  835         test3log = pjoin(tmp, "test3.log")
  836 
  837         os.mkdir(pjoin(cfg, "action.d"))
  838         def _write_action_cfg(actname="test-action1", allow=True, 
  839             start="", reload="", ban="", unban="", stop=""):
  840             fn = pjoin(cfg, "action.d", "%s.conf" % actname)
  841             if not allow:
  842                 os.remove(fn)
  843                 return
  844             _write_file(fn, "w",
  845                 "[DEFAULT]",
  846                 "_exec_once = 0",
  847                 "",
  848                 "[Definition]",
  849                 "norestored = %(_exec_once)s",
  850                 "restore = ",
  851                 "info = ",
  852                 "_use_flush_ = echo '[%(name)s] %(actname)s: -- flushing IPs'",
  853                 "actionstart =  echo '[%(name)s] %(actname)s: ** start'", start,
  854                 "actionreload = echo '[%(name)s] %(actname)s: .. reload'", reload,
  855                 "actionban =    echo '[%(name)s] %(actname)s: ++ ban <ip> %(restore)s%(info)s'", ban,
  856                 "actionunban =  echo '[%(name)s] %(actname)s: -- unban <ip>'", unban,
  857                 "actionstop =   echo '[%(name)s] %(actname)s: __ stop'", stop,
  858             )
  859             if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover
  860                 _out_file(fn)
  861 
  862         def _write_jail_cfg(enabled=(1, 2), actions=(), backend="polling"):
  863             _write_file(pjoin(cfg, "jail.conf"), "w",
  864                 "[INCLUDES]", "",
  865                 "[DEFAULT]", "",
  866                 "usedns = no",
  867                 "maxretry = 3",
  868                 "findtime = 10m",
  869                 r"failregex = ^\s*failure <F-ERRCODE>401|403</F-ERRCODE> from <HOST>",
  870                 "datepattern = {^LN-BEG}EPOCH",
  871                 "ignoreip = 127.0.0.1/8 ::1", # just to cover ignoreip in jailreader/transmitter
  872                 "",
  873                 "[test-jail1]", "backend = " + backend, "filter =", 
  874                 "action = ",
  875                 "         test-action1[name='%(__name__)s']" \
  876                     if 1 in actions else "",
  877                 "         test-action2[name='%(__name__)s', restore='restored: <restored>', info=', err-code: <F-ERRCODE>']" \
  878                     if 2 in actions else "",
  879                 "         test-action2[name='%(__name__)s', actname=test-action3, _exec_once=1, restore='restored: <restored>',"
  880                                         " actionflush=<_use_flush_>]" \
  881                     if 3 in actions else "",
  882                 "logpath = " + test1log,
  883                 "          " + test2log if 2 in enabled else "",
  884                 "          " + test3log if 2 in enabled else "",
  885                 r"failregex = ^\s*failure <F-ERRCODE>401|403</F-ERRCODE> from <HOST>",
  886                 r"            ^\s*error <F-ERRCODE>401|403</F-ERRCODE> from <HOST>" \
  887                     if 2 in enabled else "",
  888                 "enabled = true" if 1 in enabled else "",
  889                 "",
  890                 "[test-jail2]", "backend = " + backend, "filter =", 
  891                 "action = ",
  892                 "         test-action2[name='%(__name__)s', restore='restored: <restored>', info=', err-code: <F-ERRCODE>']" \
  893                     if 2 in actions else "",
  894                 "         test-action2[name='%(__name__)s', actname=test-action3, _exec_once=1, restore='restored: <restored>']"
  895                                         " actionflush=<_use_flush_>]" \
  896                     if 3 in actions else "",
  897                 "logpath = " + test2log,
  898                 "enabled = true" if 2 in enabled else "",
  899             )
  900             if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover
  901                 _out_file(pjoin(cfg, "jail.conf"))
  902 
  903         # create default test actions:
  904         _write_action_cfg(actname="test-action1")
  905         _write_action_cfg(actname="test-action2")
  906 
  907         _write_jail_cfg(enabled=[1], actions=[1,2,3])
  908         # append one wrong configured jail:
  909         _write_file(pjoin(cfg, "jail.conf"), "a", "", "[broken-jail]", 
  910             "", "filter = broken-jail-filter", "enabled = true")
  911 
  912         _write_file(test1log, "w", *((str(int(MyTime.time())) + " failure 401 from 192.0.2.1: test 1",) * 3))
  913         _write_file(test2log, "w")
  914         _write_file(test3log, "w")
  915         
  916         # reload and wait for ban:
  917         self.pruneLog("[test-phase 1a]")
  918         if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
  919             _out_file(test1log)
  920         self.execCmd(SUCCESS, startparams, "reload")
  921         self.assertLogged(
  922             "Reload finished.",
  923             "1 ticket(s) in 'test-jail1", all=True, wait=MID_WAITTIME)
  924         self.assertLogged("Added logfile: %r" % test1log)
  925         self.assertLogged("[test-jail1] Ban 192.0.2.1")
  926         # test actions started:
  927         self.assertLogged(
  928             "stdout: '[test-jail1] test-action1: ** start'", 
  929             "stdout: '[test-jail1] test-action2: ** start'", all=True)
  930         # test restored is 0 (both actions available):
  931         self.assertLogged(
  932             "stdout: '[test-jail1] test-action2: ++ ban 192.0.2.1 restored: 0, err-code: 401'",
  933             "stdout: '[test-jail1] test-action3: ++ ban 192.0.2.1 restored: 0'",
  934             all=True, wait=MID_WAITTIME)
  935 
  936         # broken jail was logged (in client and server log):
  937         self.assertLogged(
  938             "Unable to read the filter 'broken-jail-filter'",
  939             "Errors in jail 'broken-jail'. Skipping...",
  940             "Jail 'broken-jail' skipped, because of wrong configuration", all=True)
  941         
  942         # enable both jails, 3 logs for jail1, etc...
  943         # truncate test-log - we should not find unban/ban again by reload:
  944         self.pruneLog("[test-phase 1b]")
  945         _write_jail_cfg(actions=[1,2])
  946         _write_file(test1log, "w+")
  947         if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
  948             _out_file(test1log)
  949         self.execCmd(SUCCESS, startparams, "reload")
  950         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
  951         # test not unbanned / banned again:
  952         self.assertNotLogged(
  953             "[test-jail1] Unban 192.0.2.1", 
  954             "[test-jail1] Ban 192.0.2.1", all=True)
  955         # test 2 new log files:
  956         self.assertLogged(
  957             "Added logfile: %r" % test2log, 
  958             "Added logfile: %r" % test3log, all=True)
  959         # test actions reloaded:
  960         self.assertLogged(
  961             "stdout: '[test-jail1] test-action1: .. reload'", 
  962             "stdout: '[test-jail1] test-action2: .. reload'", all=True)
  963         # test 1 new jail:
  964         self.assertLogged(
  965             "Creating new jail 'test-jail2'",
  966             "Jail 'test-jail2' started", all=True)
  967         # test action3 removed, test flushing successful (and no single unban occurred):
  968         self.assertLogged(
  969             "stdout: '[test-jail1] test-action3: -- flushing IPs'",
  970             "stdout: '[test-jail1] test-action3: __ stop'", all=True)
  971         self.assertNotLogged(
  972             "stdout: '[test-jail1] test-action3: -- unban 192.0.2.1'")
  973         
  974         # update action1, delete action2 (should be stopped via configuration)...
  975         self.pruneLog("[test-phase 2a]")
  976         _write_jail_cfg(actions=[1])
  977         _write_action_cfg(actname="test-action1", 
  978             start= "               echo '[<name>] %s: started.'" % "test-action1",
  979             reload="               echo '[<name>] %s: reloaded.'" % "test-action1", 
  980             stop=  "               echo '[<name>] %s: stopped.'" % "test-action1")
  981         self.execCmd(SUCCESS, startparams, "reload")
  982         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
  983         # test not unbanned / banned again:
  984         self.assertNotLogged(
  985             "[test-jail1] Unban 192.0.2.1", 
  986             "[test-jail1] Ban 192.0.2.1", all=True)
  987         # no new log files:
  988         self.assertNotLogged("Added logfile:")
  989         # test action reloaded (update):
  990         self.assertLogged(
  991             "stdout: '[test-jail1] test-action1: .. reload'",
  992             "stdout: '[test-jail1] test-action1: reloaded.'", all=True)
  993         # test stopped action unbans:
  994         self.assertLogged(
  995             "stdout: '[test-jail1] test-action2: -- unban 192.0.2.1'")
  996         # test action stopped:
  997         self.assertLogged(
  998             "stdout: '[test-jail1] test-action2: __ stop'")
  999         self.assertNotLogged(
 1000             "stdout: '[test-jail1] test-action1: -- unban 192.0.2.1'")
 1001         
 1002         # don't need action1 anymore:
 1003         _write_action_cfg(actname="test-action1", allow=False)
 1004         # leave action2 just to test restored interpolation:
 1005         _write_jail_cfg(actions=[2,3])
 1006         
 1007         # write new failures:
 1008         self.pruneLog("[test-phase 2b]")
 1009         _write_file(test2log, "w+", *(
 1010             (str(int(MyTime.time())) + "   error 403 from 192.0.2.2: test 2",) * 3 +
 1011           (str(int(MyTime.time())) + "   error 403 from 192.0.2.3: test 2",) * 3 +
 1012           (str(int(MyTime.time())) + " failure 401 from 192.0.2.4: test 2",) * 3 +
 1013           (str(int(MyTime.time())) + " failure 401 from 192.0.2.8: test 2",) * 3
 1014         ))
 1015         if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
 1016             _out_file(test2log)
 1017         # test all will be found in jail1 and one in jail2:
 1018         self.assertLogged(
 1019             "2 ticket(s) in 'test-jail2",
 1020             "5 ticket(s) in 'test-jail1", all=True, wait=MID_WAITTIME)
 1021         self.assertLogged(
 1022             "[test-jail1] Ban 192.0.2.2",
 1023             "[test-jail1] Ban 192.0.2.3",
 1024             "[test-jail1] Ban 192.0.2.4",
 1025             "[test-jail1] Ban 192.0.2.8",
 1026             "[test-jail2] Ban 192.0.2.4",
 1027             "[test-jail2] Ban 192.0.2.8", all=True)
 1028         # test ips at all not visible for jail2:
 1029         self.assertNotLogged(
 1030             "[test-jail2] Found 192.0.2.2", 
 1031             "[test-jail2] Ban 192.0.2.2",
 1032             "[test-jail2] Found 192.0.2.3", 
 1033             "[test-jail2] Ban 192.0.2.3", 
 1034             all=True)
 1035         # if observer available wait for it becomes idle (write all tickets to db):
 1036         _observer_wait_idle()
 1037 
 1038         # rotate logs:
 1039         _write_file(test1log, "w+")
 1040         _write_file(test2log, "w+")
 1041 
 1042         # restart jail without unban all:
 1043         self.pruneLog("[test-phase 2c]")
 1044         self.execCmd(SUCCESS, startparams,
 1045             "restart", "test-jail2")
 1046         self.assertLogged(
 1047             "Reload finished.",
 1048             "Restore Ban",
 1049             "2 ticket(s) in 'test-jail2", all=True, wait=MID_WAITTIME)
 1050         # stop/start and unban/restore ban:
 1051         self.assertLogged(
 1052             "Jail 'test-jail2' stopped",
 1053             "Jail 'test-jail2' started",
 1054             "[test-jail2] Unban 192.0.2.4",
 1055             "[test-jail2] Unban 192.0.2.8",
 1056             "[test-jail2] Restore Ban 192.0.2.4",
 1057             "[test-jail2] Restore Ban 192.0.2.8", all=True
 1058         )
 1059         # test restored is 1 (only test-action2):
 1060         self.assertLogged(
 1061             "stdout: '[test-jail2] test-action2: ++ ban 192.0.2.4 restored: 1, err-code: 401'",
 1062             "stdout: '[test-jail2] test-action2: ++ ban 192.0.2.8 restored: 1, err-code: 401'",
 1063             all=True, wait=MID_WAITTIME)
 1064         # test test-action3 not executed at all (norestored check):
 1065         self.assertNotLogged(
 1066             "stdout: '[test-jail2] test-action3: ++ ban 192.0.2.4 restored: 1'",
 1067             "stdout: '[test-jail2] test-action3: ++ ban 192.0.2.8 restored: 1'",
 1068             all=True)
 1069 
 1070         # ban manually to test later flush by unban all:
 1071         self.pruneLog("[test-phase 2d]")
 1072         self.execCmd(SUCCESS, startparams,
 1073             "set", "test-jail2", "banip", "192.0.2.21")
 1074         self.execCmd(SUCCESS, startparams,
 1075             "set", "test-jail2", "banip", "192.0.2.22")
 1076         self.assertLogged(
 1077             "stdout: '[test-jail2] test-action3: ++ ban 192.0.2.22",
 1078             "stdout: '[test-jail2] test-action3: ++ ban 192.0.2.22 ", all=True, wait=MID_WAITTIME)
 1079 
 1080         # get banned ips:
 1081         _observer_wait_idle()
 1082         self.pruneLog("[test-phase 2d.1]")
 1083         self.execCmd(SUCCESS, startparams, "get", "test-jail2", "banip", "\n")
 1084         self.assertLogged(
 1085             "192.0.2.4", "192.0.2.8", "192.0.2.21", "192.0.2.22", all=True, wait=MID_WAITTIME)
 1086         self.pruneLog("[test-phase 2d.2]")
 1087         self.execCmd(SUCCESS, startparams, "get", "test-jail1", "banip")
 1088         self.assertLogged(
 1089             "192.0.2.1", "192.0.2.2", "192.0.2.3", "192.0.2.4", "192.0.2.8", all=True, wait=MID_WAITTIME)
 1090 
 1091         # restart jail with unban all:
 1092         self.pruneLog("[test-phase 2e]")
 1093         self.execCmd(SUCCESS, startparams,
 1094             "restart", "--unban", "test-jail2")
 1095         self.assertLogged(
 1096             "Reload finished.",
 1097             "Jail 'test-jail2' started", all=True, wait=MID_WAITTIME)
 1098         self.assertLogged(
 1099             "Jail 'test-jail2' stopped",
 1100             "Jail 'test-jail2' started",
 1101             "[test-jail2] Unban 192.0.2.4",
 1102             "[test-jail2] Unban 192.0.2.8", all=True
 1103         )
 1104         # test unban (action2):
 1105         self.assertLogged(
 1106             "stdout: '[test-jail2] test-action2: -- unban 192.0.2.21",
 1107             "stdout: '[test-jail2] test-action2: -- unban 192.0.2.22'", all=True)
 1108         # test flush (action3, and no single unban via action3 occurred):
 1109         self.assertLogged(
 1110             "stdout: '[test-jail2] test-action3: -- flushing IPs'")
 1111         self.assertNotLogged(
 1112             "stdout: '[test-jail2] test-action3: -- unban 192.0.2.21'",
 1113             "stdout: '[test-jail2] test-action3: -- unban 192.0.2.22'", all=True)
 1114         # no more ban (unbanned all):
 1115         self.assertNotLogged(
 1116             "[test-jail2] Ban 192.0.2.4",
 1117             "[test-jail2] Ban 192.0.2.8", all=True
 1118         )
 1119 
 1120         # don't need actions anymore:
 1121         _write_action_cfg(actname="test-action2", allow=False)
 1122         _write_jail_cfg(actions=[])
 1123 
 1124         # reload jail1 without restart (without ban/unban):
 1125         self.pruneLog("[test-phase 3]")
 1126         self.execCmd(SUCCESS, startparams, "reload", "test-jail1")
 1127         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1128         self.assertLogged(
 1129             "Reload jail 'test-jail1'",
 1130             "Jail 'test-jail1' reloaded", all=True)
 1131         self.assertNotLogged(
 1132             "Reload jail 'test-jail2'",
 1133             "Jail 'test-jail2' reloaded",
 1134             "Jail 'test-jail1' started", all=True
 1135         )
 1136 
 1137         # whole reload, but this time with jail1 only (jail2 should be stopped via configuration):
 1138         self.pruneLog("[test-phase 4]")
 1139         _write_jail_cfg(enabled=[1])
 1140         self.execCmd(SUCCESS, startparams, "reload")
 1141         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1142         # test both jails should be reloaded:
 1143         self.assertLogged(
 1144             "Reload jail 'test-jail1'")
 1145         # test jail2 goes down:
 1146         self.assertLogged(
 1147             "Stopping jail 'test-jail2'", 
 1148             "Jail 'test-jail2' stopped", all=True)
 1149         # test 2 log files removed:
 1150         self.assertLogged(
 1151             "Removed logfile: %r" % test2log, 
 1152             "Removed logfile: %r" % test3log, all=True)
 1153 
 1154         # now write failures again and check already banned (jail1 was alive the whole time) and new bans occurred (jail1 was alive the whole time):
 1155         self.pruneLog("[test-phase 5]")
 1156         _write_file(test1log, "w+", *(
 1157             (str(int(MyTime.time())) + " failure 401 from 192.0.2.1: test 5",) * 3 + 
 1158             (str(int(MyTime.time())) + "   error 403 from 192.0.2.5: test 5",) * 3 +
 1159             (str(int(MyTime.time())) + " failure 401 from 192.0.2.6: test 5",) * 3
 1160         ))
 1161         if unittest.F2B.log_level < logging.DEBUG: # pragma: no cover
 1162             _out_file(test1log)
 1163         self.assertLogged(
 1164             "6 ticket(s) in 'test-jail1",
 1165             "[test-jail1] 192.0.2.1 already banned", all=True, wait=MID_WAITTIME)
 1166         # test "failure" regexp still available:
 1167         self.assertLogged(
 1168             "[test-jail1] Found 192.0.2.1",
 1169             "[test-jail1] Found 192.0.2.6",
 1170             "[test-jail1] 192.0.2.1 already banned",
 1171             "[test-jail1] Ban 192.0.2.6", all=True)
 1172         # test "error" regexp no more available:
 1173         self.assertNotLogged("[test-jail1] Found 192.0.2.5")
 1174 
 1175         # unban single ips:
 1176         self.pruneLog("[test-phase 6]")
 1177         self.execCmd(SUCCESS, startparams,
 1178             "--async", "unban", "192.0.2.5", "192.0.2.6")
 1179         self.assertLogged(
 1180             "192.0.2.5 is not banned",
 1181             "[test-jail1] Unban 192.0.2.6", all=True, wait=MID_WAITTIME
 1182         )
 1183 
 1184         # reload all (one jail) with unban all:
 1185         self.pruneLog("[test-phase 7]")
 1186         self.execCmd(SUCCESS, startparams,
 1187             "reload", "--unban")
 1188         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1189         # reloads unbanned all:
 1190         self.assertLogged(
 1191             "Jail 'test-jail1' reloaded",
 1192             "[test-jail1] Unban 192.0.2.1",
 1193             "[test-jail1] Unban 192.0.2.2",
 1194             "[test-jail1] Unban 192.0.2.3",
 1195             "[test-jail1] Unban 192.0.2.4", all=True
 1196         )
 1197         # no restart occurred, no more ban (unbanned all using option "--unban"):
 1198         self.assertNotLogged(
 1199             "Jail 'test-jail1' stopped",
 1200             "Jail 'test-jail1' started",
 1201             "[test-jail1] Ban 192.0.2.1",
 1202             "[test-jail1] Ban 192.0.2.2",
 1203             "[test-jail1] Ban 192.0.2.3",
 1204             "[test-jail1] Ban 192.0.2.4", all=True
 1205         )
 1206 
 1207         # unban all (just to test command, already empty - nothing to unban):
 1208         self.pruneLog("[test-phase 7b]")
 1209         self.execCmd(SUCCESS, startparams,
 1210             "--async", "unban", "--all")
 1211         self.assertLogged(
 1212             "Flush ban list",
 1213             "Unbanned 0, 0 ticket(s) in 'test-jail1'", all=True)
 1214 
 1215         # backend-switch (restart instead of reload):
 1216         self.pruneLog("[test-phase 8a]")
 1217         _write_jail_cfg(enabled=[1], backend="xxx-unknown-backend-zzz")
 1218         self.execCmd(FAILED, startparams, "reload")
 1219         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1220         self.assertLogged(
 1221             "Restart jail 'test-jail1' (reason: 'polling' != ", 
 1222             "Unknown backend ", all=True)
 1223 
 1224         self.pruneLog("[test-phase 8b]")
 1225         _write_jail_cfg(enabled=[1])
 1226         self.execCmd(SUCCESS, startparams, "reload")
 1227         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1228 
 1229         # several small cases (cover several parts):
 1230         self.pruneLog("[test-phase end-1]")
 1231         # wrong jail (not-started):
 1232         self.execCmd(FAILED, startparams,
 1233             "--async", "reload", "test-jail2")
 1234         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1235         self.assertLogged("the jail 'test-jail2' does not exist")
 1236         self.pruneLog()
 1237         # unavailable jail (but exit 0), using --if-exists option:
 1238         self.execCmd(SUCCESS, startparams,
 1239             "--async", "reload", "--if-exists", "test-jail2")
 1240         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1241         self.assertNotLogged(
 1242             "Creating new jail 'test-jail2'",
 1243             "Jail 'test-jail2' started", all=True)
 1244 
 1245         # restart all jails (without restart server):
 1246         self.pruneLog("[test-phase end-2]")
 1247         self.execCmd(SUCCESS, startparams,
 1248             "--async", "reload", "--restart", "--all")
 1249         self.assertLogged("Reload finished.", wait=MID_WAITTIME)
 1250         self.assertLogged(
 1251             "Jail 'test-jail1' stopped", 
 1252             "Jail 'test-jail1' started", all=True, wait=MID_WAITTIME)
 1253 
 1254         # Coverage for pickle of IPAddr (as string):
 1255         self.pruneLog("[test-phase end-3]")
 1256         self.execCmd(SUCCESS, startparams,
 1257             "--async", "set", "test-jail1", "addignoreip", "192.0.2.1/32", "2001:DB8::1/96")
 1258         self.execCmd(SUCCESS, startparams,
 1259             "--async", "get", "test-jail1", "ignoreip")
 1260         self.assertLogged("192.0.2.1/32", "2001:DB8::1/96", all=True)
 1261 
 1262     # test action.d/nginx-block-map.conf --
 1263     @unittest.F2B.skip_if_cfg_missing(action="nginx-block-map")
 1264     @with_foreground_server_thread(startextra={
 1265         # create log-file (avoid "not found" errors):
 1266         'create_before_start': ('%(tmp)s/blck-failures.log',),
 1267         # we need action.d/nginx-block-map.conf and blocklist_de:
 1268         'use_stock_cfg': ('action.d',),
 1269         # jail-config:
 1270         'jails': (
 1271             '[nginx-blck-lst]',
 1272             'backend = polling',
 1273             'usedns = no',
 1274             'logpath = %(tmp)s/blck-failures.log',
 1275             'action = nginx-block-map[blck_lst_reload="", blck_lst_file="%(tmp)s/blck-lst.map"]',
 1276             '         blocklist_de[actionban=\'curl() { echo "*** curl" "$*";}; <Definition/actionban>\', email="Fail2Ban <fail2ban@localhost>", '
 1277                                                       'apikey="TEST-API-KEY", agent="fail2ban-test-agent", service=<name>]',
 1278             'filter =',
 1279             'datepattern = ^Epoch',
 1280             'failregex = ^ failure "<F-ID>[^"]+</F-ID>" - <ADDR>',
 1281             'maxretry = 1', # ban by first failure
 1282             'enabled = true',
 1283       )
 1284     })
 1285     def testServerActions_NginxBlockMap(self, tmp, startparams):
 1286         cfg = pjoin(tmp, "config")
 1287         lgfn = '%(tmp)s/blck-failures.log' % {'tmp': tmp}
 1288         mpfn = '%(tmp)s/blck-lst.map' % {'tmp': tmp}
 1289         # ban sessions (write log like nginx does it with f2b_session_errors log-format):
 1290         _write_file(lgfn, "w+",
 1291             str(int(MyTime.time())) + ' failure "125-000-001" - 192.0.2.1',
 1292             str(int(MyTime.time())) + ' failure "125-000-002" - 192.0.2.1',
 1293             str(int(MyTime.time())) + ' failure "125-000-003" - 192.0.2.1 (\xf2\xf0\xe5\xf2\xe8\xe9)',
 1294             str(int(MyTime.time())) + ' failure "125-000-004" - 192.0.2.1 (\xf2\xf0\xe5\xf2\xe8\xe9)',
 1295             str(int(MyTime.time())) + ' failure "125-000-005" - 192.0.2.1',
 1296         )
 1297         # check all sessions are banned (and blacklisted in map-file):
 1298         self.assertLogged(
 1299             "[nginx-blck-lst] Ban 125-000-001",
 1300             "[nginx-blck-lst] Ban 125-000-002",
 1301             "[nginx-blck-lst] Ban 125-000-003",
 1302             "[nginx-blck-lst] Ban 125-000-004",
 1303             "[nginx-blck-lst] Ban 125-000-005",
 1304             "5 ticket(s)",
 1305             all=True, wait=MID_WAITTIME
 1306         )
 1307         _out_file(mpfn)
 1308         mp = _read_file(mpfn)
 1309         self.assertIn('\\125-000-001 1;\n', mp)
 1310         self.assertIn('\\125-000-002 1;\n', mp)
 1311         self.assertIn('\\125-000-003 1;\n', mp)
 1312         self.assertIn('\\125-000-004 1;\n', mp)
 1313         self.assertIn('\\125-000-005 1;\n', mp)
 1314 
 1315         # check blocklist_de substitution (e. g. new-line after <matches>):
 1316         self.assertLogged(
 1317             "stdout: '*** curl --fail --data-urlencode server=Fail2Ban <fail2ban@localhost>"
 1318                              " --data apikey=TEST-API-KEY --data service=nginx-blck-lst ",
 1319             "stdout: ' --data format=text --user-agent fail2ban-test-agent",
 1320             all=True, wait=MID_WAITTIME
 1321         )
 1322 
 1323         # unban 1, 2 and 5:
 1324         self.execCmd(SUCCESS, startparams, 'unban', '125-000-001', '125-000-002', '125-000-005')
 1325         _out_file(mpfn)
 1326         # check really unbanned but other sessions are still present (blacklisted in map-file):
 1327         mp = _read_file(mpfn)
 1328         self.assertNotIn('\\125-000-001 1;\n', mp)
 1329         self.assertNotIn('\\125-000-002 1;\n', mp)
 1330         self.assertNotIn('\\125-000-005 1;\n', mp)
 1331         self.assertIn('\\125-000-003 1;\n', mp)
 1332         self.assertIn('\\125-000-004 1;\n', mp)
 1333 
 1334         # stop server and wait for end:
 1335         self.stopAndWaitForServerEnd(SUCCESS)
 1336 
 1337         # check flushed (all sessions were deleted from map-file):
 1338         self.assertLogged("[nginx-blck-lst] Flush ticket(s) with nginx-block-map")
 1339         _out_file(mpfn)
 1340         mp = _read_file(mpfn)
 1341         self.assertEqual(mp, '')
 1342 
 1343     @unittest.F2B.skip_if_cfg_missing(filter="sendmail-auth")
 1344     @with_foreground_server_thread(startextra={
 1345         # create log-file (avoid "not found" errors):
 1346         'create_before_start': ('%(tmp)s/test.log',),
 1347         'use_stock': True,
 1348         # fail2ban.local:
 1349         'f2b_local': (
 1350             '[DEFAULT]',
 1351             'dbmaxmatches = 1'
 1352         ),
 1353         # jail.local config:
 1354         'jails': (
 1355             # default:
 1356             '''test_action = dummy[actionstart_on_demand=1, init="start: %(__name__)s", target="%(tmp)s/test.txt",
 1357       actionban='<known/actionban>;
 1358         echo "<matches>"; printf "=====\\n%%b\\n=====\\n\\n" "<matches>" >> <target>']''',
 1359             # jail sendmail-auth:
 1360             '[sendmail-auth]',
 1361             'backend = polling',
 1362             'usedns = no',
 1363             'logpath = %(tmp)s/test.log',
 1364             'action = %(test_action)s',
 1365             'filter = sendmail-auth[logtype=short]',
 1366             'datepattern = ^Epoch',
 1367             'maxretry = 3',
 1368             'maxmatches = 2',
 1369             'enabled = true',
 1370             # jail sendmail-reject:
 1371             '[sendmail-reject]',
 1372             'backend = polling',
 1373             'usedns = no',
 1374             'logpath = %(tmp)s/test.log',
 1375             'action = %(test_action)s',
 1376             'filter = sendmail-reject[logtype=short]',
 1377             'datepattern = ^Epoch',
 1378             'maxretry = 3',
 1379             'enabled = true',
 1380         )
 1381     })
 1382     def testServerJails_Sendmail(self, tmp, startparams):
 1383         cfg = pjoin(tmp, "config")
 1384         lgfn = '%(tmp)s/test.log' % {'tmp': tmp}
 1385         tofn = '%(tmp)s/test.txt' % {'tmp': tmp}
 1386 
 1387         smaut_msg = (
 1388             str(int(MyTime.time())) + ' smtp1 sm-mta[5133]: s1000000000001: [192.0.2.1]: possible SMTP attack: command=AUTH, count=1',
 1389             str(int(MyTime.time())) + ' smtp1 sm-mta[5133]: s1000000000002: [192.0.2.1]: possible SMTP attack: command=AUTH, count=2',
 1390             str(int(MyTime.time())) + ' smtp1 sm-mta[5133]: s1000000000003: [192.0.2.1]: possible SMTP attack: command=AUTH, count=3',
 1391         )
 1392         smrej_msg = (
 1393             str(int(MyTime.time())) + ' smtp1 sm-mta[21134]: s2000000000001: ruleset=check_rcpt, arg1=<123@example.com>, relay=xxx.dynamic.example.com [192.0.2.2], reject=550 5.7.1 <123@example.com>... Relaying denied. Proper authentication required.',
 1394             str(int(MyTime.time())) + ' smtp1 sm-mta[21134]: s2000000000002: ruleset=check_rcpt, arg1=<345@example.com>, relay=xxx.dynamic.example.com [192.0.2.2], reject=550 5.7.1 <345@example.com>... Relaying denied. Proper authentication required.',
 1395             str(int(MyTime.time())) + ' smtp1 sm-mta[21134]: s3000000000003: ruleset=check_rcpt, arg1=<567@example.com>, relay=xxx.dynamic.example.com [192.0.2.2], reject=550 5.7.1 <567@example.com>... Relaying denied. Proper authentication required.',
 1396         )
 1397 
 1398         self.pruneLog("[test-phase sendmail-auth]")
 1399         # write log:
 1400         _write_file(lgfn, "w+", *smaut_msg)
 1401         # wait and check it caused banned (and dump in the test-file):
 1402         self.assertLogged(
 1403             "[sendmail-auth] Ban 192.0.2.1", "1 ticket(s) in 'sendmail-auth'", all=True, wait=MID_WAITTIME)
 1404         _out_file(tofn)
 1405         td = _read_file(tofn)
 1406         # check matches (maxmatches = 2, so only 2 & 3 available):
 1407         m = smaut_msg[0]
 1408         self.assertNotIn(m, td)
 1409         for m in smaut_msg[1:]:
 1410             self.assertIn(m, td)
 1411 
 1412         self.pruneLog("[test-phase sendmail-reject]")
 1413         # write log:
 1414         _write_file(lgfn, "w+", *smrej_msg)
 1415         # wait and check it caused banned (and dump in the test-file):
 1416         self.assertLogged(
 1417             "[sendmail-reject] Ban 192.0.2.2", "1 ticket(s) in 'sendmail-reject'", all=True, wait=MID_WAITTIME)
 1418         _out_file(tofn)
 1419         td = _read_file(tofn)
 1420         # check matches (no maxmatches, so all matched messages are available):
 1421         for m in smrej_msg:
 1422             self.assertIn(m, td)
 1423 
 1424         self.pruneLog("[test-phase restart sendmail-*]")
 1425         # restart jails (active ban-tickets should be restored):
 1426         self.execCmd(SUCCESS, startparams,
 1427             "reload", "--restart", "--all")
 1428         # wait a bit:
 1429         self.assertLogged(
 1430             "Reload finished.",
 1431             "[sendmail-auth] Restore Ban 192.0.2.1", "1 ticket(s) in 'sendmail-auth'", all=True, wait=MID_WAITTIME)
 1432         # check matches again - (dbmaxmatches = 1), so it should be only last match after restart:
 1433         td = _read_file(tofn)
 1434         m = smaut_msg[-1]
 1435         self.assertLogged(m)
 1436         self.assertIn(m, td)
 1437         for m in smaut_msg[0:-1]:
 1438             self.assertNotLogged(m)
 1439             self.assertNotIn(m, td)
 1440         # wait for restore of reject-jail:
 1441         self.assertLogged(
 1442             "[sendmail-reject] Restore Ban 192.0.2.2", "1 ticket(s) in 'sendmail-reject'", all=True, wait=MID_WAITTIME)
 1443         td = _read_file(tofn)
 1444         m = smrej_msg[-1]
 1445         self.assertLogged(m)
 1446         self.assertIn(m, td)
 1447         for m in smrej_msg[0:-1]:
 1448             self.assertNotLogged(m)
 1449             self.assertNotIn(m, td)
 1450 
 1451         self.pruneLog("[test-phase stop server]")
 1452         # stop server and wait for end:
 1453         self.stopAndWaitForServerEnd(SUCCESS)
 1454 
 1455         # just to debug actionstop:
 1456         self.assertFalse(exists(tofn))
 1457 
 1458     @with_foreground_server_thread()
 1459     def testServerObserver(self, tmp, startparams):
 1460         cfg = pjoin(tmp, "config")
 1461         test1log = pjoin(tmp, "test1.log")
 1462 
 1463         os.mkdir(pjoin(cfg, "action.d"))
 1464         def _write_action_cfg(actname="test-action1", prolong=True):
 1465             fn = pjoin(cfg, "action.d", "%s.conf" % actname)
 1466             _write_file(fn, "w",
 1467                 "[DEFAULT]",
 1468                 "",
 1469                 "[Definition]",
 1470                 "actionban =     printf %%s \"[%(name)s] %(actname)s: ++ ban <ip> -c <bancount> -t <bantime> : <F-MSG>\"", \
 1471                 "actionprolong = printf %%s \"[%(name)s] %(actname)s: ++ prolong <ip> -c <bancount> -t <bantime> : <F-MSG>\"" \
 1472                     if prolong else "",
 1473                 "actionunban =   printf %%b '[%(name)s] %(actname)s: -- unban <ip>'",
 1474             )
 1475             if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover
 1476                 _out_file(fn)
 1477 
 1478         def _write_jail_cfg(backend="polling"):
 1479             _write_file(pjoin(cfg, "jail.conf"), "w",
 1480                 "[INCLUDES]", "",
 1481                 "[DEFAULT]", "",
 1482                 "usedns = no",
 1483                 "maxretry = 3",
 1484                 "findtime = 1m",
 1485                 "bantime = 5m",
 1486                 "bantime.increment = true",
 1487                 "datepattern = {^LN-BEG}EPOCH",
 1488                 "",
 1489                 "[test-jail1]", "backend = " + backend, "filter =", 
 1490                 "action = test-action1[name='%(__name__)s']",
 1491                 "         test-action2[name='%(__name__)s']",
 1492                 "logpath = " + test1log,
 1493                 r"failregex = ^\s*failure <F-ERRCODE>401|403</F-ERRCODE> from <HOST>:\s*<F-MSG>.*</F-MSG>$",
 1494                 "enabled = true",
 1495                 "",
 1496             )
 1497             if unittest.F2B.log_level <= logging.DEBUG: # pragma: no cover
 1498                 _out_file(pjoin(cfg, "jail.conf"))
 1499 
 1500         # create test config:
 1501         _write_action_cfg(actname="test-action1", prolong=False)
 1502         _write_action_cfg(actname="test-action2", prolong=True)
 1503         _write_jail_cfg()
 1504 
 1505         _write_file(test1log, "w")
 1506         # initial start:
 1507         self.pruneLog("[test-phase 0) time-0]")
 1508         self.execCmd(SUCCESS, startparams, "reload")
 1509         # generate bad ip:
 1510         _write_file(test1log, "w+", *(
 1511           (str(int(MyTime.time())) + " failure 401 from 192.0.2.11: I'm bad \"hacker\" `` $(echo test)",) * 3
 1512         ))
 1513         # wait for ban:
 1514         _observer_wait_idle()
 1515         self.assertLogged(
 1516             "stdout: '[test-jail1] test-action1: ++ ban 192.0.2.11 -c 1 -t 300 : ",
 1517             "stdout: '[test-jail1] test-action2: ++ ban 192.0.2.11 -c 1 -t 300 : ",
 1518             all=True, wait=MID_WAITTIME)
 1519         # wait for observer idle (write all tickets to db):
 1520         _observer_wait_idle()
 1521 
 1522         self.pruneLog("[test-phase 1) time+10m]")
 1523         # jump to the future (+10 minutes):
 1524         _time_shift(10)
 1525         _observer_wait_idle()
 1526         self.assertLogged(
 1527             "stdout: '[test-jail1] test-action1: -- unban 192.0.2.11",
 1528             "stdout: '[test-jail1] test-action2: -- unban 192.0.2.11",
 1529             "0 ticket(s) in 'test-jail1'",
 1530             all=True, wait=MID_WAITTIME)
 1531         _observer_wait_idle()
 1532 
 1533         self.pruneLog("[test-phase 2) time+10m]")
 1534         # following tests are time-related - observer can prolong ticket (increase ban-time) 
 1535         # before banning, so block it here before banFound called, prolong case later:
 1536         wakeObs = False
 1537         _observer_wait_before_incrban(lambda: wakeObs)
 1538         # write again (IP already bad):
 1539         _write_file(test1log, "w+", *(
 1540           (str(int(MyTime.time())) + " failure 401 from 192.0.2.11: I'm very bad \"hacker\" `` $(echo test)",) * 2
 1541         ))
 1542         # wait for ban:
 1543         self.assertLogged(
 1544             "stdout: '[test-jail1] test-action1: ++ ban 192.0.2.11 -c 2 -t 300 : ",
 1545             "stdout: '[test-jail1] test-action2: ++ ban 192.0.2.11 -c 2 -t 300 : ",
 1546             all=True, wait=MID_WAITTIME)
 1547         # get banned ips with time:
 1548         self.pruneLog("[test-phase 2) time+10m - get-ips]")
 1549         self.execCmd(SUCCESS, startparams, "get", "test-jail1", "banip", "--with-time")
 1550         self.assertLogged(
 1551             "192.0.2.11", "+ 300 =", all=True, wait=MID_WAITTIME)
 1552         # unblock observer here and wait it is done:
 1553         wakeObs = True
 1554         _observer_wait_idle()
 1555 
 1556         self.pruneLog("[test-phase 2) time+11m]")
 1557         # jump to the future (+1 minute):
 1558         _time_shift(1)
 1559         # wait for observer idle (write all tickets to db):
 1560         _observer_wait_idle()
 1561         # wait for prolong:
 1562         self.assertLogged(
 1563             "stdout: '[test-jail1] test-action2: ++ prolong 192.0.2.11 -c 2 -t 600 : ",
 1564             all=True, wait=MID_WAITTIME)
 1565 
 1566         # get banned ips with time:
 1567         _observer_wait_idle()
 1568         self.pruneLog("[test-phase 2) time+11m - get-ips]")
 1569         self.execCmd(SUCCESS, startparams, "get", "test-jail1", "banip", "--with-time")
 1570         self.assertLogged(
 1571             "192.0.2.11", "+ 600 =", all=True, wait=MID_WAITTIME)
 1572 
 1573     # test multiple start/stop of the server (threaded in foreground) --
 1574     if False: # pragma: no cover
 1575         @with_foreground_server_thread()
 1576         def _testServerStartStop(self, tmp, startparams):
 1577             # stop server and wait for end:
 1578             self.stopAndWaitForServerEnd(SUCCESS)
 1579 
 1580         def testServerStartStop(self):
 1581             for i in xrange(2000):
 1582                 self._testServerStartStop()
 1583