Skip to content

feat: forward backend tracing logs to pixi as JSON-RPC notifications#6525

Draft
Hofer-Julian wants to merge 9 commits into
mainfrom
claude/pixi-pr-6312-design-41w08v
Draft

feat: forward backend tracing logs to pixi as JSON-RPC notifications#6525
Hofer-Julian wants to merge 9 commits into
mainfrom
claude/pixi-pr-6312-design-41w08v

Conversation

@Hofer-Julian

Copy link
Copy Markdown
Contributor

Description

Supersedes #6312.

Backend build processes previously rendered all their tracing output to stderr as plain text, so pixi could only treat it as opaque build output: no levels, no targets, no span context, and no interaction with pixi's own log filtering. This PR surfaces backend diagnostics as first-class tracing data in pixi, redesigned from scratch around the review feedback on #6312 (per-RPC span scoping, wrong dynamic-callsite levels, and the fragility of sentinel-tagged JSON sharing stderr with child processes).

Transport — JSON-RPC notifications instead of stderr sentinels or a dedicated socket. Structured records travel as log/message notifications on the existing stdin/stdout channel (LSP-style). This structurally resolves all three review concerns: the channel is process-scoped by nature (span ids stay valid across RPC calls, during setup, and between requests), it can never interleave with child-process stderr at the byte level, and there is zero platform-specific transport code — no Unix sockets, no named-pipe retry loops. To let the backend push notifications, the deprecated jsonrpc-stdio-server dependency is replaced with a small loop around the existing jsonrpc_core::IoHandler in which a single writer task owns stdout, fed by both RPC responses and notifications. The frontend receives them through jsonrpsee's subscribe_to_method.

Negotiation — a supports_log_messages flag on FrontendCapabilities. Backends stay silent unless the frontend advertises support during negotiateCapabilities, so both mixed-version directions (old pixi ↔ new backend, new pixi ↔ old backend) degrade to today's behavior. No Pixi Build API version bump is needed; the addition is documented as non-breaking in the version history.

Content split — INFO stays plaintext, the rest goes structured. rattler-build uses INFO-level tracing as its plaintext build-output stream, and pixi's UX depends on receiving those lines unconditionally (buffered and replayed when a build fails). INFO events therefore keep flowing as rendered text on stderr — the existing stream_stderr path is untouched — while WARN/ERROR/DEBUG/TRACE events plus span lifecycles go over the structured channel. After activation the backend's stderr handler is pinned to INFO-only so records never render twice.

