BF: race condition -- file should not be read unless it is not empty

Previous code would store md5sum of an empty line as the one
identifying the monitored file.  That file then was read and possibly
failures were found.  Upon next "container.open()", md5 digest of now
present first line was compared against previous digest of an empty
line, which was different, thus file was assumed to be rotated and all
the log lines were read once again.

The History
-----------
In rare cases various tests failed somewhat consistently.  Below you
can find one case in test_move_file where such failure really made no
sense -- we should have not had 4 failures by that point.

Fail2ban 0.8.10.dev test suite. Python 2.4.6 (#2, Sep 25 2009, 22:22:06) [GCC 4.3.4]. Please wait...
I: Skipping gamin backend testing. Got exception 'No module named gamin'
I: Skipping pyinotify backend testing. Got exception 'No module named pyinotify'
D: fn=/home/yoh/test/monitorfailures_FilterPoll9nUKoCfail2ban-0 hashes=d41d8cd98f00b204e9800998ecf8427e/d41d8cd98f00b204e9800998ecf8427e inos=5398862/5398862 pos=0 rotate=False
D: Adding a ticket for ('193.168.0.128', 1124013599.0, ['Aug 14 11:59:59 [sshd] error: PAM: Authentication failure for kevin from 193.168.0.128\n'])
D: Adding a ticket for ('193.168.0.128', 1124013599.0, ['Aug 14 11:59:59 [sshd] error: PAM: Authentication failure for kevin from 193.168.0.128\n'])
D: Closed <closed file '/home/yoh/test/monitorfailures_FilterPoll9nUKoCfail2ban-0', mode 'r' at 0x7f472b2efdc8> with pos 1231
D: fn=/home/yoh/test/monitorfailures_FilterPoll9nUKoCfail2ban-0 hashes=d41d8cd98f00b204e9800998ecf8427e/aeb4e73e6922a746d027eb365ece2149 inos=5398862/5398862 pos=1231 rotate=True
D: Adding a ticket for ('193.168.0.128', 1124013599.0, ['Aug 14 11:59:59 [sshd] error: PAM: Authentication failure for kevin from 193.168.0.128\n'])
D: Adding a ticket for ('193.168.0.128', 1124013599.0, ['Aug 14 11:59:59 [sshd] error: PAM: Authentication failure for kevin from 193.168.0.128\n'])
D: Closed <closed file '/home/yoh/test/monitorfailures_FilterPoll9nUKoCfail2ban-0', mode 'r' at 0x7f472b2ef558> with pos 1231
F
======================================================================
FAIL: test_move_file (testcases.filtertestcase.MonitorFailures<FilterPoll>(/home/yoh/test/monitorfailures_FilterPoll9nUKoCfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/yoh/deb/gits/fail2ban/testcases/filtertestcase.py", line 451, in test_move_file
    "Queue must be empty but it is not: %s."
AssertionError: Queue must be empty but it is not: server.ticket.FailTicket: ip=193.168.0.128 time=1124013599.0 #attempts=4.

----------------------------------------------------------------------

N.B.1 I preserved here and in the code corresponding additional debug
print statements, which are commented out by default. sensible md5
digest was generated by using hexdigest() instead of current a bit
faster digest().  Running tests with all the debug output simply
breaks the race loose and failure doesn't trigger.

N.B.2 d41d8cd98f00b204e9800998ecf8427e is an md5sum of an empty
string, and aeb4e73e6922a746d027eb365ece2149 of the first line in that
file.

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()