filter, datedetector, datetemplate: performance optimizing of combination datedetector.matchTime/getTime2, because early getTime search a template and call template.matchTime again (so the date parsing was really executed twice, now just once);

debug logging optimized;
added info line log "Start Fail2ban ..." after changed logging target;

fail2ban/server/action.py

@@ -592,10 +592,12 @@ class CommandAction(ActionBase):
 
 		std_level = retcode == 0 and logging.DEBUG or logging.ERROR
 		if std_level >= logSys.getEffectiveLevel():
-			stdout.seek(0)
+			stdout.seek(0); msg = stdout.read()
-			logSys.log(std_level, "%s -- stdout: %r" % (realCmd, stdout.read()))
+			if msg != '':
-			stderr.seek(0)
+				logSys.log(std_level, "%s -- stdout: %r", realCmd, msg)
-			logSys.log(std_level, "%s -- stderr: %r" % (realCmd, stderr.read()))
+			stderr.seek(0); msg = stderr.read()
+			if msg != '':
+				logSys.log(std_level, "%s -- stderr: %r", realCmd, msg)
 		stdout.close()
 		stderr.close()
 

fail2ban/server/datedetector.py

@@ -29,6 +29,8 @@ from ..helpers import getLogger
 # Gets the instance of the logger.
 logSys = getLogger(__name__)
 
+logLevel = 6
+
 
 class DateDetector(object):
 	"""Manages one or more date templates to find a date within a log line.
@@ -147,7 +149,7 @@ class DateDetector(object):
 
 		Returns
 		-------
-		re.MatchObject
+		re.MatchObject, DateTemplate
 			The regex match returned from the first successfully matched
 			template.
 		"""
@@ -156,10 +158,11 @@ class DateDetector(object):
 			for template in self.__templates:
 				match = template.matchDate(line)
 				if not match is None:
-					logSys.debug("Matched time template %s" % template.name)
+					if logSys.getEffectiveLevel() <= logLevel:
+						logSys.log(logLevel, "Matched time template %s", template.name)
 					template.hits += 1
-					return match
+					return (match, template)
-			return None
+			return (None, None)
 		finally:
 			self.__lock.release()
 
@@ -178,7 +181,7 @@ class DateDetector(object):
 		-------
 		float
 			The Unix timestamp returned from the first successfully matched
-			template.
+			template or None if not found.
 		"""
 		self.__lock.acquire()
 		try:
@@ -187,8 +190,9 @@ class DateDetector(object):
 					date = template.getDate(line)
 					if date is None:
 						continue
-					logSys.debug("Got time %f for \"%r\" using template %s" %
+					if logSys.getEffectiveLevel() <= logLevel:
-						(date[0], date[1].group(), template.name))
+						logSys.log(logLevel, "Got time %f for \"%r\" using template %s", 
+							date[0], date[1].group(), template.name)
 					return date
 				except ValueError:
 					pass
@@ -196,6 +200,38 @@ class DateDetector(object):
 		finally:
 			self.__lock.release()
 
+	def getTime2(self, line, timeMatch = None):
+		"""Attempts to return the date on a log line using given template.
+
+		This uses the templates' `getDate` method in an attempt to find
+		a date.
+		Method 'getTime2' is a little bit faster as 'getTime' if template was specified (cause works without locking and without cycle)
+
+		Parameters
+		----------
+		line : str
+			Line which is searched by the date templates.
+		timeMatch (timeMatch, template) : (Match, DateTemplate)
+			Time match and template previously returned from matchTime
+
+		Returns
+		-------
+		float
+			The Unix timestamp returned from the first successfully matched
+			template or None if not found.
+		"""
+		date = None
+		if timeMatch:
+			template = timeMatch[1]
+			if template is not None:
+				date = template.getDate(line, timeMatch[0])
+		if date is not None:
+			if logSys.getEffectiveLevel() <= logLevel:
+				logSys.log(logLevel, "Got time(2) %f for \"%r\" using template %s",
+					date[0], date[1].group(), template.name)
+			return date
+		return self.getTime(line)
+
 	def sortTemplate(self):
 		"""Sort the date templates by number of hits
 