Span fidelity — real spans, lazily opened. The backend mirrors span open/close over the wire; open records are emitted lazily, only when an event actually flows inside the span, which keeps eventless spans off the wire and transparently absorbs the pre-negotiation window. The frontend reconstructs real tracing spans via runtime-interned callsites keyed by (name, target, level) — so events render with their full outer:inner: context and EnvFilter rules evaluate against correct metadata (the exact keying the #6312 review asked for). Events re-emit under a backend::-prefixed target (e.g. backend::rattler_build_core::packaging) with structured fields folded into the message, making backend logs filterable as a group via RUST_LOG=backend=trace.

Verbosity propagation. Pixi sets PIXI_BUILD_BACKEND_LOG_LEVEL on the spawned backend from its own subscriber's current max level; the backend treats it as a floor for its filter. pixi -vvv now surfaces backend debug/trace end-to-end, with no tracing-subscriber reload machinery.

How Has This Been Tested?

  • Wire types (pixi_build_types): JSON round-trips for all record kinds; empty collections omitted from the wire format.
  • Backend layer (pixi_build_backend): events carry their lazily-opened span chain root-first with correct parent links; INFO events and eventless spans stay off the wire; nothing is sent before negotiation activates the layer.
  • Server loop (pixi_build_backend): driven over in-process pipes — negotiation flips the activation flag, responses and notifications share the output channel without interleaving, and stdin EOF shuts the server down cleanly.
  • Frontend forwarder (pixi_build_frontend): span hierarchy reconstruction (nesting, close handling, unknown/rootless span fallbacks), field folding, and callsite interning keyed by name/target/level.
  • End-to-end (pixi_build_frontend): setup_with_transport against a fake backend over a duplex transport, asserting that pushed notifications re-emit through a captured tracing subscriber with correct level, target prefix, and span scope — plus the negative case that the frontend advertises the capability and that backends which never send notifications work unchanged.
  • cargo clippy clean on the three touched crates; full workspace compiles.

Not yet exercised: a live pixi build against a compiled backend binary — the in-process tests cover both real transport halves, but a manual smoke test before merge would be a sensible extra check.

AI Disclosure

  • This PR contains AI-generated content.
    • I have tested any AI-generated content in my PR.
    • I take responsibility for any AI-generated content in my PR.

Tools: Claude Code

One of my colleagues tried to tackle this issue but it failed review. Try to learn
from that approach and the comments of my colleagues and find one that is actually
good https://github.com/prefix-dev/pixi/pull/6312. Interview me relentlessly about
every aspect of this plan until we reach a shared understanding. Walk down each
branch of the design tree, resolving dependencies between decisions one-by-one.
For each question, provide your recommended answer.

Checklist:

  • I have performed a self-review of my own code
  • I have commented my code, particularly in hard-to-understand areas
  • I have added sufficient tests to cover my changes.

🤖 Generated with Claude Code

https://claude.ai/code/session_0198Tqr2t6wZwTcBLM6DEuAG


Generated by Claude Code

@Hofer-Julian Hofer-Julian marked this pull request as draft July 6, 2026 07:42
Backend build processes previously rendered all their tracing output to
stderr as plain text, so pixi could only treat it as opaque build output:
no levels, no targets, no span context, and no interaction with pixi's
own log filtering. This surfaces backend diagnostics as first-class
tracing data in pixi.

Design (supersedes the approach reviewed in #6312):

- Transport: structured records travel as `log/message` JSON-RPC
  notifications on the existing stdin/stdout channel, instead of
  sentinel-tagged JSON on stderr (fragile: child processes share the
  inherited stderr handle) or a dedicated socket/named pipe (two
  platform-specific transports and a second lifecycle to manage). The
  channel is inherently process-scoped, so span ids stay valid across
  RPC calls, during setup, and between requests.

- Negotiation: a new `supports_log_messages` field on
  `FrontendCapabilities`. Backends stay silent unless the frontend
  advertises it, so both mixed-version directions degrade to today's
  behavior without a Pixi Build API version bump.

- Content split: INFO events keep flowing as rendered plain text on
  stderr because rattler-build uses INFO as its plaintext build-output
  stream, which pixi buffers and replays when a build fails. Everything
  else (WARN/ERROR/DEBUG/TRACE plus span lifecycles) goes over the
  structured channel. After activation, the stderr handler is pinned to
  INFO-only so records are never rendered twice.

- Span fidelity: the backend mirrors span open/close over the wire
  (lazily: a span's open record is only sent once an event actually
  flows inside it, which also absorbs the pre-negotiation window), and
  the frontend reconstructs real `tracing` spans through runtime-interned
  callsites keyed by (name, target, level), so events render with their
  `outer:inner:` context and EnvFilter directives apply with correct
  metadata. Events re-emit under a `backend::`-prefixed target with
  fields folded into the message.

- Verbosity: pixi passes its current max level to the backend via
  PIXI_BUILD_BACKEND_LOG_LEVEL, which the backend treats as a floor for
  its own filter, so `pixi -vvv` surfaces backend debug/trace without
  any reload machinery.

The backend server loop now owns stdout through a single writer task
fed by both RPC responses and notifications, replacing the deprecated
jsonrpc-stdio-server dependency.
@Hofer-Julian Hofer-Julian force-pushed the claude/pixi-pr-6312-design-41w08v branch from 9ff5ba3 to 8eb6963 Compare July 6, 2026 07:58
The Pytest linux job's 10-minute timeout is below pytest's 600s per-test
timeout, so hanging tests die as an opaque job cancellation before
pytest can report anything. Lower the per-test timeout for this job and
raise the job timeout so a hang produces pytest's timeout diagnostics:
the Python stack of the waiting test and the captured output of the
stuck pixi invocation.

To be reverted once the hang is understood.
Dispatching each JSON-RPC request onto a spawned task changed the
runtime geometry that build backends have always executed under, and
intermittently livelocked rattler-build's script output pump: its
select! loop keeps re-polling an already-EOF'd output stream (which
completes immediately, forever), and with the request future running on
a worker the runtime's I/O driver ended up unpolled, so the second
output pipe's EOF was never delivered. The backend then spun at 100%
CPU with the finished build script left as a zombie while the frontend
waited indefinitely for the conda/build_v1 response — the CI hang on
the Linux integration tests.

Handle requests inline on the root task instead, exactly like the
previous jsonrpc-stdio-server loop: read a line, await the response,
queue it to the writer. The frontend serializes requests per backend,
so concurrent dispatch bought nothing. Notifications are unaffected —
the writer task remains the single point where responses and
log/message notifications are serialized to stdout.

Reproduced with 4 concurrent `pixi publish -v` loops on the rust
minimal workspace (hang within <10 iterations, ~25% per iteration,
confirmed with gdb/strace: Lines::poll_next_line hot loop, zero epoll
activity, both pipe write-ends closed). Also reproduced with a released
pixi 0.72 frontend against the new backend, proving the notification
machinery (dormant in that pairing) was not the trigger.
…bution

Route backend log records under a backend::<name>::<module> target, add a
dedicated fmt layer that always renders that target so it is clear which
backend produced a message, and add a backend={pixi_level} filter directive so
backend logs start at warn and scale with -v like pixi's own logs.
`pixi_filter_directives` is only called from the
non-console-subscriber `setup_logging`, so building with
--all-features (as the rustdoc CI job does) flagged it as dead code;
gate it on the same feature. The typos linter prefers 'parentless'
over 'unparented'.
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