update logging setup to respect json setting (#13216)

* fix json_log to ensure we really only log json

* also control gunicorn

* reduce noise in action

.github/workflows/qc_checks.yaml

@@ -22,6 +22,7 @@ env:
   INVENTREE_BACKUP_DIR: /home/runner/work/InvenTree/test_inventree_backup
   INVENTREE_SITE_URL: http://localhost:8000
   INVENTREE_DEBUG: true
+  INVENTREE_GUNICORN_ACCESS_LOG: false
 
 permissions:
   contents: read

contrib/container/gunicorn.conf.py

@@ -4,12 +4,22 @@ import logging
 import multiprocessing
 import os
 
+
+def _env_flag(name: str):
+    """Read a boolean environment variable."""
+    value = os.environ.get(name, str(True))
+    return value.strip().lower() in ['1', 'y', 'yes', 't', 'true', 'on']
+
+
 # Logger configuration
+GUNICORN_ACCESS_LOG = _env_flag('INVENTREE_GUNICORN_ACCESS_LOG')
+GUNICORN_ERROR_LOG = _env_flag('INVENTREE_GUNICORN_ERROR_LOG')
+
 logger = logging.getLogger('inventree')
-accesslog = '-'
-errorlog = '-'
+accesslog = '-' if GUNICORN_ACCESS_LOG else None
+errorlog = '-' if GUNICORN_ERROR_LOG else None
 loglevel = os.environ.get('INVENTREE_LOG_LEVEL', 'warning').lower()
-capture_output = True
+capture_output = GUNICORN_ERROR_LOG
 
 # Worker configuration
 #  TODO: Implement support for gevent

docs/docs/start/config.md

@@ -102,6 +102,8 @@ The following debugging / logging options are available:
 {{ configsetting("INVENTREE_DEBUG_QUERYCOUNT") }} Enable support for [django-querycount](../develop/index.md#django-querycount) middleware. |
 {{ configsetting("INVENTREE_DEBUG_SILK") }} Enable support for [django-silk](../develop/index.md#django-silk) profiling tool. |
 | `INVENTREE_DEBUG_SILK_PROFILING` | `debug_silk_profiling` | False | Enable detailed profiling in django-silk |
+| `INVENTREE_GUNICORN_ACCESS_LOG` | - | True | Enable gunicorn access logging |
+| `INVENTREE_GUNICORN_ERROR_LOG` | - | True | Enable gunicorn error logging |
 
 ### Debug Mode
 

src/backend/InvenTree/InvenTree/settings.py

@@ -108,7 +108,29 @@ JSON_LOG = get_boolean_setting('INVENTREE_JSON_LOG', 'json_log', False)
 WRITE_LOG = get_boolean_setting('INVENTREE_WRITE_LOG', 'write_log', False)
 CONSOLE_LOG = get_boolean_setting('INVENTREE_CONSOLE_LOG', 'console_log', True)
 
-logging.basicConfig(level=LOG_LEVEL, format='%(asctime)s %(levelname)s %(message)s')
+# Ensure all log records have the same shape
+LOG_FOREIGN_PRE_CHAIN = [
+    structlog.processors.TimeStamper(fmt='iso'),
+    structlog.stdlib.add_logger_name,
+    structlog.stdlib.add_log_level,
+]
+LOG_JSON_PROCESSORS = [
+    structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+    structlog.processors.format_exc_info,
+    structlog.processors.JSONRenderer(),
+]
+
+if JSON_LOG:
+    # startup logging
+    _early_log_handler = logging.StreamHandler()
+    _early_log_handler.setFormatter(
+        structlog.stdlib.ProcessorFormatter(
+            processors=LOG_JSON_PROCESSORS, foreign_pre_chain=LOG_FOREIGN_PRE_CHAIN
+        )
+    )
+    logging.basicConfig(level=LOG_LEVEL, handlers=[_early_log_handler])
+else:
+    logging.basicConfig(level=LOG_LEVEL, format='%(asctime)s %(levelname)s %(message)s')
 
 if LOG_LEVEL not in ['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']:
     LOG_LEVEL = 'WARNING'  # pragma: no cover
@@ -124,27 +146,34 @@ LOGGING = {
     'formatters': {
         'json_formatter': {
             '()': structlog.stdlib.ProcessorFormatter,
-            'processor': structlog.processors.JSONRenderer(),
+            'processors': LOG_JSON_PROCESSORS,
+            'foreign_pre_chain': LOG_FOREIGN_PRE_CHAIN,
         },
         'plain_console': {
             '()': structlog.stdlib.ProcessorFormatter,
             'processor': structlog.dev.ConsoleRenderer(),
+            'foreign_pre_chain': LOG_FOREIGN_PRE_CHAIN,
         },
         'key_value': {
             '()': structlog.stdlib.ProcessorFormatter,
             'processor': structlog.processors.KeyValueRenderer(
                 key_order=['timestamp', 'level', 'event', 'logger']
             ),
+            'foreign_pre_chain': LOG_FOREIGN_PRE_CHAIN,
         },
     },
     'handlers': {
-        'console': {'class': 'logging.StreamHandler', 'formatter': 'plain_console'}
+        'console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'json_formatter' if JSON_LOG else 'plain_console',
+        }
     }
     if CONSOLE_LOG
     else {},
+    'root': {'handlers': DEFAULT_LOG_HANDLER, 'level': LOG_LEVEL},
     'loggers': {
-        'django_structlog': {'handlers': DEFAULT_LOG_HANDLER, 'level': LOG_LEVEL},
-        'inventree': {'handlers': DEFAULT_LOG_HANDLER, 'level': LOG_LEVEL},
+        'django_structlog': {'level': LOG_LEVEL},
+        'inventree': {'level': LOG_LEVEL},
     },
 }
 
@@ -514,10 +543,7 @@ if LDAP_AUTH:  # pragma: no cover
     if LDAP_DEBUG:
         if 'loggers' not in LOGGING:
             LOGGING['loggers'] = {}
-        LOGGING['loggers']['django_auth_ldap'] = {
-            'level': 'DEBUG',
-            'handlers': DEFAULT_LOG_HANDLER,
-        }
+        LOGGING['loggers']['django_auth_ldap'] = {'level': 'DEBUG'}
 
     # Determine LDAP settings
     ldap_settings = ldap.get_ldap_config(debug=LDAP_DEBUG)