fix: add extra info to logs

.conf/gunicorn.conf.py

@@ -1,9 +1,27 @@
 from logging.handlers import DEFAULT_TCP_LOGGING_PORT
 
+from gunicorn.glogging import Logger
+
+
 workers = 7
 threads = 10
 limit_request_line = 8190
 
+
+class CustomLogger(Logger):
+
+    def atoms(self, resp, req, environ, request_time):
+        atoms = super().atoms(resp, req, environ, request_time)
+        atoms.update({
+            "user_id": environ.get('user_id', '---'),
+            "trace_id": environ.get('trace_id', '---'),
+            "impersonating": environ.get('impersonating', '---'),
+        })
+        return atoms
+
+
+logger_class = CustomLogger
+
 logconfig_dict = dict(
     version=1,
     disable_existing_loggers=False,

admin_cohort/middleware/context_request_middleware.py

@@ -2,9 +2,11 @@
 from contextvars import ContextVar, Token
 from typing import Optional, Any, Type
 
+import jwt
 from django.conf import settings
 from django.http import HttpRequest
 
+
 context_request: ContextVar[Optional[HttpRequest]] = ContextVar("context_request", default=None)
 
 
@@ -13,8 +15,19 @@ def get_trace_id() -> str:
     if not request:
         return str(uuid.uuid4())
     trace_id_header = settings.TRACE_ID_HEADER
-    trace_id = request.headers.get(trace_id_header, request.META.get(f"HTTP_{trace_id_header}"))
-    return trace_id
+    return request.headers.get(trace_id_header, request.META.get(f"HTTP_{trace_id_header}"))
+
+def get_request_user_id(request) -> str:
+    user_id = "Anonymous"
+    bearer_token = request.META.get("HTTP_AUTHORIZATION")
+    auth_token = bearer_token and bearer_token.split("Bearer ")[1] or None
+    if auth_token is not None:
+        try:
+            decoded = jwt.decode(jwt=auth_token, options={'verify_signature': False})
+            user_id = decoded.get("preferred_username", decoded.get("username"))
+        except jwt.PyJWTError:
+            pass
+    return user_id
 
 
 class ContextRequestHolder:
@@ -38,6 +51,11 @@ def __init__(self, get_response):
         self.get_response = get_response
 
     def __call__(self, request):
+        request.environ.update({
+            'user_id': get_request_user_id(request),
+            'trace_id': request.headers.get(settings.TRACE_ID_HEADER, str(uuid.uuid4())),
+            'impersonating': request.headers.get(settings.IMPERSONATING_HEADER, "-")
+        })
         with ContextRequestHolder(request):
             response = self.get_response(request)
         return response

admin_cohort/settings.py

@@ -8,7 +8,7 @@
 from celery.schedules import crontab
 
 TITLE = "Portail/Cohort360 API"
-VERSION = "3.24.1"
+VERSION = "3.24.2"
 AUTHOR = "Assistance Publique - Hopitaux de Paris, Département I&D"
 DESCRIPTION_MD = f"""Supports the official **Cohort360** web app and **Portail**  
                      Built by **{AUTHOR}**
@@ -66,13 +66,12 @@
                loggers={
                    'info': {
                        'level': "INFO",
-                       'handlers': ['info_handler'] + (DEBUG and ['console'] or []),
+                       'handlers': ['info'] + (DEBUG and ['console'] or []),
                        'propagate': False
                    },
                    'django.request': {
                        'level': "ERROR",
-                       'handlers': ['error_handler'] + (DEBUG and ['console'] or []) + (
-                               NOTIFY_ADMINS and ['mail_admins'] or []),
+                       'handlers': ['error'] + (DEBUG and ['console'] or []) + (NOTIFY_ADMINS and ['mail_admins'] or []),
                        'propagate': False
                    }
                },
@@ -87,14 +86,14 @@
                        'class': "logging.StreamHandler",
                        'filters': ["request_headers_interceptor"]
                    },
-                   'info_handler': {
+                   'info': {
                        'level': "INFO",
                        'class': "admin_cohort.tools.logging.CustomSocketHandler",
                        'host': "localhost",
                        'port': DEFAULT_TCP_LOGGING_PORT,
                        'filters': ["request_headers_interceptor"]
                    },
-                   'error_handler': {
+                   'error': {
                        'level': "ERROR",
                        'class': "admin_cohort.tools.logging.CustomSocketHandler",
                        'host': "localhost",

admin_cohort/tools/logging.py

@@ -4,6 +4,7 @@
 import traceback
 from logging.handlers import SocketHandler
 
+from gunicorn.glogging import SafeAtoms
 from django.conf import settings
 
 from admin_cohort.middleware.context_request_middleware import context_request
@@ -41,12 +42,19 @@ def makePickle(self, record):
 
         trace_id, user_id, impersonating = None, None, None
 
-        request_metadata = d.pop("request_metadata", None)
-        if request_metadata is not None:
+        # logs from Django
+        request_metadata = d.pop("request_metadata", {})
+        if request_metadata:
             trace_id = request_metadata.get("trace_id")
             user_id = request_metadata.get("user_id")
             impersonating = request_metadata.get("impersonating")
 
+        # logs from Gunicorn
+        if isinstance(record.args, SafeAtoms):
+            trace_id = record.args.get("trace_id")
+            user_id = record.args.get("user_id")
+            impersonating = record.args.get("impersonating")
+
         d['trace_id'] = trace_id
         d['user_id'] = user_id
         d['impersonating'] = impersonating

setup_logging.py

@@ -4,7 +4,6 @@
 import logging
 import socketserver
 import struct
-import sys
 from logging.handlers import DEFAULT_TCP_LOGGING_PORT
 from pathlib import Path
 
@@ -31,14 +30,12 @@ def handle(self, record):
 
 
 def configure_handlers() -> [logging.Handler]:
-    stream_handler = logging.StreamHandler(stream=sys.stdout)
     dj_info_handler = CustomFileHandler(name='info', filename=BASE_DIR / "log/django.log")
     dj_error_handler = CustomFileHandler(name='django.request', filename=BASE_DIR / "log/django.error.log")
     guni_error_handler = CustomFileHandler(name='gunicorn.error', filename=BASE_DIR / "log/gunicorn.error.log")
     guni_access_handler = CustomFileHandler(name='gunicorn.access', filename=BASE_DIR / "log/gunicorn.access.log")
 
-    handlers = [stream_handler,
-                dj_info_handler,
+    handlers = [dj_info_handler,
                 dj_error_handler,
                 guni_error_handler,
                 guni_access_handler]
@@ -55,8 +52,9 @@ def configure_handlers() -> [logging.Handler]:
                               " - %(message)s",
                               rename_fields={
                                   "asctime": "timestamp",
-                                  "trace_id": "traceId",
-                                  "user_id": "userId",
+                                  "trace_id": "x_traceId",
+                                  "user_id": "x_userId",
+                                  "impersonating": "x_impersonating",
                                   "levelname": "level",
                                   "threadName": "thread",
                                   "filename": "logger"
@@ -110,10 +108,7 @@ def serve_until_stopped(self):
 
 
 def main():
-    fmt = "%(levelname)s %(asctime)s <%(name)s> traceId=%(trace_id)s " \
-          "pid=%(process)d module=%(filename)s msg=`%(message)s`"
     logging.basicConfig(level=logging.INFO,
-                        format=fmt,
                         handlers=configure_handlers())
     tcp_server = LogRecordSocketReceiver()
     tcp_server.serve_until_stopped()