trAvis - MANAGER

Edit File: datedetector.py

# emacs: -*- mode: python; py-indent-offset: 4; indent-tabs-mode: t -*-
# vi: set ft=python sts=4 ts=4 sw=4 noet :

# This file is part of Fail2Ban.
#
# Fail2Ban is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; either version 2 of the License, or
# (at your option) any later version.
#
# Fail2Ban is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with Fail2Ban; if not, write to the Free Software
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.

__author__ = "Cyril Jaquier and Fail2Ban Contributors"
__copyright__ = "Copyright (c) 2004 Cyril Jaquier"
__license__ = "GPL"

import copy
import time

from threading import Lock

from .datetemplate import re, DateTemplate, DatePatternRegex, DateTai64n, DateEpoch, \
	RE_EPOCH_PATTERN
from .strptime import validateTimeZone
from .utils import Utils
from ..helpers import getLogger

# Gets the instance of the logger.
logSys = getLogger(__name__)

logLevel = 6

RE_DATE_PREMATCH = re.compile(r"(?<!\\)\{DATE\}", re.IGNORECASE)
DD_patternCache = Utils.Cache(maxCount=1000, maxTime=60*60)

def _getPatternTemplate(pattern, key=None):
	if key is None:
		key = pattern
		if '%' not in pattern:
			key = pattern.upper()
	template = DD_patternCache.get(key)

if not template:
		if "EPOCH" in key:
			if RE_EPOCH_PATTERN.search(pattern):
				template = DateEpoch(pattern=pattern, longFrm="LEPOCH" in key)
			elif key in ("EPOCH", "{^LN-BEG}EPOCH", "^EPOCH"):
				template = DateEpoch(lineBeginOnly=(key != "EPOCH"))
			elif key in ("LEPOCH", "{^LN-BEG}LEPOCH", "^LEPOCH"):
				template = DateEpoch(lineBeginOnly=(key != "LEPOCH"), longFrm=True)
		if template is None:
			if key in ("TAI64N", "{^LN-BEG}TAI64N", "^TAI64N"):
				template = DateTai64n(wordBegin=('start' if key != "TAI64N" else False))
			else:
				template = DatePatternRegex(pattern)

DD_patternCache.set(key, template)
	return template

def _getAnchoredTemplate(template, wrap=lambda s: '{^LN-BEG}' + s):
	# wrap name:
	name = wrap(template.name)
	# try to find in cache (by name):
	template2 = DD_patternCache.get(name)
	if not template2:
		# wrap pattern (or regexp if not pattern template):
		regex = wrap(getattr(template, 'pattern', template.regex))
		if hasattr(template, 'pattern'):
			# try to find in cache (by pattern):
			template2 = DD_patternCache.get(regex)
		# make duplicate and set new anchored regex:
		if not template2:
			if not hasattr(template, 'pattern'):
				template2 = _getPatternTemplate(name)
			else:
				template2 = _getPatternTemplate(regex)
	return template2

class DateDetectorCache(object):
	"""Implements the caching of the default templates list.
	"""
	def __init__(self):
		self.__lock = Lock()
		self.__templates = list()

@property
	def templates(self):
		"""List of template instances managed by the detector.
		"""
		if self.__templates:
			return self.__templates
		with self.__lock:
			if self.__templates: # pragma: no cover - race-condition + multi-threaded environment only
				return self.__templates
			self._addDefaultTemplate()
			return self.__templates

def _cacheTemplate(self, template):
		"""Cache Fail2Ban's default template.

"""
		# if not already line-begin anchored, additional template, that prefers datetime 
		# at start of a line (safety+performance feature):
		name = template.name
		if not name.startswith('{^LN-BEG}') and not name.startswith('^') and hasattr(template, 'regex'):
			template2 = _getAnchoredTemplate(template)
			# prevent to add duplicates:
			if template2.name != name:
				# increase weight of such templates, because they should be always
				# preferred in template sorting process (bubble up):
				template2.weight = 100.0
				self.__tmpcache[0].append(template2)
		# add template:
		self.__tmpcache[1].append(template)

