diff --git a/ChangeLog b/ChangeLog index 9dc616aa..1d3e3024 100644 --- a/ChangeLog +++ b/ChangeLog @@ -64,6 +64,13 @@ ver. 0.10.4-dev-1 (20??/??/??) - development edition * `filter.d/dovecot.conf`: failregex enhancement to catch sql password mismatch errors (gh-2153); * `action.d/hostsdeny.conf`: fix parameter in config (dynamic parameters stating with '_' are protected and don't allowed in command-actions), see gh-2114; +* decoding stability fix by wrong encoded characters like utf-8 surrogate pairs, etc (gh-2171): + - fail2ban running in the preferred encoding now (as default encoding also within python 2.x), mostly + `UTF-8` in opposite to `ascii` previously, so minimizes influence of implicit conversions errors; + - actions: avoid possible conversion errors on wrong-chars by replace tags; + - database: improve adapter/converter handlers working on invalid characters in sense of json and/or sqlite-database; + additionally both are exception-safe now, so avoid possible locking of database (closes gh-2137); + - logging in fail2ban is process-wide exception-safe now. ### New Features diff --git a/config/action.d/badips.py b/config/action.d/badips.py index 6a6760b5..4e50890c 100644 --- a/config/action.d/badips.py +++ b/config/action.d/badips.py @@ -18,16 +18,16 @@ # Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. import sys -if sys.version_info < (2, 7): +if sys.version_info < (2, 7): # pragma: no cover raise ImportError("badips.py action requires Python >= 2.7") import json import threading import logging -if sys.version_info >= (3, ): +if sys.version_info >= (3, ): # pragma: 2.x no cover from urllib.request import Request, urlopen from urllib.parse import urlencode from urllib.error import HTTPError -else: +else: # pragma: 3.x no cover from urllib2 import Request, urlopen, HTTPError from urllib import urlencode diff --git a/fail2ban/helpers.py b/fail2ban/helpers.py index 11dec5aa..5681c31b 100644 --- a/fail2ban/helpers.py +++ b/fail2ban/helpers.py @@ -45,7 +45,7 @@ if PREFER_ENC.startswith('ANSI_'): # pragma: no cover # caused by implicit converting of string/unicode (e. g. `str(u"\uFFFD")` produces an error # if default encoding is 'ascii'); if sys.version_info < (3,): # pragma: 3.x no cover - # correct default (global system) encoding (mostly UTF-8): + # correct default (global system) encoding (mostly UTF-8): def __resetDefaultEncoding(encoding): global PREFER_ENC ode = sys.getdefaultencoding().upper() @@ -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 df6ef3cb..662601e6 100644 --- a/fail2ban/server/database.py +++ b/fail2ban/server/database.py @@ -40,7 +40,7 @@ logSys = getLogger(__name__) def _json_default(x): - """Avoid errors on types unknow in json-adapters.""" + """Avoid errors on types unknown in json-adapters.""" if isinstance(x, set): x = list(x) return uni_string(x) @@ -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/action_d/test_badips.py b/fail2ban/tests/action_d/test_badips.py index 1cc3b19d..3ea1fc76 100644 --- a/fail2ban/tests/action_d/test_badips.py +++ b/fail2ban/tests/action_d/test_badips.py @@ -29,9 +29,9 @@ from ..dummyjail import DummyJail from ..servertestcase import IPAddr from ..utils import LogCaptureTestCase, CONFIG_DIR -if sys.version_info >= (3, ): +if sys.version_info >= (3, ): # pragma: 2.x no cover from urllib.error import HTTPError, URLError -else: +else: # pragma: 3.x no cover from urllib2 import HTTPError, URLError def skip_if_not_available(f): diff --git a/fail2ban/tests/databasetestcase.py b/fail2ban/tests/databasetestcase.py index c4e2e9bd..248ea9fd 100644 --- a/fail2ban/tests/databasetestcase.py +++ b/fail2ban/tests/databasetestcase.py @@ -305,6 +305,7 @@ class DatabaseTest(LogCaptureTestCase): self.assertEqual(readtickets[i].getIP(), ticket.getIP()) self.assertEqual(len(readtickets[i].getMatches()), len(ticket.getMatches())) + self.pruneLog('[test-phase 2] simulate errors') ## simulate errors in dumps/loads: priorEnc = database.PREFER_ENC try: @@ -323,6 +324,13 @@ class DatabaseTest(LogCaptureTestCase): self.assertEqual(len(readtickets), 14) finally: database.PREFER_ENC = priorEnc + + ## check the database is still operable (not locked) after all the errors: + self.pruneLog('[test-phase 3] still operable?') + self.db.addBan(self.jail, FailTicket("127.0.0.8")) + readtickets = self.db.getBans(jail=self.jail) + self.assertEqual(len(readtickets), 15) + self.assertNotLogged("json loads failed", "json dumps failed") def _testAdd3Bans(self): self.testAddJail() diff --git a/fail2ban/tests/misctestcase.py b/fail2ban/tests/misctestcase.py index 707b6423..cd27ad92 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 @@ -374,13 +416,10 @@ class TestsUtilsTest(LogCaptureTestCase): def testLazyLogging(self): logSys = DefLogSys - if unittest.F2B.log_lazy: - # wrong logging syntax will throw an error lazy (on demand): - logSys.debug('test', 1, 2, 3) - self.assertRaisesRegexp(Exception, 'not all arguments converted', lambda: self.assertNotLogged('test')) - else: # pragma: no cover - # wrong logging syntax will throw an error directly: - self.assertRaisesRegexp(Exception, 'not all arguments converted', lambda: logSys.debug('test', 1, 2, 3)) + logSys.debug('lazy logging: %r', unittest.F2B.log_lazy) + # wrong logging syntax will don't throw an error anymore (logged now): + logSys.notice('test', 1, 2, 3) + self.assertLogged('not all arguments converted') class MyTimeTest(unittest.TestCase): diff --git a/fail2ban/tests/utils.py b/fail2ban/tests/utils.py index 73f80e2a..b65e1c7c 100644 --- a/fail2ban/tests/utils.py +++ b/fail2ban/tests/utils.py @@ -671,11 +671,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."""