fix: Custom Gunicorn logger not sending StatsD stats (#4819)

Flagsmith · Nov 14, 2024 · 9bbfdf0 · 9bbfdf0
1 parent 4a310b0
commit 9bbfdf0
Show file tree

Hide file tree

Showing 2 changed files with 78 additions and 20 deletions.
diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py
@@ -2,12 +2,13 @@
 import logging
 import logging.config
 import os
+from datetime import datetime
 
 import pytest
-from gunicorn.config import Config
+from gunicorn.config import AccessLogFormat, Config
 from pytest_django.fixtures import SettingsWrapper
 
-from util.logging import JsonFormatter
+from util.logging import GunicornAccessLogJsonFormatter, JsonFormatter
 
 
 @pytest.mark.freeze_time("2023-12-08T06:05:47.320000+00:00")
@@ -28,7 +29,7 @@ def test_json_formatter__outputs_expected(
     expected_tb_string = (
         "Traceback (most recent call last):\n"
         f'  File "{expected_module_path}",'
-        " line 37, in _log_traceback\n"
+        " line 38, in _log_traceback\n"
         "    raise Exception()\nException"
     )
 
@@ -64,6 +65,66 @@ def _log_traceback() -> None:
     ]
 
 
+@pytest.mark.freeze_time("2023-12-08T06:05:47.320000+00:00")
+def test_gunicorn_access_log_json_formatter__outputs_expected() -> None:
+    # Given
+    gunicorn_access_log_json_formatter = GunicornAccessLogJsonFormatter()
+    log_record = logging.LogRecord(
+        name="gunicorn.access",
+        level=logging.INFO,
+        pathname="",
+        lineno=1,
+        msg=AccessLogFormat.default,
+        args={
+            "a": "requests",
+            "b": "-",
+            "B": None,
+            "D": 1000000,
+            "f": "-",
+            "h": "192.168.0.1",
+            "H": None,
+            "l": "-",
+            "L": "1.0",
+            "m": "GET",
+            "M": 1000,
+            "p": "<42>",
+            "q": "foo=bar",
+            "r": "GET",
+            "s": 200,
+            "T": 1,
+            "t": datetime.fromisoformat("2023-12-08T06:05:47.320000+00:00").strftime(
+                "[%d/%b/%Y:%H:%M:%S %z]"
+            ),
+            "u": "-",
+            "U": "/test",
+        },
+        exc_info=None,
+    )
+    expected_pid = os.getpid()
+
+    # When
+    json_log = gunicorn_access_log_json_formatter.get_json_record(log_record)
+
+    # Then
+    assert json_log == {
+        "duration_in_ms": 1000,
+        "levelname": "INFO",
+        "logger_name": "gunicorn.access",
+        "message": '192.168.0.1 - - [08/Dec/2023:06:05:47 +0000] "GET" 200 - "-" "requests"',
+        "method": "GET",
+        "path": "/test?foo=bar",
+        "pid": "<42>",
+        "process_id": expected_pid,
+        "referer": "-",
+        "remote_ip": "192.168.0.1",
+        "status": "200",
+        "thread_name": "MainThread",
+        "time": "2023-12-08T06:05:47+00:00",
+        "timestamp": "2023-12-08 06:05:47,319",
+        "user_agent": "requests",
+    }
+
+
 def test_gunicorn_json_capable_logger__non_existent_setting__not_raises(
     settings: SettingsWrapper,
 ) -> None:

diff --git a/api/util/logging.py b/api/util/logging.py
@@ -6,7 +6,7 @@
 
 from django.conf import settings
 from gunicorn.config import Config
-from gunicorn.glogging import Logger as GunicornLogger
+from gunicorn.instrument.statsd import Statsd as GunicornLogger
 
 
 class JsonFormatter(logging.Formatter):
@@ -27,30 +27,27 @@ def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]:
         return json_record
 
     def format(self, record: logging.LogRecord) -> str:
-        try:
-            return json.dumps(self.get_json_record(record))
-        except (ValueError, TypeError) as e:
-            return json.dumps({"message": f"{e} when dumping log"})
+        return json.dumps(self.get_json_record(record))
 
 
 class GunicornAccessLogJsonFormatter(JsonFormatter):
     def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]:
-        response_time = datetime.strptime(record.args["t"], "[%d/%b/%Y:%H:%M:%S %z]")
-        url = record.args["U"]
-        if record.args["q"]:
-            url += f"?{record.args['q']}"
+        args = record.args
+        url = args["U"]
+        if q := args["q"]:
+            url += f"?{q}"
 
         return {
             **super().get_json_record(record),
-            "time": response_time.isoformat(),
+            "time": datetime.strptime(args["t"], "[%d/%b/%Y:%H:%M:%S %z]").isoformat(),
             "path": url,
-            "remote_ip": record.args["h"],
-            "method": record.args["m"],
-            "status": str(record.args["s"]),
-            "user_agent": record.args["a"],
-            "referer": record.args["f"],
-            "duration_in_ms": record.args["M"],
-            "pid": record.args["p"],
+            "remote_ip": args["h"],
+            "method": args["m"],
+            "status": str(args["s"]),
+            "user_agent": args["a"],
+            "referer": args["f"],
+            "duration_in_ms": args["M"],
+            "pid": args["p"],
         }