DEFAULT_TEMPLATES = [
		# ISO 8601, simple date, optional subsecond and timezone:
		# 2005-01-23T21:59:59.981746, 2005-01-23 21:59:59, 2005-01-23  8:59:59
		# simple date: 2005/01/23 21:59:59 
		# custom for syslog-ng 2006.12.21 06:43:20
		r"%ExY(?P<_sep>[-/.])%m(?P=_sep)%d(?:T|  ?)%H:%M:%S(?:[.,]%f)?(?:\s*%z)?",
		# asctime with optional day, subsecond and/or year:
		# Sun Jan 23 21:59:59.011 2005 
		r"(?:%a )?%b %d %k:%M:%S(?:\.%f)?(?: %ExY)?",
		# asctime with optional day, subsecond and/or year coming after day
		# http://bugs.debian.org/798923
		# Sun Jan 23 2005 21:59:59.011
		r"(?:%a )?%b %d %ExY %k:%M:%S(?:\.%f)?",
		# simple date too (from x11vnc): 23/01/2005 21:59:59 
		# and with optional year given by 2 digits: 23/01/05 21:59:59 
		# (See http://bugs.debian.org/537610)
		# 17-07-2008 17:23:25
		r"%d(?P<_sep>[-/])%m(?P=_sep)(?:%ExY|%Exy) %k:%M:%S",
		# Apache format optional time zone:
		# [31/Oct/2006:09:22:55 -0000]
		# 26-Jul-2007 15:20:52
		# named 26-Jul-2007 15:20:52.252
		# roundcube 26-Jul-2007 15:20:52 +0200
		r"%d(?P<_sep>[-/])%b(?P=_sep)%ExY[ :]?%H:%M:%S(?:\.%f)?(?: %z)?",
		# CPanel 05/20/2008:01:57:39
		r"%m/%d/%ExY:%H:%M:%S",
		# 01-27-2012 16:22:44.252
		# subseconds explicit to avoid possible %m<->%d confusion
		# with previous ("%d-%m-%ExY %k:%M:%S" by "%d(?P<_sep>[-/])%m(?P=_sep)(?:%ExY|%Exy) %k:%M:%S")
		r"%m-%d-%ExY %k:%M:%S(?:\.%f)?",
		# Epoch
		r"EPOCH",
		# Only time information in the log
		r"{^LN-BEG}%H:%M:%S",
		# <09/16/08@05:03:30>
		r"^<%m/%d/%Exy@%H:%M:%S>",
		# MySQL: 130322 11:46:11
		r"%Exy%Exm%Exd  ?%H:%M:%S",
		# Apache Tomcat
		r"%b %d, %ExY %I:%M:%S %p",
		# ASSP: Apr-27-13 02:33:06
		r"^%b-%d-%Exy %k:%M:%S",
		# 20050123T215959, 20050123 215959, 20050123  85959
		r"%ExY%Exm%Exd(?:T|  ?)%ExH%ExM%ExS(?:[.,]%f)?(?:\s*%z)?",
		# prefixed with optional named time zone (monit):
		# PDT Apr 16 21:05:29
		r"(?:%Z )?(?:%a )?%b %d %k:%M:%S(?:\.%f)?(?: %ExY)?",
		# +00:00 Jan 23 21:59:59.011 2005 
		r"(?:%z )?(?:%a )?%b %d %k:%M:%S(?:\.%f)?(?: %ExY)?",
		# TAI64N
		r"TAI64N",
	]

@property
	def defaultTemplates(self):
		if isinstance(DateDetectorCache.DEFAULT_TEMPLATES[0], str):
			for i, dt in enumerate(DateDetectorCache.DEFAULT_TEMPLATES):
				dt = _getPatternTemplate(dt)
				DateDetectorCache.DEFAULT_TEMPLATES[i] = dt
		return DateDetectorCache.DEFAULT_TEMPLATES

def _addDefaultTemplate(self):
		"""Add resp. cache Fail2Ban's default set of date templates.
		"""
		self.__tmpcache = [], []
		# cache default templates:
		for dt in self.defaultTemplates:
			self._cacheTemplate(dt)
		#
		self.__templates = self.__tmpcache[0] + self.__tmpcache[1]
		del self.__tmpcache

