Query logs carry no query id and no info events

[robinskil]

What is missing

A query produces no log line at the default level. The default level is info.

run_query holds no info! event. The query handler holds none either.

The logs also hold no query id. run_query makes the id at runtime.rs:99. No log event records it.

The client reads the id from the x-beacon-query-id header. No log line matches that id.

Why this matters

The Atlas read path logs real numbers at debug level. Three examples:

• atlas create_physical_plan reports the collection count and the dataset count.
• atlas infer_schema reports the field count.
• AtlasSource morsel scan reports the datasets and the partitions.

No reader can attribute these lines to a query.

Two queries run at the same time. Their lines interleave. Nothing separates them.

Current state

The codebase holds one span. See runtime.rs:93:

#[tracing::instrument(skip(self, query, identity))]

The attribute skips every argument. So the span carries no field. It adds only a function name.

No other span exists. The codebase holds no info_span! call.

Steps

1. Make an info_span! after run_query makes the query id.
2. Record the id, the user and the query kind on the span.
3. Attach the span to the result stream. Use tracing::Instrument.
4. Add an info! event when a query starts.
5. Add an info! event when a query ends. Record the duration, the rows and the bytes.

Why step 3 matters

The setup ends before the scan runs. A client pulls batches after run_query returns.

A span on the function alone covers none of the read path.

One risk

Worker::prefetch starts each dataset open with tokio::spawn. A spawned task does not inherit the current span.

Instrument that task with Span::current(). Without this step the open logs stay orphaned.

Issue #482 changes the same spawn. Do both in one change.

Do not

Do not log per chunk. Do not log per batch.

A collection holds up to millions of datasets. Such an event floods the log.

The crate docs already state this rule. A skipped column logs at debug for the same reason.

Files

beacon-db/beacon-core/src/runtime.rs

beacon-server/beacon-server/src/axum/client/query.rs

beacon-db/beacon-file-formats/beacon-nd-array/src/arrow/morsel.rs

Related

#481, #482

Issue #486 covers the progress of an active query. This issue covers the logs of one query.