Merge branch 0.10-full with 0.10

Resolved several conflicts and code review after merge

ChangeLog

@@ -20,6 +20,9 @@ TODO: implementing of options resp. other tasks from PR #1346
 * testSocket: sporadical bug repaired - wait for server thread starts a socket (listener)
 * testExecuteTimeoutWithNastyChildren: sporadical bug repaired - wait for pid file inside bash,
   kill tree in any case (gh-1155)
+* purge database will be executed now (within observer).
+* restoring currently banned ip after service restart fixed 
+  (now < timeofban + bantime), ignore old log failures (already banned)
 * Fixed high-load of pyinotify-backend,
   see https://github.com/fail2ban/fail2ban/issues/885#issuecomment-248964591
 * Database: stability fix - repack cursor iterator as long as locked
@@ -41,6 +44,9 @@ TODO: implementing of options resp. other tasks from PR #1346
     - new conditional section functionality used in config resp. includes:
       - [Init?family=inet4] - IPv4 qualified hosts only
       - [Init?family=inet6] - IPv6 qualified hosts only
+* Increment ban time (+ observer) functionality introduced.
+  Thanks Serg G. Brester (sebres)
+* Database functionality extended with bad ips.
 * New reload functionality (now totally without restart, unbanning/rebanning, etc.),
   see gh-1557
 * Several commands extended and new commands introduced:

MANIFEST

@@ -195,6 +195,7 @@ fail2ban/server/jail.py
 fail2ban/server/jails.py
 fail2ban/server/jailthread.py
 fail2ban/server/mytime.py
+fail2ban/server/observer.py
 fail2ban/server/server.py
 fail2ban/server/strptime.py
 fail2ban/server/ticket.py
@@ -247,6 +248,7 @@ fail2ban/tests/files/config/apache-auth/digest_wrongrelm/.htpasswd
 fail2ban/tests/files/config/apache-auth/noentry/.htaccess
 fail2ban/tests/files/config/apache-auth/README
 fail2ban/tests/files/database_v1.db
+fail2ban/tests/files/database_v2.db
 fail2ban/tests/files/filter.d/substition.conf
 fail2ban/tests/files/filter.d/testcase01.conf
 fail2ban/tests/files/filter.d/testcase-common.conf
@@ -343,6 +345,7 @@ fail2ban/tests/files/testcase-wrong-char.log
 fail2ban/tests/filtertestcase.py
 fail2ban/tests/__init__.py
 fail2ban/tests/misctestcase.py
+fail2ban/tests/observertestcase.py
 fail2ban/tests/samplestestcase.py
 fail2ban/tests/servertestcase.py
 fail2ban/tests/sockettestcase.py

THANKS

@@ -109,7 +109,7 @@ Russell Odom
 SATO Kentaro
 Sean DuBois
 Sebastian Arcus
-Serg G. Brester
+Serg G. Brester (sebres)
 Sireyessire
 silviogarbes
 Stefan Tatschner

config/jail.conf

@@ -44,6 +44,44 @@ before = paths-debian.conf
 # MISCELLANEOUS OPTIONS
 #
 
+# "bantime.increment" allows to use database for searching of previously banned ip's to increase a 
+# default ban time using special formula, default it is banTime * 1, 2, 4, 8, 16, 32...
+#bantime.increment = true
+
+# "bantime.rndtime" is the max number of seconds using for mixing with random time 
+# to prevent "clever" botnets calculate exact time IP can be unbanned again:
+#bantime.rndtime = 
+
+# "bantime.maxtime" is the max number of seconds using the ban time can reach (don't grows further)
+#bantime.maxtime = 
+
+# "bantime.factor" is a coefficient to calculate exponent growing of the formula or common multiplier,
+# default value of factor is 1 and with default value of formula, the ban time 
+# grows by 1, 2, 4, 8, 16 ...
+#bantime.factor = 1
+
+# "bantime.formula" used by default to calculate next value of ban time, default value bellow,
+# the same ban time growing will be reached by multipliers 1, 2, 4, 8, 16, 32...
+#bantime.formula = ban.Time * (1<<(ban.Count if ban.Count<20 else 20)) * banFactor
+#
+# more aggressive example of formula has the same values only for factor "2.0 / 2.885385" :
+#bantime.formula = ban.Time * math.exp(float(ban.Count+1)*banFactor)/math.exp(1*banFactor)
+
+# "bantime.multipliers" used to calculate next value of ban time instead of formula, coresponding 
+# previously ban count and given "bantime.factor" (for multipliers default is 1);
+# following example grows ban time by 1, 2, 4, 8, 16 ... and if last ban count greater as multipliers count, 
+# always used last multiplier (64 in example), for factor '1' and original ban time 600 - 10.6 hours
+#bantime.multipliers = 1 2 4 8 16 32 64
+# following example can be used for small initial ban time (bantime=60) - it grows more aggressive at begin,
+# for bantime=60 the multipliers are minutes and equal: 1 min, 5 min, 30 min, 1 hour, 5 hour, 12 hour, 1 day, 2 day
+#bantime.multipliers = 1 5 30 60 300 720 1440 2880
+
+# "bantime.overalljails" (if true) specifies the search of IP in the database will be executed 
+# cross over all jails, if false (dafault), only current jail of the ban IP will be searched
+#bantime.overalljails = false
+
+# --------------------
+
 # "ignoreip" can be an IP address, a CIDR mask or a DNS host. Fail2ban will not
 # ban a host which matches an address in this list. Several addresses can be
 # defined using space (and/or comma) separator.

fail2ban/client/jailreader.py

@@ -106,6 +106,13 @@ class JailReader(ConfigReader):
 				["int",    "maxretry", None],
 				["string", "findtime", None],
 				["string", "bantime", None],
+				["bool",   "bantime.increment", None],
+				["string", "bantime.factor", None],
+				["string", "bantime.formula", None],
+				["string", "bantime.multipliers", None],
+				["string", "bantime.maxtime", None],
+				["string", "bantime.rndtime", None],
+				["bool",   "bantime.overalljails", None],
 				["string", "usedns", None], # be sure usedns is before all regex(s) in stream
 				["string", "failregex", None],
 				["string", "ignoreregex", None],
@@ -225,6 +232,8 @@ class JailReader(ConfigReader):
 				stream.append(["set", self.__name, "findtime", value])
 			elif opt == "bantime":
 				stream.append(["set", self.__name, "bantime", value])
+			elif opt.startswith("bantime."):
+				stream.append(["set", self.__name, opt, self.__opts[opt]])
 			elif opt == "usedns":
 				stream.append(["set", self.__name, "usedns", value])
 			elif opt in ("failregex", "ignoreregex"):

fail2ban/server/action.py

@@ -611,8 +611,5 @@ class CommandAction(ActionBase):
 			logSys.debug("Nothing to do")
 			return True
 
-		_cmd_lock.acquire()
+		with _cmd_lock:
-		try:
 			return Utils.executeCmd(realCmd, timeout, shell=True, output=False)
-		finally:
-			_cmd_lock.release()

fail2ban/server/actions.py

@@ -35,6 +35,7 @@ except ImportError:
 	OrderedDict = dict
 
 from .banmanager import BanManager
+from .observer import Observers
 from .jailthread import JailThread
 from .action import ActionBase, CommandAction, CallingMap
 from .mytime import MyTime
@@ -343,11 +344,20 @@ class Actions(JailThread, Mapping):
 				break
 			aInfo = CallingMap()
 			bTicket = BanManager.createBanTicket(ticket)
+			btime = ticket.getBanTime()
+			if btime is not None:
+				bTicket.setBanTime(btime)
+				bTicket.setBanCount(ticket.getBanCount())
+			else:
+				btime = self.__banManager.getBanTime()
+			if ticket.restored:
+				bTicket.restored = True
 			ip = bTicket.getIP()
 			aInfo["ip"] = ip
 			aInfo["failures"] = bTicket.getAttempt()
 			aInfo["time"] = bTicket.getTime()
 			aInfo["matches"] = "\n".join(bTicket.getMatches())
+			# retarded merge info via twice lambdas : once for merge, once for matches/failures:
 			if self._jail.database is not None:
 				mi4ip = lambda overalljails=False, self=self, \
 					mi={'ip':ip, 'ticket':bTicket}: self.__getBansMerged(mi, overalljails)
@@ -358,7 +368,11 @@ class Actions(JailThread, Mapping):
 			reason = {}
 			if self.__banManager.addBanTicket(bTicket, reason=reason):
 				cnt += 1
+				# report ticket to observer, to check time should be increased and hereafter observer writes ban to database (asynchronous)
+				if Observers.Main is not None and not bTicket.restored:
+					Observers.Main.add('banFound', bTicket, self._jail, btime)
 				logSys.notice("[%s] %sBan %s", self._jail.name, ('' if not bTicket.restored else 'Restore '), ip)
+				# do actions :
 				for name, action in self._actions.iteritems():
 					try:
 						action.ban(aInfo.copy())
@@ -371,7 +385,10 @@ class Actions(JailThread, Mapping):
 				# after all actions are processed set banned flag:
 				bTicket.banned = True
 			else:
-				bTicket = reason['ticket']
+				if reason.get('expired', 0):
+					logSys.info('[%s] Ignore %s, expired bantime', self._jail.name, ip)
+					continue
+				bTicket = reason.get('ticket', bTicket)
 				# if already banned (otherwise still process some action)
 				if bTicket.banned:
 					# compare time of failure occurrence with time ticket was really banned:

fail2ban/server/banmanager.py

@@ -267,6 +267,9 @@ class BanManager:
 	
 	def addBanTicket(self, ticket, reason={}):
 		eob = ticket.getEndOfBanTime(self.__banTime)
+		if eob < MyTime.time():
+			reason['expired'] = 1
+			return False
 		with self.__lock:
 			# check already banned
 			fid = ticket.getID()

fail2ban/server/database.py

@@ -126,7 +126,7 @@ class Fail2BanDb(object):
 	filename
 	purgeage
 	"""
-	__version__ = 2
+	__version__ = 4
 	# Note all _TABLE_* strings must end in ';' for py26 compatibility
 	_TABLE_fail2banDb = "CREATE TABLE fail2banDb(version INTEGER);"
 	_TABLE_jails = "CREATE TABLE jails(" \
@@ -153,6 +153,8 @@ class Fail2BanDb(object):
 			"jail TEXT NOT NULL, " \
 			"ip TEXT, " \
 			"timeofban INTEGER NOT NULL, " \
+			"bantime INTEGER NOT NULL, " \
+			"bancount INTEGER NOT NULL default 1, " \
 			"data JSON, " \
 			"FOREIGN KEY(jail) REFERENCES jails(name) " \
 			");" \
@@ -160,8 +162,21 @@ class Fail2BanDb(object):
 			"CREATE INDEX bans_jail_ip ON bans(jail, ip);" \
 			"CREATE INDEX bans_ip ON bans(ip);" \
 
+	_TABLE_bips = "CREATE TABLE bips(" \
+			"ip TEXT NOT NULL, " \
+			"jail TEXT NOT NULL, " \
+			"timeofban INTEGER NOT NULL, " \
+			"bantime INTEGER NOT NULL, " \
+			"bancount INTEGER NOT NULL default 1, " \
+			"data JSON, " \
+			"PRIMARY KEY(ip, jail), " \
+			"FOREIGN KEY(jail) REFERENCES jails(name) " \
+			");" \
+			"CREATE INDEX bips_timeofban ON bips(timeofban);" \
+			"CREATE INDEX bips_ip ON bips(ip);" \
 
-	def __init__(self, filename, purgeAge=24*60*60):
+
+	def __init__(self, filename, purgeAge=24*60*60, outDatedFactor=3):
 		self.maxEntries = 50
 		try:
 			self._lock = RLock()
@@ -170,6 +185,7 @@ class Fail2BanDb(object):
 				detect_types=sqlite3.PARSE_DECLTYPES)
 			self._dbFilename = filename
 			self._purgeAge = purgeAge
+			self._outDatedFactor = outDatedFactor;
 
 			self._bansMergedCache = {}
 
@@ -257,6 +273,8 @@ class Fail2BanDb(object):
 		cur.executescript(Fail2BanDb._TABLE_logs)
 		# Bans
 		cur.executescript(Fail2BanDb._TABLE_bans)
+		# BIPs (bad ips)
+		cur.executescript(Fail2BanDb._TABLE_bips)
 
 		cur.execute("SELECT version FROM fail2banDb LIMIT 1")
 		return cur.fetchone()[0]
@@ -285,6 +303,20 @@ class Fail2BanDb(object):
 						"UPDATE fail2banDb SET version = 2;"
 						"COMMIT;" % Fail2BanDb._TABLE_logs)
 
+		if version < 3:
+			cur.executescript("BEGIN TRANSACTION;"
+						"CREATE TEMPORARY TABLE bans_temp AS SELECT jail, ip, timeofban, 600 as bantime, 1 as bancount, data FROM bans;"
+						"DROP TABLE bans;"
+						"%s;"
+						"INSERT INTO bans SELECT * from bans_temp;"
+						"DROP TABLE bans_temp;"
+						"COMMIT;" % Fail2BanDb._TABLE_bans)
+		if version < 4:
+			cur.executescript("BEGIN TRANSACTION;"
+						"%s;"
+						"UPDATE fail2banDb SET version = 4;"
+						"COMMIT;" % Fail2BanDb._TABLE_bips)
+
 		cur.execute("SELECT version FROM fail2banDb LIMIT 1")
 		return cur.fetchone()[0]
 
@@ -445,9 +477,13 @@ class Fail2BanDb(object):
 			pass
 		#TODO: Implement data parts once arbitrary match keys completed
 		cur.execute(
-			"INSERT INTO bans(jail, ip, timeofban, data) VALUES(?, ?, ?, ?)",
+			"INSERT INTO bans(jail, ip, timeofban, bantime, bancount, data) VALUES(?, ?, ?, ?, ?, ?)",
-			(jail.name, ip, int(round(ticket.getTime())),
+			(jail.name, ip, int(round(ticket.getTime())), ticket.getBanTime(jail.actions.getBanTime()), ticket.getBanCount(),
 				ticket.getData()))
+		cur.execute(
+			"INSERT OR REPLACE INTO bips(ip, jail, timeofban, bantime, bancount, data) VALUES(?, ?, ?, ?, ?, ?)",
+			(ip, jail.name, int(round(ticket.getTime())), ticket.getBanTime(jail.actions.getBanTime()), ticket.getBanCount(),
+				{"matches": ticket.getMatches(), "failures": ticket.getAttempt()}))
 
 	@commitandrollback
 	def delBan(self, cur, jail, ip):
@@ -461,6 +497,9 @@ class Fail2BanDb(object):
 			IP to be removed.
 		"""
 		queryArgs = (jail.name, str(ip));
+		cur.execute(
+			"DELETE FROM bips WHERE jail = ? AND ip = ?", 
+			queryArgs)
 		cur.execute(
 			"DELETE FROM bans WHERE jail = ? AND ip = ?", 
 			queryArgs);
@@ -618,6 +657,93 @@ class Fail2BanDb(object):
 
 		return tickets if ip is None else ticket
 
+	@commitandrollback
+	def getBan(self, cur, ip, jail=None, forbantime=None, overalljails=None, fromtime=None):
+		ip = str(ip)
+		if not overalljails:
+			query = "SELECT bancount, timeofban, bantime FROM bips"
+		else:
+			query = "SELECT sum(bancount), max(timeofban), sum(bantime) FROM bips"
+		query += " WHERE ip = ?"
+		queryArgs = [ip]
+		if not overalljails and jail is not None:
+			query += " AND jail=?"
+			queryArgs.append(jail.name)
+		if forbantime is not None:
+			query += " AND timeofban > ?"
+			queryArgs.append(MyTime.time() - forbantime)
+		if fromtime is not None:
+			query += " AND timeofban > ?"
+			queryArgs.append(fromtime)
+		if overalljails or jail is None:
+			query += " GROUP BY ip ORDER BY timeofban DESC LIMIT 1"
+		cur = self._db.cursor()
+		return cur.execute(query, queryArgs)
+
+	@commitandrollback
+	def _getCurrentBans(self, cur, jail = None, ip = None, forbantime=None, fromtime=None):
+		if fromtime is None:
+			fromtime = MyTime.time()
+		queryArgs = []
+		if jail is not None:
+			query = "SELECT ip, timeofban, bantime, bancount, data FROM bips WHERE jail=?"
+			queryArgs.append(jail.name)
+		else:
+			query = "SELECT ip, max(timeofban), bantime, bancount, data FROM bips WHERE 1"
+		if ip is not None:
+			query += " AND ip=?"
+			queryArgs.append(ip)
+		query += " AND (timeofban + bantime > ? OR bantime = -1)"
+		queryArgs.append(fromtime)
+		if forbantime is not None:
+			query += " AND timeofban > ?"
+			queryArgs.append(fromtime - forbantime)
+		if ip is None:
+			query += " GROUP BY ip ORDER BY ip, timeofban DESC"
+		cur = self._db.cursor()
+		return cur.execute(query, queryArgs)
+
+	def getCurrentBans(self, jail = None, ip = None, forbantime=None, fromtime=None):
+		tickets = []
+		ticket = None
+
+		results = list(self._getCurrentBans(jail=jail, ip=ip, forbantime=forbantime, fromtime=fromtime))
+
+		if results:
+			matches = []
+			failures = 0
+			for banip, timeofban, bantime, bancount, data in results:
+				#TODO: Implement data parts once arbitrary match keys completed
+				ticket = FailTicket(banip, timeofban, matches)
+				ticket.setAttempt(failures)
+				ticket.setBanTime(bantime)
+				ticket.setBanCount(bancount)
+				matches = []
+				failures = 0
+				matches.extend(data['matches'])
+				failures += data['failures']
+				ticket.setAttempt(failures)
+				tickets.append(ticket)
+
+		return tickets if ip is None else ticket
+
+	def _cleanjails(self, cur):
+		"""Remove empty jails jails and log files from database.
+		"""
+		cur.execute(
+			"DELETE FROM jails WHERE enabled = 0 "
+				"AND NOT EXISTS(SELECT * FROM bans WHERE jail = jails.name) "
+				"AND NOT EXISTS(SELECT * FROM bips WHERE jail = jails.name)")
+
+	def _purge_bips(self, cur):
+		"""Purge old bad ips (jails and log files from database).
+		Currently it is timed out IP, whose time since last ban is several times out-dated (outDatedFactor is default 3).
+		Permanent banned ips will be never removed.
+		"""
+		cur.execute(
+			"DELETE FROM bips WHERE timeofban < ? and bantime != -1 and (timeofban + (bantime * ?)) < ?",
+			(int(MyTime.time()) - self._purgeAge, self._outDatedFactor, int(MyTime.time()) - self._purgeAge))
+
 	@commitandrollback
 	def purge(self, cur):
 		"""Purge old bans, jails and log files from database.
@@ -626,7 +752,6 @@ class Fail2BanDb(object):
 		cur.execute(
 			"DELETE FROM bans WHERE timeofban < ?",
 			(MyTime.time() - self._purgeAge, ))
-		cur.execute(
+		self._purge_bips(cur)
-			"DELETE FROM jails WHERE enabled = 0 "
+		self._cleanjails(cur)
-				"AND NOT EXISTS(SELECT * FROM bans WHERE jail = jails.name)")
 

fail2ban/server/failmanager.py

@@ -75,7 +75,7 @@ class FailManager:
 	def getMaxTime(self):
 		return self.__maxTime
 
-	def addFailure(self, ticket, count=1):
+	def addFailure(self, ticket, count=1, observed=False):
 		attempts = 1
 		with self.__lock:
 			fid = ticket.getID()
@@ -102,6 +102,9 @@ class FailManager:
 				if len(matches) > self.maxEntries:
 					fData.setMatches(matches[-self.maxEntries:])
 			except KeyError:
+				# not found - already banned - prevent to add failure if comes from observer:
+				if observed:
+					return
 				# if already FailTicket - add it direct, otherwise create (using copy all ticket data):
 				if isinstance(ticket, FailTicket):
 					fData = ticket;

fail2ban/server/filter.py

@@ -32,6 +32,7 @@ import time
 
 from .failmanager import FailManagerEmpty, FailManager
 from .ipdns import DNSUtils, IPAddr
+from .observer import Observers
 from .ticket import FailTicket
 from .jailthread import JailThread
 from .datedetector import DateDetector
@@ -499,6 +500,9 @@ class Filter(JailThread):
 				)
 				tick = FailTicket(ip, unixTime, lines, data=fail)
 				self.failManager.addFailure(tick)
+				# report to observer - failure was found, for possibly increasing of it retry counter (asynchronous)
+				if Observers.Main is not None:
+					Observers.Main.add('failureFound', self.failManager, self.jail, tick)
 			# reset (halve) error counter (successfully processed line):
 			if self._errors:
 				self._errors //= 2

fail2ban/server/jail.py

@@ -24,11 +24,14 @@ __copyright__ = "Copyright (c) 2004 Cyril Jaquier, 2011-2012 Lee Clemens, 2012 Y
 __license__ = "GPL"
 
 import logging
+import math
+import random
 import Queue
 
 from .actions import Actions
 from ..client.jailreader import JailReader
 from ..helpers import getLogger, MyTime
+from .mytime import MyTime
 
 # Gets the instance of the logger.
 logSys = getLogger(__name__)
@@ -76,6 +79,8 @@ class Jail(object):
 		self.__name = name
 		self.__queue = Queue.Queue()
 		self.__filter = None
+		# Extra parameters for increase ban time
+		self._banExtra = {};
 		logSys.info("Creating new jail '%s'" % self.name)
 		if backend is not None:
 			self._setBackend(backend)
@@ -194,8 +199,8 @@ class Jail(object):
 		Used by filter to add a failure for banning.
 		"""
 		self.__queue.put(ticket)