class DateDetectorTemplate(object):
	"""Used for "shallow copy" of the template object.

Prevents collectively usage of hits/lastUsed in cached templates
	"""
	__slots__ = ('template', 'hits', 'lastUsed', 'distance')
	def __init__(self, template):
		self.template = template
		self.hits = 0
		self.lastUsed = 0
		# the last distance to date-match within the log file:
		self.distance = 0x7fffffff

@property
	def weight(self):
		return self.hits * self.template.weight / max(1, self.distance)

def __getattr__(self, name):
		""" Returns attribute of template (called for parameters not in slots)
		"""
		return getattr(self.template, name)

class DateDetector(object):
	"""Manages one or more date templates to find a date within a log line.

Attributes
	----------
	templates
	"""
	_defCache = DateDetectorCache()

def __init__(self):
		self.__templates = list()
		self.__known_names = set()
		# time the template was long unused (currently 300 == 5m):
		self.__unusedTime = 300
		# last known distance (bypass one char collision) and end position:
		self.__lastPos = 1, None
		self.__lastEndPos = 0x7fffffff, None
		self.__lastTemplIdx = 0x7fffffff
		# first free place:
		self.__firstUnused = 0
		# pre-match pattern:
		self.__preMatch = None
		# default TZ (if set, treat log lines without explicit time zone to be in this time zone):
		self.__default_tz = None

def _appendTemplate(self, template, ignoreDup=False):
		name = template.name
		if name in self.__known_names:
			if ignoreDup: return
			raise ValueError(
				"There is already a template with name %s" % name)
		self.__known_names.add(name)
		self.__templates.append(DateDetectorTemplate(template))

def appendTemplate(self, template):
		"""Add a date template to manage and use in search of dates.

Parameters
		----------
		template : DateTemplate or str
			Can be either a `DateTemplate` instance, or a string which will
			be used as the pattern for the `DatePatternRegex` template. The
			template will then be added to the detector.

Raises
		------
		ValueError
			If a template already exists with the same name.
		"""
		if isinstance(template, str):
			key = pattern = template
			if '%' not in pattern:
				key = pattern.upper()
			template = DD_patternCache.get(key)
			if not template:
				if key in ("{^LN-BEG}", "{DEFAULT}"):
					flt = \
						lambda template: template.flags & DateTemplate.LINE_BEGIN if key == "{^LN-BEG}" else None
					self.addDefaultTemplate(flt)
					return
				elif "{DATE}" in key:
					self.addDefaultTemplate(preMatch=pattern, allDefaults=False)
					return
				elif key == "{NONE}":
					template = _getPatternTemplate('{UNB}^', key)
				else:
					template = _getPatternTemplate(pattern, key)

DD_patternCache.set(key, template)

self._appendTemplate(template)
		logSys.info("  date pattern `%r`: `%s`",
			getattr(template, 'pattern', ''), template.name)
		logSys.debug("  date pattern regex for %r: %s",
			getattr(template, 'pattern', ''), template.regex)

def addDefaultTemplate(self, filterTemplate=None, preMatch=None, allDefaults=True):
		"""Add Fail2Ban's default set of date templates.
		"""
		ignoreDup = len(self.__templates) > 0
		for template in (
			DateDetector._defCache.templates if allDefaults else DateDetector._defCache.defaultTemplates
		):
			# filter if specified:
			if filterTemplate is not None and not filterTemplate(template): continue
			# if exact pattern available - create copy of template, contains replaced {DATE} with default regex:
			if preMatch is not None:
				# get cached or create a copy with modified name/pattern, using preMatch replacement for {DATE}:
				template = _getAnchoredTemplate(template,
					wrap=lambda s: RE_DATE_PREMATCH.sub(lambda m: DateTemplate.unboundPattern(s), preMatch))
			# append date detector template (ignore duplicate if some was added before default):
			self._appendTemplate(template, ignoreDup=ignoreDup)

@property
	def templates(self):
		"""List of template instances managed by the detector.
		"""
		return self.__templates

