diff --git a/README.md b/README.md index a3cfdb2..b62c430 100644 --- a/README.md +++ b/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/). diff --git a/docs/STARTING_GUIDE.md b/docs/STARTING_GUIDE.md index a60bd3a..b492f28 100644 --- a/docs/STARTING_GUIDE.md +++ b/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 diff --git a/examples/README.md b/examples/README.md index 47d474a..e4751b4 100644 --- a/examples/README.md +++ b/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 diff --git a/examples/fastapi_app/service.py b/examples/fastapi_app/service.py index 6f4e4a8..c7c3de4 100644 --- a/examples/fastapi_app/service.py +++ b/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, ) diff --git a/gfmodules/logging/events.py b/gfmodules/logging/events.py index f9ec16a..6f91e0a 100644 --- a/gfmodules/logging/events.py +++ b/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, ) diff --git a/gfmodules/logging/exceptions.py b/gfmodules/logging/exceptions.py index 1659e3f..718592d 100644 --- a/gfmodules/logging/exceptions.py +++ b/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, ) diff --git a/gfmodules/logging/lifecycle.py b/gfmodules/logging/lifecycle.py index 48e4751..96538d4 100644 --- a/gfmodules/logging/lifecycle.py +++ b/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()}, ) diff --git a/gfmodules/logging/middleware.py b/gfmodules/logging/middleware.py index 6f99f2d..fe8a72e 100644 --- a/gfmodules/logging/middleware.py +++ b/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, ) diff --git a/tests/test_end_to_end.py b/tests/test_end_to_end.py index 6e233a8..da987ee 100644 --- a/tests/test_end_to_end.py +++ b/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": []}) diff --git a/tests/test_events.py b/tests/test_events.py index c9da329..952acd8 100644 --- a/tests/test_events.py +++ b/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",) diff --git a/tests/test_lifecycle.py b/tests/test_lifecycle.py index 5bf6d99..8ae86f5 100644 --- a/tests/test_lifecycle.py +++ b/tests/test_lifecycle.py @@ -107,20 +107,55 @@ async def test_config_path_is_optional(self, logger: logging.Logger, records: Re async def test_carries_the_applications_own_fields_on_started( self, logger: logging.Logger, records: RecordingHandler ) -> None: - async with lifespan_logging(logger, version="1.2.3", read_only_mode=True): + async with lifespan_logging(logger, version="1.2.3", started_fields={"read_only_mode": True}): pass assert records.with_event_id(STARTED)[0].read_only_mode is True # type: ignore[attr-defined] - async def test_the_applications_own_fields_do_not_leak_onto_stopped( + async def test_the_started_fields_do_not_leak_onto_stopped( self, logger: logging.Logger, records: RecordingHandler ) -> None: """Stopped reports why the process ended, not how it was configured.""" - async with lifespan_logging(logger, version="1.2.3", read_only_mode=True): + async with lifespan_logging(logger, version="1.2.3", started_fields={"read_only_mode": True}): pass assert not hasattr(_stopped_records(records)[0], "read_only_mode") + async def test_carries_the_applications_own_fields_on_stopped( + self, logger: logging.Logger, records: RecordingHandler + ) -> None: + async with lifespan_logging(logger, version="1.2.3", stopped_fields={"requests_served": 41}): + pass + + assert _stopped_records(records)[0].requests_served == 41 # type: ignore[attr-defined] + + async def test_the_stopped_fields_do_not_leak_onto_started( + self, logger: logging.Logger, records: RecordingHandler + ) -> None: + async with lifespan_logging(logger, version="1.2.3", stopped_fields={"requests_served": 41}): + pass + + assert not hasattr(records.with_event_id(STARTED)[0], "requests_served") + + async def test_the_stopped_fields_are_read_when_the_process_ends( + self, logger: logging.Logger, records: RecordingHandler + ) -> None: + """What the application ended up doing is only known by then.""" + teardown: dict[str, Any] = {"requests_served": 0} + + async with lifespan_logging(logger, version="1.2.3", stopped_fields=teardown): + teardown["requests_served"] = 41 + + assert _stopped_records(records)[0].requests_served == 41 # type: ignore[attr-defined] + + async def test_the_shutdown_reason_is_not_the_applications_to_overwrite( + self, logger: logging.Logger, records: RecordingHandler + ) -> None: + async with lifespan_logging(logger, version="1.2.3", stopped_fields={"shutdown_reason": "whatever"}): + _record_signal_shutdown() + + assert _stopped_records(records)[0].shutdown_reason == "signal:SIGTERM" # type: ignore[attr-defined] + class TestExcepthook: def test_logs_the_crash_with_its_traceback(self, logger: logging.Logger, records: RecordingHandler) -> None: diff --git a/tests/test_routing.py b/tests/test_routing.py index 4ca0806..8bc970d 100644 --- a/tests/test_routing.py +++ b/tests/test_routing.py @@ -110,9 +110,7 @@ def test_an_application_event_reaches_the_streams_it_declares(self, delivered: l logging.getLogger("app.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", - owner_id="o-1", - created_by="alice", + fields={"resource_id": "r-1", "owner_id": "o-1", "created_by": "alice"}, ) event = CompleteCatalogue.RESOURCE_CREATED @@ -137,9 +135,7 @@ def test_an_application_logging_under_its_own_root_reaches_every_stream( logging.getLogger("svc.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", - owner_id="o-1", - created_by="alice", + fields={"resource_id": "r-1", "owner_id": "o-1", "created_by": "alice"}, ) assert streams_for(delivered, CompleteCatalogue.RESOURCE_CREATED.event_id) >= {"app", "siem"} @@ -152,7 +148,7 @@ def test_the_old_root_stops_being_routed(self, delivered: list[dict[str, Any]]) logging.getLogger("app.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", + fields={"resource_id": "r-1"}, ) assert streams_for(delivered, CompleteCatalogue.RESOURCE_CREATED.event_id) == {"debug"} @@ -185,7 +181,7 @@ def test_an_event_logged_outside_the_root_is_reported(self, delivered: list[dict logging.getLogger("app.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", + fields={"resource_id": "r-1"}, ) assert "logger app.service is outside the svc tree" in misrouting_reports(delivered)[0] @@ -196,7 +192,7 @@ def test_it_is_reported_once_per_logger(self, delivered: list[dict[str, Any]]) - stray = logging.getLogger("app.service") for _ in range(3): - gflog.emit(stray, CompleteCatalogue.RESOURCE_CREATED, "resource created", resource_id="r-1") + gflog.emit(stray, CompleteCatalogue.RESOURCE_CREATED, "resource created", fields={"resource_id": "r-1"}) assert len({report for report in misrouting_reports(delivered)}) == 1 @@ -208,7 +204,7 @@ def test_the_report_reaches_the_app_stream(self, delivered: list[dict[str, Any]] logging.getLogger("app.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", + fields={"resource_id": "r-1"}, ) assert streams_reporting(delivered, "is outside the") == {"app", "debug"} @@ -220,7 +216,7 @@ def test_a_correctly_routed_event_is_not_reported(self, delivered: list[dict[str logging.getLogger("svc.service"), CompleteCatalogue.RESOURCE_CREATED, "resource created", - resource_id="r-1", + fields={"resource_id": "r-1"}, ) assert misrouting_reports(delivered) == [] diff --git a/tests/test_testing_helpers.py b/tests/test_testing_helpers.py index a0bbf2d..2458ce8 100644 --- a/tests/test_testing_helpers.py +++ b/tests/test_testing_helpers.py @@ -27,7 +27,7 @@ def propagating_logger() -> None: class TestCaptureRecords: def test_captures_what_was_logged(self) -> None: with capture_records() as captured: - emit(logger, CREATED, "resource created", resource_id="12345") + emit(logger, CREATED, "resource created", fields={"resource_id": "12345"}) assert len(captured) == 1 assert captured.entries[0].event_id == "100607" @@ -36,7 +36,7 @@ def test_captures_what_was_logged(self) -> None: def test_renders_the_message_the_log_server_would_receive(self) -> None: with capture_records() as captured: - emit(logger, CREATED, "resource created", resource_id="12345", owner_id="o-1") + emit(logger, CREATED, "resource created", fields={"resource_id": "12345", "owner_id": "o-1"}) assert captured.entries[0].message == {"resource_id": "12345", "owner_id": "o-1"} @@ -84,13 +84,13 @@ def test_selects_records_by_stream_using_the_real_filters(self) -> None: class TestCaptureStream: def test_applies_the_per_event_field_allow_list(self) -> None: with capture_stream(LoggingStreams.SIEM) as siem: - emit(logger, CREATED, "created", resource_id="12345", owner_id="o-1", created_by="alice") + emit(logger, CREATED, "created", fields={"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}) assert siem == [{"resource_id": "12345"}] def test_the_app_stream_sees_its_own_allow_list(self) -> None: with capture_stream(LoggingStreams.APP) as app: - emit(logger, CREATED, "created", resource_id="12345", owner_id="o-1", created_by="alice") + emit(logger, CREATED, "created", fields={"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}) assert app == [{"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}] @@ -117,21 +117,21 @@ class TestNestedCaptures: def test_two_streams_observe_the_same_record(self) -> None: with capture_stream(LoggingStreams.APP) as app, capture_stream(LoggingStreams.SIEM) as siem: - emit(logger, CREATED, "created", resource_id="12345", owner_id="o-1", created_by="alice") + emit(logger, CREATED, "created", fields={"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}) assert app == [{"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}] assert siem == [{"resource_id": "12345"}] def test_a_field_can_be_shown_absent_from_one_stream_only(self) -> None: with capture_stream(LoggingStreams.APP) as app, capture_stream(LoggingStreams.SIEM) as siem: - emit(logger, CREATED, "created", resource_id="12345", owner_id="o-1", created_by="alice") + emit(logger, CREATED, "created", fields={"resource_id": "12345", "owner_id": "o-1", "created_by": "alice"}) assert_fields_absent(siem, "owner_id", "created_by") assert app[0]["owner_id"] == "o-1" def test_record_and_stream_captures_nest_together(self) -> None: with capture_records() as captured, capture_stream(LoggingStreams.SIEM) as siem: - emit(logger, CREATED, "created", resource_id="12345", owner_id="o-1") + emit(logger, CREATED, "created", fields={"resource_id": "12345", "owner_id": "o-1"}) assert len(captured) == 1 assert siem == [{"resource_id": "12345"}] @@ -139,8 +139,8 @@ def test_record_and_stream_captures_nest_together(self) -> None: def test_the_inner_capture_stops_at_its_own_block(self) -> None: with capture_stream(LoggingStreams.APP) as app: with capture_stream(LoggingStreams.SIEM) as siem: - emit(logger, CREATED, "created", resource_id="1") - emit(logger, CREATED, "created", resource_id="2") + emit(logger, CREATED, "created", fields={"resource_id": "1"}) + emit(logger, CREATED, "created", fields={"resource_id": "2"}) assert [message["resource_id"] for message in app] == ["1", "2"] assert [message["resource_id"] for message in siem] == ["1"] @@ -161,7 +161,7 @@ def test_captures_still_detach_the_real_handlers(self) -> None: class TestAssertEventEmitted: def test_returns_the_matching_record(self) -> None: with capture_records() as captured: - emit(logger, CREATED, "created", resource_id="12345") + emit(logger, CREATED, "created", fields={"resource_id": "12345"}) entry = assert_event_emitted(captured, CREATED, resource_id="12345") @@ -176,15 +176,15 @@ def test_fails_when_the_event_was_never_emitted(self) -> None: def test_fails_when_no_record_carries_the_expected_fields(self) -> None: with capture_records() as captured: - emit(logger, CREATED, "created", resource_id="99999") + emit(logger, CREATED, "created", fields={"resource_id": "99999"}) with pytest.raises(AssertionError, match="none carried"): assert_event_emitted(captured, CREATED, resource_id="12345") def test_matches_the_right_record_among_several(self) -> None: with capture_records() as captured: - emit(logger, CREATED, "first", resource_id="11111") - emit(logger, CREATED, "second", resource_id="22222") + emit(logger, CREATED, "first", fields={"resource_id": "11111"}) + emit(logger, CREATED, "second", fields={"resource_id": "22222"}) assert assert_event_emitted(captured, CREATED, resource_id="22222").description == "second"