Merge branch 'cmd-timeout' (PR #190) of https://github.com/kwirk/fail2ban into 0.9

* 'cmd-timeout' of https://github.com/kwirk/fail2ban:
  NF: For action execution, log stdout and stderr if debug or cmd error
  NF: Allow setting of timeout for execution of action commands

Conflicts:
	fail2ban/client/actionreader.py
	fail2ban/server/action.py

fail2ban/client/actionreader.py

@@ -72,8 +72,10 @@ class ActionReader(DefinitionInitConfigReader):
 				stream.append(head + ["actionban", self._name, self._opts[opt]])
 			elif opt == "actionunban":
 				stream.append(head + ["actionunban", self._name, self._opts[opt]])
-		# cInfo
 		if self._initOpts:
+			if "timeout" in self._initOpts:
+				stream.append(head + ["timeout", self._file, self._opts["timeout"]])
+			# cInfo
 			for p in self._initOpts:
 				stream.append(head + ["setcinfo", self._name, p, self._initOpts[p]])
 

fail2ban/protocol.py

@@ -73,6 +73,7 @@ protocol = [
 ["set <JAIL> delaction <ACT>", "removes the action <NAME> from <JAIL>"], 
 ["set <JAIL> setcinfo <ACT> <KEY> <VALUE>", "sets <VALUE> for <KEY> of the action <NAME> for <JAIL>"], 
 ["set <JAIL> delcinfo <ACT> <KEY>", "removes <KEY> for the action <NAME> for <JAIL>"], 
+["set <JAIL> timeout <ACT> <TIMEOUT>", "sets <TIMEOUT> as the command timeout in seconds for the action <ACT> for <JAIL>"],
 ["set <JAIL> actionstart <ACT> <CMD>", "sets the start command <CMD> of the action <ACT> for <JAIL>"], 
 ["set <JAIL> actionstop <ACT> <CMD>", "sets the stop command <CMD> of the action <ACT> for <JAIL>"], 
 ["set <JAIL> actioncheck <ACT> <CMD>", "sets the check command <CMD> of the action <ACT> for <JAIL>"], 
@@ -97,6 +98,7 @@ protocol = [
 ["get <JAIL> actionban <ACT>", "gets the ban command for the action <ACT> for <JAIL>"],
 ["get <JAIL> actionunban <ACT>", "gets the unban command for the action <ACT> for <JAIL>"],
 ["get <JAIL> cinfo <ACT> <KEY>", "gets the value for <KEY> for the action <ACT> for <JAIL>"],
+["get <JAIL> timeout <ACT>", "gets the command timeout in seconds for the action <ACT> for <JAIL>"],
 ]
 
 ##

fail2ban/server/action.py

@@ -21,7 +21,7 @@ __author__ = "Cyril Jaquier and Fail2Ban Contributors"
 __copyright__ = "Copyright (c) 2004 Cyril Jaquier, 2011-2012 Yaroslav Halchenko"
 __license__ = "GPL"
 
-import logging, os
+import logging, os, subprocess, time, signal, tempfile
 import threading, re
 #from subprocess import call
 
@@ -33,7 +33,7 @@ _cmd_lock = threading.Lock()
 
 # Some hints on common abnormal exit codes
 _RETCODE_HINTS = {
-	0x7f00: '"Command not found".  Make sure that all commands in %(realCmd)r '
+	127: '"Command not found".  Make sure that all commands in %(realCmd)r '
 	        'are in the PATH of fail2ban-server process '
 			'(grep -a PATH= /proc/`pidof -x fail2ban-server`/environ). '
 			'You may want to start '
@@ -42,6 +42,10 @@ _RETCODE_HINTS = {
 			'additional informative error messages appear in the terminals.'
 	}
 
+# Dictionary to lookup signal name from number
+signame = dict((num, name)
+	for name, num in signal.__dict__.iteritems() if name.startswith("SIG"))
+
 ##
 # Execute commands.
 #
@@ -53,6 +57,7 @@ class Action:
 	
 	def __init__(self, name):
 		self.__name = name
+		self.__timeout = 60
 		self.__cInfo = dict()
 		## Command executed in order to initialize the system.
 		self.__actionStart = ''
@@ -82,6 +87,23 @@ class Action:
 	def getName(self):
 		return self.__name
 	
+	##
+	# Sets the timeout period for commands.
+	#
+	# @param timeout timeout period in seconds
+	
+	def setTimeout(self, timeout):
+		self.__timeout = int(timeout)
+		logSys.debug("Set action %s timeout = %i" % (self.__name, timeout))
+	
+	##
+	# Returns the action timeout period for commands.
+	#
+	# @return the timeout period in seconds
+	
+	def getTimeout(self):
+		return self.__timeout
+	
 	##
 	# Sets a "CInfo".
 	#
@@ -142,7 +164,7 @@ class Action:
 				logSys.error("Cinfo/definitions contain self referencing definitions and cannot be resolved")
 				return False
 		startCmd = Action.replaceTag(self.__actionStart, self.__cInfo)
-		return Action.executeCmd(startCmd)
+		return Action.executeCmd(startCmd, self.__timeout)
 	
 	##
 	# Set the "ban" command.
@@ -238,7 +260,7 @@ class Action:
 	
 	def execActionStop(self):
 		stopCmd = Action.replaceTag(self.__actionStop, self.__cInfo)
-		return Action.executeCmd(stopCmd)
+		return Action.executeCmd(stopCmd, self.__timeout)
 
 	##
 	# Sort out tag definitions within other tags
@@ -324,12 +346,12 @@ class Action:
 			return True
 		
 		checkCmd = Action.replaceTag(self.__actionCheck, self.__cInfo)
-		if not Action.executeCmd(checkCmd):
+		if not Action.executeCmd(checkCmd, self.__timeout):
 			logSys.error("Invariant check failed. Trying to restore a sane" +
 						 " environment")
 			self.execActionStop()
 			self.execActionStart()
-			if not Action.executeCmd(checkCmd):
+			if not Action.executeCmd(checkCmd, self.__timeout):
 				logSys.fatal("Unable to restore environment")
 				return False
 
@@ -342,7 +364,7 @@ class Action:
 		# Replace static fields
 		realCmd = Action.replaceTag(realCmd, self.__cInfo)
 		
-		return Action.executeCmd(realCmd)
+		return Action.executeCmd(realCmd, self.__timeout)
 
 	##
 	# Executes a command.
@@ -357,27 +379,59 @@ class Action:
 	# @return True if the command succeeded
 
 	#@staticmethod
-	def executeCmd(realCmd):
+	def executeCmd(realCmd, timeout=60):
 		logSys.debug(realCmd)
 		_cmd_lock.acquire()
 		try: # Try wrapped within another try needed for python version < 2.5
+			stdout = tempfile.TemporaryFile(suffix=".stdout", prefix="fai2ban_")
+			stderr = tempfile.TemporaryFile(suffix=".stderr", prefix="fai2ban_")
 			try:
-				# The following line gives deadlock with multiple jails
-				#retcode = call(realCmd, shell=True)
-				retcode = os.system(realCmd)
-				if retcode == 0:
-					logSys.debug("%s returned successfully" % realCmd)
-					return True
-				else:
-					msg = _RETCODE_HINTS.get(retcode, None)
-					logSys.error("%s returned %x" % (realCmd, retcode))
-					if msg:
-						logSys.info("HINT on %x: %s"
-									% (retcode, msg % locals()))
+				popen = subprocess.Popen(
+					realCmd, stdout=stdout, stderr=stderr, shell=True)
+				stime = time.time()
+				retcode = popen.poll()
+				while time.time() - stime <= timeout and retcode is None:
+					time.sleep(0.1)
+					retcode = popen.poll()
+				if retcode is None:
+					logSys.error("%s timed out after %i seconds." %
+						(realCmd, timeout))
+					os.kill(popen.pid, signal.SIGTERM) # Terminate the process
+					time.sleep(0.1)
+					retcode = popen.poll()
+					if retcode is None: # Still going...
+						os.kill(popen.pid, signal.SIGKILL) # Kill the process
+						time.sleep(0.1)
+						retcode = popen.poll()
 			except OSError, e:
 				logSys.error("%s failed with %s" % (realCmd, e))
+				return False
 		finally:
 			_cmd_lock.release()
+
+		std_level = retcode == 0 and logging.DEBUG or logging.ERROR
+		if std_level >= logSys.getEffectiveLevel():
+			stdout.seek(0)
+			logSys.log(std_level, "%s stdout: %r" % (realCmd, stdout.read()))
+			stderr.seek(0)
+			logSys.log(std_level, "%s stderr: %r" % (realCmd, stderr.read()))
+		stdout.close()
+		stderr.close()
+
+		if retcode == 0:
+			logSys.debug("%s returned successfully" % realCmd)
+			return True
+		elif retcode is None:
+			logSys.error("Unable to kill PID %i: %s" % (popen.pid, realCmd))
+		elif retcode < 0:
+			logSys.error("%s killed with %s" %
+				(realCmd, signame.get(-retcode, "signal %i" % -retcode)))
+		else:
+			msg = _RETCODE_HINTS.get(retcode, None)
+			logSys.error("%s returned %i" % (realCmd, retcode))
+			if msg:
+				logSys.info("HINT on %i: %s"
+							% (retcode, msg % locals()))
 		return False
 	executeCmd = staticmethod(executeCmd)
 	

fail2ban/server/server.py

@@ -292,6 +292,12 @@ class Server:
 	
 	def getActionUnban(self, name, action):
 		return self.__jails.getAction(name).getAction(action).getActionUnban()
+	
+	def setActionTimeout(self, name, action, value):
+		self.__jails.getAction(name).getAction(action).setTimeout(value)
+	
+	def getActionTimeout(self, name, action):
+		return self.__jails.getAction(name).getAction(action).getTimeout()
 		
 	# Status
 	def status(self):

fail2ban/server/transmitter.py

@@ -234,6 +234,11 @@ class Transmitter:
 			value = " ".join(command[3:])
 			self.__server.setActionUnban(name, act, value)
 			return self.__server.getActionUnban(name, act)
+		elif command[1] == "timeout":
+			act = command[2]
+			value = int(command[3])
+			self.__server.setActionTimeout(name, act, value)
+			return self.__server.getActionTimeout(name, act)
 		raise Exception("Invalid command (no set action or not yet implemented)")
 	
 	def __commandGet(self, command):
@@ -288,6 +293,9 @@ class Transmitter:
 			act = command[2]
 			key = command[3]
 			return self.__server.getCInfo(name, act, key)
+		elif command[1] == "timeout":
+			act = command[2]
+			return self.__server.getActionTimeout(name, act)
 		raise Exception("Invalid command (no get action or not yet implemented)")
 	
 	def status(self, command):

fail2ban/tests/actiontestcase.py

@@ -116,4 +116,19 @@ class ExecuteAction(unittest.TestCase):
 
 	def testExecuteIncorrectCmd(self):
 		Action.executeCmd('/bin/ls >/dev/null\nbogusXXX now 2>/dev/null')
-		self.assertTrue(self._is_logged('HINT on 7f00: "Command not found"'))
+		self.assertTrue(self._is_logged('HINT on 127: "Command not found"'))
+
+	def testExecuteTimeout(self):
+		stime = time.time()
+		Action.executeCmd('sleep 60', timeout=2) # Should take a minute
+		self.assertAlmostEqual(time.time() - stime, 2.1, places=1)
+		self.assertTrue(self._is_logged('sleep 60 timed out after 2 seconds'))
+		self.assertTrue(self._is_logged('sleep 60 killed with SIGTERM'))
+
+	def testCaptureStdOutErr(self):
+		Action.executeCmd('echo "How now brown cow"')
+		self.assertTrue(self._is_logged("'How now brown cow\\n'"))
+		Action.executeCmd(
+			'echo "The rain in Spain stays mainly in the plain" 1>&2')
+		self.assertTrue(self._is_logged(
+			"'The rain in Spain stays mainly in the plain\\n'"))

fail2ban/tests/servertestcase.py

@@ -471,6 +471,14 @@ class Transmitter(TransmitterBase):
 			self.transm.proceed(
 				["set", self.jailName, "delcinfo", action, "KEY"]),
 			(0, None))
+		self.assertEqual(
+			self.transm.proceed(
+				["set", self.jailName, "timeout", action, "10"]),
+			(0, 10))
+		self.assertEqual(
+			self.transm.proceed(
+				["get", self.jailName, "timeout", action]),
+			(0, 10))
 		self.assertEqual(
 			self.transm.proceed(["set", self.jailName, "delaction", action]),
 			(0, None))