From 1422c5c2797023dcfb5e38d2ad0d04db85343c61 Mon Sep 17 00:00:00 2001
From: Kevin Michel <kevin.michel@aiven.io>
Date: Wed, 17 Jan 2024 14:08:24 +0100
Subject: [PATCH] lower log level of GET calls to DEBUG

`POST` and `PUT` calls are much more interesting than `GET` calls,
at  least from the point of view of the server.

Log `GET` requests at the `DEBUG` level while logging other methods
at the `INFO` level.
---
 astacus/common/access_log.py         | 16 +++++++
 astacus/server.py                    |  6 +++
 tests/unit/common/test_access_log.py | 63 ++++++++++++++++++++++++++++
 3 files changed, 85 insertions(+)
 create mode 100644 astacus/common/access_log.py
 create mode 100644 tests/unit/common/test_access_log.py

diff --git a/astacus/common/access_log.py b/astacus/common/access_log.py
new file mode 100644
index 00000000..5a2a66b4
--- /dev/null
+++ b/astacus/common/access_log.py
@@ -0,0 +1,16 @@
+"""
+Copyright (c) 2024 Aiven Ltd
+See LICENSE for details
+"""
+from collections.abc import Sequence
+
+import logging
+
+
+class AccessLogLevelFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        # Lower the log level of GET requests from INFO to DEBUG
+        if isinstance(record.args, Sequence) and len(record.args) >= 2 and record.args[1] == "GET":
+            record.levelno = logging.DEBUG
+            record.levelname = logging.getLevelName(record.levelno)
+        return True
diff --git a/astacus/server.py b/astacus/server.py
index 932ed001..f83b6a8d 100644
--- a/astacus/server.py
+++ b/astacus/server.py
@@ -110,6 +110,11 @@ def _run_server(args) -> bool:
                     "fmt": '%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s',
                 },
             },
+            "filters": {
+                "access_log_level": {
+                    "()": "astacus.common.access_log.AccessLogLevelFilter",
+                },
+            },
             "handlers": {
                 "default": {
                     "class": "logging.StreamHandler",
@@ -119,6 +124,7 @@ def _run_server(args) -> bool:
                 "access": {
                     "class": "logging.StreamHandler",
                     "formatter": "access",
+                    "filters": ["access_log_level"],
                     "stream": "ext://sys.stdout",
                 },
             },
diff --git a/tests/unit/common/test_access_log.py b/tests/unit/common/test_access_log.py
new file mode 100644
index 00000000..fddc032e
--- /dev/null
+++ b/tests/unit/common/test_access_log.py
@@ -0,0 +1,63 @@
+"""
+Copyright (c) 2024 Aiven Ltd
+See LICENSE for details
+"""
+from astacus.common.access_log import AccessLogLevelFilter
+from collections.abc import Mapping
+from typing import Any
+
+import logging
+import pytest
+
+
+def create_record(msg: str, args: tuple[Any, ...] | Mapping[str, Any]) -> logging.LogRecord:
+    return logging.LogRecord(
+        name="test",
+        level=logging.INFO,
+        pathname="/",
+        lineno=0,
+        msg=msg,
+        args=args,
+        exc_info=None,
+    )
+
+
+def create_access_record(method: str) -> logging.LogRecord:
+    return create_record(
+        msg='%s - "%s %s HTTP/%s" %d',
+        args=("127.0.0.1:1234", method, "/foo", "HTTP/1.1"),
+    )
+
+
+def test_filter_lowers_level_of_get_method() -> None:
+    record = create_access_record(method="GET")
+    should_keep = AccessLogLevelFilter().filter(record)
+    assert should_keep
+    assert record.levelno == logging.DEBUG
+    assert record.levelname == "DEBUG"
+
+
+@pytest.mark.parametrize("method", ["POST", "PUT", "DELETE", "UNKNOWN"])
+def test_filter_keeps_level_of_other_methods(method: str) -> None:
+    record = create_access_record(method=method)
+    should_keep = AccessLogLevelFilter().filter(record)
+    assert should_keep
+    assert record.levelno == logging.INFO
+    assert record.levelname == "INFO"
+
+
+@pytest.mark.parametrize(
+    "record",
+    [
+        create_record(msg="no args", args=()),
+        create_record(msg="one arg:%s", args=("arg",)),
+        create_record(msg="arg1:%s, arg2: %s", args=("arg1", 2)),
+        create_record(msg="dict arg: %(a)s", args=({"a": 1},)),
+    ],
+    ids=["no args", "one arg", "non-method arg2", "dict args"],
+)
+def test_filter_ignores_surprising_log_messages(record: logging.LogRecord) -> None:
+    should_keep = AccessLogLevelFilter().filter(record)
+    assert should_keep
+    assert record.levelno == logging.INFO
+    assert record.levelname == "INFO"