Refactor logging field handling to use a unified fields mapping instead of loose keyword arguments

README.md

@@ -52,7 +52,7 @@ exception handling. Omit it for non-web applications.
    startup, and call `gflog.install_excepthook()` and `gflog.install_signal_handlers()`.
 
 5. **Log events:** Call `gflog.emit(logger, Log.YOUR_EVENT, "message",
-   field="value")`. Context is attached automatically.
+   fields={"field": "value"})`. Fields travel as one mapping. Context is attached automatically.
 
 For detailed steps with examples, see [docs/STARTING_GUIDE.md](docs/STARTING_GUIDE.md).
 A complete working FastAPI application is in [examples/](examples/).

docs/STARTING_GUIDE.md

@@ -224,30 +224,48 @@ pass to `FastAPI(lifespan=...)`, so it sits alongside whatever else the
 application does at startup. After a crash it emits no stopped event, because the
 excepthook has already reported it.
 
-Any further keyword argument is reported on the started event, for an
-application whose startup record carries more than the version and config path:
+The two events carry their own fields: how the process was configured belongs on
+started, what it ended up doing on stopped.
 
 ```python
-async with gflog.lifespan_logging(logger, version=read_version(), read_only_mode=True):
+async with gflog.lifespan_logging(
+    logger,
+    version=read_version(),
+    started_fields={"read_only_mode": True},
+    stopped_fields=teardown,
+):
 ```
 
-Routing still comes from the catalogue, so override `SYS_APP_STARTED` to name
-the field in its allow-list or it reaches no stream.
+Each mapping is read when its event fires, so `stopped_fields` may be a dict the
+application still holds and fills in while it runs. `version` and `config_path`
+win on started, `shutdown_reason` on stopped.
+
+Routing still comes from the catalogue, so override `SYS_APP_STARTED` or
+`SYS_APP_STOPPED` to name the field in its allow-list or it reaches no stream.
 
 ## 5. Log an event
 
 ```python
 logger = logging.getLogger("app.resources")   # under the configured logger_root
 
-gflog.emit(logger, Log.RESOURCE_CREATED, "resource created", resource_id="r-1", owner_id="o-1")
+gflog.emit(logger, Log.RESOURCE_CREATED, "resource created",
+           fields={"resource_id": "r-1", "owner_id": "o-1"})
+```
+
+Fields travel as one mapping, never as loose keyword arguments, pass such a mapping as one field:
+
+```python
+gflog.emit(logger, Log.REQUEST_RECEIVED, "request received",
+           fields={"request_headers": dict(request.headers)})
 ```
 
 `source` reports the real call site. An application helper that wraps `emit`
 should pass `stacklevel=2` so records point past the wrapper:
 
 ```python
-def log_rejected_request(logger, reason, **kwargs):
-    gflog.emit(logger, Log.REQUEST_REJECTED, reason, error_reason=reason, stacklevel=2, **kwargs)
+def log_rejected_request(logger, reason, fields=None):
+    gflog.emit(logger, Log.REQUEST_REJECTED, reason,
+               fields={**(fields or {}), "error_reason": reason}, stacklevel=2)
 ```
 
 ## 6. Bind context outside a request

examples/README.md

@@ -45,8 +45,8 @@ Four things have to happen, in this order:
    to `FastAPI(lifespan=...)`, so your startup work still fits alongside it.
 
 After that, call sites just log: `gflog.emit(logger, Log.SOMETHING, "message",
-field="value")`. The request id, client ip, endpoint, method and correlation
-metadata are attached for you.
+fields={"field": "value"})`. The request id, client ip, endpoint, method and
+correlation metadata are attached for you.
 
 ## The part worth copying most carefully
 

examples/fastapi_app/service.py

@@ -25,9 +25,7 @@ def create_resource(resource_id: str, owner_id: str, created_by: str) -> None:
         logger,
         Log.RESOURCE_CREATED,
         "resource created",
-        resource_id=resource_id,
-        owner_id=owner_id,
-        created_by=created_by,
+        fields={"resource_id": resource_id, "owner_id": owner_id, "created_by": created_by},
     )
 
 
