refactor: clean up logging (#7419)

* fix: log to stdout/stderr in json format

* chore: remove UTILS_LOGGER_LEVELS

This is not used (there _is_ a setting for the
django.security logger in settings_local.py on
production, but it is redundant with the
settings.LOGGING configuration and is not doing
anything).

* chore: revert to debug_console django logging

* chore: log.log to syslog via datatracker logger

* chore: remove unused imports

---------

Co-authored-by: Robert Sparks <rjsparks@nostrum.com>

ietf/settings.py

@@ -236,7 +236,7 @@ LOGGING = {
     #
     'loggers': {
         'django': {
-            'handlers': ['debug_console', 'mail_admins'],
+            'handlers': ['debug_console', 'mail_admins',],
             'level': 'INFO',
         },
         'django.request': {
@@ -248,13 +248,17 @@ LOGGING = {
             'level': 'INFO',
         },
         'django.security': {
-	    'handlers': ['debug_console', ],
+	        'handlers': ['debug_console', ],
+            'level': 'INFO',
+        },
+ 	    'oidc_provider': {
+	        'handlers': ['debug_console', ],
+	        'level': 'DEBUG',
+	    },
+        'datatracker': {
+            'handlers': ['syslog'],
             'level': 'INFO',
         },
- 	'oidc_provider': {
-	    'handlers': ['debug_console', ],
-	    'level': 'DEBUG',
-	},
     },
     #
     # No logger filters
@@ -263,14 +267,7 @@ LOGGING = {
         'console': {
             'level': 'DEBUG',
             'class': 'logging.StreamHandler',
-            'formatter': 'plain',
+            'formatter': 'json',
-        },
-        'syslog': {
-            'level': 'DEBUG',
-            'class': 'logging.handlers.SysLogHandler',
-            'facility': 'user',
-            'formatter': 'plain',
-            'address': '/dev/log',
         },
         'debug_console': {
             # Active only when DEBUG=True
@@ -284,6 +281,13 @@ LOGGING = {
             'class': 'logging.StreamHandler',
             'formatter': 'django.server',
         },
+        'syslog': {
+            'level': 'DEBUG',
+            'class': 'logging.handlers.SysLogHandler',
+            'facility': 'user',
+            'formatter': 'plain',
+            'address': '/dev/log',
+        },
         'mail_admins': {
             'level': 'ERROR',
             'filters': [
@@ -325,18 +329,12 @@ LOGGING = {
             'style': '{',
             'format': '{levelname}: {name}:{lineno}: {message}',
         },
+        'json' : {
+            '()': 'pythonjsonlogger.jsonlogger.JsonFormatter'
+        }
     },
 }
 
-# This should be overridden by settings_local for any logger where debug (or
-# other) custom log settings are wanted.  Use "ietf/manage.py showloggers -l"
-# to show registered loggers.  The content here should match the levels above
-# and is shown as an example:
-UTILS_LOGGER_LEVELS: Dict[str, str] = {
-#    'django':           'INFO',
-#    'django.server':    'INFO',
-}
-
 # End logging
 # ------------------------------------------------------------------------
 

ietf/utils/log.py

@@ -9,37 +9,10 @@ import inspect
 import os.path
 import traceback
 
-from typing import Callable         # pyflakes:ignore
-
-try:
-    import syslog
-    logfunc = syslog.syslog             # type: Callable
-except ImportError:                     # import syslog will fail on Windows boxes
-    logging.basicConfig(filename='tracker.log',level=logging.INFO)
-    logfunc = logging.info
-    pass
-
 from django.conf import settings
 
 import debug                            # pyflakes:ignore
 
-formatter = logging.Formatter('{levelname}: {name}:{lineno}: {message}', style='{')
-for name, level in settings.UTILS_LOGGER_LEVELS.items():
-    logger = logging.getLogger(name)
-    if not logger.hasHandlers():
-        debug.say(' Adding handlers to logger %s' % logger.name)
-        
-        handlers = [
-                logging.StreamHandler(),
-                logging.handlers.SysLogHandler(address='/dev/log',
-                    facility=logging.handlers.SysLogHandler.LOG_USER),
-            ]
-        for h in handlers:
-            h.setFormatter(formatter)
-            h.setLevel(level)
-            logger.addHandler(h)
-    debug.say(" Setting %s logging level to %s" % (logger.name, level))
-    logger.setLevel(level)
 
 def getclass(frame):
     cls = None
@@ -56,20 +29,9 @@ def getcaller():
     return (pmodule, pclass, pfunction, pfile, pline)
 
 def log(msg, e=None):
-    "Uses syslog by preference.  Logs the given calling point and message."
+    "Logs the given calling point and message to the logging framework's datatracker handler at severity INFO"
-    global logfunc
+    if settings.SERVER_MODE == 'test' and not getattr(settings, 'show_logging',False):
-    def _flushfunc():
-        pass
-    _logfunc = logfunc
-    if settings.SERVER_MODE == 'test':
-        if getattr(settings, 'show_logging', False) is True:
-            _logfunc = debug.say
-            _flushfunc = sys.stdout.flush   # pyflakes:ignore (intentional redefinition)
-        else:
             return
-    elif settings.DEBUG == True:
-        _logfunc = debug.say
-        _flushfunc = sys.stdout.flush   # pyflakes:ignore (intentional redefinition)
     if not isinstance(msg, str):
         msg = msg.encode('unicode_escape')
     try:
@@ -82,11 +44,8 @@ def log(msg, e=None):
             where = " in " + func + "()"
     except IndexError:
         file, line, where = "/<UNKNOWN>", 0, ""
-    _flushfunc()
-    _logfunc("ietf%s(%d)%s: %s" % (file, line, where, msg))
-
-logger = logging.getLogger('django')
 
+    logging.getLogger("datatracker").info(msg=msg, extra = {"file":file, "line":line, "where":where})
 
 
 def exc_parts():
@@ -124,6 +83,7 @@ def assertion(statement, state=True, note=None):
     This acts like an assertion.  It uses the django logger in order to send
     the failed assertion and a backtrace as for an internal server error.
     """
+    logger = logging.getLogger("django") # Note this is a change - before this would have gone to "django"
     frame = inspect.currentframe().f_back
     value = eval(statement, frame.f_globals, frame.f_locals)
     if bool(value) != bool(state):
@@ -148,6 +108,7 @@ def assertion(statement, state=True, note=None):
 
 def unreachable(date="(unknown)"):
     "Raises an assertion or sends traceback to admins if executed."
+    logger = logging.getLogger("django")
     frame = inspect.currentframe().f_back
     if settings.DEBUG is True or settings.SERVER_MODE == 'test':
         raise AssertionError("Arrived at code in %s() which was marked unreachable on %s." % (frame.f_code.co_name, date))

ietf/utils/management/commands/showloggers.py

@@ -11,18 +11,7 @@ from django.core.management.base import BaseCommand
 import debug                            # pyflakes:ignore
 
 class Command(BaseCommand):
-    """
+    """Display a list or tree representation of python loggers"""
-    Display a list or tree representation of python loggers.
-
-    Add a UTILS_LOGGER_LEVELS setting in settings_local.py to configure
-    non-default logging levels for any registered logger, for instance:
-
-    UTILS_LOGGER_LEVELS = {
-        'oicd_provider': 'DEBUG',
-        'urllib3.connection': 'DEBUG',
-    }
-
-    """
 
     help = dedent(__doc__).strip()
 

requirements.txt

@@ -53,6 +53,7 @@ pyopenssl>=22.0.0    # Used by urllib3.contrib, which is used by PyQuery but not
 pyquery>=1.4.3
 python-dateutil>=2.8.2
 types-python-dateutil>=2.8.2
+python-json-logger>=2.0.7
 python-magic==0.4.18    # Versions beyond the yanked .19 and .20 introduce form failures
 pymemcache>=4.0.0  # for django.core.cache.backends.memcached.PyMemcacheCache
 python-mimeparse>=1.6    # from TastyPie