#1308 - add IP and request ID to auth logs

Author: alitheg

atr/docs/authentication-security.md

@@ -256,6 +256,8 @@ ATR also does not ship with built in alert thresholds or automatic blocking rule
 An audit log, at `<STATE_DIR>/audit/auth-audit.log`, contains a log of all auth-adjacent operations. This should include authentication success/failures, token issuance/revocation,
 and anything else that would be relevant to authentication when investigating a potential security issue.
 
+Each entry is also tagged with the `request_id` and `source_ip` of the originating request, where one is in scope, so auth events can be correlated with the request summaries in `<STATE_DIR>/logs/requests.log`. Both are pulled from the request log context rather than passed at the call site.
+
 This log is logged to by calling the specialised methods on atr.log (all args passed below as kwargs for readability):
 
 ```python

atr/log.py

@@ -224,7 +224,17 @@ def warning(msg: str, **kwargs) -> None:
 def _auth_log(**kwargs):
     now = datetime.datetime.now(datetime.UTC).isoformat(timespec="milliseconds")
     now = now.replace("+00:00", "Z")
-    kwargs = {"datetime": now, **kwargs}
+    # Pull the request-scoped correlation fields from the log context, the same
+    # way the caller's user_id is sourced, so every auth entry can be tied back
+    # to a request and its origin
+    context: dict[str, Any] = {"datetime": now}
+    request_id = get_request_id()
+    if request_id is not None:
+        context["request_id"] = request_id
+    source_ip = get_context("source_ip")
+    if isinstance(source_ip, str):
+        context["source_ip"] = source_ip
+    kwargs = {**context, **kwargs}
     msg = json.dumps(kwargs, allow_nan=False)
     logger = logging.getLogger("atr.auth")
     logger.info(msg)

atr/server.py

@@ -1179,6 +1179,7 @@ async def handle_rate_limit(e):
 async def _reset_request_log_context():
     log.clear_context()
     log.add_context(request_id=str(uuid.uuid4()))
+    log.add_context(source_ip=quart.request.remote_addr)
     session = await sessions.read()
     if isinstance(session, sql.UserSession):
         log.add_context(user_id=session.uid)

tests/unit/test_auth_audit_log.py

@@ -0,0 +1,60 @@
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+#
+#   http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+import json
+import logging
+
+import atr.log as log
+
+
+def _capture_auth_log() -> list[str]:
+    captured: list[str] = []
+
+    class _Handler(logging.Handler):
+        def emit(self, record: logging.LogRecord) -> None:
+            captured.append(record.getMessage())
+
+    logger = logging.getLogger("atr.auth")
+    logger.handlers.clear()
+    logger.addHandler(_Handler())
+    logger.setLevel(logging.INFO)
+    logger.propagate = False
+    return captured
+
+
+def test_auth_log_omits_request_fields_when_no_request_context_is_bound() -> None:
+    log.clear_context()
+    captured = _capture_auth_log()
+
+    log.auth_success(type="oauth", asfuid="alice")
+
+    entry = json.loads(captured[-1])
+    assert "request_id" not in entry
+    assert "source_ip" not in entry
+
+
+def test_auth_log_carries_request_id_and_source_ip_from_the_log_context() -> None:
+    log.clear_context()
+    log.add_context(request_id="req-123", source_ip="203.0.113.7")
+    captured = _capture_auth_log()
+    try:
+        log.auth_failure(type="jwt", reason="bad token", asfuid="bob")
+
+        entry = json.loads(captured[-1])
+        assert entry["request_id"] == "req-123"
+        assert entry["source_ip"] == "203.0.113.7"
+    finally:
+        log.clear_context()