From e0a5e6fade0f303cf2f595cde9c8f6519cc72698 Mon Sep 17 00:00:00 2001 From: Greg Price Date: Tue, 26 Sep 2017 17:28:28 -0700 Subject: [PATCH] logging: Explain quirks of Python logging config, and apply a style. This should make it a little easier to understand our logging config and make changes to it with confidence. Many of these items that are now redundant used to be required when we were setting disable_existing_loggers to True (before 500d81bf2), in order to exempt those loggers from being cleared out. Now they're not. One bit of test code needed a tweak to how it got its hands on the AdminZulipHandler instance; it can do it from the list on the root logger just as well as on the `django` logger. --- zerver/tests/test_logging_handlers.py | 14 +++---- zproject/settings.py | 55 ++++++++++++++------------- zproject/test_settings.py | 11 ++++-- 3 files changed, 41 insertions(+), 39 deletions(-) diff --git a/zerver/tests/test_logging_handlers.py b/zerver/tests/test_logging_handlers.py index b29eea7af9..6be0e23ebc 100644 --- a/zerver/tests/test_logging_handlers.py +++ b/zerver/tests/test_logging_handlers.py @@ -59,21 +59,17 @@ class AdminZulipHandlerTest(ZulipTestCase): # type: () -> None settings.LOGGING_NOT_DISABLED = True - def get_admin_zulip_handler(self, logger): - # type: (logging.Logger) -> Any - - # Ensure that AdminEmailHandler does not get filtered out - # even with DEBUG=True. - admin_email_handler = [ - h for h in logger.handlers + def get_admin_zulip_handler(self): + # type: () -> Any + return [ + h for h in logging.getLogger('').handlers if h.__class__.__name__ == "AdminZulipHandler" ][0] - return admin_email_handler def test_basic(self): # type: () -> None """A random exception passes happily through AdminZulipHandler""" - handler = self.get_admin_zulip_handler(self.logger) + handler = self.get_admin_zulip_handler() try: raise Exception("Testing Error!") except Exception: diff --git a/zproject/settings.py b/zproject/settings.py index f024a53bf5..30c25c32ba 100644 --- a/zproject/settings.py +++ b/zproject/settings.py @@ -1116,24 +1116,39 @@ LOGGING = { }, }, 'loggers': { + # The Python logging module uses a hierarchy of logger names for config: + # "foo.bar" has parent "foo" has parent "", the root. But the semantics + # are subtle: it walks this hierarchy once to find the log level to + # decide whether to log the record at all, then a separate time to find + # handlers to emit the record. + # + # For `level`, the most specific ancestor that has a `level` counts. + # For `handlers`, the most specific ancestor that has a `handlers` + # counts (assuming we set `propagate=False`, which we always do.) + # These are independent -- they might come at the same layer, or + # either one could come before the other. + # + # For `filters`, no ancestors count at all -- only the exact logger name + # the record was logged at. + # + # Upstream docs: https://docs.python.org/3/library/logging + # + # Style rules: + # * Always set `propagate=False` if setting `handlers`. + # * Setting `level` equal to the parent is redundant; don't. + # * Setting `handlers` equal to the parent is redundant; don't. + # * Always write in order: level, filters, handlers, propagate. + # root logger '': { - 'handlers': DEFAULT_ZULIP_HANDLERS, - 'filters': ['require_logging_enabled'], 'level': 'INFO', - 'propagate': False, + 'filters': ['require_logging_enabled'], + 'handlers': DEFAULT_ZULIP_HANDLERS, }, # Django, alphabetized - 'django': { - 'handlers': DEFAULT_ZULIP_HANDLERS, - 'level': 'INFO', - 'propagate': False, - }, 'django.request': { - 'handlers': DEFAULT_ZULIP_HANDLERS, 'level': 'WARNING', - 'propagate': False, 'filters': ['skip_boring_404s'], }, 'django.security.DisallowedHost': { @@ -1141,21 +1156,21 @@ LOGGING = { 'propagate': False, }, 'django.server': { + 'filters': ['skip_200_and_304'], 'handlers': ['console', 'file'], 'propagate': False, - 'filters': ['skip_200_and_304'], }, 'django.template': { - 'handlers': ['console'], - 'filters': ['require_debug_true', 'skip_site_packages_logs'], 'level': 'DEBUG', + 'filters': ['require_debug_true', 'skip_site_packages_logs'], + 'handlers': ['console'], 'propagate': False, }, ## Uncomment the following to get all database queries logged to the console # 'django.db': { - # 'handlers': ['console'], # 'level': 'DEBUG', + # 'handlers': ['console'], # 'propagate': False, # }, @@ -1164,35 +1179,23 @@ LOGGING = { 'level': 'WARNING', }, 'requests': { - 'handlers': DEFAULT_ZULIP_HANDLERS, 'level': 'WARNING', - 'propagate': False, }, # our own loggers, alphabetized 'zulip.management': { 'handlers': ['file', 'errors_file'], - 'level': 'INFO', 'propagate': False, }, 'zulip.queue': { - 'handlers': DEFAULT_ZULIP_HANDLERS, 'level': 'WARNING', - 'propagate': False, - }, - 'zulip.requests': { - 'handlers': DEFAULT_ZULIP_HANDLERS, - 'level': 'INFO', - 'propagate': False, }, 'zulip.soft_deactivation': { 'handlers': ['file', 'errors_file'], - 'level': 'INFO', 'propagate': False, }, 'zulip.zerver.webhooks': { 'handlers': ['file', 'errors_file'], - 'level': 'INFO', 'propagate': False, }, } diff --git a/zproject/test_settings.py b/zproject/test_settings.py index 7764d1bbdf..4bd8445aeb 100644 --- a/zproject/test_settings.py +++ b/zproject/test_settings.py @@ -109,10 +109,13 @@ else: CACHES['default'] = { 'BACKEND': 'django.core.cache.backends.locmem.LocMemCache' } - LOGGING['loggers']['zulip.requests']['level'] = 'CRITICAL' - LOGGING['loggers']['zulip.management']['level'] = 'CRITICAL' - LOGGING['loggers']['django.request'] = {'level': 'ERROR'} - LOGGING['loggers']['fakeldap'] = {'level': 'ERROR'} + + def set_loglevel(logger_name, level): + LOGGING['loggers'].setdefault(logger_name, {})['level'] = level + set_loglevel('zulip.requests', 'CRITICAL') + set_loglevel('zulip.management', 'CRITICAL') + set_loglevel('django.request', 'ERROR') + set_loglevel('fakeldap', 'ERROR') # Enable file:/// hyperlink support by default in tests ENABLE_FILE_LINKS = True