Merge pull request #680 from nationalarchives/AYR-1297/logging-format

update logger config to json format

README.md

@@ -630,7 +630,42 @@ current_app.audit_logger.error('Some error message')
 
 The logs from the webapp, when used as above are output as a stream to stdout in the following format:
 
+LOG ENTRY for a page view using the @log_page_view decorator:
+
 ```sh
+START RequestId: 4e2b263b-fc27-4db2-b87e-867fc4596e69 Version: $LATEST
+
+[DEBUG]	2024-12-11T12:43:26.106Z	4e2b263b-fc27-4db2-b87e-867fc4596e69	host found: [test-url]
+
+{
+    "log_type": "audit_logger",
+    "timestamp": "2024-12-11 12:43:26,106",
+    "level": "INFO",
+    "remote_addr": "13.42.156.7",
+    "url": "test-url",
+    "event": "api_request",
+    "user_id": "anonymous",
+    "route": "/callback",
+    "method": "GET",
+    "caller_function": "callback",
+    "caller_module": "app.main.routes"
+}
+
+{
+    "event": "api_request",
+    "user_id": "anonymous",
+    "route": "/callback",
+    "method": "GET",
+    "caller_function": "callback",
+    "caller_module": "app.main.routes"
+}
+
+
+END RequestId: 4e2b263b-fc27-4db2-b87e-867fc4596e69
+```
+
+LOG ENTRY for an Error
+```
 [2023-12-15 15:40:14,119] 127.0.0.1 requested https://localhost:5000/logger_test?log_level=error
 ERROR in routes: Some error
 ```

app/logger_config.py

@@ -1,17 +1,50 @@
+import inspect
+import json
 import logging
 
 from flask import has_request_context, request
 
 
 class RequestFormatter(logging.Formatter):
     def format(self, record):
+
+        log_record = {
+            "log_type": record.name,
+            "timestamp": self.formatTime(record),
+            "level": record.levelname,
+        }
+
+        caller_function = ""
+        caller_module = ""
+
+        for frame in inspect.stack():
+            module_name = str(frame.frame.f_globals.get("__name__", ""))
+            if "app.logger_config" not in module_name:
+                if "app." in module_name:
+                    caller_function = frame.function
+                    caller_module = module_name
+                    break
+
         if has_request_context():
-            record.url = request.url
-            record.remote_addr = request.remote_addr
-        else:
-            record.url = None
-            record.remote_addr = None
-        return super().format(record)
+            log_record.update(
+                {
+                    "remote_addr": request.remote_addr,
+                    "url": request.url,
+                    "caller_function": caller_function,
+                    "caller_module": caller_module,
+                }
+            )
+
+        try:
+            message_data = json.loads(record.getMessage())
+            if isinstance(message_data, dict):
+                log_record.update(message_data)
+            else:
+                log_record["message"] = message_data
+        except json.JSONDecodeError:
+            log_record["message"] = record.getMessage()
+
+        return json.dumps(log_record)
 
 
 def setup_logger(name, level, formatter):
@@ -26,18 +59,10 @@ def setup_logger(name, level, formatter):
 
 def setup_logging(app):
     """Set up loggers for the app."""
-    audit_log_formatter = RequestFormatter(
-        "AUDIT_LOG\n"
-        "[%(asctime)s] %(remote_addr)s requested %(url)s\n"
-        "%(levelname)s in %(module)s: %(message)s"
-    )
+    audit_log_formatter = RequestFormatter()
     app.audit_logger = setup_logger(
         "audit_logger", logging.INFO, audit_log_formatter
     )
 
-    app_log_formatter = RequestFormatter(
-        "APP_LOG\n"
-        "[%(asctime)s] %(remote_addr)s requested %(url)s\n"
-        "%(levelname)s in %(module)s: %(message)s"
-    )
+    app_log_formatter = RequestFormatter()
     app.app_logger = setup_logger("app_logger", logging.INFO, app_log_formatter)

app/tests/test_middlewares.py

@@ -1,3 +1,5 @@
+import json
+
 import pytest
 from flask.testing import FlaskClient
 from moto import mock_aws
@@ -16,23 +18,32 @@
             {"user_id": "test_user"},
             lambda: "Test Response",
             b"Test Response",
-            f'{{"event": "api_request", "user_id": "test_user", "route": "{HOST}/test_route", "method": "GET"}}',
+            json.loads(
+                """{"event": "api_request", "user_id": "test_user", "route": "http://localhost/test_route",
+                "method": "GET"}"""
+            ),
         ),
         (
             "/anonymous_route",
             "GET",
             {},
             lambda: "Anonymous Response",
             b"Anonymous Response",
-            f'{{"event": "api_request", "user_id": "anonymous", "route": "{HOST}/anonymous_route", "method": "GET"}}',
+            json.loads(
+                """{"event": "api_request", "user_id": "anonymous", "route": "http://localhost/anonymous_route",
+                "method": "GET"}"""
+            ),
         ),
         (
             "/post_route",
             "POST",
             {"user_id": "test_user"},
             lambda: "Post Response",
             b"Post Response",
-            f'{{"event": "api_request", "user_id": "test_user", "route": "{HOST}/post_route", "method": "POST"}}',
+            json.loads(
+                """{"event": "api_request", "user_id": "test_user", "route": "http://localhost/post_route",
+                "method": "POST"}"""
+            ),
         ),
     ],
 )
@@ -48,9 +59,6 @@ def test_log_page_view(
     expected_log,
     caplog,
 ):
-    """Test that the log_page_view middleware generates the correct log when an
-    endpoint decorated with it is requested"""
-
     @app.route(route_path, methods=[method])
     @log_page_view
     def dynamic_route():
@@ -64,5 +72,6 @@ def dynamic_route():
     assert response.status_code == 200
     assert response.data == expected_response
 
+    logged_message = json.loads(caplog.records[0].message)
     assert caplog.records[0].levelname == "INFO"
-    assert caplog.records[0].message == expected_log
+    assert logged_message == expected_log