Skip to content

QFw: write a job's story in five log lines, stitched to its trace - #125

Merged
DougSO merged 3 commits into
mainfrom
telemetry-log-story
Oct 9, 2026
Merged

DougSO merged 3 commits into
mainfrom
telemetry-log-story

Conversation

@DougSO

@DougSO DougSO commented Oct 9, 2026

Copy link
Copy Markdown
Collaborator

Follow-up to #123 from wiring Loki into the cluster: the fake IQM logs nothing of its own inside a job's spans (its two per-job lines belong to the device query the client makes before the job starts), so its traces had no lines under the waterfall.

With the logs tier on, the instrumentation layer now writes the job's milestones itself, at debug like the rest of what QFw logs about a job:

  • client: submitted job <id>: N circuit(s), S shots and job <id> completed after T ms;
  • QPM: received circuit <cid> (qtask N): Q qubits, S shots, executing circuit <cid> on <device> via <api path>, circuit <cid> completed on <device> after T ms.

Each line is written while the job's span is current, so the tier stamps it with the trace and span ids. Two of those spans are not current on their own, the execute span begin_backend_execution opens and the job span outside job_scope, so the helper makes the span current for the one call. With the tier off the lines cost a boolean test and write nothing, to Loki or to DEFw's file.

The mock suite now runs the tier at debug and asserts the five lines against the trace ids of the QPM run and the client job. Syntax clean, mock 587 passed, unit 124 passed.

@DougSO

DougSO commented Oct 9, 2026

Copy link
Copy Markdown
Collaborator Author

Second commit, found by running this on the cluster: a DEFw service sets its Python log level after QFw's configure(), and DEFw's set_logging_level_helper removes every root handler when it does, the tier's included. In every real service process the tier therefore believed it was on while nothing was listening; the suite, without DEFw, could not see it. logs_enabled() now re-attaches the handler when it finds it gone, the story lines ask it before writing, and a unit test strips the root logger the way DEFw does and checks the recovery. The README's caveat is reworded accordingly.

DougSO added 3 commits October 9, 2026 16:33
…tier

QFw's own code writes a job's story at debug: a QPM's device query, the
circuit's qubit cap, a driver's progress. On the reference cluster those
are the lines a trace should show, and the warning tier never saw them,
while the debug tier drowned them in DEFw's work-request and RPC chatter.

The category filter no longer depends on the level. DEFw's transport
internals (CORE, WORKER, RPC, STACKTRACE) leave only with the new "all"
tier, whatever level they would otherwise pass, so "debug" is QFw's own
lines plus DEFw's service and application lines, and "all" is everything.
The seam takes a logs_internals flag for tests, which cover both.

Signed-off-by: Doug Oucharek <dougso@me.com>
With the logs tier on, the instrumentation layer now logs the job's
milestones itself: submitted and finished on the client, received,
executing and done on the QPM. Each line is written while the job's span
is current, so the tier stamps it with the trace, and the logs panel
under a waterfall has something to show for every backend. The fake IQM
logs nothing of its own inside a job's spans, so until now its traces
had no lines at all.

Debug, like the rest of what QFw logs about a job, and only when the
tier is on: with it off these cost a boolean test and write nothing to
DEFw's file. The spans that are not current when a milestone happens,
the execute span opened by begin_backend_execution and the job span
outside job_scope, are made current for the one call.

Signed-off-by: Doug Oucharek <dougso@me.com>
A DEFw service sets its Python log level after QFw has configured
telemetry, and DEFw's set_logging_level_helper removes every handler on
the root logger when it does. The tier's handler went with them, so in
every real service process the tier believed it was on while nothing it
owned was listening; the unit tests, with no DEFw, could not see it.

logs_enabled() now puts the handler back whenever it finds it gone. The
story lines ask it before they write, so the first line of the next job
restores the tier for everything the process logs from then on. A test
strips the root logger the way DEFw does and checks the recovery.

Signed-off-by: Doug Oucharek <dougso@me.com>
@DougSO
DougSO force-pushed the telemetry-log-story branch from d4bfeb9 to 4384208 Compare October 9, 2026 23:34
@DougSO

DougSO commented Oct 9, 2026

Copy link
Copy Markdown
Collaborator Author

Rebased onto main at c5a3048 and stacked on #124, since both change the same telemetry files: this branch now carries #124's commit followed by its own two, so the two PRs no longer collide. Merge #124 first and this one merges clean afterwards. (If this one were merged first, #124 would show no changes and could simply be closed.) One conflict on the rebase, in the design doc's logs bullet; resolved by keeping #124's wording and appending this PR's sentence. Syntax clean, mock 619 passed, unit 126 passed on the stacked tree. The earlier ci-mock failure was test_foreground_run_stops_on_sigterm, a service-plane test with a five-second readiness wait that passes here three times in a row and is unrelated to these changes.

@DougSO
DougSO merged commit 920a020 into main Oct 9, 2026
6 checks passed
@DougSO
DougSO deleted the telemetry-log-story branch October 9, 2026 23:38
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