@@ -41,8 +39,7 @@ def delete_resource(resource_id: str, reason: str) -> None:
         logger,
         Log.RESOURCE_DELETED,
         "resource deleted",
-        resource_id=resource_id,
-        reason=reason,
+        fields={"resource_id": resource_id, "reason": reason},
     )
 
 
@@ -54,7 +51,6 @@ def log_rejected_lookup(resource_id: str, error_reason: str) -> None:
         logger,
         Log.LOOKUP_REJECTED,
         "lookup rejected",
-        resource_id=resource_id,
-        error_reason=error_reason,
+        fields={"resource_id": resource_id, "error_reason": error_reason},
         stacklevel=2,
     )

gfmodules/logging/events.py

@@ -131,16 +131,22 @@ def emit(
     event: LogEvent,
     message: str,
     *,
+    fields: Mapping[str, Any] | None = None,
     event_id: str | None = None,
     exc_info: Any = None,
     stacklevel: int = 1,
-    **fields: Any,
 ) -> None:
     """``stacklevel`` follows the stdlib convention: 1 reports this function's
     caller, and a helper wrapping ``emit`` passes 2 to point past itself.
     """
+    values = dict(fields) if fields else {}
+
+    reserved = sorted(RESERVED_FIELDS & values.keys())
+    if reserved:
+        raise ValueError(f"event {event.event_id} names fields a log record reserves: {', '.join(reserved)}")
+
     if _strict_fields:
-        unrouted = unrouted_fields(event, fields)
+        unrouted = unrouted_fields(event, values)
         if unrouted:
             raise ValueError(f"event {event.event_id} routes none of these fields to any stream: {', '.join(unrouted)}")
 
@@ -153,7 +159,7 @@ def emit(
     }
     if event.fields:
         extra["field_streams"] = event.fields
-    extra.update(fields)
+    extra.update(values)
     logger.log(event.level, message, extra=extra, exc_info=exc_info, stacklevel=stacklevel + 1)
 
 
@@ -175,19 +181,19 @@ def event(
         event: LogEvent,
         message: str,
         *,
+        fields: Mapping[str, Any] | None = None,
         event_id: str | None = None,
         exc_info: Any = None,
         stacklevel: int = 1,
-        **fields: Any,
     ) -> None:
         emit(
             logger,
             event,
             message,
+            fields=fields,
             event_id=event_id,
             exc_info=exc_info,
             stacklevel=stacklevel + 1,
-            **fields,
         )
 
 

gfmodules/logging/exceptions.py

@@ -26,8 +26,10 @@ def log_unhandled_exception(
             logger,
             events.SYS_UNHANDLED_EXCEPTION,
             "unhandled exception",
+            fields={
+                "exception_type": type(exc).__name__,
+                "endpoint": request.url.path,
+                "method": request.method,
+            },
             exc_info=exc,
-            exception_type=type(exc).__name__,
-            endpoint=request.url.path,
-            method=request.method,
         )

gfmodules/logging/lifecycle.py

@@ -1,7 +1,7 @@
 import logging
 import signal
 import sys
-from collections.abc import AsyncGenerator
+from collections.abc import AsyncGenerator, Mapping
 from contextlib import asynccontextmanager
 from types import FrameType, TracebackType
 from typing import Any
@@ -54,8 +54,10 @@ def hook(
             logger,
             events.SYS_APP_CRASHED,
             "application crashed: uncaught exception",
-            shutdown_reason=shutdown_reason(),
-            last_exception_type=exc_type.__name__,
+            fields={
+                "shutdown_reason": shutdown_reason(),
+                "last_exception_type": exc_type.__name__,
+            },
             exc_info=(exc_type, exc_value, exc_tb),
         )
 
@@ -95,19 +97,22 @@ async def lifespan_logging(
     version: str,
     config_path: str | None = None,
     catalogue: type[EventCatalogue] | None = None,
-    **fields: Any,
+    started_fields: Mapping[str, Any] | None = None,
+    stopped_fields: Mapping[str, Any] | None = None,
 ) -> AsyncGenerator[None]:
