Additional information for web process in JSONFormatter (PP-1148) (#1771

)

When troubleshooting issues though cloudwatch logs on a busy server, its difficult to correlate particular requests made to the server to the log messages that are output, since many requests are coming in at once. I've come across this a couple times recently when troubleshooting.

This adds some additional keys to the output of JSONFormatter and to our UWSGI log output, so we can better correlate logs to requests.

core/service/logging/log.py

@@ -15,6 +15,16 @@
 if TYPE_CHECKING:
     from mypy_boto3_logs import CloudWatchLogsClient
 
+try:
+    from flask import request as flask_request
+except ImportError:
+    flask_request = None  # type: ignore[assignment]
+
+try:
+    import uwsgi
+except ImportError:
+    uwsgi = None
+
 
 class JSONFormatter(logging.Formatter):
     def __init__(self) -> None:
@@ -68,6 +78,23 @@ def ensure_str(s: Any) -> Any:
         )
         if record.exc_info:
             data["traceback"] = self.formatException(record.exc_info)
+        if record.process:
+            data["process"] = record.process
+
+        # If we are running in a Flask context, we include the request data in the log
+        if flask_request:
+            data["request"] = {
+                "path": flask_request.path,
+                "method": flask_request.method,
+                "host": flask_request.host_url,
+            }
+            if flask_request.query_string:
+                data["request"]["query"] = flask_request.query_string.decode()
+
+        # If we are running in uwsgi context, we include the worker id in the log
+        if uwsgi:
+            data["uwsgi"] = {"worker": uwsgi.worker_id()}
+
         return json.dumps(data)
 
 

docker/services/uwsgi/uwsgi.d/40_log.ini

@@ -1,5 +1,5 @@
 [uwsgi]
-log-format = [uwsgi] %(var.HTTP_X_FORWARDED_FOR) (%(addr)) - - [%(ltime)] "%(method) %(uri) %(proto)" %(status) %(size) "%(referer)" "%(uagent)" host_hdr=%(host) req_time_elapsed=%(msecs)
+log-format = [uwsgi] %(var.HTTP_X_FORWARDED_FOR) (%(addr)) - - [%(ltime)] "%(method) %(uri) %(proto)" %(status) %(size) "%(referer)" "%(uagent)" host_hdr=%(host) req_time_elapsed=%(msecs) process=%(pid) worker=%(wid)
 logfile-chmod = 644
 logger = stdio:
 logger = file:/var/log/uwsgi/uwsgi.log

pyproject.toml

@@ -163,6 +163,7 @@ module = [
     "pyld",
     "textblob.*",
     "unicodecsv",
+    "uwsgi",
     "wcag_contrast_ratio",
     "webpub_manifest_parser.*",
 ]

tests/core/conftest.py

@@ -4,6 +4,7 @@
     "tests.fixtures.announcements",
     "tests.fixtures.csv_files",
     "tests.fixtures.database",
+    "tests.fixtures.flask",
     "tests.fixtures.library",
     "tests.fixtures.opds2_files",
     "tests.fixtures.opds_files",

tests/core/service/logging/test_log.py

@@ -3,6 +3,7 @@
 import functools
 import json
 import logging
+import os
 import sys
 from collections.abc import Callable, Mapping
 from functools import partial
@@ -20,6 +21,7 @@
     create_stream_handler,
     setup_logging,
 )
+from tests.fixtures.flask import FlaskAppFixture
 
 
 class TestJSONFormatter:
@@ -40,6 +42,25 @@ def log_record(self) -> LogRecordCallable:
         )
 
     @freeze_time("1990-05-05")
+    def test_format(self, log_record: LogRecordCallable):
+        formatter = JSONFormatter()
+        record = log_record()
+        data = json.loads(formatter.format(record))
+        assert "host" in data
+        assert data["name"] == "some logger"
+        assert data["timestamp"] == "1990-05-05T00:00:00+00:00"
+        assert data["level"] == "DEBUG"
+        assert data["message"] == "A message"
+        assert data["filename"] == "pathname"
+        assert "traceback" not in data
+        assert data["process"] == os.getpid()
+
+        # If the record has no process, the process field is not included in the log.
+        record = log_record()
+        record.process = None
+        data = json.loads(formatter.format(record))
+        assert "process" not in data
+
     def test_format_exception(self, log_record: LogRecordCallable) -> None:
         formatter = JSONFormatter()
 
@@ -52,11 +73,7 @@ def test_format_exception(self, log_record: LogRecordCallable) -> None:
 
         record = log_record(exc_info=exc_info)
         data = json.loads(formatter.format(record))
-        assert data["name"] == "some logger"
-        assert data["timestamp"] == "1990-05-05T00:00:00+00:00"
-        assert data["level"] == "DEBUG"
-        assert data["message"] == "A message"
-        assert data["filename"] == "pathname"
+        assert "traceback" in data
         assert "ValueError: fake exception" in data["traceback"]
 
     @pytest.mark.parametrize(
@@ -116,6 +133,56 @@ def test_format_args(
         # The resulting data is always a Unicode string.
         assert data["message"] == expected
 
+    def test_flask_request(
+        self,
+        log_record: LogRecordCallable,
+        flask_app_fixture: FlaskAppFixture,
+    ) -> None:
+        # Outside a Flask request context, the request data is not included in the log.
+        formatter = JSONFormatter()
+        record = log_record()
+        data = json.loads(formatter.format(record))
+        assert "request" not in data
+
+        # Inside a Flask request context, the request data is included in the log.
+        with flask_app_fixture.test_request_context("/"):
+            data = json.loads(formatter.format(record))
+            assert "request" in data
+            request = data["request"]
+            assert request["path"] == "/"
+            assert request["method"] == "GET"
+            assert "host" in request
+            assert "query" not in request
+
+        with flask_app_fixture.test_request_context(
+            "/test?query=string&foo=bar", method="POST"
+        ):
+            data = json.loads(formatter.format(record))
+            assert "request" in data
+            request = data["request"]
+            assert request["path"] == "/test"
+            assert request["method"] == "POST"
+            assert request["query"] == "query=string&foo=bar"
+
+        # If flask is not installed, the request data is not included in the log.
+        with patch("core.service.logging.log.flask_request", None):
+            data = json.loads(formatter.format(record))
+            assert "request" not in data
+
+    def test_uwsgi_worker(self, log_record: LogRecordCallable) -> None:
+        # Outside a uwsgi context, the worker id is not included in the log.
+        formatter = JSONFormatter()
+        record = log_record()
+        data = json.loads(formatter.format(record))
+        assert "uwsgi" not in data
+
+        # Inside a uwsgi context, the worker id is included in the log.
+        with patch("core.service.logging.log.uwsgi") as mock_uwsgi:
+            mock_uwsgi.worker_id.return_value = 42
+            data = json.loads(formatter.format(record))
+            assert "uwsgi" in data
+            assert data["uwsgi"]["worker"] == 42
+
 
 class TestLogLoopPreventionFilter:
     @pytest.mark.parametrize(