FE-1221, SRE-810: Add structured correlated logging across the Petrinaut optimization pipeline#9059
Conversation
|
The latest updates on your projects. Learn more about Vercel for GitHub.
1 Skipped Deployment
|
github-actions
Bot
added
area/apps > hash*
PR SummaryMedium Risk Overview NodeAPI logs capacity rejections, stream open, terminal outcomes (
Tests and README document correlation, privacy constraints, and observability setup. Reviewed by Cursor Bugbot for commit 4de6125. Bugbot is set up for automated code reviews on this repo. Configure here. |
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
2f81742 to
e481051
Compare
…ization pipeline
One optimization is now traceable end to end: NodeAPI's x-hash-request-id
is forwarded upstream, the optimizer's run_id comes back as
X-Optimization-Run-ID and is logged on both sides, and the CLI receives
the run id at spawn as PETRINAUT_CORRELATION_ID.
- petrinaut-optimizer-client: openPetrinautOptimizationStream accepts a
requestId (sent as x-hash-request-id) and returns { events,
optimizationRunId } read from the X-Optimization-Run-ID header.
- hash-api: request-scoped child logger (Apollo pattern); logs request
acceptance, validation failures (issue counts and schema paths only),
capacity rejections, stream opening, and a terminal outcome with
durationMs (completed / timeout kind / upstream-error /
client-disconnected — disconnects no longer return silently).
- petrinaut-opt: stdlib JSON-lines logging to stdout (logging_config.py,
HASH_PETRINAUT_OPT_LOG_LEVEL, idempotent setup); inbound
x-hash-request-id and traceparent headers threaded into every study
lifecycle log (admission, capacity rejection, initialization,
study start/completion, per-trial outcomes, wall-clock ceiling,
disconnect, worker join timeout, CLI termination path, slot release).
CLI stderr is no longer discarded: each line is forwarded to a pn_cli
logger, truncated with a bounded pending buffer.
- petrinaut-cli: minimal JSON stderr diagnostics after the unchanged
ready handshake (bootstrap_completed, per-request id/method/durationMs/
outcome, stdin_eof), correlation id injected via cli.ts.
Logs never include manifests, user-authored code, or raw request bodies;
docs updated (README logging section, CLI stderr contract, threat model).
- Cap forwarded CLI stderr at 1000 lines/run (drain the rest) so a chatty or hostile CLI cannot flood the log pipeline; seed the drain thread with bytes read past the bootstrap handshake so an early CLI diagnostic is forwarded rather than dropped. - Truncate the per-trial pruned-error field and stop interpolating the raw CLI error into the log message; correct the docstring. - Log an error type and coarse category instead of the raw initialization error string, which can embed a user identifier or expression error; the full message still reaches the requester in the 500 detail. - Cap validation issue-path segments before they reach the 400 response or the log, since manifest keys are user-controlled and unbounded. - Capture the optimizer run id from a failed response so a pre-stream upstream failure still correlates end to end. - Charset-validate the traceparent trace id instead of int(..., 16), which accepted 0x-prefixed, underscored, and signed values. - Document the aggregate stderr cap and header validation in the threat model.
e481051 to
f813baf
Compare
![graphite-app[bot]](https://avatars.githubusercontent.com/in/158384?s=60&v=4){kind=small}
|
@kube do you want to change the description of the PR to mention that it now includes yz/sre-810-otlp-for-petrinaut-opt? |
kube
changed the title
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Reviewed with a focus on the OTel setup now included in this PR (SRE-810) alongside the correlated logging. Two blocking issues: (1) the new INFO-level lifecycle records are never emitted in production — the root logger stays at WARNING under python -m uvicorn, so the OTLP LoggingHandler receives nothing below WARNING (tests mask this via caplog.at_level); (2) the Docker HEALTHCHECK's GET /status probe is instrumented and produces a span every 30s whose name won't match the gateway's health-check drop rules, spamming Tempo (SRE-844-class noise) — excluded_urls fixes it at the source. One should-fix: the pruned-trial warning ships raw CLI stderr (potentially user-authored content) to Loki once the log bridge is live, contradicting the PR's own redaction rule. One non-blocking suggestion: constructing the OTLP exporters with explicit endpoint=/insecure= bypasses the standard per-signal/insecure env vars the SDK would honour on its own.
What I checked and found sound: provider wiring order (tracer/meter/logger providers set globally before instrument_app, resource/service name matches the infra-provisioned OTEL_SERVICE_NAME default, grpc default matches OTEL_EXPORTER_OTLP_PROTOCOL=grpc); graceful-shutdown flush via the lifespan; the study/trial span hierarchy — the explicit contextvars re-attach on the Optuna worker thread correctly parents optimization.trial under optimization.study under the request span, and FastAPI's instrumentation will extract an incoming W3C traceparent from the Node API when the caller injects one; pruned trials correctly avoid ERROR span status; the study span is reliably ended in the stream generators' finally; SSE streaming interacts fine with the instrumentation (long-lived request spans export on completion). I didn't re-raise points from existing threads (e.g. the open Bugbot note that shutdown_telemetry leaves _configured = True, which is worth addressing for the multi-lifespan/test case).
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 9b3110e. Configure here.
There was a problem hiding this comment.
Toolkit pass (pr-review-toolkit review-pr orchestration) supplementing the earlier Claude review at ee91b5f31 — reviewed at head 9b3110e89.
Dimensions run: code-reviewer, pr-test-analyzer, comment-analyzer, silent-failure-hunter, type-design-analyzer (code-simplifier skipped per command rules). Findings already raised by the existing Claude, Bugbot, and Graphite threads were deduplicated away; only the two README accuracy issues below are new.
Re-confirmed at this head, without re-raising: the four open comments from the earlier Claude review still apply, and Bugbot's open finding (shut-down TracerProvider left globally registered when bootstrap fails after trace.set_tracer_provider) is real — global registration happens before instrument_app can fail, and the OTEL API offers no un-set, so registration would need to move after the last fallible step. Notably solid in this PR: the terminal-outcome commit semantics in forwardOptimizationEvents, the lifecycle/timeout listener cleanup, the partial-bootstrap rollback test, and test coverage of every new lifecycle event on both sides of the service boundary.
2 participants
🌟 What is the purpose of this PR?
Make an optimization request traceable across NodeAPI and
petrinaut-opt, with enough boundary logging to diagnose the intermittent stagingnetwork error.This PR now configures OpenTelemetry, exporters, tracing providers, RED metrics, or CLI diagnostics since
yz/sre-810-otlp-for-petrinaut-optwas merged here. This PR supplies a small set of correlation attributes and lifecycle events that its OTEL logging bridge can export.🔗 Related links
network errorreproduction and diagnosisyz/sre-810-otlp-for-petrinaut-opt— complementary OTEL instrumentation🤝 Scope boundary with the OTEL branch
loggingOTEL_EXPORTER_OTLP_ENDPOINT,OTEL_EXPORTER_OTLP_PROTOCOL,OTEL_SERVICE_NAME, and other standardOTEL_*variables per H-5069At OTEL-branch commit
fcf1d0ce72, a three-way merge with this PR succeeds without conflicts. The OTEL branch still usesHASH_OTLP_ENDPOINTat that commit; changing it to standard OTEL variables remains SRE-810 work.This PR was trimmed to avoid overlap: it contains no Python logging-handler setup, JSON formatter, manual
traceparentparsing, custom OTEL variables, per-trial instrumentation, CLI JSON diagnostics, or CLI stderr log forwarding.🪪 Correlation identifiers and variables
requestIdx-hash-request-idpetrinaut-optrequest_idpetrinaut-optfromx-hash-request-idrun_idpetrinaut-optX-Optimization-Run-IDpetrinaut-optoptimizationRunIdX-Optimization-Run-IDThe two correlation chains are:
requestId→x-hash-request-id→ Pythonrequest_idrun_id→X-Optimization-Run-ID→ NodeAPI/browseroptimizationRunId🔍 What does this change?
requestIdas ordinary metadata; logs local capacity rejections, stream-open, client disconnect, and one terminal outcome withdurationMs,outcome, andoptimizationRunId.x-hash-request-idand returns{ events, optimizationRunId }, including the run id from failed upstream responses.petrinaut-opt: returnsX-Optimization-Run-IDand attachesrequest_idandrun_idto bounded capacity, initialization-failure, study-start, completion, failure, disconnect, and worker-timeout records.🧾 What is logged at each step?
warnrequestId,activeOptimizationCountwarnrequestId, active/max countsinforequestId,optimizationRunIdinforequestId,optimizationRunId,durationMs,outcome=completedwarnrequestId,optimizationRunId,durationMs,outcome=upstream-errorinforequestId,optimizationRunId,durationMs,outcome=client-disconnectedwarnrequestId,optimizationRunId,durationMs,outcome,errorType,timeoutKind,upstreamStatuswarnrequestId,optimizationRunId, internal write errorpetrinaut-optAPIcapacity_rejected)warningrequest_id, active/max countspetrinaut-optAPIinitialization_failed)errorrequest_id,run_id,error_typestudy_started)inforequest_id,run_id,trialsstudy_completed)inforequest_id,run_id,trialsstudy_failed)warningrequest_id,run_idclient_disconnected)inforequest_id,run_idworker_join_timeout)errorrequest_id,run_idPre-Merge Checklist 🚀
🚢 Has this modified a publishable library?
This PR:
📜 Does this require a change to the docs?
The changes in this PR:
🕸️ Does this require a change to the Turbo Graph?
The changes in this PR:
🛡 What tests cover this?
@apps/petrinaut-optunit suite — 53 passed@hashintel/petrinaut-cliunit suite — 33 passed; typecheck and ESLint passed@local/petrinaut-optimizer-clientbuild — passedThe fresh worktree does not contain the generated Petrinaut/design-system artifacts required for a package-wide website typecheck; CI is the authoritative full-package validation.
🐾 Remaining work
HASH_OTLP_ENDPOINTwith standard OTEL configuration (OTEL_EXPORTER_OTLP_ENDPOINT,OTEL_EXPORTER_OTLP_PROTOCOL,OTEL_SERVICE_NAME, etc.).network errorand use the NodeAPI terminal record (durationMs,outcome,optimizationRunId) to identify the failing boundary.How the loggers work
NodeAPI uses the existing application logger and passes
requestIdwith each record. This avoids constructing a new Winston logger and transport set per request. It logs only operational boundaries: local capacity, upstream stream-open, disconnect, and terminal success/failure.Python uses the named stdlib loggers
pn_apiandpn_optimize, attaching stable fields such asevent,request_id, andrun_idthroughextra. It does not install a handler or exporter here. The complementary OTEL setup can export those records and add active span context without competing configuration.The CLI cannot log to stdout because stdout carries protocol responses. Its stderr pipe is drained and discarded solely to prevent backpressure; this PR does not turn CLI output into service logs.