relocate exception-safe logging from database json-handler to common logger handling, using injection on _log-method of Logger class;

additionally provides more info if handler/conversion failed (with double protection inside catch-case);
tests/utils.py: log handler "_MemHandler" of LogCaptureTestCase fixed now to be safe also (test-cases only);
tests/misctestcase.py: the safe logging of all possible constellations is covered in testSafeLogging now.

fail2ban/helpers.py

@@ -202,6 +202,35 @@ class FormatterWithTraceBack(logging.Formatter):
 		return logging.Formatter.format(self, record)
 
 
+__origLog = logging.Logger._log
+def __safeLog(self, level, msg, args, **kwargs):
+	"""Safe log inject to avoid possible errors by unsafe log-handlers, 
+	concat, str. conversion, representation fails, etc.
+
+	Used to intrude exception-safe _log-method instead of _log-method 
+	of Logger class to be always safe by logging and to get more-info about.
+
+	See testSafeLogging test-case for more information. At least the errors
+	covered in phase 3 seems to affected in all known pypy/python versions 
+	until now.
+	"""
+	try:
+		# if isEnabledFor(level) already called...
+		__origLog(self, level, msg, args, **kwargs)
+	except Exception as e: # pragma: no cover - unreachable if log-handler safe in this python-version
+		try:
+			for args in (
+				("logging failed: %r on %s", (e, uni_string(msg))),
+				("  args: %r", ([uni_string(a) for a in args],))
+			):
+				try:
+					__origLog(self, level, *args)
+				except: # pragma: no cover
+					pass
+		except: # pragma: no cover
+			pass
+logging.Logger._log = __safeLog
+
 def getLogger(name):
 	"""Get logging.Logger instance with Fail2Ban logger name convention
 	"""

fail2ban/server/database.py

@@ -51,11 +51,8 @@ if sys.version_info >= (3,): # pragma: 2.x no cover
 			x = json.dumps(x, ensure_ascii=False, default=_json_default).encode(
 				PREFER_ENC, 'replace')
 		except Exception as e:
-			# adapter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
+			# adapter handler should be exception-safe
 			logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
 			x = '{}'
 		return x
 
@@ -63,11 +60,8 @@ if sys.version_info >= (3,): # pragma: 2.x no cover
 		try:
 			x = json.loads(x.decode(PREFER_ENC, 'replace'))
 		except Exception as e:
-			# converter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
+			# converter handler should be exception-safe
 			logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
 			x = {}
 		return x
 else: # pragma: 3.x no cover
@@ -87,11 +81,8 @@ else: # pragma: 3.x no cover
 		try:
 			x = json.dumps(_normalize(x), ensure_ascii=False, default=_json_default)
 		except Exception as e:
-			# adapter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
+			# adapter handler should be exception-safe
 			logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
 			x = '{}'
 		return x
 
@@ -99,11 +90,8 @@ else: # pragma: 3.x no cover
 		try:
 			x = json.loads(x.decode(PREFER_ENC, 'replace'))
 		except Exception as e:
-			# converter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
+			# converter handler should be exception-safe
 			logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
 			x = {}
 		return x
 

fail2ban/tests/misctestcase.py

@@ -201,6 +201,48 @@ class TestsUtilsTest(LogCaptureTestCase):
 		uni_string('test\xcf')
 		uni_string(u'test\xcf')
 
+	def testSafeLogging(self):
+		# logging should be exception-safe, to avoid possible errors (concat, str. conversion, representation failures, etc)
+		logSys = DefLogSys
+		class Test:
+			def __init__(self, err=1):
+				self.err = err
+			def __repr__(self):
+				if self.err:
+					raise Exception('no represenation for test!')
+				else:
+					return u'conv-error (\xf2\xf0\xe5\xf2\xe8\xe9), unterminated utf \xcf'
+		test = Test()
+		logSys.log(logging.NOTICE, "test 1a: %r", test)
+		self.assertLogged("Traceback", "no represenation for test!")
+		self.pruneLog()
+		logSys.notice("test 1b: %r", test)
+		self.assertLogged("Traceback", "no represenation for test!")
+
+		self.pruneLog('[phase 2] test error conversion by encoding %s' % sys.getdefaultencoding())
+		test = Test(0)
+		# this may produce coversion error on ascii default encoding:
+		#str(test)
+		logSys.log(logging.NOTICE, "test 2a: %r, %s", test, test)
+		self.assertLogged("test 2a", "Error by logging handler", all=False)
+		logSys.notice("test 2b: %r, %s", test, test)
+		self.assertLogged("test 2b", "Error by logging handler", all=False)
+
+		self.pruneLog('[phase 3] test unexpected error in handler')
+		class _ErrorHandler(logging.Handler):
+			def handle(self, record):
+				raise Exception('error in handler test!')
+		_org_handler = logSys.handlers
+		try:
+			logSys.handlers = list(logSys.handlers)
+			logSys.handlers += [_ErrorHandler()]
+			logSys.log(logging.NOTICE, "test 3a")
+			logSys.notice("test 3b")
+		finally:
+			logSys.handlers = _org_handler
+		# we should reach this line without errors!
+		self.pruneLog('OK')
+
 	def testTraceBack(self):
 		# pretty much just a smoke test since tests runners swallow all the detail
 

fail2ban/tests/utils.py

@@ -667,11 +667,14 @@ class LogCaptureTestCase(unittest.TestCase):
 				self._strm.truncate(0)
 
 		def __write(self, record):
+			try:
 				msg = record.getMessage() + '\n'
 				try:
 					self._strm.write(msg)
 				except UnicodeEncodeError: # pragma: no cover - normally unreachable now
 					self._strm.write(msg.encode('UTF-8', 'replace'))
+			except Exception as e: # pragma: no cover - normally unreachable
+				self._strm.write('Error by logging handler: %r' % e)
 
 		def getvalue(self):
 			"""Return current buffer as whole string."""