Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 6 additions & 11 deletions docs/module/logger.md
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
| --- | --- | --- |
Expand Down Expand Up @@ -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):

Expand Down
4 changes: 2 additions & 2 deletions src/fastapi_toolsets/logger/context.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
Expand Down Expand Up @@ -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:
Expand Down
4 changes: 2 additions & 2 deletions src/fastapi_toolsets/logger/formatters.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
8 changes: 4 additions & 4 deletions tests/test_logger.py
Original file line number Diff line number Diff line change
Expand Up @@ -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"):
Expand Down Expand Up @@ -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$",
),
(
Expand Down
Loading