From bcf557990e15922aff22485cc86ddd2fcf41b796 Mon Sep 17 00:00:00 2001 From: sebres Date: Thu, 5 Jul 2018 22:35:35 +0200 Subject: [PATCH] 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 | 29 +++++++++++++++++++++++ fail2ban/server/database.py | 28 +++++++---------------- fail2ban/tests/misctestcase.py | 42 ++++++++++++++++++++++++++++++++++ fail2ban/tests/utils.py | 11 +++++---- 4 files changed, 86 insertions(+), 24 deletions(-) diff --git a/fail2ban/helpers.py b/fail2ban/helpers.py index 3297375b..5681c31b 100644 --- a/fail2ban/helpers.py +++ b/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 """ diff --git a/fail2ban/server/database.py b/fail2ban/server/database.py index 26e0223d..90a48d8d 100644 --- a/fail2ban/server/database.py +++ b/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: - logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) - except: # pragma: no cover - pass + # adapter handler should be exception-safe + logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) 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: - logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) - except: # pragma: no cover - pass + # converter handler should be exception-safe + logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) 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: - logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) - except: # pragma: no cover - pass + # adapter handler should be exception-safe + logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) 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: - logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) - except: # pragma: no cover - pass + # converter handler should be exception-safe + logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4) x = {} return x diff --git a/fail2ban/tests/misctestcase.py b/fail2ban/tests/misctestcase.py index 707b6423..1e75fb95 100644 --- a/fail2ban/tests/misctestcase.py +++ b/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 diff --git a/fail2ban/tests/utils.py b/fail2ban/tests/utils.py index 4a243cbe..55617874 100644 --- a/fail2ban/tests/utils.py +++ b/fail2ban/tests/utils.py @@ -667,11 +667,14 @@ class LogCaptureTestCase(unittest.TestCase): self._strm.truncate(0) def __write(self, record): - 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')) + 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."""