From 4766547e1f9a9311e9534459633bd9687d37af68 Mon Sep 17 00:00:00 2001 From: sebres Date: Fri, 28 Feb 2020 11:49:43 +0100 Subject: [PATCH 1/2] performance optimization of `datepattern` (better search algorithm); datetemplate: improved anchor detection for capturing groups `(^...)`; introduced new prefix `{UNB}` for `datepattern` to disable word boundaries in regex; datedetector: speedup special case if only one template is defined (every match wins - no collision, no sorting, no other best match possible) --- ChangeLog | 3 ++ fail2ban/server/datedetector.py | 69 +++++++++++++++----------- fail2ban/server/datetemplate.py | 21 +++++--- fail2ban/tests/datedetectortestcase.py | 21 ++++++++ 4 files changed, 78 insertions(+), 36 deletions(-) diff --git a/ChangeLog b/ChangeLog index 007e4ffc..2bb07385 100644 --- a/ChangeLog +++ b/ChangeLog @@ -37,6 +37,9 @@ ver. 0.10.6-dev (20??/??/??) - development edition ### New Features ### Enhancements +* introduced new prefix `{UNB}` for `datepattern` to disable word boundaries in regex; +* datetemplate: improved anchor detection for capturing groups `(^...)`; +* performance optimization of `datepattern` (better search algorithm in datedetector, especially for single template); ver. 0.10.5 (2020/01/10) - deserve-more-respect-a-jedis-weapon-must diff --git a/fail2ban/server/datedetector.py b/fail2ban/server/datedetector.py index 5942e3e0..0a6451be 100644 --- a/fail2ban/server/datedetector.py +++ b/fail2ban/server/datedetector.py @@ -337,65 +337,76 @@ class DateDetector(object): # if no templates specified - default templates should be used: if not len(self.__templates): self.addDefaultTemplate() - logSys.log(logLevel-1, "try to match time for line: %.120s", line) - match = None + 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): - if logSys.getEffectiveLevel() <= logLevel-1: # pragma: no cover - very-heavy debug - logSys.log(logLevel-1, " try to match last anchored template #%02i ...", i) + 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] - if logSys.getEffectiveLevel() <= logLevel-1: - logSys.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[1]) - # check same boundaries left/right, otherwise possible collision/pattern switch: - if (line[distance-1:distance] == self.__lastPos[1] and - line[endpos:endpos+1] == self.__lastEndPos[1] - ): + 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]) ): - logSys.log(logLevel, " matched last time template #%02i", i) + log(logLevel, " matched last time template #%02i", i) else: - logSys.log(logLevel, " ** last pattern collision - pattern change, search ...") + log(logLevel, " ** last pattern collision - pattern change, reserve & search ...") + found = match, distance, endpos, i; # save current best alternative match = None else: - logSys.log(logLevel, " ** last pattern not found - pattern change, search ...") + log(logLevel, " ** last pattern not found - pattern change, search ...") # search template and better match: if not match: - logSys.log(logLevel, " search template (%i) ...", len(self.__templates)) - found = None, 0x7fffffff, 0x7fffffff, -1 + log(logLevel, " search template (%i) ...", len(self.__templates)) i = 0 for ddtempl in self.__templates: - if logSys.getEffectiveLevel() <= logLevel-1: - logSys.log(logLevel-1, " try template #%02i: %s", i, ddtempl.name) 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() - if logSys.getEffectiveLevel() <= logLevel: - logSys.log(logLevel, " matched time template #%02i (at %r <= %r, %r) %s", - i, distance, ddtempl.distance, self.__lastPos[0], template.name) + 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 @@ -408,7 +419,7 @@ class DateDetector(object): ## [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]: - logSys.log(logLevel, " ** distance collision - pattern change, reserve") + log(logLevel, " ** distance collision - pattern change, reserve") ## shortest of both: if distance < found[1]: found = match, distance, endpos, i @@ -422,7 +433,7 @@ class DateDetector(object): # check other template was found (use this one with shortest distance): if not match and found[0]: match, distance, endpos, i = found - logSys.log(logLevel, " use best time template #%02i", i) + 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: @@ -432,8 +443,8 @@ class DateDetector(object): ddtempl.distance = distance if self.__firstUnused == i: self.__firstUnused += 1 - self.__lastPos = distance, line[distance-1:distance] - self.__lastEndPos = endpos, line[endpos:endpos+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) @@ -442,7 +453,7 @@ class DateDetector(object): return (match, template) # not found: - logSys.log(logLevel, " no template.") + log(logLevel, " no template.") return (None, None) @property diff --git a/fail2ban/server/datetemplate.py b/fail2ban/server/datetemplate.py index 973a8a51..a198e4ed 100644 --- a/fail2ban/server/datetemplate.py +++ b/fail2ban/server/datetemplate.py @@ -36,15 +36,16 @@ logSys = getLogger(__name__) RE_GROUPED = re.compile(r'(? Date: Mon, 2 Mar 2020 17:05:00 +0100 Subject: [PATCH 2/2] failmanager, ticket: avoid reset of retry count by pause between attempts near to findTime - adjust time of ticket will now change current attempts considering findTime as an estimation from rate by previous known interval (if it exceeds the findTime); this should avoid some false positives as well as provide more safe handling around `maxretry/findtime` relation especially on busy circumstances. --- fail2ban/server/failmanager.py | 9 +++---- fail2ban/server/ticket.py | 43 ++++++++++++++++---------------- fail2ban/tests/tickettestcase.py | 28 +++++++++++++-------- 3 files changed, 42 insertions(+), 38 deletions(-) diff --git a/fail2ban/server/failmanager.py b/fail2ban/server/failmanager.py index 80a6414a..eee979fd 100644 --- a/fail2ban/server/failmanager.py +++ b/fail2ban/server/failmanager.py @@ -92,10 +92,7 @@ class FailManager: if attempt <= 0: attempt += 1 unixTime = ticket.getTime() - fData.setLastTime(unixTime) - if fData.getLastReset() < unixTime - self.__maxTime: - fData.setLastReset(unixTime) - fData.setRetry(0) + fData.adjustTime(unixTime, self.__maxTime) fData.inc(matches, attempt, count) # truncate to maxMatches: if self.maxMatches: @@ -136,7 +133,7 @@ class FailManager: def cleanup(self, time): with self.__lock: todelete = [fid for fid,item in self.__failList.iteritems() \ - if item.getLastTime() + self.__maxTime <= time] + if item.getTime() + self.__maxTime <= time] if len(todelete) == len(self.__failList): # remove all: self.__failList = dict() @@ -150,7 +147,7 @@ class FailManager: else: # create new dictionary without items to be deleted: self.__failList = dict((fid,item) for fid,item in self.__failList.iteritems() \ - if item.getLastTime() + self.__maxTime > time) + if item.getTime() + self.__maxTime > time) self.__bgSvc.service() def delFailure(self, fid): diff --git a/fail2ban/server/ticket.py b/fail2ban/server/ticket.py index 4f509ea9..8feeac9a 100644 --- a/fail2ban/server/ticket.py +++ b/fail2ban/server/ticket.py @@ -218,21 +218,20 @@ class FailTicket(Ticket): def __init__(self, ip=None, time=None, matches=None, data={}, ticket=None): # this class variables: - self.__retry = 0 - self.__lastReset = None + self._firstTime = None + self._retry = 1 # create/copy using default ticket constructor: Ticket.__init__(self, ip, time, matches, data, ticket) # init: - if ticket is None: - self.__lastReset = time if time is not None else self.getTime() - if not self.__retry: - self.__retry = self._data['failures']; + if not isinstance(ticket, FailTicket): + self._firstTime = time if time is not None else self.getTime() + self._retry = self._data.get('failures', 1) def setRetry(self, value): """ Set artificial retry count, normally equal failures / attempt, used in incremental features (BanTimeIncr) to increase retry count for bad IPs """ - self.__retry = value + self._retry = value if not self._data['failures']: self._data['failures'] = 1 if not value: @@ -243,10 +242,23 @@ class FailTicket(Ticket): """ Returns failures / attempt count or artificial retry count increased for bad IPs """ - return max(self.__retry, self._data['failures']) + return self._retry + + def adjustTime(self, time, maxTime): + """ Adjust time of ticket and current attempts count considering given maxTime + as estimation from rate by previous known interval (if it exceeds the findTime) + """ + if time > self._time: + # expand current interval and attemps count (considering maxTime): + if self._firstTime < time - maxTime: + # adjust retry calculated as estimation from rate by previous known interval: + self._retry = int(round(self._retry / float(time - self._firstTime) * maxTime)) + self._firstTime = time - maxTime + # last time of failure: + self._time = time def inc(self, matches=None, attempt=1, count=1): - self.__retry += count + self._retry += count self._data['failures'] += attempt if matches: # we should duplicate "matches", because possibly referenced to multiple tickets: @@ -255,19 +267,6 @@ class FailTicket(Ticket): else: self._data['matches'] = matches - def setLastTime(self, value): - if value > self._time: - self._time = value - - def getLastTime(self): - return self._time - - def getLastReset(self): - return self.__lastReset - - def setLastReset(self, value): - self.__lastReset = value - ## # Ban Ticket. # diff --git a/fail2ban/tests/tickettestcase.py b/fail2ban/tests/tickettestcase.py index 277c2f28..d7d5f19a 100644 --- a/fail2ban/tests/tickettestcase.py +++ b/fail2ban/tests/tickettestcase.py @@ -69,10 +69,10 @@ class TicketTests(unittest.TestCase): self.assertEqual(ft.getTime(), tm) self.assertEqual(ft.getMatches(), matches2) ft.setAttempt(2) - self.assertEqual(ft.getAttempt(), 2) - # retry is max of set retry and failures: - self.assertEqual(ft.getRetry(), 2) ft.setRetry(1) + self.assertEqual(ft.getAttempt(), 2) + self.assertEqual(ft.getRetry(), 1) + ft.setRetry(2) self.assertEqual(ft.getRetry(), 2) ft.setRetry(3) self.assertEqual(ft.getRetry(), 3) @@ -86,13 +86,21 @@ class TicketTests(unittest.TestCase): self.assertEqual(ft.getRetry(), 14) self.assertEqual(ft.getMatches(), matches3) # last time (ignore if smaller as time): - self.assertEqual(ft.getLastTime(), tm) - ft.setLastTime(tm-60) self.assertEqual(ft.getTime(), tm) - self.assertEqual(ft.getLastTime(), tm) - ft.setLastTime(tm+60) + ft.adjustTime(tm-60, 3600) + self.assertEqual(ft.getTime(), tm) + self.assertEqual(ft.getRetry(), 14) + ft.adjustTime(tm+60, 3600) self.assertEqual(ft.getTime(), tm+60) - self.assertEqual(ft.getLastTime(), tm+60) + self.assertEqual(ft.getRetry(), 14) + ft.adjustTime(tm+3600, 3600) + self.assertEqual(ft.getTime(), tm+3600) + self.assertEqual(ft.getRetry(), 14) + # adjust time so interval is larger than find time (3600), so reset retry count: + ft.adjustTime(tm+7200, 3600) + self.assertEqual(ft.getTime(), tm+7200) + self.assertEqual(ft.getRetry(), 7); # estimated attempts count + self.assertEqual(ft.getAttempt(), 4); # real known failure count ft.setData('country', 'DE') self.assertEqual(ft.getData(), {'matches': ['first', 'second', 'third'], 'failures': 4, 'country': 'DE'}) @@ -102,10 +110,10 @@ class TicketTests(unittest.TestCase): self.assertEqual(ft, ft2) self.assertEqual(ft.getData(), ft2.getData()) self.assertEqual(ft2.getAttempt(), 4) - self.assertEqual(ft2.getRetry(), 14) + self.assertEqual(ft2.getRetry(), 7) self.assertEqual(ft2.getMatches(), matches3) self.assertEqual(ft2.getTime(), ft.getTime()) - self.assertEqual(ft2.getLastTime(), ft.getLastTime()) + self.assertEqual(ft2.getTime(), ft.getTime()) self.assertEqual(ft2.getBanTime(), ft.getBanTime()) def testTicketFlags(self):