From e6983b4f9b476e174995b9814260e9e1c5c4d6c5 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 12:45:08 -0400 Subject: [PATCH 1/7] BF: Remove custom __str__ for MonitorFailures and just adjust __name__ of the generated class Also to guarantee unique file names across tests -- append incremental numeric suffix. This should prevent unittest from not reporting specific unittest method names, thus complicating the analysis of failures --- testcases/filtertestcase.py | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/testcases/filtertestcase.py b/testcases/filtertestcase.py index 5833e296..88cbf382 100644 --- a/testcases/filtertestcase.py +++ b/testcases/filtertestcase.py @@ -324,11 +324,15 @@ def get_monitor_failures_testcase(Filter_): """Generator of TestCase's for different filters/backends """ + _, testclass_name = tempfile.mkstemp('fail2ban', 'monitorfailures') + class MonitorFailures(unittest.TestCase): + count = 0 def setUp(self): """Call before every test case.""" self.filter = self.name = 'NA' - _, self.name = tempfile.mkstemp('fail2ban', 'monitorfailures') + self.name = '%s-%d' % (testclass_name, self.count) + MonitorFailures.count += 1 # so we have unique filenames across tests self.file = open(self.name, 'a') self.jail = DummyJail() self.filter = Filter_(self.jail) @@ -351,12 +355,9 @@ def get_monitor_failures_testcase(Filter_): self.filter.join() # wait for the thread to terminate #print "D: KILLING THE FILE" _killfile(self.file, self.name) + #time.sleep(0.2) # Give FS time to ack the removal pass - def __str__(self): # pragma: no cover - will only show up if unexpected exception is thrown - return "MonitorFailures%s(%s)" \ - % (Filter_, hasattr(self, 'name') and self.name or 'tempfile') - def isFilled(self, delay=2.): """Wait up to `delay` sec to assure that it was modified or not """ @@ -488,7 +489,8 @@ def get_monitor_failures_testcase(Filter_): # yoh: not sure why count here is not 9... TODO self.assert_correct_last_attempt(GetFailures.FAILURES_01)#, count=9) - + MonitorFailures.__name__ = "MonitorFailures<%s>(%s)" \ + % (Filter_.__name__, testclass_name) # 'tempfile') return MonitorFailures From 5ea2ab14e6bc848e7782d4f8e3ee23ed8a0aa708 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 14:42:44 -0400 Subject: [PATCH 2/7] ENH: elaborated debug log message about already detected failures Now it should be evaluated only if logging mode is debug or "lower", and also should happen not only on initial detections but for every added failure. It also reports counts per each IP now --- server/failmanager.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/server/failmanager.py b/server/failmanager.py index 82c2ed6f..93a3a351 100644 --- a/server/failmanager.py +++ b/server/failmanager.py @@ -105,8 +105,15 @@ class FailManager: fData.setLastReset(unixTime) fData.setLastTime(unixTime) self.__failList[ip] = fData - logSys.debug("Currently have failures from %d IPs: %s" - % (len(self.__failList), self.__failList.keys())) + + if logSys.getEffectiveLevel() <= logging.DEBUG: + # yoh: Since composing this list might be somewhat time consuming + # in case of having many active failures, it should be ran only + # if debug level is "low" enough + failures_summary = ', '.join(['%s:%d' % (k, v.getRetry()) + for k,v in self.__failList.iteritems()]) + logSys.debug("Currently have failures from %d IPs (IP:count): %s" + % (len(self.__failList), failures_summary)) self.__failTotal += 1 finally: self.__lock.release() From f72bc13111ebfdee95ece936d95fcae961748826 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 16:33:02 -0400 Subject: [PATCH 3/7] BF: allow to wait longer for FilterPoll in test_move_file --- testcases/filtertestcase.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/testcases/filtertestcase.py b/testcases/filtertestcase.py index 88cbf382..4aef2c9d 100644 --- a/testcases/filtertestcase.py +++ b/testcases/filtertestcase.py @@ -432,9 +432,10 @@ def get_monitor_failures_testcase(Filter_): # if we move file into a new location while it has been open already self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, n=14, mode='w') - self.assertTrue(self.isEmpty(2)) + # Poll might need more time + self.assertTrue(self.isEmpty(2 + int(isinstance(self.filter, FilterPoll))*4)) self.assertRaises(FailManagerEmpty, self.filter.failManager.toBan) - self.assertEqual(self.filter.failManager.getFailTotal(), 2) # Fails with Poll from time to time + self.assertEqual(self.filter.failManager.getFailTotal(), 2) # move aside, but leaving the handle still open... os.rename(self.name, self.name + '.bak') From c29553354b9527722ce3ee87bfe60ebf6268682d Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 17:11:03 -0400 Subject: [PATCH 4/7] ENH: FailManager -- improve log message to report total # of detected failures as well --- server/failmanager.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/server/failmanager.py b/server/failmanager.py index 93a3a351..02f16ce3 100644 --- a/server/failmanager.py +++ b/server/failmanager.py @@ -106,15 +106,16 @@ class FailManager: fData.setLastTime(unixTime) self.__failList[ip] = fData + self.__failTotal += 1 + if logSys.getEffectiveLevel() <= logging.DEBUG: # yoh: Since composing this list might be somewhat time consuming # in case of having many active failures, it should be ran only # if debug level is "low" enough failures_summary = ', '.join(['%s:%d' % (k, v.getRetry()) for k,v in self.__failList.iteritems()]) - logSys.debug("Currently have failures from %d IPs (IP:count): %s" - % (len(self.__failList), failures_summary)) - self.__failTotal += 1 + logSys.debug("Total # of detected failures: %d. Current failures from %d IPs (IP:count): %s" + % (self.__failTotal, len(self.__failList), failures_summary)) finally: self.__lock.release() From 52af29a08044d77d727d68fa17494c08fb48c1d7 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 21:28:58 -0400 Subject: [PATCH 5/7] ENH: adding ability to incorporate tracebacks into log lines while running tests --- fail2ban-testcases | 23 ++++++++--- testcases/utils.py | 101 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 119 insertions(+), 5 deletions(-) create mode 100644 testcases/utils.py diff --git a/fail2ban-testcases b/fail2ban-testcases index d6b25b91..e00cc908 100755 --- a/fail2ban-testcases +++ b/fail2ban-testcases @@ -36,6 +36,8 @@ from testcases import servertestcase from testcases import datedetectortestcase from testcases import actiontestcase from testcases import sockettestcase + +from testcases.utils import FormatterWithTraceBack from server.mytime import MyTime from optparse import OptionParser, Option @@ -52,12 +54,14 @@ def get_opt_parser(): choices=('debug', 'info', 'warn', 'error', 'fatal'), default=None, help="Log level for the logger to use during running tests"), - ]) - - p.add_options([ Option('-n', "--no-network", action="store_true", dest="no_network", help="Do not run tests that require the network"), + Option("-t", "--log-traceback", action='store_true', + help="Enrich log-messages with compressed tracebacks"), + Option("--full-traceback", action='store_true', + help="Either to make the tracebacks full, not compressed (as by default)"), + ]) return p @@ -89,12 +93,21 @@ else: # pragma: no cover # Add the default logging handler stdout = logging.StreamHandler(sys.stdout) + +fmt = ' %(message)s' + +if opts.log_traceback: + Formatter = FormatterWithTraceBack + fmt = (opts.full_traceback and ' %(tb)s' or ' %(tbc)s') + fmt +else: + Formatter = logging.Formatter + # Custom log format for the verbose tests runs if verbosity > 1: # pragma: no cover - stdout.setFormatter(logging.Formatter(' %(asctime)-15s %(thread)s %(message)s')) + stdout.setFormatter(Formatter(' %(asctime)-15s %(thread)s' + fmt)) else: # pragma: no cover # just prefix with the space - stdout.setFormatter(logging.Formatter(' %(message)s')) + stdout.setFormatter(Formatter(fmt)) logSys.addHandler(stdout) # diff --git a/testcases/utils.py b/testcases/utils.py new file mode 100644 index 00000000..6b894193 --- /dev/null +++ b/testcases/utils.py @@ -0,0 +1,101 @@ +# emacs: -*- mode: python; py-indent-offset: 4; indent-tabs-mode: t -*- +# vi: set ft=python sts=4 ts=4 sw=4 noet : + +# This file is part of Fail2Ban. +# +# Fail2Ban is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation; either version 2 of the License, or +# (at your option) any later version. +# +# Fail2Ban is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with Fail2Ban; if not, write to the Free Software +# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. + + +__author__ = "Yaroslav Halchenko" +__copyright__ = "Copyright (c) 2013 Yaroslav Halchenko" +__license__ = "GPL" + +import logging, os, re, traceback +from os.path import basename, dirname + +# +# Following "traceback" functions are adopted from PyMVPA distributed +# under MIT/Expat and copyright by PyMVPA developers (i.e. me and +# Michael). Hereby I re-license derivative work on these pieces under GPL +# to stay in line with the main Fail2Ban license +# +def mbasename(s): + """Custom function to include directory name if filename is too common + + Also strip .py at the end + """ + base = basename(s) + if base.endswith('.py'): + base = base[:-3] + if base in set(['base', '__init__']): + base = basename(dirname(s)) + '.' + base + return base + +class TraceBack(object): + """Customized traceback to be included in debug messages + """ + + def __init__(self, compress=False): + """Initialize TrackBack metric + + Parameters + ---------- + compress : bool + if True then prefix common with previous invocation gets + replaced with ... + """ + self.__prev = "" + self.__compress = compress + + def __call__(self): + ftb = traceback.extract_stack(limit=100)[:-2] + entries = [[mbasename(x[0]), str(x[1])] for x in ftb] + entries = [ e for e in entries + if not e[0] in ['unittest', 'logging.__init__' ]] + + # lets make it more consize + entries_out = [entries[0]] + for entry in entries[1:]: + if entry[0] == entries_out[-1][0]: + entries_out[-1][1] += ',%s' % entry[1] + else: + entries_out.append(entry) + sftb = '>'.join(['%s:%s' % (mbasename(x[0]), + x[1]) for x in entries_out]) + if self.__compress: + # lets remove part which is common with previous invocation + prev_next = sftb + common_prefix = os.path.commonprefix((self.__prev, sftb)) + common_prefix2 = re.sub('>[^>]*$', '', common_prefix) + + if common_prefix2 != "": + sftb = '...' + sftb[len(common_prefix2):] + self.__prev = prev_next + + return sftb + +class FormatterWithTraceBack(logging.Formatter): + """Custom formatter which expands %(tb) and %(tbc) with tracebacks + + TODO: might need locking in case of compressed tracebacks + """ + def __init__(self, fmt, *args, **kwargs): + logging.Formatter.__init__(self, fmt=fmt, *args, **kwargs) + compress = '%(tbc)s' in fmt + self._tb = TraceBack(compress=compress) + + def format(self, record): + record.tbc = record.tb = self._tb() + return logging.Formatter.format(self, record) From ba042c6e3a847afc2ec4d6def0d70e3ad8f34793 Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 21:29:39 -0400 Subject: [PATCH 6/7] ENH: move pyinotify callback debug message into callback + delay string interpolations --- server/filterpyinotify.py | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/server/filterpyinotify.py b/server/filterpyinotify.py index a2eea9d7..e86498b0 100644 --- a/server/filterpyinotify.py +++ b/server/filterpyinotify.py @@ -63,16 +63,17 @@ class FilterPyinotify(FileFilter): logSys.debug("Created FilterPyinotify") - def callback(self, event): + def callback(self, event, origin=''): + logSys.debug("%sCallback for Event: %s", origin, event) path = event.pathname if event.mask & pyinotify.IN_CREATE: # skip directories altogether if event.mask & pyinotify.IN_ISDIR: - logSys.debug("Ignoring creation of directory %s" % path) + logSys.debug("Ignoring creation of directory %s", path) return # check if that is a file we care about if not path in self.__watches: - logSys.debug("Ignoring creation of %s we do not monitor" % path) + logSys.debug("Ignoring creation of %s we do not monitor", path) return else: # we need to substitute the watcher with a new one, so first @@ -104,8 +105,8 @@ class FilterPyinotify(FileFilter): def _addFileWatcher(self, path): wd = self.__monitor.add_watch(path, pyinotify.IN_MODIFY) self.__watches.update(wd) - logSys.debug("Added file watcher for %s" % path) - # process the file since we did get even + logSys.debug("Added file watcher for %s", path) + # process the file since we did get even self._process_file(path) @@ -114,7 +115,7 @@ class FilterPyinotify(FileFilter): wd = self.__monitor.rm_watch(wdInt) if wd[wdInt]: del self.__watches[path] - logSys.debug("Removed file watcher for %s" % path) + logSys.debug("Removed file watcher for %s", path) return True else: return False @@ -130,7 +131,7 @@ class FilterPyinotify(FileFilter): # we need to watch also the directory for IN_CREATE self.__watches.update( self.__monitor.add_watch(path_dir, pyinotify.IN_CREATE)) - logSys.debug("Added monitor for the parent directory %s" % path_dir) + logSys.debug("Added monitor for the parent directory %s", path_dir) self._addFileWatcher(path) @@ -151,7 +152,7 @@ class FilterPyinotify(FileFilter): # since there is no other monitored file under this directory wdInt = self.__watches.pop(path_dir) _ = self.__monitor.rm_watch(wdInt) - logSys.debug("Removed monitor for the parent directory %s" % path_dir) + logSys.debug("Removed monitor for the parent directory %s", path_dir) ## @@ -165,7 +166,7 @@ class FilterPyinotify(FileFilter): self.__notifier = pyinotify.ThreadedNotifier(self.__monitor, ProcessPyinotify(self)) self.__notifier.start() - logSys.debug("pyinotifier started for %s." % self.jail.getName()) + logSys.debug("pyinotifier started for %s.", self.jail.getName()) # TODO: verify that there is nothing really to be done for # idle jails return True @@ -201,5 +202,4 @@ class ProcessPyinotify(pyinotify.ProcessEvent): # just need default, since using mask on watch to limit events def process_default(self, event): - logSys.debug("Callback for Event: %s" % event) - self.__FileFilter.callback(event) + self.__FileFilter.callback(event, origin='Default ') From 7064a411c2d6b2993bf05904c9e7447d747674bc Mon Sep 17 00:00:00 2001 From: Yaroslav Halchenko Date: Mon, 25 Mar 2013 22:36:23 -0400 Subject: [PATCH 7/7] ENH: _copy_lines_between_files -- read all needed, and only then write/flush at once I think this is the one which should resolve https://github.com/fail2ban/fail2ban/issues/103 --- testcases/filtertestcase.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/testcases/filtertestcase.py b/testcases/filtertestcase.py index 4aef2c9d..a20a932d 100644 --- a/testcases/filtertestcase.py +++ b/testcases/filtertestcase.py @@ -105,20 +105,23 @@ def _copy_lines_between_files(fin, fout, n=None, skip=0, mode='a', terminal_line time.sleep(1) if isinstance(fin, str): # pragma: no branch - only used with str in test cases fin = open(fin, 'r') - if isinstance(fout, str): - fout = open(fout, mode) # Skip for i in xrange(skip): _ = fin.readline() - # Read/Write + # Read i = 0 + lines = [] while n is None or i < n: l = fin.readline() if terminal_line is not None and l == terminal_line: break - fout.write(l) - fout.flush() + lines.append(l) i += 1 + # Write: all at once and flush + if isinstance(fout, str): + fout = open(fout, mode) + fout.write('\n'.join(lines)) + fout.flush() # to give other threads possibly some time to crunch time.sleep(0.1) return fout