-    """Extra keyword arguments are reported on the started event. Nothing is
-    emitted on the way out of a crash: the excepthook has already reported it.
+    """Emit startup and shutdown lifecycle events.
+
+    Started event includes version, config_path, and custom started_fields.
+    Stopped event includes shutdown_reason and custom stopped_fields.
+    Field mappings are evaluated when their event fires, allowing stopped_fields
+    to be updated during the run. Crashes are handled by excepthook.
     """
     events = resolve_catalogue(catalogue)
     events.event(
         logger,
         events.SYS_APP_STARTED,
         "application started",
-        version=version,
-        config_path=config_path,
-        **fields,
+        fields={**(started_fields or {}), "version": version, "config_path": config_path},
     )
     try:
         yield
@@ -117,5 +122,5 @@ async def lifespan_logging(
                 logger,
                 events.SYS_APP_STOPPED,
                 "application stopped",
-                shutdown_reason=shutdown_reason(),
+                fields={**(stopped_fields or {}), "shutdown_reason": shutdown_reason()},
             )

gfmodules/logging/middleware.py

@@ -223,8 +223,7 @@ async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -
                     _internal_logger(),
                     catalogue.SYS_MISSING_CORRELATION_ID,
                     f"request arrived without {CORRELATION_ID_HEADER}",
-                    endpoint=context.endpoint,
-                    method=context.method,
+                    fields={"endpoint": context.endpoint, "method": context.method},
                 )
 
             body = (
@@ -262,8 +261,8 @@ def _log_access(
             _access_logger(),
             catalogue.ACCESS_REQUEST,
             "access",
+            fields=fields,
             event_id=catalogue.access_event_id.get((request.method, _router_path(request))),
-            **fields,
         )
 
 

tests/test_end_to_end.py

@@ -41,9 +41,7 @@ async def list_resources() -> Response:
             logger,
             CompleteCatalogue.RESOURCE_CREATED,
             "resource created",
-            resource_id="12345",
-            owner_id="o-1",
-            created_by="alice",
+            fields={"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"},
         )
         return JSONResponse({"resources": []})
 

tests/test_events.py

@@ -52,7 +52,7 @@ class TestEmit:
     def test_stamps_the_event_id_and_streams_on_the_record(
         self, logger: logging.Logger, handler: RecordingHandler
     ) -> None:
-        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "resource created", resource_id="12345")
+        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "resource created", fields={"resource_id": "12345"})
 
         record = handler.records[0]
         assert record.event_id == "100607"  # type: ignore[attr-defined]
@@ -102,12 +102,80 @@ def test_carries_exception_information(self, logger: logging.Logger, handler: Re
         assert handler.records[0].exc_info[1] is exc
 
     def test_extra_fields_may_shadow_nothing_builtin(self, logger: logging.Logger, handler: RecordingHandler) -> None:
-        emit(logger, CompleteCatalogue.ACCESS_REQUEST, "access", status_code=204, duration_ms=7)
+        emit(logger, CompleteCatalogue.ACCESS_REQUEST, "access", fields={"status_code": 204, "duration_ms": 7})
 
         assert handler.records[0].status_code == 204  # type: ignore[attr-defined]
         assert handler.records[0].duration_ms == 7  # type: ignore[attr-defined]
 
 
+class TestFieldNamespace:
+    def test_a_splatted_mapping_cannot_reach_the_event_id(
+        self, logger: logging.Logger, handler: RecordingHandler
+    ) -> None:
+        headers = {"user-agent": "curl/8.5", "event_id": "666"}
+
+        with pytest.raises(TypeError):
+            emit(logger, CompleteCatalogue.ACCESS_REQUEST, "access", **headers)  # type: ignore[arg-type]
+
+        assert handler.records == []
+
+    def test_untrusted_keys_reach_the_record_only_as_field_values(
+        self, logger: logging.Logger, handler: RecordingHandler
+    ) -> None:
+        headers = {"user-agent": "curl/8.5", "event_id": "666"}
+
+        emit(logger, CompleteCatalogue.ACCESS_REQUEST, "access", fields={"request_headers": headers})
+
+        record = handler.records[0]
+        assert record.event_id == "094500"  # type: ignore[attr-defined]
+        assert record.request_headers == headers  # type: ignore[attr-defined]
+
+    def test_a_field_cannot_overwrite_the_stream_the_event_routes_to(
+        self, logger: logging.Logger, handler: RecordingHandler
+    ) -> None:
+        with pytest.raises(ValueError, match="stream"):
+            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"stream": "siem"})
+
+        assert handler.records == []
+
+    def test_a_field_cannot_overwrite_the_event_id(self, logger: logging.Logger) -> None:
+        with pytest.raises(ValueError, match="event_id"):
+            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"event_id": "666"})
+
+    def test_names_every_reserved_field_at_once(self, logger: logging.Logger) -> None:
+        with pytest.raises(ValueError, match="event_id, module"):
+            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"module": "auth", "event_id": "666"})
+
+    def test_refuses_reserved_names_with_strict_fields_off(self, logger: logging.Logger) -> None:
+        set_strict_fields(False)
+
+        with pytest.raises(ValueError, match="stream"):
+            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"stream": "siem"})
+
+    def test_the_reserved_parameters_still_work_as_keywords(
+        self, logger: logging.Logger, handler: RecordingHandler
+    ) -> None:
+        exc = ValueError("boom")
+
+        emit(
+            logger,
+            CompleteCatalogue.ACCESS_REQUEST,
+            "access",
+            fields={"status_code": 500},
+            event_id="100700",
+            exc_info=exc,
+        )
+
+        record = handler.records[0]
+        assert record.event_id == "100700"  # type: ignore[attr-defined]
+        assert record.status_code == 500  # type: ignore[attr-defined]
+        assert record.exc_info is not None
+
+    def test_the_catalogue_helper_guards_the_same_way(self, logger: logging.Logger) -> None:
+        with pytest.raises(ValueError, match="stream"):
+            CompleteCatalogue.event(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"stream": "siem"})
+
+
 class TestSourceResolution:
     """``source`` must name the call site, not the library's own wrapper."""
 
