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

@@ -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:

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,
         },
     }

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