def matchTime(self, line):
		"""Attempts to find date on a log line using templates.

This uses the templates' `matchDate` method in an attempt to find
		a date. It also increments the match hit count for the winning
		template.

Parameters
		----------
		line : str
			Line which is searched by the date templates.

Returns
		-------
		re.MatchObject, DateTemplate
			The regex match returned from the first successfully matched
			template.
		"""
		# if no templates specified - default templates should be used:
		if not len(self.__templates):
			self.addDefaultTemplate()
		log = logSys.log if logSys.getEffectiveLevel() <= logLevel else lambda *args: None
		log(logLevel-1, "try to match time for line: %.120s", line)

# first try to use last template with same start/end position:
		match = None
		found = None, 0x7fffffff, 0x7fffffff, -1
		ignoreBySearch = 0x7fffffff
		i = self.__lastTemplIdx
		if i < len(self.__templates):
			ddtempl = self.__templates[i]
			template = ddtempl.template
			if template.flags & (DateTemplate.LINE_BEGIN|DateTemplate.LINE_END):
				log(logLevel-1, "  try to match last anchored template #%02i ...", i)
				match = template.matchDate(line)
				ignoreBySearch = i
			else:
				distance, endpos = self.__lastPos[0], self.__lastEndPos[0]
				log(logLevel-1, "  try to match last template #%02i (from %r to %r): ...%r==%r %s %r==%r...",
					i, distance, endpos,
					line[distance-1:distance], self.__lastPos[1],
					line[distance:endpos],
					line[endpos:endpos+1], self.__lastEndPos[2])
				# check same boundaries left/right, outside fully equal, inside only if not alnum (e. g. bound RE
				# with space or some special char), otherwise possible collision/pattern switch:
				if ((
					line[distance-1:distance] == self.__lastPos[1] or
						(line[distance] == self.__lastPos[2] and not self.__lastPos[2].isalnum())
					) and (
					line[endpos:endpos+1] == self.__lastEndPos[2] or
						(line[endpos-1] == self.__lastEndPos[1] and not self.__lastEndPos[1].isalnum())
				)):
					# search in line part only:
					log(logLevel-1, "  boundaries are correct, search in part %r", line[distance:endpos])
					match = template.matchDate(line, distance, endpos)
				else:
					log(logLevel-1, "  boundaries show conflict, try whole search")
					match = template.matchDate(line)
					ignoreBySearch = i
			if match:
				distance = match.start()
				endpos = match.end()
				# if different position, possible collision/pattern switch:
				if (
					len(self.__templates) == 1 or # single template:
					template.flags & (DateTemplate.LINE_BEGIN|DateTemplate.LINE_END) or 
					(distance == self.__lastPos[0] and endpos == self.__lastEndPos[0])
				):
					log(logLevel, "  matched last time template #%02i", i)
				else:
					log(logLevel, "  ** last pattern collision - pattern change, reserve & search ...")
					found = match, distance, endpos, i; # save current best alternative
					match = None
			else:
				log(logLevel, "  ** last pattern not found - pattern change, search ...")
		# search template and better match:
		if not match:
			log(logLevel, " search template (%i) ...", len(self.__templates))
			i = 0
			for ddtempl in self.__templates:
				if i == ignoreBySearch:
					i += 1
					continue
				log(logLevel-1, "  try template #%02i: %s", i, ddtempl.name)
				template = ddtempl.template
				match = template.matchDate(line)
				if match:
					distance = match.start()
					endpos = match.end()
					log(logLevel, "  matched time template #%02i (at %r <= %r, %r) %s",
						i, distance, ddtempl.distance, self.__lastPos[0], template.name)
					## last (or single) template - fast stop:
					if i+1 >= len(self.__templates):
						break
					## if line-begin/end anchored - stop searching:
					if template.flags & (DateTemplate.LINE_BEGIN|DateTemplate.LINE_END):
						break
					## stop searching if next template still unused, but we had already hits:
					if (distance == 0 and ddtempl.hits) and not self.__templates[i+1].template.hits:
						break
					## [grave] if distance changed, possible date-match was found somewhere 
					## in body of message, so save this template, and search further:
					if distance > ddtempl.distance or distance > self.__lastPos[0]:
						log(logLevel, "  ** distance collision - pattern change, reserve")
						## shortest of both:
						if distance < found[1]:
							found = match, distance, endpos, i
						## search further:
						match = None
						i += 1
						continue
					## winner - stop search:
					break
				i += 1
			# check other template was found (use this one with shortest distance):
			if not match and found[0]:
				match, distance, endpos, i = found
				log(logLevel, "  use best time template #%02i", i)
				ddtempl = self.__templates[i]
				template = ddtempl.template
		# we've winner, incr hits, set distance, usage, reorder, etc:
		if match:
			ddtempl.hits += 1
			ddtempl.lastUsed = time.time()
			ddtempl.distance = distance
			if self.__firstUnused == i:
				self.__firstUnused += 1
			self.__lastPos = distance, line[distance-1:distance], line[distance]
			self.__lastEndPos = endpos, line[endpos-1], line[endpos:endpos+1]
			# if not first - try to reorder current template (bubble up), they will be not sorted anymore:
			if i and i != self.__lastTemplIdx:
				i = self._reorderTemplate(i)
			self.__lastTemplIdx = i
			# return tuple with match and template reference used for parsing:
			return (match, template)

