ENH: To help with gh-87 added hints into the log on some failure return codes (e.g. 0x7f00 for this one)

server/action.py

@@ -37,6 +37,17 @@ logSys = logging.getLogger("fail2ban.actions.action")
 # Create a lock for running system commands
 _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 '
+	        'are in the PATH of fail2ban-server process '
+			'(grep -a PATH= /proc/`pidof -x fail2ban-server`/environ). '
+			'You may want to start '
+			'"fail2ban-server -f" separately, initiate it with '
+			'"fail2ban-client reload" in another shell session and observe if '
+			'additional informative error messages appear in the terminals.'
+	}
+
 ##
 # Execute commands.
 #
@@ -330,7 +341,11 @@ class Action:
 					logSys.debug("%s returned successfully" % realCmd)
 					return True
 				else:
-					logSys.error("%s returned %x" % (realCmd, retcode))
+					msg = _RETCODE_HINTS.get(retcode, None)
+ 					logSys.error("%s returned %x" % (realCmd, retcode))
+					if msg:
+						logSys.info("HINT on %x: %s"
+									% (retcode, msg % locals()))
 			except OSError, e:
 				logSys.error("%s failed with %s" % (realCmd, e))
 		finally:

testcases/actiontestcase.py

@@ -28,7 +28,9 @@ __copyright__ = "Copyright (c) 2004 Cyril Jaquier"
 __license__ = "GPL"
 
 import unittest, time
+import logging, sys
 from server.action import Action
+from StringIO import StringIO
 
 class ExecuteAction(unittest.TestCase):
 
@@ -36,15 +38,43 @@ class ExecuteAction(unittest.TestCase):
 		"""Call before every test case."""
 		self.__action = Action("Test")
 
+		# For extended testing of what gets output into logging
+		# system, we will redirect it to a string
+		logSys = logging.getLogger("fail2ban")
+
+		# Keep old settings
+		self._old_level = logSys.level
+		self._old_handlers = logSys.handlers
+		# Let's log everything into a string
+		self._log = StringIO()
+		logSys.handlers = [logging.StreamHandler(self._log)]
+		logSys.setLevel(getattr(logging, 'DEBUG'))
+
 	def tearDown(self):
 		"""Call after every test case."""
+		# print "O: >>%s<<" % self._log.getvalue()
+		logSys = logging.getLogger("fail2ban")
+		logSys.handlers = self._old_handlers
+		logSys.level = self._old_level
 		self.__action.execActionStop()
-	
+
+	def _is_logged(self, s):
+		return s in self._log.getvalue()
+
 	def testExecuteActionBan(self):
 		self.__action.setActionStart("touch /tmp/fail2ban.test")
 		self.__action.setActionStop("rm -f /tmp/fail2ban.test")
 		self.__action.setActionBan("echo -n")
 		self.__action.setActionCheck("[ -e /tmp/fail2ban.test ]")
-		
+
+		self.assertFalse(self._is_logged('returned'))
+		# no action was actually executed yet
+
 		self.assertTrue(self.__action.execActionBan(None))
-		
+		self.assertTrue(self._is_logged('Invariant check failed'))
+		self.assertTrue(self._is_logged('returned successfully'))
+
+
+	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"'))