@@ -206,9 +242,11 @@ class DateDetector(object):
 		"""
 		self.__lock.acquire()
 		try:
-			logSys.debug("Sorting the template list")
+			if logSys.getEffectiveLevel() <= logLevel:
+				logSys.log(logLevel, "Sorting the template list")
 			self.__templates.sort(key=lambda x: x.hits, reverse=True)
 			t = self.__templates[0]
-			logSys.debug("Winning template: %s with %d hits" % (t.name, t.hits))
+			if logSys.getEffectiveLevel() <= logLevel:
+				logSys.log(logLevel, "Winning template: %s with %d hits", t.name, t.hits)
 		finally:
 			self.__lock.release()

fail2ban/server/datetemplate.py

@@ -98,7 +98,7 @@ class DateTemplate(object):
 		return dateMatch
 
 	@abstractmethod
-	def getDate(self, line):
+	def getDate(self, line, dateMatch=None):
 		"""Abstract method, which should return the date for a log line
 
 		This should return the date for a log line, typically taking the
@@ -134,7 +134,7 @@ class DateEpoch(DateTemplate):
 		DateTemplate.__init__(self)
 		self.regex = "(?:^|(?P<square>(?<=^\[))|(?P<selinux>(?<=audit\()))\d{10}(?:\.\d{3,6})?(?(selinux)(?=:\d+\))(?(square)(?=\])))"
 
-	def getDate(self, line):
+	def getDate(self, line, dateMatch=None):
 		"""Method to return the date for a log line.
 
 		Parameters
@@ -148,7 +148,8 @@ class DateEpoch(DateTemplate):
 			Tuple containing a Unix timestamp, and the string of the date
 			which was matched and in turned used to calculated the timestamp.
 		"""
-		dateMatch = self.matchDate(line)
+		if not dateMatch:
+			dateMatch = self.matchDate(line)
 		if dateMatch:
 			# extract part of format which represents seconds since epoch
 			return (float(dateMatch.group()), dateMatch)
@@ -212,7 +213,7 @@ class DatePatternRegex(DateTemplate):
 	def name(self, value):
 		raise NotImplementedError("Name derived from pattern")
 
-	def getDate(self, line):
+	def getDate(self, line, dateMatch=None):
 		"""Method to return the date for a log line.
 
 		This uses a custom version of strptime, using the named groups
@@ -229,7 +230,8 @@ class DatePatternRegex(DateTemplate):
 			Tuple containing a Unix timestamp, and the string of the date
 			which was matched and in turned used to calculated the timestamp.
 		"""
-		dateMatch = self.matchDate(line)
+		if not dateMatch:
+			dateMatch = self.matchDate(line)
 		if dateMatch:
 			groupdict = dict(
 				(key, value)
@@ -253,7 +255,7 @@ class DateTai64n(DateTemplate):
 		# yoh: we should not add an additional front anchor
 		self.setRegex("@[0-9a-f]{24}", wordBegin=False)
 
-	def getDate(self, line):
+	def getDate(self, line, dateMatch=None):
 		"""Method to return the date for a log line.
 
 		Parameters
@@ -267,7 +269,8 @@ class DateTai64n(DateTemplate):
 			Tuple containing a Unix timestamp, and the string of the date
 			which was matched and in turned used to calculated the timestamp.
 		"""
-		dateMatch = self.matchDate(line)
+		if not dateMatch:
+			dateMatch = self.matchDate(line)
 		if dateMatch:
 			# extract part of format which represents seconds since epoch
 			value = dateMatch.group()

fail2ban/server/filter.py

@@ -406,14 +406,16 @@ class Filter(JailThread):
 			l = line.rstrip('\r\n')
 			logSys.log(7, "Working on line %r", line)
 
-			timeMatch = self.dateDetector.matchTime(l)
+			(timeMatch, template) = self.dateDetector.matchTime(l)
 			if timeMatch:
 				tupleLine  = (
 					l[:timeMatch.start()],
 					l[timeMatch.start():timeMatch.end()],
-					l[timeMatch.end():])
+					l[timeMatch.end():],
+					(timeMatch, template)
+				)
 			else:
