Skip to content

JSON logging mode for Kibana - #437

Open
krokicki wants to merge 1 commit into
fix-s3-listingsfrom
json-ecs-logging
Open

JSON logging mode for Kibana#437
krokicki wants to merge 1 commit into
fix-s3-listingsfrom
json-ecs-logging

Conversation

@krokicki

@krokicki krokicki commented Aug 28, 2026

Copy link
Copy Markdown
Member

Response times only ever existed in the text access log, where they could not be aggregated. Setting log_format: json (or FGC_LOG_FORMAT=json) now writes one Elastic Common Schema object per line to stdout, which a shipper parses straight off the container's logs — so p95/p99 can be charted from event.duration and broken down by endpoint, user or status code.

Text remains the default and stays human-readable; nothing changes unless you turn this on. Turn it on in production, leave it off for development.

Companion to JaneliaSciComp/x2s3#31, which does the same thing for x2s3 so both services land in Kibana with the same field names.

What's in it

The access log middleware keeps emitting exactly the line it emitted before, and additionally binds the same facts as ECS fields, which text mode ignores. Each line carries event.duration (nanoseconds, the ECS unit), http.request.method, http.response.status_code, url.path, client.ip, user.name, labels.token_id on API-token requests, and labels.endpoint — the handler function name, since raw paths have unbounded cardinality and are useless to aggregate over.

Each request also gets an id, returned in the x-request-id header and bound as trace.id to every line logged while serving it, so a bug report quoting the id finds the whole request, not just its access line.

ECS fields are written as dotted keys rather than nested dicts; Elasticsearch expands them on ingest, so the indexed document is the same one without any dict-building in the code.

Output configuration lives in a new fileglancer/logconf.py, deliberately free of Fileglancer imports so the setuid user worker can configure its logging without pulling in the server's auth stack. Workers inherit the format over FGC_LOG_FORMAT (added to the env allowlist — it is a literal text/json, not a secret). In text mode a worker's output is forwarded through the parent tagged [worker:username] as before; in JSON mode it writes its own complete records to the shared stdout, identifiable by process.pid.

Known limitation, and a possible follow-up

event.duration here is time-to-first-byte, not transfer time, because BaseHTTPMiddleware returns as soon as the response starts. That is fine for the API, and x2s3 serves the bulk data and does measure full transfer time.

If download latency ever needs charting, the follow-up is to rewrite AccessLogMiddleware as pure ASGI, the way x2s3's is — it can then measure to the last body chunk and count bytes off the wire. A comment marks the spot. Deliberately out of scope here.

Testing

tests/test_log.py gains coverage for both formats: JSON mode emits one parseable ECS object per request with a numeric duration, the handler's own log lines share the access line's trace.id, exceptions arrive as error.type/error.message/error.stack_trace rather than a wall of text, and text mode is confirmed to still be the default and still human-readable. 930 pass.

Docs

docs/StructuredLogging.md covers the field list, a Filebeat input snippet, and the Kibana side (set event.duration's field format to Duration/nanoseconds and a percentile agg reads as p95/p99 directly).

@StephanPreibisch @JaneliaSciComp/fileglancer

Response times were only ever in the text access log, where they could not be
aggregated. Setting log_format: json (or FGC_LOG_FORMAT=json) now writes one
Elastic Common Schema object per line to stdout, which a shipper can parse
straight off the container's logs, so p95/p99 can be charted from
event.duration and broken down by endpoint, user or status code. Text remains
the default and stays human-readable.

The access log middleware keeps emitting the same line and additionally binds
the same facts as ECS fields, which text mode ignores. Each request also gets
an id, returned in the x-request-id header and bound to every line logged while
serving it, so a bug report quoting the id finds the whole request.

Output configuration lives in a new fileglancer.logconf, kept free of
Fileglancer imports so the setuid user worker can configure its logging without
pulling in the server's auth stack. Workers inherit the format over
FGC_LOG_FORMAT.

event.duration here is time-to-first-byte, not transfer time, because
BaseHTTPMiddleware returns as soon as the response starts. That is fine for the
API; x2s3 serves the bulk data and does measure full transfer time. Charting
download latency would mean rewriting the middleware as pure ASGI, the way
x2s3's is.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@krokicki krokicki mentioned this pull request Aug 28, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant