automatic reban (repeat banning action) after repair/restore sane environment, if already logged ticket causes new failures (part of #980, closes #1680);

introduces banning epoch for actions and tickets (to distinguish or recognize removed set of tickets)

fail2ban/server/action.py

@@ -217,6 +217,7 @@ class ActionBase(object):
 			"start",
 			"stop",
 			"ban",
+			"reban",
 			"unban",
 			)
 		for method in required:
@@ -250,6 +251,17 @@ class ActionBase(object):
 		"""
 		pass
 
+	def reban(self, aInfo): # pragma: no cover - abstract
+		"""Executed when a ban occurs.
+
+		Parameters
+		----------
+		aInfo : dict
+			Dictionary which includes information in relation to
+			the ban.
+		"""
+		return self.ban(aInfo)
+
 	def unban(self, aInfo): # pragma: no cover - abstract
 		"""Executed when a ban expires.
 
@@ -281,6 +293,7 @@ class CommandAction(ActionBase):
 	----------
 	actionban
 	actioncheck
+	actionreban
 	actionreload
 	actionrepair
 	actionstart
@@ -301,6 +314,7 @@ class CommandAction(ActionBase):
 			self.actionstart = ''
 			## Command executed when ticket gets banned.
 			self.actionban = ''
+			self.actionreban = ''
 			## Command executed when ticket gets removed.
 			self.actionunban = ''
 			## Command executed in order to check requirements.
@@ -504,8 +518,8 @@ class CommandAction(ActionBase):
 		ret = self._executeOperation('<actionstart>', 'starting', family=family, afterExec=_started)
 		return ret
 
-	def ban(self, aInfo):
-		"""Executes the "actionban" command.
+	def ban(self, aInfo, cmd='<actionban>'):
+		"""Executes the given command ("actionban" or "actionreban").
 
 		Replaces the tags in the action command with actions properties
 		and ban information, and executes the resulting command.
@@ -522,7 +536,7 @@ class CommandAction(ActionBase):
 			if not self.__started.get(family):
 				self._start(family, forceStart=True)
 		# ban:
-		if not self._processCmd('<actionban>', aInfo):
+		if not self._processCmd(cmd, aInfo):
 			raise RuntimeError("Error banning %(ip)s" % aInfo)
 		self.__started[family] = self.__started.get(family, 0) | 3; # started and contains items
 
@@ -543,6 +557,21 @@ class CommandAction(ActionBase):
 			if not self._processCmd('<actionunban>', aInfo):
 				raise RuntimeError("Error unbanning %(ip)s" % aInfo)
 
+	def reban(self, aInfo):
+		"""Executes the "actionreban" command if available, otherwise simply repeat "actionban".
+
+		Replaces the tags in the action command with actions properties
+		and ban information, and executes the resulting command.
+
+		Parameters
+		----------
+		aInfo : dict
+			Dictionary which includes information in relation to
+			the ban.
+		"""
+		# re-ban:
+		return self.ban(aInfo, '<actionreban>' if self.actionreban else '<actionban>')
+
 	def flush(self):
 		"""Executes the "actionflush" command.
 		
@@ -812,6 +841,17 @@ class CommandAction(ActionBase):
 			realCmd = Utils.buildShellCmd(realCmd, varsDict)
 		return realCmd
 
+	@property
+	def banEpoch(self):
+		return getattr(self, '_banEpoch', 0)
+	def invalidateBanEpoch(self):
+		"""Increments ban epoch of jail and this action, so already banned tickets would cause
+		a re-ban for all tickets with previous epoch."""
+		if self._jail is not None:
+			self._banEpoch = self._jail.actions.banEpoch = self._jail.actions.banEpoch + 1
+		else:
+			self._banEpoch = self.banEpoch + 1
+
 	def _invariantCheck(self, family=None, beforeRepair=None, forceStart=True):
 		"""Executes a substituted `actioncheck` command.
 		"""
@@ -826,6 +866,8 @@ class CommandAction(ActionBase):
 			return -1
 		self._logSys.error(
 			"Invariant check failed. Trying to restore a sane environment")
+		# increment ban epoch of jail and this action (allows re-ban on already banned):
+		self.invalidateBanEpoch()
 		# try to find repair command, if exists - exec it:
 		repairCmd = self._getOperation('<actionrepair>', family)
 		if repairCmd:

fail2ban/server/actions.py

@@ -81,6 +81,8 @@ class Actions(JailThread, Mapping):
 		self._actions = OrderedDict()
 		## The ban manager.
 		self.__banManager = BanManager()
+		self.banEpoch = 0
+		self.__lastConsistencyCheckTM = 0
 		## Precedence of ban (over unban), so max number of tickets banned (to call an unban check):
 		self.banPrecedence = 10
 		## Max count of outdated tickets to unban per each __checkUnBan operation:
@@ -439,6 +441,7 @@ class Actions(JailThread, Mapping):
 		cnt = 0
 		if not tickets:
 			tickets = self.__getFailTickets(self.banPrecedence)
+		rebanacts = None
 		for ticket in tickets:
 			bTicket = BanManager.createBanTicket(ticket)
 			ip = bTicket.getIP()
@@ -461,6 +464,8 @@ class Actions(JailThread, Mapping):
 							exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
 				# after all actions are processed set banned flag:
 				bTicket.banned = True
+				if self.banEpoch: # be sure tickets always have the same ban epoch (default 0):
+					bTicket.banEpoch = self.banEpoch
 			else:
 				bTicket = reason['ticket']
 				# if already banned (otherwise still process some action)
@@ -475,11 +480,61 @@ class Actions(JailThread, Mapping):
 					else logging.NOTICE  if diftm < 60 \
 					else logging.WARNING
 					logSys.log(ll, "[%s] %s already banned", self._jail.name, ip)
+					# if long time after ban - do consistency check (something is wrong here):
+					if bTicket.banEpoch == self.banEpoch and diftm > 3:
+						# avoid too often checks:
+						if not rebanacts and MyTime.time() > self.__lastConsistencyCheckTM + 3:
+							for action in self._actions.itervalues():
+								action.consistencyCheck()
+							self.__lastConsistencyCheckTM = MyTime.time()
+					# check epoch in order to reban it:
+					if bTicket.banEpoch < self.banEpoch:
+						if not rebanacts: rebanacts = dict(
+							(name, action) for name, action in self._actions.iteritems()
+								if action.banEpoch > bTicket.banEpoch)
+						cnt += self.__reBan(bTicket, actions=rebanacts)
+				else:
+					# pragma: no cover - unexpected: ticket is not banned for some reasons - reban using all actions:
+					cnt += self.__reBan(bTicket)
 		if cnt:
 			logSys.debug("Banned %s / %s, %s ticket(s) in %r", cnt, 
 				self.__banManager.getBanTotal(), self.__banManager.size(), self._jail.name)
 		return cnt
 
+	def __reBan(self, ticket, actions=None, log=True):
+		"""Repeat bans for the ticket.
+
+		Executes the actions in order to reban the host given in the
+		ticket.
+
+		Parameters
+		----------
+		ticket : Ticket
+			Ticket to reban
+		"""
+		actions = actions or self._actions
+		ip = ticket.getIP()
+		aInfo = self.__getActionInfo(ticket)
+		if log:
+			logSys.notice("[%s] Reban %s%s", self._jail.name, aInfo["ip"], (', action %r' % actions.keys()[0] if len(actions) == 1 else ''))
+		for name, action in actions.iteritems():
+			try:
+				logSys.debug("[%s] action %r: reban %s", self._jail.name, name, ip)
+				if not aInfo.immutable: aInfo.reset()
+				action.reban(aInfo)
+			except Exception as e:
+				logSys.error(
+					"Failed to execute reban jail '%s' action '%s' "
+					"info '%r': %s",
+					self._jail.name, name, aInfo, e,
+					exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
+				return 0
+		# after all actions are processed set banned flag:
+		ticket.banned = True
+		if self.banEpoch: # be sure tickets always have the same ban epoch (default 0):
+			ticket.banEpoch = self.banEpoch
+		return 1
+
 	def __checkUnBan(self, maxCount=None):
 		"""Check for IP address to unban.
 
@@ -522,7 +577,7 @@ class Actions(JailThread, Mapping):
 				logSys.error("Failed to flush bans in jail '%s' action '%s': %s",
 					self._jail.name, name, e,
 					exc_info=logSys.getEffectiveLevel()<=logging.DEBUG)
-				logSys.info("No flush occured, do consistency check")
+				logSys.info("No flush occurred, do consistency check")
 				if hasattr(action, 'consistencyCheck'):
 					def _beforeRepair():
 						if stop and not getattr(action, 'actionrepair_on_unban', None): # don't need repair on stop
@@ -569,8 +624,6 @@ class Actions(JailThread, Mapping):
 			logSys.notice("[%s] Unban %s", self._jail.name, aInfo["ip"])
 		for name, action in unbactions.iteritems():
 			try:
-				if ticket.restored and getattr(action, 'norestored', False):
-					continue
 				logSys.debug("[%s] action %r: unban %s", self._jail.name, name, ip)
 				if not aInfo.immutable: aInfo.reset()
 				action.unban(aInfo)

fail2ban/server/ticket.py

@@ -206,6 +206,13 @@ class Ticket(object):
 		# return single value of data:
 		return self._data.get(key, default)
 
+	@property
+	def banEpoch(self):
+		return getattr(self, '_banEpoch', 0)
+	@banEpoch.setter
+	def banEpoch(self, value):
+		self._banEpoch = value
+
 
 class FailTicket(Ticket):
 

fail2ban/tests/actionstestcase.py

@@ -28,11 +28,10 @@ import time
 import os
 import tempfile
 
-from ..server.actions import Actions
 from ..server.ticket import FailTicket
 from ..server.utils import Utils
 from .dummyjail import DummyJail
-from .utils import LogCaptureTestCase, with_alt_time, MyTime
+from .utils import LogCaptureTestCase, with_alt_time, with_tmpdir, MyTime
 
 TEST_FILES_DIR = os.path.join(os.path.dirname(__file__), "files")
 
@@ -43,7 +42,7 @@ class ExecuteActions(LogCaptureTestCase):
 		"""Call before every test case."""
 		super(ExecuteActions, self).setUp()
 		self.__jail = DummyJail()
-		self.__actions = Actions(self.__jail)
+		self.__actions = self.__jail.actions
 
 	def tearDown(self):
 		super(ExecuteActions, self).tearDown()
@@ -52,8 +51,8 @@ class ExecuteActions(LogCaptureTestCase):
 		self.__actions.add('ip')
 		act = self.__actions['ip']
 		act.actionstart = 'echo ip start'+o.get('start', '')
-		act.actionban = 'echo ip ban <ip>'
-		act.actionunban = 'echo ip unban <ip>'
+		act.actionban = 'echo ip ban <ip>'+o.get('ban', '')
+		act.actionunban = 'echo ip unban <ip>'+o.get('unban', '')
 		act.actioncheck = 'echo ip check'+o.get('check', '')
 		act.actionflush = 'echo ip flush'+o.get('flush', '')
 		act.actionstop = 'echo ip stop'+o.get('stop', '')
@@ -239,7 +238,7 @@ class ExecuteActions(LogCaptureTestCase):
 			"stdout: %r" % 'ip flush inet4',
 			"stdout: %r" % 'ip flush inet6',
 			'Failed to flush bans',
-			'No flush occured, do consistency check',
+			'No flush occurred, do consistency check',
 			'Invariant check failed. Trying to restore a sane environment',
 			"stdout: %r" % 'ip stop',  # same for both families
 			'Failed to flush bans',
@@ -259,7 +258,7 @@ class ExecuteActions(LogCaptureTestCase):
 		self.pruneLog('[test-phase 3] failed flush in consistent env')
 		self.__actions._Actions__flushBan()
 		self.assertLogged('Failed to flush bans',
-			'No flush occured, do consistency check',
+			'No flush occurred, do consistency check',
 			"stdout: %r" % 'ip flush inet6',
 			"stdout: %r" % 'ip check inet6',
 			all=True, wait=True)
@@ -341,7 +340,7 @@ class ExecuteActions(LogCaptureTestCase):
 			"stdout: %r" % 'ip flush inet4',
 			"stdout: %r" % 'ip flush inet6',
 			'Failed to flush bans',
-			'No flush occured, do consistency check',
+			'No flush occurred, do consistency check',
 			'Invariant check failed. Trying to restore a sane environment',
 			"stdout: %r" % 'ip stop inet6',
 			'Failed to flush bans in jail',
@@ -368,7 +367,7 @@ class ExecuteActions(LogCaptureTestCase):
 		act['actioncheck?family=inet6'] = act.actioncheck
 		self.__actions._Actions__flushBan()
 		self.assertLogged('Failed to flush bans',
-			'No flush occured, do consistency check',
+			'No flush occurred, do consistency check',
 			"stdout: %r" % 'ip flush inet6',
 			"stdout: %r" % 'ip check inet6',
 			all=True, wait=True)
@@ -396,3 +395,103 @@ class ExecuteActions(LogCaptureTestCase):
 			"stdout: %r" % 'ip flush inet4',
 			'Unban tickets each individualy',
 			all=True)
+
+	@with_alt_time
+	@with_tmpdir
+	def testActionsRebanBrokenAfterRepair(self, tmp):
+		act = self.defaultAction({
+			'start':' <family>; touch "<FN>"',
+			'check':' <family>; test -f "<FN>"',
+			'flush':' <family>; echo -n "" > "<FN>"',
+			'stop': ' <family>; rm -f "<FN>"',
+			'ban':  ' <family>; echo "<ip> <family>" >> "<FN>"',
+		})
+		act['FN'] = tmp+'/<family>'
+		act.actionstart_on_demand = True
+		act.actionrepair = 'echo ip repair <family>; touch "<FN>"'
+		act.actionreban = 'echo ip reban <ip> <family>; echo "<ip> <family> -- rebanned" >> "<FN>"'
+		self.pruneLog('[test-phase 0] initial ban')
+		self.assertEqual(self.__actions.addBannedIP(['192.0.2.1', '2001:db8::1']), 2)
+		self.assertLogged('Ban 192.0.2.1', 'Ban 2001:db8::1',
+			"stdout: %r" % 'ip start inet4',
+			"stdout: %r" % 'ip ban 192.0.2.1 inet4',
+			"stdout: %r" % 'ip start inet6',
+			"stdout: %r" % 'ip ban 2001:db8::1 inet6',
+			all=True)
+
+		self.pruneLog('[test-phase 1] check ban')
+		self.dumpFile(tmp+'/inet4')
+		self.assertLogged('192.0.2.1 inet4')
+		self.assertNotLogged('2001:db8::1 inet6')
+		self.pruneLog()
+		self.dumpFile(tmp+'/inet6')
+		self.assertLogged('2001:db8::1 inet6')
+		self.assertNotLogged('192.0.2.1 inet4')
+
+		# simulate 3 seconds past:
+		MyTime.setTime(MyTime.time() + 4)
+		# already banned produces events:
+		self.pruneLog('[test-phase 2] check already banned')
+		self.assertEqual(self.__actions.addBannedIP(['192.0.2.1', '2001:db8::1', '2001:db8::2']), 1)
+		self.assertLogged(
+			'192.0.2.1 already banned', '2001:db8::1 already banned', 'Ban 2001:db8::2',
+			"stdout: %r" % 'ip check inet4', # both checks occurred
+			"stdout: %r" % 'ip check inet6',
+			all=True)
+		self.dumpFile(tmp+'/inet4')
+		self.dumpFile(tmp+'/inet6')
+		# no reban should occur:
+		self.assertNotLogged('Reban 192.0.2.1', 'Reban 2001:db8::1',
+			"stdout: %r" % 'ip ban 192.0.2.1 inet4',
+			"stdout: %r" % 'ip reban 192.0.2.1 inet4',
+			"stdout: %r" % 'ip ban 2001:db8::1 inet6',
+			"stdout: %r" % 'ip reban 2001:db8::1 inet6',
+			'192.0.2.1 inet4 -- repaired',
+			'2001:db8::1 inet6 -- repaired',
+			all=True)
+
+		# simulate 3 seconds past:
+		MyTime.setTime(MyTime.time() + 4)
+		# break env (remove both files, so check would fail):
+		os.remove(tmp+'/inet4')
+		os.remove(tmp+'/inet6')
+		# test again already banned (it shall cause reban now):
+		self.pruneLog('[test-phase 3a] check reban after sane env repaired')
+		self.assertEqual(self.__actions.addBannedIP(['192.0.2.1', '2001:db8::1']), 2)
+		self.assertLogged(
+			"Invariant check failed. Trying to restore a sane environment",
+			"stdout: %r" % 'ip repair inet4', # both repairs occurred
+			"stdout: %r" % 'ip repair inet6',
+			"Reban 192.0.2.1, action 'ip'", "Reban 2001:db8::1, action 'ip'", # both rebans also
+			"stdout: %r" % 'ip reban 192.0.2.1 inet4',
+			"stdout: %r" % 'ip reban 2001:db8::1 inet6',
+			all=True)
+
+		# now last IP (2001:db8::2) - no repair, but still old epoch of ticket, so it gets rebanned:
+		self.pruneLog('[test-phase 3a] check reban by epoch mismatch (without repair)')
+		self.assertEqual(self.__actions.addBannedIP('2001:db8::2'), 1)
+		self.assertLogged(
+			"Reban 2001:db8::2, action 'ip'",
+			"stdout: %r" % 'ip reban 2001:db8::2 inet6',
+			all=True)
+		self.assertNotLogged(
+			"Invariant check failed. Trying to restore a sane environment",
+			"stdout: %r" % 'ip repair inet4', # both repairs occurred
+			"stdout: %r" % 'ip repair inet6',
+			"Reban 192.0.2.1, action 'ip'", "Reban 2001:db8::1, action 'ip'", # both rebans also
+			"stdout: %r" % 'ip reban 192.0.2.1 inet4',
+			"stdout: %r" % 'ip reban 2001:db8::1 inet6',
+			all=True)
+
+		# and bans present in files:
+		self.pruneLog('[test-phase 4] check reban')
+		self.dumpFile(tmp+'/inet4')
+		self.assertLogged('192.0.2.1 inet4 -- rebanned')
+		self.assertNotLogged('2001:db8::1 inet6 -- rebanned')
+		self.pruneLog()
+		self.dumpFile(tmp+'/inet6')
+		self.assertLogged(
+			'2001:db8::1 inet6 -- rebanned', 
+			'2001:db8::2 inet6 -- rebanned', all=True)
+		self.assertNotLogged('192.0.2.1 inet4 -- rebanned')
+

fail2ban/tests/fail2banclienttestcase.py

@@ -113,16 +113,7 @@ fail2banclient.input_command = _test_input_command
 fail2bancmdline.PRODUCTION = \
 fail2banserver.PRODUCTION = False
 
-
-def _out_file(fn, handle=logSys.debug):
-	"""Helper which outputs content of the file at HEAVYDEBUG loglevels"""
-	if (handle != logSys.debug or logSys.getEffectiveLevel() <= logging.DEBUG):
-		handle('---- ' + fn + ' ----')
-		for line in fileinput.input(fn):
-			line = line.rstrip('\n')
-			handle(line)
-		handle('-'*30)
-
+_out_file = LogCaptureTestCase.dumpFile
 
 def _write_file(fn, mode, *lines):
 	f = open(fn, mode)

fail2ban/tests/servertestcase.py

@@ -752,7 +752,7 @@ class Transmitter(TransmitterBase):
 		self.assertSortedEqual(
 			self.transm.proceed(["get", self.jailName, "actionmethods",
 				action])[1],
-			['ban', 'start', 'stop', 'testmethod', 'unban'])
+			['ban', 'reban', 'start', 'stop', 'testmethod', 'unban'])
 		self.assertEqual(
 			self.transm.proceed(["set", self.jailName, "action", action,
 				"testmethod", '{"text": "world!"}']),

fail2ban/tests/utils.py

@@ -22,6 +22,7 @@ __author__ = "Yaroslav Halchenko"
 __copyright__ = "Copyright (c) 2013 Yaroslav Halchenko"
 __license__ = "GPL"
 
+import fileinput
 import itertools
 import logging
 import optparse
@@ -741,11 +742,8 @@ class LogCaptureTestCase(unittest.TestCase):
 				self._dirty |= 2 # records changed
 
 	def setUp(self):
-
 		# For extended testing of what gets output into logging
 		# system, we will redirect it to a string
-		logSys = getLogger("fail2ban")
-
 		# Keep old settings
 		self._old_level = logSys.level
 		self._old_handlers = logSys.handlers
@@ -762,7 +760,6 @@ class LogCaptureTestCase(unittest.TestCase):
 		"""Call after every test case."""
 		# print "O: >>%s<<" % self._log.getvalue()
 		self.pruneLog()
-		logSys = getLogger("fail2ban")
 		logSys.handlers = self._old_handlers
 		logSys.level = self._old_level
 		super(LogCaptureTestCase, self).tearDown()
@@ -845,5 +842,15 @@ class LogCaptureTestCase(unittest.TestCase):
 	def getLog(self):
 		return self._log.getvalue()
 
+	@staticmethod
+	def dumpFile(fn, handle=logSys.debug):
+		"""Helper which outputs content of the file at HEAVYDEBUG loglevels"""
+		if (handle != logSys.debug or logSys.getEffectiveLevel() <= logging.DEBUG):
+			handle('---- ' + fn + ' ----')
+			for line in fileinput.input(fn):
+				line = line.rstrip('\n')
+				handle(line)
+			handle('-'*30)
+
 
 pid_exists = Utils.pid_exists