-				tupleLine = (l, "", "")
+				tupleLine = (l, "", "", None)
 
 		return "".join(tupleLine[::2]), self.findFailure(
 			tupleLine, date, returnRawHost, checkAllRegex)
@@ -475,7 +477,7 @@ class Filter(JailThread):
 			self.__lastDate = date
 		elif timeText:
 
-			dateTimeMatch = self.dateDetector.getTime(timeText)
+			dateTimeMatch = self.dateDetector.getTime2(timeText, tupleLine[3])
 
 			if dateTimeMatch is None:
 				logSys.error("findFailure failed to parse timeText: " + timeText)
@@ -492,7 +494,7 @@ class Filter(JailThread):
 			date = self.__lastDate
 
 		self.__lineBuffer = (
-			self.__lineBuffer + [tupleLine])[-self.__lineBufferSize:]
+			self.__lineBuffer + [tupleLine[:3]])[-self.__lineBufferSize:]
 		logSys.log(5, "Looking for failregex match of %r" % self.__lineBuffer)
 
 		# Iterates over all the regular expressions.
@@ -731,9 +733,9 @@ class FileFilter(Filter):
 					break
 				llen += len(line)
 				l = line.rstrip('\r\n')
-				timeMatch = self.dateDetector.matchTime(l)
+				(timeMatch, template) = self.dateDetector.matchTime(l)
 				if timeMatch:
-					dateTimeMatch = self.dateDetector.getTime(l[timeMatch.start():timeMatch.end()])
+					dateTimeMatch = self.dateDetector.getTime2(l[timeMatch.start():timeMatch.end()], (timeMatch, template))
 				if not dateTimeMatch and lncntr:
 					lncntr -= 1
 					continue

fail2ban/server/server.py

@@ -81,7 +81,7 @@ class Server:
 		self.flushLogs()
 
 	def start(self, sock, pidfile, force = False):
-		logSys.info("Starting Fail2ban v" + version.version)
+		logSys.info("Starting Fail2ban v%s", version.version)
 		
 		# Install signal handlers
 		signal.signal(signal.SIGTERM, self.__sigTERMhandler)
@@ -443,6 +443,7 @@ class Server:
 			logger.addHandler(hdlr)
 			# Does not display this message at startup.
 			if not self.__logTarget is None:
+				logSys.info("Start Fail2ban v%s", version.version)
 				logSys.info(
 					"Changed logging target to %s for Fail2ban v%s"
 					% ((target

fail2ban/tests/datedetectortestcase.py

@@ -106,6 +106,7 @@ class DateDetectorTest(unittest.TestCase):
 										 (not anchored, "bogus-prefix ")):
 				log = prefix + sdate + "[sshd] error: PAM: Authentication failure"
 
+				# with getTime:
 				logtime = self.__datedetector.getTime(log)
 				if should_match:
 					self.assertNotEqual(logtime, None, "getTime retrieved nothing: failure for %s, anchored: %r, log: %s" % ( sdate, anchored, log))
@@ -118,6 +119,20 @@ class DateDetectorTest(unittest.TestCase):
 						self.assertEqual(logMatch.group(), sdate)
 				else:
 					self.assertEqual(logtime, None, "getTime should have not matched for %r Got: %s" % (sdate, logtime))
+				# with matchTime and getTime2 (this combination used in filter) :
+				matchTime = self.__datedetector.matchTime(log)
+				logtime = self.__datedetector.getTime2(log, matchTime)
+				if should_match:
+					self.assertNotEqual(logtime, None, "getTime retrieved nothing: failure for %s, anchored: %r, log: %s" % ( sdate, anchored, log))
+					( logUnix, logMatch ) = logtime
+					self.assertEqual(logUnix, dateUnix, "getTime comparison failure for %s: \"%s\" is not \"%s\"" % (sdate, logUnix, dateUnix))
+					if sdate.startswith('audit('):
+						# yes, special case, the group only matches the number
+						self.assertEqual(logMatch.group(), '1106513999.000')
+					else:
+						self.assertEqual(logMatch.group(), sdate)
+				else:
+					self.assertEqual(logtime, None, "getTime should have not matched for %r Got: %s" % (sdate, logtime))
 
 	def testStableSortTemplate(self):
 		old_names = [x.name for x in self.__datedetector.templates]