# not found:
		log(logLevel, " no template.")
		return (None, None)

@property
	def default_tz(self):
		return self.__default_tz

@default_tz.setter
	def default_tz(self, value):
		self.__default_tz = validateTimeZone(value)

def getTime(self, line, timeMatch=None):
		"""Attempts to return the date on a log line using templates.

This uses the templates' `getDate` method in an attempt to find
		a date. 
		For the faster usage, always specify a parameter timeMatch (the previous tuple result
		of the matchTime), then this will work without locking and without cycle over templates.

Parameters
		----------
		line : str
			Line which is searched by the date templates.

Returns
		-------
		float
			The Unix timestamp returned from the first successfully matched
			template or None if not found.
		"""
		# search match for all specified templates:
		if timeMatch is None:
			timeMatch = self.matchTime(line)
		# convert:
		template = timeMatch[1]
		if template is not None:
			try:
				date = template.getDate(line, timeMatch[0], default_tz=self.__default_tz)
				if date is not None:
					if logSys.getEffectiveLevel() <= logLevel: # pragma: no cover - heavy debug
						logSys.log(logLevel, "  got time %f for %r using template %s",
							date[0], date[1].group(1), template.name)
					return date
			except ValueError:
				pass
		return None

def _reorderTemplate(self, num):
		"""Reorder template (bubble up) in template list if hits grows enough.

Parameters
		----------
		num : int
			Index of template should be moved.
		"""
		if num:
			templates = self.__templates
			ddtempl = templates[num]
			if logSys.getEffectiveLevel() <= logLevel:
				logSys.log(logLevel, "  -> reorder template #%02i, hits: %r", num, ddtempl.hits)
		  ## current hits and time the template was long unused:
			untime = ddtempl.lastUsed - self.__unusedTime
			weight = ddtempl.weight
			## try to move faster (first if unused available, or half of part to current template position):
			pos = self.__firstUnused if self.__firstUnused < num else num // 2
			## don't move too often (multiline logs resp. log's with different date patterns),
			## if template not used too long, replace it also :
			def _moveable():
				pweight = templates[pos].weight
				if logSys.getEffectiveLevel() <= logLevel:
					logSys.log(logLevel, "  -> compare template #%02i & #%02i, weight %.3f > %.3f, hits %r > %r",
						num, pos, weight, pweight, ddtempl.hits, templates[pos].hits)
				return weight > pweight or untime > templates[pos].lastUsed
			##
			## if not moveable (smaller weight or target position recently used):
			if not _moveable():
				## try to move slow (exact 1 position):
				if pos == num-1:
					return num				
				pos = num-1
				## if still smaller and template at position used, don't move:
				if not _moveable():
					return num				
			## move:
			del templates[num]
			templates[pos:0] = [ddtempl]
			## correct first unused:
			while self.__firstUnused < len(templates) and templates[self.__firstUnused].hits:
				self.__firstUnused += 1
			if logSys.getEffectiveLevel() <= logLevel:
				logSys.log(logLevel, "  -> moved template #%02i -> #%02i", num, pos)
			return pos
		return num