-		if not ticket.restored and self.database is not None:
+		# add ban to database moved to observer (should previously check not already banned 
-			self.database.addBan(self, ticket)
+		# and increase ticket time if "bantime.increment" set)
 
 	def getFailTicket(self):
 		"""Get a fail ticket from the jail.
@@ -208,12 +213,66 @@ class Jail(object):
 		except Queue.Empty:
 			return False
 
+	def setBanTimeExtra(self, opt, value):
+		# merge previous extra with new option:
+		be = self._banExtra;
+		if value == '':
+			value = None
+		if value is not None:
+			be[opt] = value;
+		elif opt in be:
+			del be[opt]
+		logSys.info('Set banTime.%s = %s', opt, value)
+		if opt == 'increment':
+			if isinstance(value, str):
+				be[opt] = value.lower() in ("yes", "true", "ok", "1")
+			if be[opt] and self.database is None:
+				logSys.warning("ban time increment is not available as long jail database is not set")
+		if opt in ['maxtime', 'rndtime']:
+			if not value is None:
+				be[opt] = MyTime.str2seconds(value)
+		# prepare formula lambda:
+		if opt in ['formula', 'factor', 'maxtime', 'rndtime', 'multipliers'] or be.get('evformula', None) is None:
+			# split multifiers to an array begins with 0 (or empty if not set):
+			if opt == 'multipliers':
+				be['evmultipliers'] = [int(i) for i in (value.split(' ') if value is not None and value != '' else [])]
+			# if we have multifiers - use it in lambda, otherwise compile and use formula within lambda
+			multipliers = be.get('evmultipliers', [])
+			banFactor = eval(be.get('factor', "1"))
+			if len(multipliers):
+				evformula = lambda ban, banFactor=banFactor: (
+					ban.Time * banFactor * multipliers[ban.Count if ban.Count < len(multipliers) else -1]
+				)
+			else:
+				formula = be.get('formula', 'ban.Time * (1<<(ban.Count if ban.Count<20 else 20)) * banFactor')
+				formula = compile(formula, '~inline-conf-expr~', 'eval')
+				evformula = lambda ban, banFactor=banFactor, formula=formula: max(ban.Time, eval(formula))
+			# extend lambda with max time :
+			if not be.get('maxtime', None) is None:
+				maxtime = be['maxtime']
+				evformula = lambda ban, evformula=evformula: min(evformula(ban), maxtime)
+			# mix lambda with random time (to prevent bot-nets to calculate exact time IP can be unbanned):
+			if not be.get('rndtime', None) is None:
+				rndtime = be['rndtime']
+				evformula = lambda ban, evformula=evformula: (evformula(ban) + random.random() * rndtime)
+			# set to extra dict:
+			be['evformula'] = evformula
+		#logSys.info('banTimeExtra : %s' % json.dumps(be))
+
+	def getBanTimeExtra(self, opt=None):
+		if opt is not None:
+			return self._banExtra.get(opt, None)
+		return self._banExtra
+
 	def restoreCurrentBans(self):
 		"""Restore any previous valid bans from the database.
 		"""
 		try:
 			if self.database is not None:
-				forbantime = self.actions.getBanTime()
+				forbantime = None;
+				# use ban time as search time if we have not enabled a increasing:
+				if not self.getBanTimeExtra('increment'):
+					forbantime = self.actions.getBanTime()
 				for ticket in self.database.getCurrentBans(jail=self, forbantime=forbantime):
 					#logSys.debug('restored ticket: %s', ticket)
 					if not self.filter.inIgnoreIPList(ticket.getIP(), log_ignore=True):
@@ -221,13 +280,14 @@ class Jail(object):
 						ticket.restored = True
 						# correct start time / ban time (by the same end of ban):
 						btm = ticket.getBanTime(forbantime)
-						diftm = MyTime.time() - ticket.getTime()
+						curtime = int(MyTime.time())
+						diftm = curtime - ticket.getTime()
 						if btm != -1 and diftm > 0:
 							btm -= diftm
 						# ignore obsolete tickets:
 						if btm != -1 and btm <= 0:
 							continue
-						ticket.setTime(MyTime.time())
+						ticket.setTime(curtime)
 						ticket.setBanTime(btm)
 						self.putFailTicket(ticket)
 		except Exception as e: # pragma: no cover

fail2ban/server/observer.py

@@ -0,0 +1,490 @@
+# 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: Serg G. Brester (sebres)
+# 
+# This module was written as part of ban time increment feature.
+
+__author__ = "Serg G. Brester (sebres)"
+__copyright__ = "Copyright (c) 2014 Serg G. Brester"
+__license__ = "GPL"
+
+import threading
+from .jailthread import JailThread
+from .failmanager import FailManagerEmpty
+import os, logging, time, datetime, math, json, random
+import sys
+from ..helpers import getLogger
+from .mytime import MyTime
+from .utils import Utils
+
+# Gets the instance of the logger.
+logSys = getLogger(__name__)
+
+class ObserverThread(JailThread):
+	"""Handles observing a database, managing bad ips and ban increment.
+
+	Parameters
+	----------
+
+	Attributes
+	----------
+	daemon
+	ident
+	name
+	status
+	active : bool
+		Control the state of the thread.
+	idle : bool
+		Control the idle state of the thread.
+	sleeptime : int
+		The time the thread sleeps for in the loop.
+	"""
+
+	# observer is event driven and it sleep organized incremental, so sleep intervals can be shortly:
+	DEFAULT_SLEEP_INTERVAL = Utils.DEFAULT_SLEEP_INTERVAL / 10
+
+	def __init__(self):
+    # init thread
+		super(ObserverThread, self).__init__(name='Observer')
+		# before started - idle:
+		self.idle = True
+		## Event queue
+		self._queue_lock = threading.RLock()
+		self._queue = []
+		## Event, be notified if anything added to event queue
+		self._notify = threading.Event()
+		## Sleep for max 60 seconds, it possible to specify infinite to always sleep up to notifying via event, 
+		## but so we can later do some service "events" occurred infrequently directly in main loop of observer (not using queue)
+		self.sleeptime = 60
+		#
+		self._timers = {}
+		self._paused = False
+		self.__db = None
+		self.__db_purge_interval = 60*60
+		# observer is a not main thread:
+		self.daemon = True
+
+	def __getitem__(self, i):
+		try:
+			return self._queue[i]
+		except KeyError:
+			raise KeyError("Invalid event index : %s" % i)
+
+	def __delitem__(self, name):
+		try:
+			del self._queue[i]
+		except KeyError:
+			raise KeyError("Invalid event index: %s" % i)
+
+	def __iter__(self):
+		return iter(self._queue)
+
+	def __len__(self):
+		return len(self._queue)
+
+	def __eq__(self, other): # Required for Threading
+		return False
+
+	def __hash__(self): # Required for Threading
+		return id(self)
+
+	def add_named_timer(self, name, starttime, *event):
+		"""Add a named timer event to queue will start (and wake) in 'starttime' seconds
+		
+		Previous timer event with same name will be canceled and trigger self into 
+		queue after new 'starttime' value
+		"""
+		t = self._timers.get(name, None)
+		if t is not None:
+			t.cancel()
+		t = threading.Timer(starttime, self.add, event)
+		self._timers[name] = t
+		t.start()
+
+	def add_timer(self, starttime, *event):
+		"""Add a timer event to queue will start (and wake) in 'starttime' seconds
+		"""
+		t = threading.Timer(starttime, self.add, event)
+		t.start()
+
+	def pulse_notify(self):
+		"""Notify wakeup (sets /and resets/ notify event)
+		"""
+		if not self._paused and self._notify:
+			self._notify.set()
+			#self._notify.clear()
+
+	def add(self, *event):
+		"""Add a event to queue and notify thread to wake up.
+		"""
+		## lock and add new event to queue:
+		with self._queue_lock:
+			self._queue.append(event)
+		self.pulse_notify()
+
+	def add_wn(self, *event):
+		"""Add a event to queue withouth notifying thread to wake up.
+		"""
+		## lock and add new event to queue:
+		with self._queue_lock:
+			self._queue.append(event)
+
+	def call_lambda(self, l, *args):
+		l(*args)
+
+	def run(self):
+		"""Main loop for Threading.
+
+		This function is the main loop of the thread.
+
+		Returns
+		-------
+		bool
+			True when the thread exits nicely.
+		"""
+		logSys.info("Observer start...")
+		## first time create named timer to purge database each hour (clean old entries) ...
+		self.add_named_timer('DB_PURGE', self.__db_purge_interval, 'db_purge')
+		## Mapping of all possible event types of observer:
+		__meth = {
+			'failureFound': self.failureFound,
+			'banFound': self.banFound,
+			# universal lambda:
+			'call': self.call_lambda,
+			# system and service events:
+			'db_set': self.db_set,
+			'db_purge': self.db_purge,
+			# service events of observer self:
+			'is_alive' : self.isAlive,
+			'is_active': self.isActive,
+			'start': self.start,
+			'stop': self.stop,
+			'nop': lambda:(),
+			'shutdown': lambda:()
+		}
+		try:
+			## check it self with sending is_alive event
+			self.add('is_alive')
+			## if we should stop - break a main loop
+			while self.active:
+				self.idle = False
+				## check events available and execute all events from queue
+				while not self._paused:
+					## lock, check and pop one from begin of queue:
+					try:
+						ev = None
+						with self._queue_lock:
+							if len(self._queue):
+								ev = self._queue.pop(0)
+						if ev is None:
+							break
+						## retrieve method by name
+						meth = __meth[ev[0]]
+						## execute it with rest of event as variable arguments
+						meth(*ev[1:])
+					except Exception as e:
+						#logSys.error('%s', e, exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
+						logSys.error('%s', e, exc_info=True)
+				## going sleep, wait for events (in queue)
+				n = self._notify
+				if n:
+					self.idle = True
+					n.wait(self.sleeptime)
+					## wake up - reset signal now (we don't need it so long as we reed from queue)
+					n.clear()
+					if self._paused:
+						continue
+				else:
+					## notify event deleted (shutdown) - just sleep a litle bit (waiting for shutdown events, prevent high cpu usage)
+					time.sleep(ObserverThread.DEFAULT_SLEEP_INTERVAL)
+					## stop by shutdown and empty queue :
+					if not self.is_full:
+						break
+				## end of main loop - exit
+			logSys.info("Observer stopped, %s events remaining.", len(self._queue))
+			#print("Observer stopped, %s events remaining." % len(self._queue))
+		except Exception as e:
+			logSys.error('Observer stopped after error: %s', e, exc_info=True)
+			#print("Observer stopped with error: %s" % str(e))
+		# clear all events - exit, for possible calls of wait_empty:
+		with self._queue_lock:
+			self._queue = []
+		self.idle = True
+		return True
+
+	def isAlive(self):
+		#logSys.debug("Observer alive...")
+		return True
+
+	def isActive(self, fromStr=None):
+		# logSys.info("Observer alive, %s%s", 
+		# 	'active' if self.active else 'inactive', 
+		# 	'' if fromStr is None else (", called from '%s'" % fromStr))
+		return self.active
+
+	def start(self):
+		with self._queue_lock:
+			if not self.active:
+				super(ObserverThread, self).start()
+
+	def stop(self):
+		if self.active and self._notify:
+			wtime = 5
+			logSys.info("Observer stop ... try to end queue %s seconds", wtime)
+			#print("Observer stop ....")
+			# just add shutdown job to make possible wait later until full (events remaining)
+			with self._queue_lock:
+				self.add_wn('shutdown')
+				#don't pulse - just set, because we will delete it hereafter (sometimes not wakeup)
+				n = self._notify
+				self._notify.set()
+				#self.pulse_notify()
+				self._notify = None
+			# wait max wtime seconds until full (events remaining)
+			self.wait_empty(wtime)
+			n.clear()
+			self.active = False
+			self.wait_idle(0.5)
+
+	@property
+	def is_full(self):
+		with self._queue_lock:
+			return True if len(self._queue) else False
+
+	def wait_empty(self, sleeptime=None):
+		"""Wait observer is running and returns if observer has no more events (queue is empty)
+		"""
+		time.sleep(ObserverThread.DEFAULT_SLEEP_INTERVAL)
+		if sleeptime is not None:
+			e = MyTime.time() + sleeptime
+		# block queue with not operation to be sure all really jobs are executed if nop goes from queue :
+		if self._notify is not None:
+			self.add_wn('nop')
+			if self.is_full and self.idle:
+				self.pulse_notify()
+		while self.is_full:
+			if sleeptime is not None and MyTime.time() > e:
+				break
+			time.sleep(ObserverThread.DEFAULT_SLEEP_INTERVAL)
+		# wait idle to be sure the last queue element is processed (because pop event before processing it) :
+		self.wait_idle(0.001)
+		return not self.is_full
+
+
+	def wait_idle(self, sleeptime=None):
+		"""Wait observer is running and returns if observer idle (observer sleeps)
+		"""
+		time.sleep(ObserverThread.DEFAULT_SLEEP_INTERVAL)
+		if self.idle:
+			return True
+		if sleeptime is not None:
+			e = MyTime.time() + sleeptime
+		while not self.idle:
+			if sleeptime is not None and MyTime.time() > e:
+				break
+			time.sleep(ObserverThread.DEFAULT_SLEEP_INTERVAL)
+		return self.idle
+
+	@property
+	def paused(self):
+		return self._paused;
+
+	@paused.setter
+	def paused(self, pause):
+		if self._paused == pause:
+			return
+		self._paused = pause
+		# wake after pause ended
+		self.pulse_notify()
+
+
+	@property
+	def status(self):
+		"""Status of observer to be implemented. [TODO]
+		"""
+		return ('', '')
+
+	## -----------------------------------------
+	## [Async] database service functionality ...
+	## -----------------------------------------
+
+	def db_set(self, db):
+		self.__db = db
+
+	def db_purge(self):
+		logSys.info("Purge database event occurred")
+		if self.__db is not None:
+			self.__db.purge()
+		# trigger timer again ...
+		self.add_named_timer('DB_PURGE', self.__db_purge_interval, 'db_purge')
+
+	## -----------------------------------------
+	## [Async] ban time increment functionality ...
+	## -----------------------------------------
+
+	def failureFound(self, failManager, jail, ticket):
+		""" Notify observer a failure for ip was found
+
+		Observer will check ip was known (bad) and possibly increase an retry count
+		"""
+		# check jail active :
+		if not jail.isAlive():
+			return
+		ip = ticket.getIP()
+		unixTime = ticket.getTime()
+		logSys.debug("[%s] Observer: failure found %s", jail.name, ip)
+		# increase retry count for known (bad) ip, corresponding banCount of it (one try will count than 2, 3, 5, 9 ...)  :
+		banCount = 0
+		retryCount = 1
+		timeOfBan = None
+		try:
+			maxRetry = failManager.getMaxRetry()
+			db = jail.database
+			if db is not None:
+				for banCount, timeOfBan, lastBanTime in db.getBan(ip, jail):
+					retryCount = ((1 << (banCount if banCount < 20 else 20))/2 + 1)
+					# if lastBanTime == -1 or timeOfBan + lastBanTime * 2 > MyTime.time():
+					# 	retryCount = maxRetry
+					break
+				retryCount = min(retryCount, maxRetry)
+				# check this ticket already known (line was already processed and in the database and will be restored from there):
+				if timeOfBan is not None and unixTime <= timeOfBan:
+					logSys.debug("[%s] Ignore failure %s before last ban %s < %s, restored",
+								jail.name, ip, unixTime, timeOfBan)
+					return
+			# for not increased failures observer should not add it to fail manager, because was already added by filter self
+			if retryCount <= 1:
+				return
+			# retry counter was increased - add it again:
+			logSys.info("[%s] Found %s, bad - %s, %s # -> %s%s", jail.name, ip, 
+				datetime.datetime.fromtimestamp(unixTime).strftime("%Y-%m-%d %H:%M:%S"), banCount, retryCount,
+				(', Ban' if retryCount >= maxRetry else ''))
+			# retryCount-1, because a ticket was already once incremented by filter self
+			retryCount = failManager.addFailure(ticket, retryCount - 1, True)
+
+			# after observe we have increased count >= maxretry ...
+			if retryCount >= maxRetry:
+				# perform the banning of the IP now (again)
+				# [todo]: this code part will be used multiple times - optimize it later.
+				try: # pragma: no branch - exception is the only way out
+					while True:
+						ticket = failManager.toBan(ip)
+						jail.putFailTicket(ticket)
+				except FailManagerEmpty:
+					failManager.cleanup(MyTime.time())
+
+		except Exception as e:
+			logSys.error('%s', e, exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
+
+
+	class BanTimeIncr:
+		def __init__(self, banTime, banCount):
+			self.Time = banTime
+			self.Count = banCount
+
+	def calcBanTime(self, jail, banTime, banCount):
+		be = jail.getBanTimeExtra()
+		return be['evformula'](self.BanTimeIncr(banTime, banCount))
+
+	def incrBanTime(self, jail, banTime, ticket):
+		"""Check for IP address to increment ban time (if was already banned).
+
+		Returns
+		-------
+		float
+			new ban time.
+		"""
+		# check jail active :
+		if not jail.isAlive() or not jail.database:
+			return
+		be = jail.getBanTimeExtra()
+		ip = ticket.getIP()
+		orgBanTime = banTime
+		# check ip was already banned (increment time of ban):
+		try:
+			if banTime > 0 and be.get('increment', False):
+				# search IP in database and increase time if found:
+				for banCount, timeOfBan, lastBanTime in \
+					jail.database.getBan(ip, jail, overalljails=be.get('overalljails', False)) \
+				:
+					logSys.debug('IP %s was already banned: %s #, %s', ip, banCount, timeOfBan);
+					ticket.setBanCount(banCount);
+					# calculate new ban time
+					if banCount > 0:
+						banTime = be['evformula'](self.BanTimeIncr(banTime, banCount))
+					ticket.setBanTime(banTime);
+					# check current ticket time to prevent increasing for twice read tickets (restored from log file besides database after restart)
+					if ticket.getTime() > timeOfBan:
+						logSys.info('[%s] IP %s is bad: %s # last %s - incr %s to %s' % (jail.name, ip, banCount, 
+							datetime.datetime.fromtimestamp(timeOfBan).strftime("%Y-%m-%d %H:%M:%S"), 
+							datetime.timedelta(seconds=int(orgBanTime)), datetime.timedelta(seconds=int(banTime))));
+					else:
+						ticket.restored = True
+					break
+		except Exception as e:
+			logSys.error('%s', e, exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
+		return banTime
+
+	def banFound(self, ticket, jail, btime):
+		""" Notify observer a ban occured for ip
+
+		Observer will check ip was known (bad) and possibly increase/prolong a ban time
+		Secondary we will actualize the bans and bips (bad ip) in database
+		"""
+		oldbtime = btime
+		ip = ticket.getIP()
+		logSys.debug("[%s] Observer: ban found %s, %s", jail.name, ip, btime)
+		try:
+			# if not permanent, not restored and ban time was not set - check time should be increased:
+			if btime != -1 and not ticket.restored and ticket.getBanTime() is None:
+				btime = self.incrBanTime(jail, btime, ticket)
+				# if we should prolong ban time:
+				if btime == -1 or btime > oldbtime:
+					ticket.setBanTime(btime)
+			# if not permanent
+			if btime != -1:
+				bendtime = ticket.getTime() + btime
+				logtime = (datetime.timedelta(seconds=int(btime)),
+					datetime.datetime.fromtimestamp(bendtime).strftime("%Y-%m-%d %H:%M:%S"))
+				# check ban is not too old :
+				if bendtime < MyTime.time():
+					logSys.debug('Ignore old bantime %s', logtime[1])
+					return False
+			else:
+				logtime = ('permanent', 'infinite')
+			# increment count:
+			ticket.incrBanCount()
+			# if ban time was prolonged - log again with new ban time:
+			if btime != oldbtime:
+				logSys.notice("[%s] Increase Ban %s (%d # %s -> %s)", jail.name, 
+					ip, ticket.getBanCount(), *logtime)
+			# add ticket to database, but only if was not restored (not already read from database):
+			if jail.database is not None and not ticket.restored:
+				# add to database always only after ban time was calculated an not yet already banned:
+				jail.database.addBan(jail, ticket)
+		except Exception as e:
+			logSys.error('%s', e, exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
+
+# Global observer initial created in server (could be later rewriten via singleton)
+class _Observers:
+	def __init__(self):
+		self.Main = None
+
+Observers = _Observers()

fail2ban/server/server.py

@@ -33,6 +33,7 @@ import signal
 import stat
 import sys
 
+from .observer import Observers, ObserverThread
 from .jails import Jails
 from .filter import FileFilter, JournalFilter
 from .transmitter import Transmitter
@@ -94,7 +95,7 @@ class Server:
 		self.__prev_signals[s] = signal.getsignal(s)
 		signal.signal(s, new)
 
-	def start(self, sock, pidfile, force=False, conf={}):
+	def start(self, sock, pidfile, force=False, observer=True, conf={}):
 		# First set the mask to only allow access to owner
 		os.umask(0077)
 		# Second daemonize before logging etc, because it will close all handles:
@@ -144,6 +145,12 @@ class Server:
 		except IOError as e:
 			logSys.error("Unable to create PID file: %s" % e)
 		
+		# Create observers and start it:
+		if observer:
+			if Observers.Main is None:
+				Observers.Main = ObserverThread()
+				Observers.Main.start()
+
 		# Start the communication
 		logSys.debug("Starting communication")
 		try:
@@ -157,6 +164,10 @@ class Server:
 			os.remove(pidfile)
 		except OSError as e:
 			logSys.error("Unable to remove PID file: %s" % e)
+		# Stop observer and exit
+		if Observers.Main is not None:
+			Observers.Main.stop()
+			Observers.Main = None
 		logSys.info("Exiting Fail2ban")
 	
 	def quit(self):
@@ -466,6 +477,12 @@ class Server:
 		
 	def getBanTime(self, name):
 		return self.__jails[name].actions.getBanTime()
+
+	def setBanTimeExtra(self, name, opt, value):
+		self.__jails[name].setBanTimeExtra(opt, value)
+
+	def getBanTimeExtra(self, name, opt):
+		return self.__jails[name].getBanTimeExtra(opt)
 	
 	def isStarted(self):
 		return self.__asyncServer is not None and self.__asyncServer.isActive()
@@ -587,7 +604,7 @@ class Server:
 				try:
 					handler.flush()
 					handler.close()
-				except (ValueError, KeyError):  # pragma: no cover
+				except (ValueError, KeyError): # pragma: no cover
 					# Is known to be thrown after logging was shutdown once
 					# with older Pythons -- seems to be safe to ignore there
 					# At least it was still failing on 2.6.2-0ubuntu1 (jaunty)
@@ -673,6 +690,8 @@ class Server:
 				logSys.error(
 					"Unable to import fail2ban database module as sqlite "
 					"is not available.")
+		if Observers.Main is not None:
+			Observers.Main.db_set(self.__db)
 	
 	def getDatabase(self):
 		return self.__db

fail2ban/server/ticket.py

@@ -24,8 +24,6 @@ __author__ = "Cyril Jaquier"
 __copyright__ = "Copyright (c) 2004 Cyril Jaquier"
 __license__ = "GPL"
 
-import sys
-
 from ..helpers import getLogger
 from .ipdns import IPAddr
 from .mytime import MyTime
@@ -62,8 +60,9 @@ class Ticket(object):
 			self.__dict__.update(i for i in ticket.__dict__.iteritems() if i[0] in self.__dict__)
 
 	def __str__(self):
-		return "%s: ip=%s time=%s #attempts=%d matches=%r" % \
+		return "%s: ip=%s time=%s bantime=%s bancount=%s #attempts=%d matches=%r" % \
 			   (self.__class__.__name__.split('.')[-1], self.__ip, self._time,
+			   	self._banTime, self._banCount,
 			   	self._data['failures'], self._data.get('matches', []))
 
 	def __repr__(self):

fail2ban/server/transmitter.py

@@ -263,6 +263,11 @@ class Transmitter:
 			value = command[2]
 			self.__server.setBanTime(name, value)
 			return self.__server.getBanTime(name)
+		elif command[1].startswith("bantime."):
+			value = command[2]
+			opt = command[1][len("bantime."):]
+			self.__server.setBanTimeExtra(name, opt, value)
+			return self.__server.getBanTimeExtra(name, opt)
 		elif command[1] == "banip":
 			value = command[2]
 			return self.__server.setBanIP(name,value)
@@ -355,6 +360,9 @@ class Transmitter:
 		# Action
 		elif command[1] == "bantime":
 			return self.__server.getBanTime(name)
+		elif command[1].startswith("bantime."):
+			opt = command[1][len("bantime."):]
+			return self.__server.getBanTimeExtra(name, opt)
 		elif command[1] == "actions":
 			return self.__server.getActions(name).keys()
 		elif command[1] == "action":

fail2ban/tests/action_d/test_smtp.py

@@ -29,16 +29,20 @@ else:
 
 from ..dummyjail import DummyJail
 
-from ..utils import CONFIG_DIR, asyncserver
+from ..utils import CONFIG_DIR, asyncserver, Utils
-
 
 class TestSMTPServer(smtpd.SMTPServer):
 
+	def __init__(self, *args):
+		smtpd.SMTPServer.__init__(self, *args)
+		self.ready = False
+
 	def process_message(self, peer, mailfrom, rcpttos, data):
 		self.peer = peer
 		self.mailfrom = mailfrom
 		self.rcpttos = rcpttos
 		self.data = data
+		self.ready = True
 
 
 class SMTPActionTest(unittest.TestCase):
@@ -74,8 +78,13 @@ class SMTPActionTest(unittest.TestCase):
 		self._active = False
 		self._loop_thread.join()
 
+	def _exec_and_wait(self, doaction):
+		self.smtpd.ready = False
+		doaction()
+		Utils.wait_for(lambda: self.smtpd.ready, 3)
+
 	def testStart(self):
-		self.action.start()
+		self._exec_and_wait(self.action.start)
 		self.assertEqual(self.smtpd.mailfrom, "fail2ban")
 		self.assertEqual(self.smtpd.rcpttos, ["root"])
 		self.assertTrue(
@@ -83,7 +92,7 @@ class SMTPActionTest(unittest.TestCase):
 			in self.smtpd.data)
 
 	def testStop(self):
-		self.action.stop()
+		self._exec_and_wait(self.action.stop)
 		self.assertEqual(self.smtpd.mailfrom, "fail2ban")
 		self.assertEqual(self.smtpd.rcpttos, ["root"])
 		self.assertTrue(
@@ -99,7 +108,7 @@ class SMTPActionTest(unittest.TestCase):
 			'ipmatches': "Test fail 1\nTest Fail2\nTest Fail3\n",
 			}
 
-		self.action.ban(aInfo)
+		self._exec_and_wait(lambda: self.action.ban(aInfo))
 		self.assertEqual(self.smtpd.mailfrom, "fail2ban")
 		self.assertEqual(self.smtpd.rcpttos, ["root"])
 		subject = "Subject: [Fail2Ban] %s: banned %s" % (
@@ -109,26 +118,26 @@ class SMTPActionTest(unittest.TestCase):
 			"%i attempts" % aInfo['failures'] in self.smtpd.data)
 
 		self.action.matches = "matches"
-		self.action.ban(aInfo)
+		self._exec_and_wait(lambda: self.action.ban(aInfo))
 		self.assertIn(aInfo['matches'], self.smtpd.data)
 
 		self.action.matches = "ipjailmatches"
-		self.action.ban(aInfo)
+		self._exec_and_wait(lambda: self.action.ban(aInfo))
 		self.assertIn(aInfo['ipjailmatches'], self.smtpd.data)
 
 		self.action.matches = "ipmatches"
-		self.action.ban(aInfo)
+		self._exec_and_wait(lambda: self.action.ban(aInfo))
 		self.assertIn(aInfo['ipmatches'], self.smtpd.data)
 
 	def testOptions(self):
-		self.action.start()
+		self._exec_and_wait(self.action.start)
 		self.assertEqual(self.smtpd.mailfrom, "fail2ban")
 		self.assertEqual(self.smtpd.rcpttos, ["root"])
 
 		self.action.fromname = "Test"
 		self.action.fromaddr = "test@example.com"
 		self.action.toaddr = "test@example.com, test2@example.com"
-		self.action.start()
+		self._exec_and_wait(self.action.start)
 		self.assertEqual(self.smtpd.mailfrom, "test@example.com")
 		self.assertTrue("From: %s <%s>" %
 			(self.action.fromname, self.action.fromaddr) in self.smtpd.data)

fail2ban/tests/actionstestcase.py

@@ -149,7 +149,7 @@ class ExecuteActions(LogCaptureTestCase):
 			"action2",
 			os.path.join(TEST_FILES_DIR, "action.d/action_modifyainfo.py"),
 			{})
-		self.__jail.putFailTicket(FailTicket("1.2.3.4", 0))
+		self.__jail.putFailTicket(FailTicket("1.2.3.4"))
 		self.__actions._Actions__checkBan()
 		# Will fail if modification of aInfo from first action propagates
 		# to second action, as both delete same key

fail2ban/tests/banmanagertestcase.py

@@ -26,18 +26,21 @@ __license__ = "GPL"
 
 import unittest
 
+from .utils import setUpMyTime, tearDownMyTime
+
 from ..server.banmanager import BanManager
 from ..server.ticket import BanTicket
 
 class AddFailure(unittest.TestCase):
 	def setUp(self):
 		"""Call before every test case."""
+		setUpMyTime()
 		self.__ticket = BanTicket('193.168.0.128', 1167605999.0)
 		self.__banManager = BanManager()
 
 	def tearDown(self):
 		"""Call after every test case."""
-		pass
+		tearDownMyTime()
 
 	def testAdd(self):
 		self.assertTrue(self.__banManager.addBanTicket(self.__ticket))
@@ -92,6 +95,24 @@ class AddFailure(unittest.TestCase):
 		self.assertTrue(self.__banManager.addBanTicket(self.__ticket))
 		ticket = BanTicket('111.111.1.111', 1167605999.0)
 		self.assertFalse(self.__banManager._inBanList(ticket))
+		
+	def testBanTimeIncr(self):
+		ticket = BanTicket(self.__ticket.getIP(), self.__ticket.getTime())
+		## increase twice and at end permanent:
+		for i in (1000, 2000, -1):
+			self.__banManager.addBanTicket(self.__ticket)
+			ticket.setBanTime(i)
+			self.assertFalse(self.__banManager.addBanTicket(ticket))
+			self.assertEqual(str(self.__banManager.getTicketByID(ticket.getIP())), 
+				"BanTicket: ip=%s time=%s bantime=%s bancount=0 #attempts=0 matches=[]" % (ticket.getIP(), ticket.getTime(), i))
+		## after permanent, it should remain permanent ban time (-1):
+		self.__banManager.addBanTicket(self.__ticket)
+		ticket.setBanTime(-1)
+		self.assertFalse(self.__banManager.addBanTicket(ticket))
+		ticket.setBanTime(1000)
+		self.assertFalse(self.__banManager.addBanTicket(ticket))
+		self.assertEqual(str(self.__banManager.getTicketByID(ticket.getIP())), 
+			"BanTicket: ip=%s time=%s bantime=%s bancount=0 #attempts=0 matches=[]" % (ticket.getIP(), ticket.getTime(), -1))
 
 	def testUnban(self):
 		btime = self.__banManager.getBanTime()

fail2ban/tests/config/filter.d/common.conf

@@ -1 +0,0 @@
-../../../../config/filter.d/common.conf

fail2ban/tests/config/filter.d/common.conf

@@ -0,0 +1,64 @@
+# Generic configuration items (to be used as interpolations) in other
+# filters  or actions configurations
+#
+
+[INCLUDES]
+
+# Load customizations if any available
+after = common.local
+
+
+[DEFAULT]
+
+# Daemon definition is to be specialized (if needed) in .conf file
+_daemon = \S*
+
+#
+# Shortcuts for easier comprehension of the failregex
+#
+# PID.
+# EXAMPLES: [123]
+__pid_re = (?:\[\d+\])
+
+# Daemon name (with optional source_file:line or whatever)
+# EXAMPLES: pam_rhosts_auth, [sshd], pop(pam_unix)
+__daemon_re = [\[\(]?%(_daemon)s(?:\(\S+\))?[\]\)]?:?
+
+# extra daemon info
+# EXAMPLE: [ID 800047 auth.info]
+__daemon_extra_re = \[ID \d+ \S+\]
+
+# Combinations of daemon name and PID
+# EXAMPLES: sshd[31607], pop(pam_unix)[4920]
+__daemon_combs_re = (?:%(__pid_re)s?:\s+%(__daemon_re)s|%(__daemon_re)s%(__pid_re)s?:?)
+
+# Some messages have a kernel prefix with a timestamp
+# EXAMPLES: kernel: [769570.846956]
+__kernel_prefix = kernel: \[ *\d+\.\d+\]
+
+__hostname = \S+
+
+# A MD5 hex
+# EXAMPLES: 07:06:27:55:b0:e3:0c:3c:5a:28:2d:7c:7e:4c:77:5f
+__md5hex = (?:[\da-f]{2}:){15}[\da-f]{2}
+
+# bsdverbose is where syslogd is started with -v or -vv and results in <4.3> or
+# <auth.info> appearing before the host as per testcases/files/logs/bsd/*.
+__bsd_syslog_verbose = <[^.]+\.[^.]+>
+
+__vserver = @vserver_\S+
+
+__date_ambit = (?:\[\])
+
+# Common line prefixes (beginnings) which could be used in filters
+#
+#      [bsdverbose]? [hostname] [vserver tag] daemon_id spaces
+#
+# This can be optional (for instance if we match named native log files)
+__prefix_line = %(__date_ambit)s?\s*(?:%(__bsd_syslog_verbose)s\s+)?(?:%(__hostname)s\s+)?(?:%(__kernel_prefix)s\s+)?(?:%(__vserver)s\s+)?(?:%(__daemon_combs_re)s\s+)?(?:%(__daemon_extra_re)s\s+)?
+
+# PAM authentication mechanism check for failures, e.g.: pam_unix, pam_sss,
+# pam_ldap
+__pam_auth = pam_unix
+
+# Author: Yaroslav Halchenko

fail2ban/tests/databasetestcase.py

@@ -124,6 +124,33 @@ class DatabaseTest(LogCaptureTestCase):
 		self.assertRaises(NotImplementedError, self.db.updateDb, Fail2BanDb.__version__ + 1)
 		os.remove(self.db._dbBackupFilename)
 
+	def testUpdateDb2(self):
+		if Fail2BanDb is None or self.db.filename == ':memory:': # pragma: no cover
+			return
+		shutil.copyfile(
+			os.path.join(TEST_FILES_DIR, 'database_v2.db'), self.dbFilename)
+		self.db = Fail2BanDb(self.dbFilename)
+		self.assertEqual(self.db.getJailNames(), set(['pam-generic']))
+		self.assertEqual(self.db.getLogPaths(), set(['/var/log/auth.log']))
+		bans = self.db.getBans()
+		self.assertEqual(len(bans), 2)
+		# compare first ticket completely:
+		ticket = FailTicket("1.2.3.7", 1417595494, [
+			u'Dec  3 09:31:08 f2btest test:auth[27658]: pam_unix(test:auth): authentication failure; logname= uid=0 euid=0 tty=test ruser= rhost=1.2.3.7',
+			u'Dec  3 09:31:32 f2btest test:auth[27671]: pam_unix(test:auth): authentication failure; logname= uid=0 euid=0 tty=test ruser= rhost=1.2.3.7',
+			u'Dec  3 09:31:34 f2btest test:auth[27673]: pam_unix(test:auth): authentication failure; logname= uid=0 euid=0 tty=test ruser= rhost=1.2.3.7'
+		])
+		ticket.setAttempt(3)
+		self.assertEqual(bans[0], ticket)
+		# second ban found also:
+		self.assertEqual(bans[1].getIP(), "1.2.3.8")
+		# updated ?
+		self.assertEqual(self.db.updateDb(Fail2BanDb.__version__), Fail2BanDb.__version__)
+		# further update should fail:
+		self.assertRaises(NotImplementedError, self.db.updateDb, Fail2BanDb.__version__ + 1)
+		# clean:
+		os.remove(self.db._dbBackupFilename)
+
 	def testAddJail(self):
 		if Fail2BanDb is None: # pragma: no cover
 			return
@@ -368,8 +395,9 @@ class DatabaseTest(LogCaptureTestCase):
 			"action_checkainfo",
 			os.path.join(TEST_FILES_DIR, "action.d/action_checkainfo.py"),
 			{})
-		ticket = FailTicket("1.2.3.4", MyTime.time(), ['test', 'test'])
+		ticket = FailTicket("1.2.3.4")
 		ticket.setAttempt(5)
+		ticket.setMatches(['test', 'test'])
 		self.jail.putFailTicket(ticket)
 		actions._Actions__checkBan()
 		self.assertLogged("ban ainfo %s, %s, %s, %s" % (True, True, True, True))

fail2ban/tests/dummyjail.py

@@ -28,6 +28,11 @@ from ..server.jail import Jail
 from ..server.actions import Actions
 
 
+class DummyActions(Actions):
+	def checkBan(self):
+		return self._Actions__checkBan()
+
+
 class DummyJail(Jail):
 	"""A simple 'jail' to suck in all the tickets generated by Filter's
 	"""
@@ -36,7 +41,7 @@ class DummyJail(Jail):
 		self.queue = []
 		super(DummyJail, self).__init__(name='DummyJail', backend=backend)
 		self.__db = None
-		self.__actions = Actions(self)
+		self.__actions = DummyActions(self)
 
 	def __len__(self):
 		with self.lock:

fail2ban/tests/failmanagertestcase.py

@@ -149,10 +149,10 @@ class AddFailure(unittest.TestCase):
 		ticket_repr = repr(ticket)
 		self.assertEqual(
 			ticket_str,
-			'FailTicket: ip=193.168.0.128 time=1167605999.0 #attempts=5 matches=[]')
+			'FailTicket: ip=193.168.0.128 time=1167605999.0 bantime=None bancount=0 #attempts=5 matches=[]')
 		self.assertEqual(
 			ticket_repr,
-			'FailTicket: ip=193.168.0.128 time=1167605999.0 #attempts=5 matches=[]')
+			'FailTicket: ip=193.168.0.128 time=1167605999.0 bantime=None bancount=0 #attempts=5 matches=[]')
 		self.assertFalse(not ticket)
 		# and some get/set-ers otherwise not tested
 		ticket.setTime(1000002000.0)
@@ -160,7 +160,7 @@ class AddFailure(unittest.TestCase):
 		# and str() adjusted correspondingly
 		self.assertEqual(
 			str(ticket),
-			'FailTicket: ip=193.168.0.128 time=1000002000.0 #attempts=5 matches=[]')
+			'FailTicket: ip=193.168.0.128 time=1000002000.0 bantime=None bancount=0 #attempts=5 matches=[]')
 	
 	def testbanNOK(self):
 		self._addDefItems()

fail2ban/tests/observertestcase.py

@@ -0,0 +1,624 @@
+# 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: Serg G. Brester (sebres)
+# 
+
+__author__ = "Serg G. Brester (sebres)"
+__copyright__ = "Copyright (c) 2014 Serg G. Brester"
+__license__ = "GPL"
+
+import os
+import sys
+import unittest
+import tempfile
+import time
+
+from ..server.mytime import MyTime
+from ..server.ticket import FailTicket
+from ..server.failmanager import FailManager
+from ..server.banmanager import BanManager
+from ..server.observer import Observers, ObserverThread
+from ..server.utils import Utils
+from .utils import LogCaptureTestCase
+from ..server.filter import Filter
+from .dummyjail import DummyJail
+
+from .databasetestcase import getFail2BanDb, Fail2BanDb
+
+
+class BanTimeIncr(LogCaptureTestCase):
+
+	def setUp(self):
+		"""Call before every test case."""
+		super(BanTimeIncr, self).setUp()
+		self.__jail = DummyJail()
+		self.__jail.calcBanTime = self.calcBanTime
+		self.Observer = ObserverThread()
+
+	def tearDown(self):
+		super(BanTimeIncr, self).tearDown()
+
+	def calcBanTime(self, banTime, banCount):
+		return self.Observer.calcBanTime(self.__jail, banTime, banCount)
+
+	def testDefault(self, multipliers = None):
+		a = self.__jail;
+		a.setBanTimeExtra('increment', 'true')
+		self.assertEqual(a.getBanTimeExtra('increment'), True)
+		a.setBanTimeExtra('maxtime', '1d')
+		self.assertEqual(a.getBanTimeExtra('maxtime'), 24*60*60)
+		a.setBanTimeExtra('rndtime', None)
+		a.setBanTimeExtra('factor', None)
+		# tests formulat or multipliers:
+		a.setBanTimeExtra('multipliers', multipliers)
+		# test algorithm and max time 24 hours :
+		self.assertEqual(
+			[a.calcBanTime(600, i) for i in xrange(1, 11)],
+			[1200, 2400, 4800, 9600, 19200, 38400, 76800, 86400, 86400, 86400]
+		)
+		# with extra large max time (30 days):
+		a.setBanTimeExtra('maxtime', '30d')
+		# using formula the ban time grows always, but using multipliers the growing will stops with last one:
+		arr = [1200, 2400, 4800, 9600, 19200, 38400, 76800, 153600, 307200, 614400]
+		if multipliers is not None:
+			multcnt = len(multipliers.split(' '))
+			if multcnt < 11:
+				arr = arr[0:multcnt-1] + ([arr[multcnt-2]] * (11-multcnt))
+		self.assertEqual(
+			[a.calcBanTime(600, i) for i in xrange(1, 11)],
+			arr
+		)
+		a.setBanTimeExtra('maxtime', '1d')
+		# change factor :
+		a.setBanTimeExtra('factor', '2');
+		self.assertEqual(
+			[a.calcBanTime(600, i) for i in xrange(1, 11)],
+			[2400, 4800, 9600, 19200, 38400, 76800, 86400, 86400, 86400, 86400]
+		)
+		# factor is float :
+		a.setBanTimeExtra('factor', '1.33');
+		self.assertEqual(
+			[int(a.calcBanTime(600, i)) for i in xrange(1, 11)],
+			[1596, 3192, 6384, 12768, 25536, 51072, 86400, 86400, 86400, 86400]
+		)
+		a.setBanTimeExtra('factor', None);
+		# change max time :
+		a.setBanTimeExtra('maxtime', '12h')
+		self.assertEqual(
+			[a.calcBanTime(600, i) for i in xrange(1, 11)],
+			[1200, 2400, 4800, 9600, 19200, 38400, 43200, 43200, 43200, 43200]
+		)
+		a.setBanTimeExtra('maxtime', '24h')
+		## test randomization - not possibe all 10 times we have random = 0:
+		a.setBanTimeExtra('rndtime', '5m')
+		self.assertTrue(
+			False in [1200 in [a.calcBanTime(600, 1) for i in xrange(10)] for c in xrange(10)]
+		)
+		a.setBanTimeExtra('rndtime', None)
+		self.assertFalse(
+			False in [1200 in [a.calcBanTime(600, 1) for i in xrange(10)] for c in xrange(10)]
+		)
+		# restore default:
+		a.setBanTimeExtra('multipliers', None)
+		a.setBanTimeExtra('factor', None);
+		a.setBanTimeExtra('maxtime', '24h')
+		a.setBanTimeExtra('rndtime', None)
+
+	def testMultipliers(self):
+		# this multipliers has the same values as default formula, we test stop growing after count 9:
+		self.testDefault('1 2 4 8 16 32 64 128 256')
+		# this multipliers has exactly the same values as default formula, test endless growing (stops by count 31 only):
+		self.testDefault(' '.join([str(1<<i) for i in xrange(31)]))
+
+	def testFormula(self):
+		a = self.__jail;
+		a.setBanTimeExtra('maxtime', '24h')
+		a.setBanTimeExtra('rndtime', None)
+		## use another formula:
+		a.setBanTimeExtra('formula', 'ban.Time * math.exp(float(ban.Count+1)*banFactor)/math.exp(1*banFactor)')
+		a.setBanTimeExtra('factor', '2.0 / 2.885385')
+		a.setBanTimeExtra('multipliers', None)
+		# test algorithm and max time 24 hours :
+		self.assertEqual(
+			[int(a.calcBanTime(600, i)) for i in xrange(1, 11)],
+			[1200, 2400, 4800, 9600, 19200, 38400, 76800, 86400, 86400, 86400]
+		)
+		# with extra large max time (30 days):
+		a.setBanTimeExtra('maxtime', '30d')
+		self.assertEqual(
+			[int(a.calcBanTime(600, i)) for i in xrange(1, 11)],
+			[1200, 2400, 4800, 9600, 19200, 38400, 76800, 153601, 307203, 614407]
+		)
+		a.setBanTimeExtra('maxtime', '24h')
+		# change factor :
+		a.setBanTimeExtra('factor', '1');
+		self.assertEqual(
+			[int(a.calcBanTime(600, i)) for i in xrange(1, 11)],
+			[1630, 4433, 12051, 32758, 86400, 86400, 86400, 86400, 86400, 86400]
+		)
+		a.setBanTimeExtra('factor', '2.0 / 2.885385')
+		# change max time :
+		a.setBanTimeExtra('maxtime', '12h')
+		self.assertEqual(
+			[int(a.calcBanTime(600, i)) for i in xrange(1, 11)],
+			[1200, 2400, 4800, 9600, 19200, 38400, 43200, 43200, 43200, 43200]
+		)
+		a.setBanTimeExtra('maxtime', '24h')
+		## test randomization - not possibe all 10 times we have random = 0:
+		a.setBanTimeExtra('rndtime', '5m')
+		self.assertTrue(
+			False in [1200 in [int(a.calcBanTime(600, 1)) for i in xrange(10)] for c in xrange(10)]
+		)
+		a.setBanTimeExtra('rndtime', None)
+		self.assertFalse(
+			False in [1200 in [int(a.calcBanTime(600, 1)) for i in xrange(10)] for c in xrange(10)]
+		)
+		# restore default:
+		a.setBanTimeExtra('factor', None);
+		a.setBanTimeExtra('multipliers', None)
+		a.setBanTimeExtra('factor', None);
+		a.setBanTimeExtra('maxtime', '24h')
+		a.setBanTimeExtra('rndtime', None)
+
+
+class BanTimeIncrDB(unittest.TestCase):
+#class BanTimeIncrDB(LogCaptureTestCase):
+
+	def setUp(self):
+		"""Call before every test case."""
+		super(BanTimeIncrDB, self).setUp()
+		if Fail2BanDb is None and sys.version_info >= (2,7): # pragma: no cover
+			raise unittest.SkipTest(
+				"Unable to import fail2ban database module as sqlite is not "
+				"available.")
+		elif Fail2BanDb is None:
+			return
+		_, self.dbFilename = tempfile.mkstemp(".db", "fail2ban_")
+		self.db = getFail2BanDb(self.dbFilename)
+		self.jail = DummyJail()
+		self.jail.database = self.db
+		self.Observer = ObserverThread()
+		Observers.Main = self.Observer
+
+	def tearDown(self):
+		"""Call after every test case."""
+		if Fail2BanDb is None: # pragma: no cover
+			return
+		# Cleanup
+		self.Observer.stop()
+		Observers.Main = None
+		os.remove(self.dbFilename)
+		super(BanTimeIncrDB, self).tearDown()
+
+	def incrBanTime(self, ticket, banTime=None):
+		jail = self.jail;
+		if banTime is None:
+			banTime = ticket.getBanTime(jail.actions.getBanTime())
+		ticket.setBanTime(None)
+		incrTime = self.Observer.incrBanTime(jail, banTime, ticket)
+		#print("!!!!!!!!! banTime: %s, %s, incr: %s " % (banTime, ticket.getBanCount(), incrTime))
+		return incrTime
+
+
+	def testBanTimeIncr(self):
+		if Fail2BanDb is None: # pragma: no cover
+			return
+		jail = self.jail
+		self.db.addJail(jail)
+		# we tests with initial ban time = 10 seconds:
+		jail.actions.setBanTime(10)
+		jail.setBanTimeExtra('increment', 'true')
+		jail.setBanTimeExtra('multipliers', '1 2 4 8 16 32 64 128 256 512 1024 2048')
+		ip = "127.0.0.2"
+		# used as start and fromtime (like now but time independence, cause test case can run slow):
+		stime = int(MyTime.time())
+		ticket = FailTicket(ip, stime, [])
+		# test ticket not yet found
+		self.assertEqual(
+			[self.incrBanTime(ticket, 10) for i in xrange(3)], 
+			[10, 10, 10]
+		)
+		# add a ticket banned
+		ticket.incrBanCount()
+		self.db.addBan(jail, ticket)
+		# get a ticket already banned in this jail:
+		self.assertEqual(
+			[(banCount, timeOfBan, lastBanTime) for banCount, timeOfBan, lastBanTime in self.db.getBan(ip, jail, None, False)],
+			[(1, stime, 10)]
+		)
+		# incr time and ban a ticket again :
+		ticket.setTime(stime + 15)
+		self.assertEqual(self.incrBanTime(ticket, 10), 20)
+		ticket.incrBanCount()
+		self.db.addBan(jail, ticket)
+		# get a ticket already banned in this jail:
+		self.assertEqual(
+			[(banCount, timeOfBan, lastBanTime) for banCount, timeOfBan, lastBanTime in self.db.getBan(ip, jail, None, False)],
+			[(2, stime + 15, 20)]
+		)
+		# get a ticket already banned in all jails:
+		self.assertEqual(
+			[(banCount, timeOfBan, lastBanTime) for banCount, timeOfBan, lastBanTime in self.db.getBan(ip, '', None, True)],
+			[(2, stime + 15, 20)]
+		)
+		# check other optional parameters of getBan:
+		self.assertEqual(
+			[(banCount, timeOfBan, lastBanTime) for banCount, timeOfBan, lastBanTime in self.db.getBan(ip, forbantime=stime, fromtime=stime)],
+			[(2, stime + 15, 20)]
+		)
+		# search currently banned and 1 day later (nothing should be found):
+		self.assertEqual(
+			self.db.getCurrentBans(forbantime=-24*60*60, fromtime=stime),
+			[]
+		)
+		# search currently banned one ticket for ip:
+		restored_tickets = self.db.getCurrentBans(ip=ip)
+		self.assertEqual(
+			str(restored_tickets), 
+			('FailTicket: ip=%s time=%s bantime=20 bancount=2 #attempts=0 matches=[]' % (ip, stime + 15))
+		)
+		# search currently banned anywhere:
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(
+			str(restored_tickets),
+			('[FailTicket: ip=%s time=%s bantime=20 bancount=2 #attempts=0 matches=[]]' % (ip, stime + 15))
+		)
+		# search currently banned:
+		restored_tickets = self.db.getCurrentBans(jail=jail, fromtime=stime)
+		self.assertEqual(
+			str(restored_tickets), 
+			('[FailTicket: ip=%s time=%s bantime=20 bancount=2 #attempts=0 matches=[]]' % (ip, stime + 15))
+		)
+		# increase ban multiple times:
+		lastBanTime = 20
+		for i in xrange(10):
+			ticket.setTime(stime + lastBanTime + 5)
+			banTime = self.incrBanTime(ticket, 10)
+			self.assertEqual(banTime, lastBanTime * 2)
+			ticket.incrBanCount()
+			self.db.addBan(jail, ticket)
+			lastBanTime = banTime
+		# increase again, but the last multiplier reached (time not increased):
+		ticket.setTime(stime + lastBanTime + 5)
+		banTime = self.incrBanTime(ticket, 10)
+		self.assertNotEqual(banTime, lastBanTime * 2)
+		self.assertEqual(banTime, lastBanTime)
+		ticket.incrBanCount()
+		self.db.addBan(jail, ticket)
+		lastBanTime = banTime
+		# add two tickets from yesterday: one unbanned (bantime already out-dated):
+		ticket2 = FailTicket(ip+'2', stime-24*60*60, [])
+		ticket2.setBanTime(12*60*60)
+		ticket2.incrBanCount()
+		self.db.addBan(jail, ticket2)
+		# and one from yesterday also, but still currently banned :
+		ticket2 = FailTicket(ip+'1', stime-24*60*60, [])
+		ticket2.setBanTime(36*60*60)
+		ticket2.incrBanCount()
+		self.db.addBan(jail, ticket2)
+		# search currently banned:
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(len(restored_tickets), 2)
+		self.assertEqual(
+			str(restored_tickets[0]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=13 #attempts=0 matches=[]' % (ip, stime + lastBanTime + 5, lastBanTime)
+		)
+		self.assertEqual(
+			str(restored_tickets[1]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=1 #attempts=0 matches=[]' % (ip+'1', stime-24*60*60, 36*60*60)
+		)
+		# search out-dated (give another fromtime now is -18 hours):
+		restored_tickets = self.db.getCurrentBans(fromtime=stime-18*60*60)
+		self.assertEqual(len(restored_tickets), 3)
+		self.assertEqual(
+			str(restored_tickets[2]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=1 #attempts=0 matches=[]' % (ip+'2', stime-24*60*60, 12*60*60)
+		)
+		# should be still banned
+		self.assertFalse(restored_tickets[1].isTimedOut(stime))
+		self.assertFalse(restored_tickets[1].isTimedOut(stime))
+		# the last should be timed out now
+		self.assertTrue(restored_tickets[2].isTimedOut(stime))
+		self.assertFalse(restored_tickets[2].isTimedOut(stime-18*60*60))
+
+		# test permanent, create timed out:
+		ticket=FailTicket(ip+'3', stime-36*60*60, [])
+		self.assertTrue(ticket.isTimedOut(stime, 600))
+		# not timed out - permanent jail:
+		self.assertFalse(ticket.isTimedOut(stime, -1))
+		# not timed out - permanent ticket:
+		ticket.setBanTime(-1)
+		self.assertFalse(ticket.isTimedOut(stime, 600))
+		self.assertFalse(ticket.isTimedOut(stime, -1))
+		# timed out - permanent jail but ticket time (not really used behavior)
+		ticket.setBanTime(600)
+		self.assertTrue(ticket.isTimedOut(stime, -1))
+
+		# get currently banned pis with permanent one:
+		ticket.setBanTime(-1)
+		ticket.incrBanCount()
+		self.db.addBan(jail, ticket)
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(len(restored_tickets), 3)
+		self.assertEqual(
+			str(restored_tickets[2]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=1 #attempts=0 matches=[]' % (ip+'3', stime-36*60*60, -1)
+		)
+		# purge (nothing should be changed):
+		self.db.purge()
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(len(restored_tickets), 3)
+		# set short time and purge again:
+		ticket.setBanTime(600)
+		ticket.incrBanCount()
+		self.db.addBan(jail, ticket)
+		self.db.purge()
+		# this old ticket should be removed now:
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(len(restored_tickets), 2)
+		self.assertEqual(restored_tickets[0].getIP(), ip)
+
+		# purge remove 1st ip
+		self.db._purgeAge = -48*60*60
+		self.db.purge()
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(len(restored_tickets), 1)
+		self.assertEqual(restored_tickets[0].getIP(), ip+'1')
+
+		# this should purge all bans, bips and logs - nothing should be found now
+		self.db._purgeAge = -240*60*60
+		self.db.purge()
+		restored_tickets = self.db.getCurrentBans(fromtime=stime)
+		self.assertEqual(restored_tickets, [])
+
+		# two separate jails :
+		jail1 = DummyJail(backend='polling')
+		jail1.database = self.db
+		self.db.addJail(jail1)
+		jail2 = DummyJail(backend='polling')
+		jail2.database = self.db
+		self.db.addJail(jail2)
+		ticket1 = FailTicket(ip, stime, [])
+		ticket1.setBanTime(6000)
+		ticket1.incrBanCount()
+		self.db.addBan(jail1, ticket1)
+		ticket2 = FailTicket(ip, stime-6000, [])
+		ticket2.setBanTime(12000)
+		ticket2.setBanCount(1)
+		ticket2.incrBanCount()
+		self.db.addBan(jail2, ticket2)
+		restored_tickets = self.db.getCurrentBans(jail=jail1, fromtime=stime)
+		self.assertEqual(len(restored_tickets), 1)
+		self.assertEqual(
+			str(restored_tickets[0]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=1 #attempts=0 matches=[]' % (ip, stime, 6000)
+		)
+		restored_tickets = self.db.getCurrentBans(jail=jail2, fromtime=stime)
+		self.assertEqual(len(restored_tickets), 1)
+		self.assertEqual(
+			str(restored_tickets[0]),
+			'FailTicket: ip=%s time=%s bantime=%s bancount=2 #attempts=0 matches=[]' % (ip, stime-6000, 12000)
+		)
+		# get last ban values for this ip separately for each jail:
+		for row in self.db.getBan(ip, jail1):
+			self.assertEqual(row, (1, stime, 6000))
+			break
+		for row in self.db.getBan(ip, jail2):
+			self.assertEqual(row, (2, stime-6000, 12000))
+			break
+		# get max values for this ip (over all jails):
+		for row in self.db.getBan(ip, overalljails=True):
+			self.assertEqual(row, (3, stime, 18000))
+			break
+		# test restoring bans from database:
+		jail1.restoreCurrentBans()
+		ticket = jail1.getFailTicket()
+		self.assertTrue(ticket.restored)
+		self.assertEqual(str(ticket), 
+			'FailTicket: ip=%s time=%s bantime=%s bancount=1 #attempts=0 matches=[]' % (ip, stime, 6000)
+		)
+		# jail2 does not restore any bans (because all ban tickets should be already expired: stime-6000):
+		jail2.restoreCurrentBans()
+		self.assertEqual(jail2.getFailTicket(), False)
+
+	def testObserver(self):
+		if Fail2BanDb is None: # pragma: no cover
+			return
+		jail = self.jail
+		self.db.addJail(jail)
+		# we tests with initial ban time = 10 seconds:
+		jail.actions.setBanTime(10)
+		jail.setBanTimeExtra('increment', 'true')
+		# observer / database features:
+		obs = Observers.Main
+		obs.start()
+		obs.db_set(self.db)
+		# wait for start ready
+		obs.add('nop')
+		obs.wait_empty(5)
+		# purge database right now, but using timer, to test it also:
+		self.db._purgeAge = -240*60*60
+		obs.add_named_timer('DB_PURGE', 0.001, 'db_purge')
+		# wait for timer ready
+		obs.wait_idle(0.025)
+		# wait for ready
+		obs.add('nop')
+		obs.wait_empty(5)
+
+		stime = int(MyTime.time())
+		# completelly empty ?
+		tickets = self.db.getBans()
+		self.assertEqual(tickets, [])
+
+		# add failure:
+		ip = "127.0.0.2"
+		ticket = FailTicket(ip, stime-120, [])
+		failManager = FailManager()
+		failManager.setMaxRetry(3)
+		for i in xrange(3):
+			failManager.addFailure(ticket)
+			obs.add('failureFound', failManager, jail, ticket)
+		obs.wait_empty(5)
+		self.assertEqual(ticket.getBanCount(), 0)
+		# check still not ban :
+		self.assertTrue(not jail.getFailTicket())
+		# add manually 4th times banned (added to bips - make ip bad):
+		ticket.setBanCount(4)
+		self.db.addBan(self.jail, ticket)
+		restored_tickets = self.db.getCurrentBans(jail=jail, fromtime=stime-120)
+		self.assertEqual(len(restored_tickets), 1)
+		# check again, new ticket, new failmanager:
+		ticket = FailTicket(ip, stime, [])
+		failManager = FailManager()
+		failManager.setMaxRetry(3)
+		# add once only - but bad - should be banned:
+		failManager.addFailure(ticket)
+		obs.add('failureFound', failManager, self.jail, ticket)
+		obs.wait_empty(5)
+		# wait until ticket transfered from failmanager into jail:
+		to = int(MyTime.time())+30
+		while True:
+			ticket2 = jail.getFailTicket()
+			if ticket2:
+				break
+			time.sleep(Utils.DEFAULT_SLEEP_INTERVAL)
+			if MyTime.time() > to: # pragma: no cover
+				raise RuntimeError('unexpected timeout: wait 30 seconds instead of few ms.')
+		# check ticket and failure count:
+		self.assertFalse(not ticket2)
+		self.assertEqual(ticket2.getRetry(), failManager.getMaxRetry())
+
+		# wrap FailTicket to BanTicket:
+		failticket2 = ticket2
+		ticket2 = BanManager.createBanTicket(failticket2)
+		self.assertEqual(ticket2, failticket2)
+		# add this ticket to ban (use observer only without ban manager):
+		obs.add('banFound', ticket2, jail, 10)
+		obs.wait_empty(5)
+		# increased?
+		self.assertEqual(ticket2.getBanTime(), 160)
+		self.assertEqual(ticket2.getBanCount(), 5)
+
+		# check prolonged in database also :
+		restored_tickets = self.db.getCurrentBans(jail=jail, fromtime=stime)
+		self.assertEqual(len(restored_tickets), 1)
+		self.assertEqual(restored_tickets[0].getBanTime(), 160)
+		self.assertEqual(restored_tickets[0].getBanCount(), 5)
+
+		# now using jail/actions:
+		ticket = FailTicket(ip, stime-60, ['test-expired-ban-time'])
+		jail.putFailTicket(ticket)
+		self.assertFalse(jail.actions.checkBan())
+
+		ticket = FailTicket(ip, MyTime.time(), ['test-actions'])
+		jail.putFailTicket(ticket)
+		self.assertTrue(jail.actions.checkBan())
+
+		obs.wait_empty(5)
+		restored_tickets = self.db.getCurrentBans(jail=jail, fromtime=stime)
+		self.assertEqual(len(restored_tickets), 1)
+		self.assertEqual(restored_tickets[0].getBanTime(), 320)
+		self.assertEqual(restored_tickets[0].getBanCount(), 6)
+
+		# and permanent:
+		ticket = FailTicket(ip+'1', MyTime.time(), ['test-permanent'])
+		ticket.setBanTime(-1)
+		jail.putFailTicket(ticket)
+		self.assertTrue(jail.actions.checkBan())
+
+		obs.wait_empty(5)
+		ticket = FailTicket(ip+'1', MyTime.time(), ['test-permanent'])
+		ticket.setBanTime(600)
+		jail.putFailTicket(ticket)
+		self.assertFalse(jail.actions.checkBan())
+
+		obs.wait_empty(5)
+		restored_tickets = self.db.getCurrentBans(jail=jail, fromtime=stime)
+		self.assertEqual(len(restored_tickets), 2)
+		self.assertEqual(restored_tickets[1].getBanTime(), -1)
+		self.assertEqual(restored_tickets[1].getBanCount(), 1)
+
+		# stop observer
+		obs.stop()
+
+class ObserverTest(LogCaptureTestCase):
+
+	def setUp(self):
+		"""Call before every test case."""
+		super(ObserverTest, self).setUp()
+
+	def tearDown(self):
+		"""Call after every test case."""
+		super(ObserverTest, self).tearDown()
+
+	def testObserverBanTimeIncr(self):
+		obs = ObserverThread()
+		obs.start()
+		# wait for idle
+		obs.wait_idle(1)
+		# observer will replace test set:
+		o = set(['test'])
+		obs.add('call', o.clear)
+		obs.add('call', o.add, 'test2')
+		# wait for observer ready:
+		obs.wait_empty(1)
+		self.assertFalse(obs.is_full)
+		self.assertEqual(o, set(['test2']))
+		# observer makes pause
+		obs.paused = True
+		# observer will replace test set, but first after pause ends:
+		obs.add('call', o.clear)
+		obs.add('call', o.add, 'test3')
+		obs.wait_empty(10 * Utils.DEFAULT_SLEEP_TIME)
+		self.assertTrue(obs.is_full)
+		self.assertEqual(o, set(['test2']))
+		obs.paused = False
+		# wait running:
+		obs.wait_empty(1)
+		self.assertEqual(o, set(['test3']))
+
+		self.assertTrue(obs.isActive())
+		self.assertTrue(obs.isAlive())
+		obs.stop()
+		obs = None
+
+	class _BadObserver(ObserverThread):
+		def run(self):
+			raise RuntimeError('run bad thread exception')
+
+	def testObserverBadRun(self):
+		obs = ObserverTest._BadObserver()
+		# don't wait for empty by stop
+		obs.wait_empty = lambda v:()
+		# save previous hook, prevent write stderr and check hereafter __excepthook__ was executed
+		prev_exchook = sys.__excepthook__
+		x = []
+		sys.__excepthook__ = lambda *args: x.append(args)
+		try:
+			obs.start()
+			obs.stop()
+			obs.join()
+			self.assertTrue( Utils.wait_for( lambda: len(x) and self._is_logged("Unhandled exception"), 3) )
+		finally:
+			sys.__excepthook__ = prev_exchook
+		self.assertLogged("Unhandled exception")
+		self.assertEqual(len(x), 1)
+		self.assertEqual(x[0][0], RuntimeError)
+		self.assertEqual(str(x[0][1]), 'run bad thread exception')

fail2ban/tests/servertestcase.py

@@ -902,6 +902,15 @@ class TransmitterLogging(TransmitterBase):
 		self.assertEqual(self.transm.proceed(["set", "logtarget", "STDERR"]), (0, "STDERR"))
 		self.assertEqual(self.transm.proceed(["flushlogs"]), (0, "flushed"))
 
+	def testBanTimeIncr(self):
+		self.setGetTest("bantime.increment", "true", True, jail=self.jailName)
+		self.setGetTest("bantime.rndtime", "30min", 30*60, jail=self.jailName)
+		self.setGetTest("bantime.maxtime", "1000 days", 1000*24*60*60, jail=self.jailName)
+		self.setGetTest("bantime.factor", "2", "2", jail=self.jailName)
+		self.setGetTest("bantime.formula", "ban.Time * math.exp(float(ban.Count+1)*banFactor)/math.exp(1*banFactor)", jail=self.jailName)
+		self.setGetTest("bantime.multipliers", "1 5 30 60 300 720 1440 2880", "1 5 30 60 300 720 1440 2880", jail=self.jailName)
+		self.setGetTest("bantime.overalljails", "true", "true", jail=self.jailName)
+
 
 class JailTests(unittest.TestCase):
 
@@ -989,9 +998,10 @@ class LoggingTests(LogCaptureTestCase):
 			badThread = _BadThread()
 			badThread.start()
 			badThread.join()
-			self.assertLogged("Unhandled exception")
+			self.assertTrue( Utils.wait_for( lambda: len(x) and self._is_logged("Unhandled exception"), 3) )
 		finally:
 			sys.__excepthook__ = prev_exchook
+		self.assertLogged("Unhandled exception")
 		self.assertEqual(len(x), 1)
 		self.assertEqual(x[0][0], RuntimeError)
 

fail2ban/tests/utils.py

@@ -317,6 +317,7 @@ def gatherTests(regexps=None, opts=None):
 	from . import sockettestcase
 	from . import misctestcase
 	from . import databasetestcase
+	from . import observertestcase
 	from . import samplestestcase
 	from . import fail2banclienttestcase
 	from . import fail2banregextestcase
@@ -347,7 +348,6 @@ def gatherTests(regexps=None, opts=None):
 		tests = FilteredTestSuite()
 
 	# Server
-	#tests.addTest(unittest.makeSuite(servertestcase.StartStop))
 	tests.addTest(unittest.makeSuite(servertestcase.Transmitter))
 	tests.addTest(unittest.makeSuite(servertestcase.JailTests))
 	tests.addTest(unittest.makeSuite(servertestcase.RegexTests))
@@ -388,6 +388,10 @@ def gatherTests(regexps=None, opts=None):
 	tests.addTest(unittest.makeSuite(misctestcase.MyTimeTest))
 	# Database
 	tests.addTest(unittest.makeSuite(databasetestcase.DatabaseTest))
+	# Observer
+	tests.addTest(unittest.makeSuite(observertestcase.ObserverTest))
+	tests.addTest(unittest.makeSuite(observertestcase.BanTimeIncr))
+	tests.addTest(unittest.makeSuite(observertestcase.BanTimeIncrDB))
 
 	# Filter
 	tests.addTest(unittest.makeSuite(filtertestcase.IgnoreIP))