Merge pull request #280 from yarikoptic/master

BF+ENHs: polling backend tracks ino and size now in addition to mtime, filters do not read file unless it has content + few other minor issues

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:

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]

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)
 

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"

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.

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)
 

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