diff --git a/ChangeLog b/ChangeLog index dd5426a2..200ecfcf 100644 --- a/ChangeLog +++ b/ChangeLog @@ -7,7 +7,7 @@ Fail2Ban (version 0.8.10) 2013/06/12 ================================================================================ -ver. 0.8.11 (2013/XX/XXX) - wanna-be-released +ver. 0.8.11 (2013/XX/XXX) - loves-unittests ----------- - Fixes: @@ -15,6 +15,15 @@ ver. 0.8.11 (2013/XX/XXX) - wanna-be-released * filter.d/common.conf -- make colon after [daemon] optional. Closes gh-267 * filter.d/apache-common.conf -- support apache 2.4 more detailed error log format. Closes gh-268 + * Backends changes detection and parsing. Close gh-223 and gh-103: + - Polling backend: detect changes in the files not only based on + mtime, but also on the size and inode. It should allow for + better detection of changes and log rotations on busy servers, + older python 2.4, and file systems with precision of mtime only + up to a second (e.g. ext3). + - All backends, possible race condition: do not read from a file + initially reported empty. Originally could have lead to + accounting for detected log lines multiple times. Daniel Black & Мернов Георгий * filter.d/dovecot.conf -- Fix when no TLS enabled - line doesn't end in , - New Features: diff --git a/fail2ban-testcases b/fail2ban-testcases index fc5cc146..89fc7deb 100755 --- a/fail2ban-testcases +++ b/fail2ban-testcases @@ -79,7 +79,7 @@ logSys = logging.getLogger("fail2ban") verbosity = {'heavydebug': 4, 'debug': 3, 'info': 2, - 'warn': 1, + 'warning': 1, 'error': 1, 'fatal': 0, None: 1}[opts.log_level] diff --git a/server/filter.py b/server/filter.py index 59e612ed..6cd37ca1 100644 --- a/server/filter.py +++ b/server/filter.py @@ -21,6 +21,8 @@ __author__ = "Cyril Jaquier and Fail2Ban Contributors" __copyright__ = "Copyright (c) 2004 Cyril Jaquier, 2011-2013 Yaroslav Halchenko" __license__ = "GPL" +import sys + from failmanager import FailManagerEmpty from failmanager import FailManager from ticket import FailTicket @@ -322,6 +324,7 @@ class Filter(JailThread): logSys.debug("Ignore %s" % ip) continue logSys.debug("Found %s" % ip) + ## print "D: Adding a ticket for %s" % ((ip, unixTime, [line]),) self.failManager.addFailure(FailTicket(ip, unixTime, [line])) ## @@ -477,7 +480,7 @@ class FileFilter(Filter): return False # Try to open log file. try: - container.open() + has_content = container.open() # see http://python.org/dev/peps/pep-3151/ except IOError, e: logSys.error("Unable to open %s" % filename) @@ -492,7 +495,12 @@ class FileFilter(Filter): logSys.exception(e) return False - while True: + # yoh: has_content is just a bool, so do not expect it to + # change -- loop is exited upon break, and is not entered at + # all if upon container opening that one was empty. If we + # start reading tested to be empty container -- race condition + # might occur leading at least to tests failures. + while has_content: line = container.readline() if (line == "") or not self._isActive(): # The jail reached the bottom or has been stopped @@ -555,10 +563,20 @@ class FileContainer: fd = self.__handler.fileno() flags = fcntl.fcntl(fd, fcntl.F_GETFD) fcntl.fcntl(fd, fcntl.F_SETFD, flags | fcntl.FD_CLOEXEC) + # Stat the file before even attempting to read it + stats = os.fstat(self.__handler.fileno()) + if not stats.st_size: + # yoh: so it is still an empty file -- nothing should be + # read from it yet + # print "D: no content -- return" + return False firstLine = self.__handler.readline() # Computes the MD5 of the first line. myHash = md5sum(firstLine).digest() - stats = os.fstat(self.__handler.fileno()) + ## print "D: fn=%s hashes=%s/%s inos=%s/%s pos=%s rotate=%s" % ( + ## self.__filename, self.__hash, myHash, stats.st_ino, self.__ino, self.__pos, + ## self.__hash != myHash or self.__ino != stats.st_ino) + ## sys.stdout.flush() # Compare hash and inode if self.__hash != myHash or self.__ino != stats.st_ino: logSys.debug("Log rotation detected for %s" % self.__filename) @@ -567,6 +585,7 @@ class FileContainer: self.__pos = 0 # Sets the file pointer to the last position. self.__handler.seek(self.__pos) + return True def readline(self): if self.__handler is None: @@ -580,6 +599,8 @@ class FileContainer: # Closes the file. self.__handler.close() self.__handler = None + ## print "D: Closed %s with pos %d" % (handler, self.__pos) + ## sys.stdout.flush() @@ -602,9 +623,9 @@ class DNSUtils: """ try: return socket.gethostbyname_ex(dns)[2] - except socket.gaierror: - logSys.warn("Unable to find a corresponding IP address for %s" - % dns) + except socket.error, e: + logSys.warn("Unable to find a corresponding IP address for %s: %s" + % (dns, e)) return list() dnsToIp = staticmethod(dnsToIp) diff --git a/server/filterpoll.py b/server/filterpoll.py index 20cde0ca..8b4038b8 100644 --- a/server/filterpoll.py +++ b/server/filterpoll.py @@ -52,7 +52,7 @@ class FilterPoll(FileFilter): FileFilter.__init__(self, jail) self.__modified = False ## The time of the last modification of the file. - self.__lastModTime = dict() + self.__prevStats = dict() self.__file404Cnt = dict() logSys.debug("Created FilterPoll") @@ -62,7 +62,7 @@ class FilterPoll(FileFilter): # @param path log file path def _addLogPath(self, path): - self.__lastModTime[path] = 0 + self.__prevStats[path] = (0, None, None) # mtime, ino, size self.__file404Cnt[path] = 0 ## @@ -71,7 +71,7 @@ class FilterPoll(FileFilter): # @param path the log file to delete def _delLogPath(self, path): - del self.__lastModTime[path] + del self.__prevStats[path] del self.__file404Cnt[path] ## @@ -84,6 +84,9 @@ class FilterPoll(FileFilter): def run(self): self.setActive(True) while self._isActive(): + if logSys.getEffectiveLevel() <= 6: + logSys.log(6, "Woke up idle=%s with %d files monitored", + self.getIdle(), len(self.getLogPath())) if not self.getIdle(): # Get file modification for container in self.getLogPath(): @@ -118,12 +121,20 @@ class FilterPoll(FileFilter): def isModified(self, filename): try: logStats = os.stat(filename) + stats = logStats.st_mtime, logStats.st_ino, logStats.st_size + pstats = self.__prevStats[filename] self.__file404Cnt[filename] = 0 - if self.__lastModTime[filename] == logStats.st_mtime: + if logSys.getEffectiveLevel() <= 7: + # we do not want to waste time on strftime etc if not necessary + dt = logStats.st_mtime - pstats[0] + logSys.log(7, "Checking %s for being modified. Previous/current stats: %s / %s. dt: %s", + filename, pstats, stats, dt) + # os.system("stat %s | grep Modify" % filename) + if pstats == stats: return False else: - logSys.debug(filename + " has been modified") - self.__lastModTime[filename] = logStats.st_mtime + logSys.debug("%s has been modified", filename) + self.__prevStats[filename] = stats return True except OSError, e: logSys.error("Unable to get stat on %s because of: %s" diff --git a/server/jailthread.py b/server/jailthread.py index 11d1a82b..ca6effae 100644 --- a/server/jailthread.py +++ b/server/jailthread.py @@ -56,7 +56,7 @@ class JailThread(Thread): def setSleepTime(self, value): self.__sleepTime = value - logSys.info("Set sleeptime = " + value) + logSys.info("Set sleeptime %s" % value) ## # Get the time that the thread sleeps. diff --git a/testcases/filtertestcase.py b/testcases/filtertestcase.py index 1657f694..d918bbf7 100644 --- a/testcases/filtertestcase.py +++ b/testcases/filtertestcase.py @@ -39,6 +39,8 @@ from server.failmanager import FailManagerEmpty # Useful helpers # +from utils import mtimesleep + # yoh: per Steven Hiscocks's insight while troubleshooting # https://github.com/fail2ban/fail2ban/issues/103#issuecomment-15542836 # adding a sufficiently large buffer might help to guarantee that @@ -68,18 +70,6 @@ def _killfile(f, name): _killfile(None, name + '.bak') -def _sleep_4_poll(): - """PollFilter relies on file timestamps - so we might need to - sleep to guarantee that they differ - """ - if sys.version_info[:2] <= (2,4): - # on old Python st_mtime is int, so we should give - # at least 1 sec so polling filter could detect - # the change - time.sleep(1.) - else: - time.sleep(0.1) - def _assert_equal_entries(utest, found, output, count=None): """Little helper to unify comparisons with the target entries @@ -119,10 +109,9 @@ def _copy_lines_between_files(fin, fout, n=None, skip=0, mode='a', terminal_line Returns open fout """ - if sys.version_info[:2] <= (2,4): # pragma: no cover - # on old Python st_mtime is int, so we should give at least 1 sec so - # polling filter could detect the change - time.sleep(1) + # on older Pythons and on some FSs st_mtime is int, so we should + # give it some time so polling filter could detect the change + mtimesleep() if isinstance(fin, str): # pragma: no branch - only used with str in test cases fin = open(fin, 'r') # Skip @@ -237,14 +226,14 @@ class LogFileMonitor(unittest.TestCase): # but not any longer self.assertTrue(self.notModified()) self.assertTrue(self.notModified()) - _sleep_4_poll() # to guarantee freshier mtime + mtimesleep() # to guarantee freshier mtime for i in range(4): # few changes # unless we write into it self.file.write("line%d\n" % i) self.file.flush() self.assertTrue(self.isModified()) self.assertTrue(self.notModified()) - _sleep_4_poll() # to guarantee freshier mtime + mtimesleep() # to guarantee freshier mtime os.rename(self.name, self.name + '.old') # we are not signaling as modified whenever # it gets away @@ -252,7 +241,7 @@ class LogFileMonitor(unittest.TestCase): f = open(self.name, 'a') self.assertTrue(self.isModified()) self.assertTrue(self.notModified()) - _sleep_4_poll() + mtimesleep() f.write("line%d\n" % i) f.flush() self.assertTrue(self.isModified()) @@ -398,7 +387,7 @@ def get_monitor_failures_testcase(Filter_): # actions might be happening too fast in the tests, # sleep a bit to guarantee reliable time stamps if isinstance(self.filter, FilterPoll): - _sleep_4_poll() + mtimesleep() def isEmpty(self, delay=0.4): # shorter wait time for not modified status @@ -458,7 +447,9 @@ def get_monitor_failures_testcase(Filter_): self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, n=14, mode='w') # Poll might need more time - self.assertTrue(self.isEmpty(4 + int(isinstance(self.filter, FilterPoll))*2)) + self.assertTrue(self.isEmpty(4 + int(isinstance(self.filter, FilterPoll))*2), + "Queue must be empty but it is not: %s." + % (', '.join([str(x) for x in self.jail.queue]))) self.assertRaises(FailManagerEmpty, self.filter.failManager.toBan) self.assertEqual(self.filter.failManager.getFailTotal(), 2) diff --git a/testcases/utils.py b/testcases/utils.py index 87aab915..643c9ad1 100644 --- a/testcases/utils.py +++ b/testcases/utils.py @@ -22,7 +22,7 @@ __author__ = "Yaroslav Halchenko" __copyright__ = "Copyright (c) 2013 Yaroslav Halchenko" __license__ = "GPL" -import logging, os, re, traceback +import logging, os, re, tempfile, sys, time, traceback from os.path import basename, dirname # @@ -100,3 +100,8 @@ class FormatterWithTraceBack(logging.Formatter): def format(self, record): record.tbc = record.tb = self._tb() return logging.Formatter.format(self, record) + +def mtimesleep(): + # no sleep now should be necessary since polling tracks now not only + # mtime but also ino and size + pass