From e340d0d2b285dbc7b46c10beed9d1ea1ba04b09b Mon Sep 17 00:00:00 2001 From: sebres Date: Fri, 12 May 2017 16:51:08 +0200 Subject: [PATCH] Fixed detection of directory-based log-rotation of pyinotify backend. If directory moved and the target is not watched path, so the monitoring of it could not be continued. Now fixed with pending files await a monitoring if there (resp. its directories) appears again (respawn). Closes gh-1769 --- fail2ban/server/filter.py | 3 +- fail2ban/server/filterpyinotify.py | 92 +++++++++++++++++++++++++++--- fail2ban/tests/filtertestcase.py | 46 ++++++++++++--- 3 files changed, 124 insertions(+), 17 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index 526f54ea..c88a6c6d 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -895,7 +895,8 @@ class FileFilter(Filter): # see http://python.org/dev/peps/pep-3151/ except IOError as e: logSys.error("Unable to open %s", filename) - logSys.exception(e) + if e.errno != 2: + logSys.exception(e) return False except OSError as e: # pragma: no cover - requires race condition to tigger this logSys.error("Error opening %s", filename) diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index 73c82099..faf01560 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -25,13 +25,14 @@ __license__ = "GPL" import logging from distutils.version import LooseVersion +import os from os.path import dirname, sep as pathsep import pyinotify from .failmanager import FailManagerEmpty from .filter import FileFilter -from .mytime import MyTime +from .mytime import MyTime, time from .utils import Utils from ..helpers import getLogger @@ -52,6 +53,11 @@ except Exception as e: # Gets the instance of the logger. logSys = getLogger(__name__) +# Override pyinotify default logger/init-handler: +def _pyinotify_logger_init(): + return logSys +pyinotify._logger_init = _pyinotify_logger_init +pyinotify.log = logSys ## # Log reader class. @@ -73,6 +79,9 @@ class FilterPyinotify(FileFilter): # Pyinotify watch manager self.__monitor = pyinotify.WatchManager() self.__watches = dict() + self.__pending = dict() + self.__pendingChkTime = 0 + self.__pendingNextTime = 0 logSys.debug("Created FilterPyinotify") def callback(self, event, origin=''): @@ -84,15 +93,36 @@ class FilterPyinotify(FileFilter): logSys.debug("Ignoring creation of directory %s", path) return # check if that is a file we care about - if not path in self.__watches: + if path not in self.__watches: 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 - # remove old one - self._delFileWatcher(path) - # place a new one - self._addFileWatcher(path) + self._refreshFileWatcher(path) + elif event.mask & (pyinotify.IN_IGNORED | pyinotify.IN_MOVE_SELF | pyinotify.IN_DELETE_SELF): + # fix pyinotify behavior with '-unknown-path' (if target not watched also): + if (event.mask & pyinotify.IN_MOVE_SELF and path not in self.__watches and + path.endswith('-unknown-path') + ): + path = path[:-len('-unknown-path')] + # watch was removed for some reasons (log-rotate?): + if not os.path.isfile(path): + for log in self.getLogs(): + logpath = log.getFileName() + if logpath.startswith(path): + # check exists (rotated): + if event.mask & pyinotify.IN_MOVE_SELF or not os.path.isfile(logpath): + self._addPendingFile(logpath, event) + else: + path = logpath + break + if path not in self.__watches: + logSys.debug("Ignoring event of %s we do not monitor", path) + return + if not os.path.isfile(path): + if self.containsLogPath(path): + self._addPendingFile(path, event) + logSys.debug("Ignoring watching/rotation event (%s) for %s", event.maskname, path) + return + self._refreshFileWatcher(path) # do nothing if idle: if self.idle: return @@ -113,6 +143,44 @@ class FilterPyinotify(FileFilter): self.failManager.cleanup(MyTime.time()) self.__modified = False + def _addPendingFile(self, path, event): + if path not in self.__pending: + self.__pending[path] = self.sleeptime / 10; + logSys.log(logging.MSG, "Log absence detected (possibly rotation) for %s, reason: %s of %s", + path, event.maskname, event.pathname) + + def _checkPendingFiles(self): + if self.__pending: + ntm = time.time() + if ntm > self.__pendingNextTime: + found = {} + minTime = 60 + for path, retardTM in self.__pending.iteritems(): + if ntm - self.__pendingChkTime > retardTM: + if not os.path.isfile(path): # not found - prolong for next time + if retardTM < 60: retardTM *= 2 + if minTime > retardTM: minTime = retardTM + self.__pending[path] = retardTM + continue + found[path] = 1 + self._refreshFileWatcher(path) + for path in found: + try: + del self.__pending[path] + except KeyError: pass + self.__pendingChkTime = time.time() + self.__pendingNextTime = self.__pendingChkTime + minTime + # process now because we'he missed it in monitoring: + for path in found: + self._process_file(path) + + def _refreshFileWatcher(self, oldPath, newPath=None): + # we need to substitute the watcher with a new one, so first + # remove old one + self._delFileWatcher(oldPath) + # place a new one + self._addFileWatcher(newPath or oldPath) + def _addFileWatcher(self, path): wd = self.__monitor.add_watch(path, pyinotify.IN_MODIFY) self.__watches.update(wd) @@ -139,7 +207,9 @@ class FilterPyinotify(FileFilter): if not (path_dir in self.__watches): # we need to watch also the directory for IN_CREATE self.__watches.update( - self.__monitor.add_watch(path_dir, pyinotify.IN_CREATE | pyinotify.IN_MOVED_TO)) + self.__monitor.add_watch(path_dir, pyinotify.IN_CREATE | + pyinotify.IN_MOVED_TO | pyinotify.IN_MOVE_SELF | + pyinotify.IN_DELETE_SELF | pyinotify.IN_ISDIR)) logSys.debug("Added monitor for the parent directory %s", path_dir) self._addFileWatcher(path) @@ -177,6 +247,9 @@ class FilterPyinotify(FileFilter): # slow check events while idle: def __check_events(self, *args, **kwargs): + # check pending files (logrotate ready): + self._checkPendingFiles() + if self.idle: if Utils.wait_for(lambda: not self.active or not self.idle, self.sleeptime * 10, self.sleeptime @@ -209,6 +282,7 @@ class FilterPyinotify(FileFilter): super(FilterPyinotify, self).stop() # Stop the notifier thread self.__notifier.stop() + self.__notifier.stop = lambda *args: 0; # prevent dual stop ## # Wait for exit with cleanup. diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index ce665e72..a9b31fd4 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -43,7 +43,7 @@ from ..server.failmanager import FailManagerEmpty from ..server.ipdns import DNSUtils, IPAddr from ..server.mytime import MyTime from ..server.utils import Utils, uni_decode -from .utils import setUpMyTime, tearDownMyTime, mtimesleep, LogCaptureTestCase +from .utils import setUpMyTime, tearDownMyTime, mtimesleep, with_tmpdir, LogCaptureTestCase from .dummyjail import DummyJail TEST_FILES_DIR = os.path.join(os.path.dirname(__file__), "files") @@ -942,17 +942,21 @@ def get_monitor_failures_testcase(Filter_): skip=3, mode='w') self.assert_correct_last_attempt(GetFailures.FAILURES_01) - def test_move_file(self): - # if we move file into a new location while it has been open already - self.file.close() - self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, - n=14, mode='w') + def _wait4failures(self, count=2): # Poll might need more time self.assertTrue(self.isEmpty(_maxWaitTime(5)), "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) - Utils.wait_for(lambda: self.filter.failManager.getFailTotal() == 2, _maxWaitTime(10)) + Utils.wait_for(lambda: self.filter.failManager.getFailTotal() >= count, _maxWaitTime(10)) + self.assertEqual(self.filter.failManager.getFailTotal(), count) + + def test_move_file(self): + # if we move file into a new location while it has been open already + self.file.close() + self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, + n=14, mode='w') + self._wait4failures() self.assertEqual(self.filter.failManager.getFailTotal(), 2) # move aside, but leaving the handle still open... @@ -967,6 +971,34 @@ def get_monitor_failures_testcase(Filter_): self.assert_correct_last_attempt(GetFailures.FAILURES_01) self.assertEqual(self.filter.failManager.getFailTotal(), 6) + @with_tmpdir + def test_move_dir(self, tmp): + self.file.close() + self.filter.delLogPath(self.name) + # if we rename parent dir into a new location (simulate directory-base log rotation) + tmpsub1 = os.path.join(tmp, "1") + tmpsub2 = os.path.join(tmp, "2") + os.mkdir(tmpsub1) + self.name = os.path.join(tmpsub1, os.path.basename(self.name)) + os.close(os.open(self.name, os.O_CREAT|os.O_APPEND)); # create empty file + self.filter.addLogPath(self.name, autoSeek=False) + + self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, + skip=12, n=1, mode='w') + self.file.close() + self._wait4failures(1) + + # rotate whole directory: rename directory 1 as 2: + os.rename(tmpsub1, tmpsub2) + os.mkdir(tmpsub1) + self.file = _copy_lines_between_files(GetFailures.FILENAME_01, self.name, + skip=12, n=1, mode='w') + self.file.close() + self._wait4failures(2) + # stop before tmpdir deleted (just prevents many monitor events) + self.filter.stop() + + def _test_move_into_file(self, interim_kill=False): # if we move a new file into the location of an old (monitored) file _copy_lines_between_files(GetFailures.FILENAME_01, self.name,