From e340d0d2b285dbc7b46c10beed9d1ea1ba04b09b Mon Sep 17 00:00:00 2001 From: sebres Date: Fri, 12 May 2017 16:51:08 +0200 Subject: [PATCH 1/7] 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, From 7b614a7a15b001e0e0e34765143dd43ea1095139 Mon Sep 17 00:00:00 2001 From: sebres Date: Fri, 12 May 2017 22:01:37 +0200 Subject: [PATCH 2/7] differentiate between watched directories and files (refreshing monitoring of files/dirs expected different flags for watcher) --- fail2ban/server/filterpyinotify.py | 168 ++++++++++++++++++----------- 1 file changed, 104 insertions(+), 64 deletions(-) diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index faf01560..6394ecef 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -78,7 +78,8 @@ class FilterPyinotify(FileFilter): self.__modified = False # Pyinotify watch manager self.__monitor = pyinotify.WatchManager() - self.__watches = dict() + self.__watchFiles = dict() + self.__watchDirs = dict() self.__pending = dict() self.__pendingChkTime = 0 self.__pendingNextTime = 0 @@ -87,45 +88,56 @@ class FilterPyinotify(FileFilter): def callback(self, event, origin=''): logSys.log(7, "[%s] %sCallback for Event: %s", self.jailName, origin, event) path = event.pathname + # check watching of this path: + isWF = isWD = False + if path in self.__watchDirs: + isWD = True + elif path in self.__watchFiles: + isWF = True + # fix pyinotify behavior with '-unknown-path' (if target not watched also): + if (event.mask & pyinotify.IN_MOVE_SELF and + path.endswith('-unknown-path') and not isWF and not isWD + ): + path = path[:-len('-unknown-path')] + isWD = path in self.__watchDirs + assumeNoDir = False if event.mask & ( pyinotify.IN_CREATE | pyinotify.IN_MOVED_TO ): + # refresh watched dir (may be expected): + if isWD: + self._refreshWatcher(path, isDir=True) + return # skip directories altogether if event.mask & pyinotify.IN_ISDIR: logSys.debug("Ignoring creation of directory %s", path) return # check if that is a file we care about - if path not in self.__watches: + if not isWF: logSys.debug("Ignoring creation of %s we do not monitor", path) return - self._refreshFileWatcher(path) + self._refreshWatcher(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) + assumeNoDir = event.mask & (pyinotify.IN_MOVE_SELF | pyinotify.IN_DELETE_SELF) + if isWD and (assumeNoDir or not os.path.isdir(path)): + self._addPending(path, event, isDir=True) + elif not isWF: + for logpath in self.__watchDirs: + if logpath.startswith(path + pathsep) and (assumeNoDir or not os.path.isdir(logpath)): + self._addPending(logpath, event, isDir=True) + # pending file: + for logpath in self.__watchFiles: + if logpath.startswith(path + pathsep) and (assumeNoDir or not os.path.isfile(logpath)): + self._addPending(logpath, event) + if isWF and not os.path.isfile(path): + self._addPending(path, event) + return # do nothing if idle: if self.idle: return + # be sure we process a file: + if not isWF: + logSys.debug("Ignoring event (%s) of %s we do not monitor", event.maskname, path) + return self._process_file(path) def _process_file(self, path): @@ -143,27 +155,36 @@ class FilterPyinotify(FileFilter): self.failManager.cleanup(MyTime.time()) self.__modified = False - def _addPendingFile(self, path, event): + def _addPending(self, path, event, isDir=False): if path not in self.__pending: - self.__pending[path] = self.sleeptime / 10; + self.__pending[path] = [self.sleeptime / 10, isDir]; + self.__pendingNextTime = 0 logSys.log(logging.MSG, "Log absence detected (possibly rotation) for %s, reason: %s of %s", path, event.maskname, event.pathname) - def _checkPendingFiles(self): + def _delPending(self, path): + try: + del self.__pending[path] + except KeyError: pass + + def _checkPending(self): if self.__pending: ntm = time.time() if ntm > self.__pendingNextTime: found = {} minTime = 60 - for path, retardTM in self.__pending.iteritems(): + for path, (retardTM, isDir) in self.__pending.iteritems(): if ntm - self.__pendingChkTime > retardTM: - if not os.path.isfile(path): # not found - prolong for next time + chkpath = os.path.isdir if isDir else os.path.isfile + if not chkpath(path): # not found - prolong for next time if retardTM < 60: retardTM *= 2 if minTime > retardTM: minTime = retardTM - self.__pending[path] = retardTM + self.__pending[path][0] = retardTM continue - found[path] = 1 - self._refreshFileWatcher(path) + logSys.log(logging.MSG, "Log presence detected for %s %s", + "directory" if isDir else "file", path) + found[path] = isDir + self._refreshWatcher(path, isDir=isDir) for path in found: try: del self.__pending[path] @@ -171,24 +192,32 @@ class FilterPyinotify(FileFilter): 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) + for path, isDir in found.iteritems(): + if not isDir: + self._process_file(path) - def _refreshFileWatcher(self, oldPath, newPath=None): + def _refreshWatcher(self, oldPath, newPath=None, isDir=False): + if not newPath: newPath = oldPath # 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) + # remove old one and then place a new one + if not isDir: + self._delFileWatcher(oldPath) + self._addFileWatcher(newPath) + else: + self._delDirWatcher(oldPath) + self._addDirWatcher(newPath) def _addFileWatcher(self, path): + # we need to watch also the directory for IN_CREATE + self._addDirWatcher(dirname(path)) + # add file watcher: wd = self.__monitor.add_watch(path, pyinotify.IN_MODIFY) - self.__watches.update(wd) + self.__watchFiles.update(wd) logSys.debug("Added file watcher for %s", path) def _delFileWatcher(self, path): try: - wdInt = self.__watches.pop(path) + wdInt = self.__watchFiles.pop(path) wd = self.__monitor.rm_watch(wdInt) if wd[wdInt]: logSys.debug("Removed file watcher for %s", path) @@ -197,21 +226,30 @@ class FilterPyinotify(FileFilter): pass return False + def _addDirWatcher(self, path_dir): + # Add watch for the directory: + if path_dir not in self.__watchDirs: + self.__watchDirs.update( + 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) + + def _delDirWatcher(self, path_dir): + # Remove watches for the directory: + try: + wdInt = self.__watchDirs.pop(path_dir) + self.__monitor.rm_watch(wdInt) + except KeyError: # pragma: no cover + pass + logSys.debug("Removed monitor for the parent directory %s", path_dir) + ## # Add a log file path # # @param path log file path def _addLogPath(self, path): - path_dir = dirname(path) - 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 | 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) self._process_file(path) @@ -223,18 +261,18 @@ class FilterPyinotify(FileFilter): def _delLogPath(self, path): if not self._delFileWatcher(path): logSys.error("Failed to remove watch on path: %s", path) + self._delPending(path) path_dir = dirname(path) - if not len([k for k in self.__watches - if k.startswith(path_dir + pathsep)]): + for k in self.__watchFiles: + if k.startswith(path_dir + pathsep): + path_dir = None + break + if path_dir: # Remove watches for the directory # since there is no other monitored file under this directory - try: - wdInt = self.__watches.pop(path_dir) - self.__monitor.rm_watch(wdInt) - except KeyError: # pragma: no cover - pass - logSys.debug("Removed monitor for the parent directory %s", path_dir) + self._delDirWatcher(path_dir) + self._delPending(path_dir) # pyinotify.ProcessEvent default handler: def __process_default(self, event): @@ -247,14 +285,16 @@ 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 ): pass + + # check pending files/dirs (logrotate ready): + if not self.idle: + self._checkPending() + self.ticks += 1 return pyinotify.ThreadedNotifier.check_events(self.__notifier, *args, **kwargs) From 9841fe52c34c966d143e17e447268fce4e896214 Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 May 2017 12:52:16 +0200 Subject: [PATCH 3/7] fixed cleanup for Gamin backend (by interim stop in the test-cases) --- fail2ban/server/filtergamin.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/fail2ban/server/filtergamin.py b/fail2ban/server/filtergamin.py index 106e4c0f..3baf8c54 100644 --- a/fail2ban/server/filtergamin.py +++ b/fail2ban/server/filtergamin.py @@ -143,6 +143,8 @@ class FilterGamin(FileFilter): # Desallocates the resources used by Gamin. def __cleanup(self): + if not self.monitor: + return for filename in self.getLogPaths(): self.monitor.stop_watch(filename) self.monitor = None From 5c1d01bf58635f10dc2a5c6c273c2a8b983b0ee8 Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 May 2017 14:31:18 +0200 Subject: [PATCH 4/7] code review, try to make recognition of pending files fewer sporadic (error prone) --- fail2ban/server/filterpyinotify.py | 50 +++++++++++++++++------------- fail2ban/tests/filtertestcase.py | 1 - 2 files changed, 29 insertions(+), 22 deletions(-) diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index 6394ecef..4926f9b7 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -38,7 +38,7 @@ from ..helpers import getLogger if not hasattr(pyinotify, '__version__') \ - or LooseVersion(pyinotify.__version__) < '0.8.3': + or LooseVersion(pyinotify.__version__) < '0.8.3': # pragma: no cover raise ImportError("Fail2Ban requires pyinotify >= 0.8.3") # Verify that pyinotify is functional on this system @@ -46,7 +46,7 @@ if not hasattr(pyinotify, '__version__') \ try: manager = pyinotify.WatchManager() del manager -except Exception as e: +except Exception as e: # pragma: no cover raise ImportError("Pyinotify is probably not functional on this system: %s" % str(e)) @@ -54,7 +54,7 @@ except Exception as e: logSys = getLogger(__name__) # Override pyinotify default logger/init-handler: -def _pyinotify_logger_init(): +def _pyinotify_logger_init(): # pragma: no cover return logSys pyinotify._logger_init = _pyinotify_logger_init pyinotify.log = logSys @@ -124,10 +124,6 @@ class FilterPyinotify(FileFilter): for logpath in self.__watchDirs: if logpath.startswith(path + pathsep) and (assumeNoDir or not os.path.isdir(logpath)): self._addPending(logpath, event, isDir=True) - # pending file: - for logpath in self.__watchFiles: - if logpath.startswith(path + pathsep) and (assumeNoDir or not os.path.isfile(logpath)): - self._addPending(logpath, event) if isWF and not os.path.isfile(path): self._addPending(path, event) return @@ -155,12 +151,14 @@ class FilterPyinotify(FileFilter): self.failManager.cleanup(MyTime.time()) self.__modified = False - def _addPending(self, path, event, isDir=False): + def _addPending(self, path, reason, isDir=False): if path not in self.__pending: self.__pending[path] = [self.sleeptime / 10, isDir]; self.__pendingNextTime = 0 + if isinstance(reason, pyinotify.Event): + reason = [reason.maskname, reason.pathname] logSys.log(logging.MSG, "Log absence detected (possibly rotation) for %s, reason: %s of %s", - path, event.maskname, event.pathname) + path, *reason) def _delPending(self, path): try: @@ -174,17 +172,18 @@ class FilterPyinotify(FileFilter): found = {} minTime = 60 for path, (retardTM, isDir) in self.__pending.iteritems(): - if ntm - self.__pendingChkTime > retardTM: - chkpath = os.path.isdir if isDir else os.path.isfile - if not chkpath(path): # not found - prolong for next time - if retardTM < 60: retardTM *= 2 - if minTime > retardTM: minTime = retardTM - self.__pending[path][0] = retardTM - continue - logSys.log(logging.MSG, "Log presence detected for %s %s", - "directory" if isDir else "file", path) - found[path] = isDir - self._refreshWatcher(path, isDir=isDir) + if ntm - self.__pendingChkTime < retardTM: + if minTime > retardTM: minTime = retardTM + continue + chkpath = os.path.isdir if isDir else os.path.isfile + if not chkpath(path): # not found - prolong for next time + if retardTM < 60: retardTM *= 2 + if minTime > retardTM: minTime = retardTM + self.__pending[path][0] = retardTM + continue + logSys.log(logging.MSG, "Log presence detected for %s %s", + "directory" if isDir else "file", path) + found[path] = isDir for path in found: try: del self.__pending[path] @@ -193,7 +192,16 @@ class FilterPyinotify(FileFilter): self.__pendingNextTime = self.__pendingChkTime + minTime # process now because we'he missed it in monitoring: for path, isDir in found.iteritems(): - if not isDir: + self._refreshWatcher(path, isDir=isDir) + if isDir: + for logpath in self.__watchFiles: + if logpath.startswith(path + pathsep): + if not os.path.isfile(logpath): + self._addPending(logpath, ['FROM_PARDIR', path]) + else: + self._refreshWatcher(logpath) + self._process_file(logpath) + else: self._process_file(path) def _refreshWatcher(self, oldPath, newPath=None, isDir=False): diff --git a/fail2ban/tests/filtertestcase.py b/fail2ban/tests/filtertestcase.py index a9b31fd4..ec2dea89 100644 --- a/fail2ban/tests/filtertestcase.py +++ b/fail2ban/tests/filtertestcase.py @@ -957,7 +957,6 @@ def get_monitor_failures_testcase(Filter_): 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... os.rename(self.name, self.name + '.bak') From 16a84ca0b5e5e5624e8d5871c356eb6d9c4c4b68 Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 May 2017 15:20:43 +0200 Subject: [PATCH 5/7] code review --- fail2ban/server/filter.py | 2 +- fail2ban/server/filterpyinotify.py | 111 +++++++++++++++-------------- 2 files changed, 57 insertions(+), 56 deletions(-) diff --git a/fail2ban/server/filter.py b/fail2ban/server/filter.py index c88a6c6d..fce02a7a 100644 --- a/fail2ban/server/filter.py +++ b/fail2ban/server/filter.py @@ -895,7 +895,7 @@ class FileFilter(Filter): # see http://python.org/dev/peps/pep-3151/ except IOError as e: logSys.error("Unable to open %s", filename) - if e.errno != 2: + if e.errno != 2: # errno.ENOENT logSys.exception(e) return False except OSError as e: # pragma: no cover - requires race condition to tigger this diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index 4926f9b7..7785b84f 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -89,23 +89,12 @@ class FilterPyinotify(FileFilter): logSys.log(7, "[%s] %sCallback for Event: %s", self.jailName, origin, event) path = event.pathname # check watching of this path: - isWF = isWD = False - if path in self.__watchDirs: - isWD = True - elif path in self.__watchFiles: + isWF = False + isWD = path in self.__watchDirs + if not isWD and path in self.__watchFiles: isWF = True - # fix pyinotify behavior with '-unknown-path' (if target not watched also): - if (event.mask & pyinotify.IN_MOVE_SELF and - path.endswith('-unknown-path') and not isWF and not isWD - ): - path = path[:-len('-unknown-path')] - isWD = path in self.__watchDirs assumeNoDir = False if event.mask & ( pyinotify.IN_CREATE | pyinotify.IN_MOVED_TO ): - # refresh watched dir (may be expected): - if isWD: - self._refreshWatcher(path, isDir=True) - return # skip directories altogether if event.mask & pyinotify.IN_ISDIR: logSys.debug("Ignoring creation of directory %s", path) @@ -116,8 +105,14 @@ class FilterPyinotify(FileFilter): return self._refreshWatcher(path) elif event.mask & (pyinotify.IN_IGNORED | pyinotify.IN_MOVE_SELF | pyinotify.IN_DELETE_SELF): - # watch was removed for some reasons (log-rotate?): assumeNoDir = event.mask & (pyinotify.IN_MOVE_SELF | pyinotify.IN_DELETE_SELF) + # fix pyinotify behavior with '-unknown-path' (if target not watched also): + if (assumeNoDir and + path.endswith('-unknown-path') and not isWF and not isWD + ): + path = path[:-len('-unknown-path')] + isWD = path in self.__watchDirs + # watch was removed for some reasons (log-rotate?): if isWD and (assumeNoDir or not os.path.isdir(path)): self._addPending(path, event, isDir=True) elif not isWF: @@ -153,7 +148,7 @@ class FilterPyinotify(FileFilter): def _addPending(self, path, reason, isDir=False): if path not in self.__pending: - self.__pending[path] = [self.sleeptime / 10, isDir]; + self.__pending[path] = [Utils.DEFAULT_SLEEP_INTERVAL, isDir]; self.__pendingNextTime = 0 if isinstance(reason, pyinotify.Event): reason = [reason.maskname, reason.pathname] @@ -166,43 +161,49 @@ class FilterPyinotify(FileFilter): except KeyError: pass def _checkPending(self): - if self.__pending: - ntm = time.time() - if ntm > self.__pendingNextTime: - found = {} - minTime = 60 - for path, (retardTM, isDir) in self.__pending.iteritems(): - if ntm - self.__pendingChkTime < retardTM: - if minTime > retardTM: minTime = retardTM - continue - chkpath = os.path.isdir if isDir else os.path.isfile - if not chkpath(path): # not found - prolong for next time - if retardTM < 60: retardTM *= 2 - if minTime > retardTM: minTime = retardTM - self.__pending[path][0] = retardTM - continue - logSys.log(logging.MSG, "Log presence detected for %s %s", - "directory" if isDir else "file", path) - found[path] = isDir - 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, isDir in found.iteritems(): - self._refreshWatcher(path, isDir=isDir) - if isDir: - for logpath in self.__watchFiles: - if logpath.startswith(path + pathsep): - if not os.path.isfile(logpath): - self._addPending(logpath, ['FROM_PARDIR', path]) - else: - self._refreshWatcher(logpath) - self._process_file(logpath) - else: - self._process_file(path) + if not self.__pending: + return + ntm = time.time() + if ntm < self.__pendingNextTime: + return + found = {} + minTime = 60 + for path, (retardTM, isDir) in self.__pending.iteritems(): + if ntm - self.__pendingChkTime < retardTM: + if minTime > retardTM: minTime = retardTM + continue + chkpath = os.path.isdir if isDir else os.path.isfile + if not chkpath(path): # not found - prolong for next time + if retardTM < 60: retardTM *= 2 + if minTime > retardTM: minTime = retardTM + self.__pending[path][0] = retardTM + continue + logSys.log(logging.MSG, "Log presence detected for %s %s", + "directory" if isDir else "file", path) + found[path] = isDir + 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've missed it in monitoring: + for path, isDir in found.iteritems(): + # refresh monitoring of this: + self._refreshWatcher(path, isDir=isDir) + if isDir: + # check all files belong to this dir: + for logpath in self.__watchFiles: + if logpath.startswith(path + pathsep): + # if still no file - add to pending, otherwise refresh and process: + if not os.path.isfile(logpath): + self._addPending(logpath, ('FROM_PARDIR', path)) + else: + self._refreshWatcher(logpath) + self._process_file(logpath) + else: + # process (possibly no old events for it from watcher): + self._process_file(path) def _refreshWatcher(self, oldPath, newPath=None, isDir=False): if not newPath: newPath = oldPath @@ -286,7 +287,7 @@ class FilterPyinotify(FileFilter): def __process_default(self, event): try: self.callback(event, origin='Default ') - except Exception as e: + except Exception as e: # pragma: no cover logSys.error("Error in FilterPyinotify callback: %s", e, exc_info=logSys.getEffectiveLevel() <= logging.DEBUG) self.ticks += 1 @@ -300,7 +301,7 @@ class FilterPyinotify(FileFilter): pass # check pending files/dirs (logrotate ready): - if not self.idle: + if not self.idle and self.active: self._checkPending() self.ticks += 1 From 62e580b7cf647a2f66c19a833e5aa703ad1c19f8 Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 May 2017 18:47:00 +0200 Subject: [PATCH 6/7] pyinotify: switch from ThreadedNotifier to Notifier: - Filter instance is already a thread; - avoid stop pyinotify processing if an interim error occurs (and breaks main-loop, e. g. during multi-threaded processing by add/remove log-files) --- fail2ban/server/filterpyinotify.py | 73 ++++++++++++++++++++---------- 1 file changed, 49 insertions(+), 24 deletions(-) diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index 7785b84f..29e29eca 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -290,23 +290,10 @@ class FilterPyinotify(FileFilter): except Exception as e: # pragma: no cover logSys.error("Error in FilterPyinotify callback: %s", e, exc_info=logSys.getEffectiveLevel() <= logging.DEBUG) + # incr common error counter: + self.commonError() self.ticks += 1 - # slow check events while idle: - def __check_events(self, *args, **kwargs): - if self.idle: - if Utils.wait_for(lambda: not self.active or not self.idle, - self.sleeptime * 10, self.sleeptime - ): - pass - - # check pending files/dirs (logrotate ready): - if not self.idle and self.active: - self._checkPending() - - self.ticks += 1 - return pyinotify.ThreadedNotifier.check_events(self.__notifier, *args, **kwargs) - ## # Main loop. # @@ -317,26 +304,64 @@ class FilterPyinotify(FileFilter): prcevent = pyinotify.ProcessEvent() prcevent.process_default = self.__process_default ## timeout for pyinotify must be set in milliseconds (our time values are floats contain seconds) - self.__notifier = pyinotify.ThreadedNotifier(self.__monitor, + self.__notifier = pyinotify.Notifier(self.__monitor, prcevent, timeout=self.sleeptime * 1000) - self.__notifier.check_events = self.__check_events - self.__notifier.start() logSys.debug("[%s] filter started (pyinotifier)", self.jailName) + while self.active: + try: + + # slow check events while idle: + if self.idle: + if Utils.wait_for(lambda: not self.active or not self.idle, + self.sleeptime * 10, self.sleeptime + ): + if not self.active: + break + + # default pyinotify handling using Notifier: + self.__notifier.process_events() + if Utils.wait_for(lambda: not self.active or self.__notifier.check_events(), self.sleeptime): + if not self.active: + break + self.__notifier.read_events() + + # check pending files/dirs (logrotate ready): + if not self.idle: + self._checkPending() + + except Exception as e: # pragma: no cover + if not self.active: # if not active - error by stop... + break + logSys.error("Caught unhandled exception in main cycle: %r", e, + exc_info=logSys.getEffectiveLevel()<=logging.DEBUG) + # incr common error counter: + self.commonError() + + self.ticks += 1 + + logSys.debug("[%s] filter exited (pyinotifier)", self.jailName) + self.__notifier = None + return True ## # Call super.stop() and then stop the 'Notifier' def stop(self): + if self.__notifier: # stop the notifier + self.__notifier.stop() + # stop filter thread: super(FilterPyinotify, self).stop() - # Stop the notifier thread - self.__notifier.stop() - self.__notifier.stop = lambda *args: 0; # prevent dual stop + self.join() + if self.__notifier: # stop the notifier + self.__notifier.stop() + self.__notifier.stop = lambda *args: 0; # prevent dual stop ## # Wait for exit with cleanup. def join(self): + self.join = lambda *args: 0 self.__cleanup() super(FilterPyinotify, self).join() logSys.debug("[%s] filter terminated (pyinotifier)", self.jailName) @@ -346,6 +371,6 @@ class FilterPyinotify(FileFilter): def __cleanup(self): if self.__notifier: - self.__notifier.join() # to not exit before notifier does - self.__notifier = None - self.__monitor = None + if Utils.wait_for(lambda: not self.__notifier, self.sleeptime * 10): + self.__notifier = None + self.__monitor = None From 050076ae42f13c74ae8ba418f5b1f40be96515cd Mon Sep 17 00:00:00 2001 From: sebres Date: Mon, 15 May 2017 19:05:40 +0200 Subject: [PATCH 7/7] code review + coverage fixes --- fail2ban/server/filterpyinotify.py | 30 +++++++++++++----------------- 1 file changed, 13 insertions(+), 17 deletions(-) diff --git a/fail2ban/server/filterpyinotify.py b/fail2ban/server/filterpyinotify.py index 29e29eca..71540f3c 100644 --- a/fail2ban/server/filterpyinotify.py +++ b/fail2ban/server/filterpyinotify.py @@ -137,14 +137,15 @@ class FilterPyinotify(FileFilter): TODO -- RF: this is a common logic and must be shared/provided by FileFilter """ - self.getFailures(path) - try: - while True: - ticket = self.failManager.toBan() - self.jail.putFailTicket(ticket) - except FailManagerEmpty: - self.failManager.cleanup(MyTime.time()) - self.__modified = False + if not self.idle: + self.getFailures(path) + try: + while True: + ticket = self.failManager.toBan() + self.jail.putFailTicket(ticket) + except FailManagerEmpty: + self.failManager.cleanup(MyTime.time()) + self.__modified = False def _addPending(self, path, reason, isDir=False): if path not in self.__pending: @@ -268,7 +269,7 @@ class FilterPyinotify(FileFilter): # @param path the log file to delete def _delLogPath(self, path): - if not self._delFileWatcher(path): + if not self._delFileWatcher(path): # pragma: no cover logSys.error("Failed to remove watch on path: %s", path) self._delPending(path) @@ -315,14 +316,12 @@ class FilterPyinotify(FileFilter): if Utils.wait_for(lambda: not self.active or not self.idle, self.sleeptime * 10, self.sleeptime ): - if not self.active: - break + if not self.active: break # default pyinotify handling using Notifier: self.__notifier.process_events() if Utils.wait_for(lambda: not self.active or self.__notifier.check_events(), self.sleeptime): - if not self.active: - break + if not self.active: break self.__notifier.read_events() # check pending files/dirs (logrotate ready): @@ -341,7 +340,7 @@ class FilterPyinotify(FileFilter): logSys.debug("[%s] filter exited (pyinotifier)", self.jailName) self.__notifier = None - + return True ## @@ -353,9 +352,6 @@ class FilterPyinotify(FileFilter): # stop filter thread: super(FilterPyinotify, self).stop() self.join() - if self.__notifier: # stop the notifier - self.__notifier.stop() - self.__notifier.stop = lambda *args: 0; # prevent dual stop ## # Wait for exit with cleanup.