@@ -202,7 +270,7 @@ def test_the_reserved_set_covers_the_libraries_own_record_keys(self) -> None:
     def test_a_reserved_field_really_does_break_the_standard_library(self, logger: logging.Logger) -> None:
         """The check is worth having only if the failure it prevents is real."""
         with pytest.raises(KeyError, match="module"):
-            emit(logger, CompleteCatalogue.ACCESS_REQUEST, "access", module="auth")
+            logger.info("access", extra={"module": "auth"})
 
     def test_the_running_interpreter_adds_no_attribute_the_frozen_set_misses(self) -> None:
         """The guard on the frozen list.
@@ -325,27 +393,27 @@ def strict(self) -> Any:
 
     def test_rejects_a_field_no_stream_would_carry(self, logger: logging.Logger) -> None:
         with pytest.raises(ValueError, match="resouce_id"):
-            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", resouce_id="r-1")
+            emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"resouce_id": "r-1"})
 
     def test_accepts_an_allow_listed_field(self, logger: logging.Logger, handler: RecordingHandler) -> None:
-        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", resource_id="r-1")
+        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"resource_id": "r-1"})
 
         assert handler.records[0].resource_id == "r-1"  # type: ignore[attr-defined]
 
     def test_accepts_correlation_metadata_that_every_stream_keeps(
         self, logger: logging.Logger, handler: RecordingHandler
     ) -> None:
-        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", request_id="req-1")
+        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"request_id": "req-1"})
 
         assert handler.records[0].request_id == "req-1"  # type: ignore[attr-defined]
 
     def test_says_nothing_about_an_event_that_declares_no_routing(self, logger: logging.Logger) -> None:
-        emit(logger, LogEvent("1", logging.INFO, (LoggingStreams.APP,)), "no routing", anything="goes")
+        emit(logger, LogEvent("1", logging.INFO, (LoggingStreams.APP,)), "no routing", fields={"anything": "goes"})
 
     def test_is_off_by_default_so_a_typo_never_takes_a_request_down(self, logger: logging.Logger) -> None:
         set_strict_fields(False)
 
-        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", resouce_id="r-1")
+        emit(logger, CompleteCatalogue.RESOURCE_CREATED, "created", fields={"resouce_id": "r-1"})
 
     def test_reports_which_fields_reach_nothing(self) -> None:
         assert unrouted_fields(CompleteCatalogue.RESOURCE_CREATED, iter(["resource_id", "nope"])) == ("nope",)