diff --git a/docs/module/logger.md b/docs/module/logger.md index 87b6f53..55e6b3f 100644 --- a/docs/module/logger.md +++ b/docs/module/logger.md @@ -120,21 +120,16 @@ You then get validation and `.env` files from pydantic, and the settings can liv On a terminal, a request logs short lines: ```text -18:00:59.934 INFO myapp.auth Flag submitted challenge_id=42 correct=False [2fd09820] +18:00:59.934 INFO myapp.auth Flag submitted challenge_id=42 correct=False [2fd09820] user=3f2a9c1e 18:00:59.934 INFO access GET /api/challenges/42 200 0.5ms [2fd09820] user=3f2a9c1e ip=127.0.0.1 ``` -- Each line shows fields passed through `extra=`, then the first characters of the request id in brackets. -- The access line shows the fields bound for the whole request once, shortened: `*_id` fields lose their suffix and are cut to the request id length, and `client_ip` becomes `ip`. `trace_id` and `span_id` are treated the same way. +- Each line shows fields passed through `extra=`, the first characters of the request id in brackets, then the fields you [bound](#request-context). +- The client IP and the trace ids are shown on the access line only. The request id links the other lines to it. +- Bound fields are shortened: `*_id` fields lose their suffix and are cut to the request id length, and `client_ip` becomes `ip`. - The access line leaves out `method`, `path`, `route`, `status` and `duration_ms`, which its message already shows. -Fields bound with `log_context` inside a handler end before the access line, so they are shown, shortened the same way, on the lines logged within the block: - -```text -18:00:59.934 INFO myapp.export Export started [2fd09820] job=nightly-export -``` - -Outside a request, bound fields are shown on every line. JSON and OpenTelemetry output always keep every field and the full ids. +Outside a request, every bound field is shown on every line. JSON and OpenTelemetry output always keep every field and the full ids. | Field | Purpose | Default | | --- | --- | --- | @@ -181,7 +176,7 @@ async def current_user(...) -> User: return user ``` -The field stays bound until the request ends, including on its access line. It works from sync dependencies too. +The field stays bound until the request ends, so it is on every line logged after the bind, access line included. It works from sync dependencies too. To bind fields for a block only, use [`log_context`](../reference/logger.md#fastapi_toolsets.logger.log_context): diff --git a/src/fastapi_toolsets/logger/context.py b/src/fastapi_toolsets/logger/context.py index b42f297..fe7ffc0 100644 --- a/src/fastapi_toolsets/logger/context.py +++ b/src/fastapi_toolsets/logger/context.py @@ -21,7 +21,7 @@ _log_context: ContextVar[dict[str, Any] | None] = ContextVar( "fastapi_toolsets_log_context", default=None ) -# The fields bound for the whole request, shared with ``_log_context`` there. +# The fields the request was opened with, before the app binds its own. _request_context: ContextVar[dict[str, Any] | None] = ContextVar( "fastapi_toolsets_request_context", default=None ) @@ -80,7 +80,7 @@ def request_log_context(**values: Any) -> Generator[None, None, None]: **values: Fields to bind. """ with log_context(**values): - token = _request_context.set(_log_context.get()) + token = _request_context.set(current_log_context()) try: yield finally: diff --git a/src/fastapi_toolsets/logger/formatters.py b/src/fastapi_toolsets/logger/formatters.py index f913588..4a5bd72 100644 --- a/src/fastapi_toolsets/logger/formatters.py +++ b/src/fastapi_toolsets/logger/formatters.py @@ -95,8 +95,8 @@ def format(self, record: logging.LogRecord) -> str: class ConsoleFormatter(logging.Formatter): """Render a record as one short line for reading in a terminal. - Within a request, the fields bound for the whole request are replaced by - a short request id tag and shown only on the access line. + Within a request, the fields it was opened with and the trace ids are + replaced by a short request id tag and shown only on the access line. Args: colors: Color the level and dim the logger name and fields. diff --git a/tests/test_logger.py b/tests/test_logger.py index 52a976e..301c3f6 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -626,12 +626,12 @@ def test_console_shows_fields_bound_inside_a_request_after_its_id(self): assert line.endswith("hello [r1] user=u2 job=export step=2") - def test_console_defers_fields_bound_on_the_request_to_the_access_line(self): - with request_log_context(request_id="r1"): + def test_console_shows_fields_bound_on_the_request_on_every_line(self): + with request_log_context(request_id="r1", client_ip="127.0.0.1"): bind_log_context(user_id="u1") line = ConsoleFormatter().format(_record(**current_log_context())) - assert line.endswith("hello [r1]") + assert line.endswith("hello [r1] user=u1") def test_console_shows_bound_fields_on_every_line_outside_a_request(self): with log_context(job="nightly", run_id="0123456789"): @@ -835,7 +835,7 @@ async def test_each_request_gets_an_id_shared_by_its_records_and_access_line( [ ( "/items/3", - " myapp reading [{id}]", + " myapp reading [{id}] user=u1", r" access GET /items/3 200 [\d.]+ms \[{id}\] user=u1 ip=127\.0\.0\.1$", ), (