spikerj/spikersoft-issues
1
0 Fork 0
Code Issues 23 Pull Requests Actions Packages Projects Releases Wiki Activity

Epic: End-to-end trace + log correlation for the art_pipe native-microservice integration (Jaeger + Seq) #428

New Issue
Closed
opened 2026-07-06 02:25:34 +00:00 by spikerj · 3 comments
spikerj commented 2026-07-06 02:25:34 +00:00
Owner
Copy link
Copy source

Goal

Full, connected observability for a ProArt asset from API submit → RabbitMQ → ArtPipeProcessor orchestration → the Python art_pipe generation worker → back, in both Jaeger (traces) and Seq (logs) — the same bar every native SpikerSoft microservice meets. Any code absorbed into the ecosystem as a native microservice must be end-to-end traceable.

Current state (verified)

Traced & context-propagated (✅): API command → RabbitMQ (traceparent in headers) → ArtPipeStageConsumer extracts context via ActivityHelper.StartActivityFromRabbitMQMessage(...) → orchestrator/GPU-lease/dispatch. ArtPipeProcessor wires .WithSerilog() (Seq http://seq:5341) + .WithTelemetry() (OTLP http://jaeger:4317, SampleRatio 1.0).

Trace breaks at the .NET→Python seam (❌):

  • No traceparent crosses into the worker. SubprocessArtPipeStageExecutor.ApplyWorkerEnvironment sets PYTHONPATH/PYTHONUNBUFFERED/BLENDER_BIN only; the stdin job spec carries job_id but no trace/span id.
  • art_pipe has zero OpenTelemetry — the actual generation work (concept/modeling/texturing/rigging/animation/export/enrichment, model inference, Blender render) emits no spans. In Jaeger it's one opaque ProcessArtAssetStage span.
  • art_pipe doesn't log to Seq — logging_config.py writes a local logs/debug.log with thread-local asset_id/job_id context. Correlation across the seam is currently by asset_id/job_id only, never by trace_id.

Reference implementation (reuse this — don't reinvent)

spikersoft-backend/SpikerSoft.EventHandlers.ImageDescription.Python/image_description_service.py (and Trellis3D.Python) already do .NET↔Python OTel correlation "and back":

  • OTel SDK: TracerProvider + Resource(SERVICE_NAME=...) + BatchSpanProcessor + OTLPSpanExporter(endpoint=JAEGER_ENDPOINT, insecure=True), default http://jaeger:4317.
  • Extract: _extract_trace_context(properties) reads traceparent/tracestate; rebuild parent via TraceContextTextMapPropagator().extract(carrier=...); start_as_current_span(..., context=parent_context).
  • Onward hop: _inject_workflow_trace_context(...) re-injects traceparent into the next request.

Known gotchas already solved there (carry them over):

  1. "invalid parent span" race — default BatchSpanProcessor 5000ms schedule delay makes the Python child span export before the .NET parent lands in Jaeger. Fix: short schedule delay (~1s), as they did.
  2. traceparent header arrives as bytes — decode utf-8 before use.
  3. Metrics are disabled (Jaeger OTLP = traces only).

Key difference for art_pipe (design note)

The precedent's carrier is RabbitMQ message headers. art_pipe is not a bus consumer — the ArtPipeProcessor spawns python -m artpipe.worker --serve and streams jobs over stdin/stdout (resident serve mode, #368). So the trace-context carrier must be the per-job stdin spec JSON (add a _traceparent field) and/or the subprocess TRACEPARENT env var — per job, not per process (the resident worker serves many jobs across its lifetime; each must start a fresh span from that job's context).

Workstreams (sub-issues)

  1. .NET side — inject W3C traceparent into the worker (stdin spec + env) and add a per-stage child span. (self-contained, backend-mergeable; no-op until #2 consumes it)
  2. art_pipe — add OTel SDK + OTLP exporter, extract parent context from the job spec, span-per-stage/model-call; reuse the BatchSpanProcessor fast-export fix.
  3. art_pipe logs → Seq — ship worker logs to Seq (CLEF) and/or stamp trace_id into the log context for trace↔log correlation.

Acceptance criteria

  • A single Jaeger trace for one asset spans API → bus → ArtPipeProcessor → each art_pipe stage/model call as child spans, correctly parented (no orphans/invalid-parent).
  • Seq shows the .NET orchestration logs and art_pipe worker logs for that asset, correlated by trace_id (not just asset_id).
  • Works in both executor modes (subprocess + resident serve).

Refs #346 (ProArt epic), #368 (resident serve), #348 (GPU worker), #389 (ArtStudioMetrics). Precedent: ImageDescription.Python / Trellis3D.Python.

Child issues (per-repo, auto-close on merge)

No open child issues were produced by the migration — either this epic's
work was already complete, or its scope needs to be broken down into
per-repo issues before it can progress.

Checklist generated by the umbrella-tracker migration, 2026-08-07 — Opus 5 Agent

## Goal Full, connected observability for a ProArt asset from **API submit → RabbitMQ → ArtPipeProcessor orchestration → the Python `art_pipe` generation worker → back**, in **both Jaeger (traces) and Seq (logs)** — the same bar every native SpikerSoft microservice meets. Any code absorbed into the ecosystem as a native microservice must be end-to-end traceable. ## Current state (verified) **Traced & context-propagated (✅):** API command → RabbitMQ (`traceparent` in headers) → `ArtPipeStageConsumer` extracts context via `ActivityHelper.StartActivityFromRabbitMQMessage(...)` → orchestrator/GPU-lease/dispatch. ArtPipeProcessor wires `.WithSerilog()` (Seq `http://seq:5341`) + `.WithTelemetry()` (OTLP `http://jaeger:4317`, `SampleRatio 1.0`). **Trace breaks at the .NET→Python seam (❌):** - No `traceparent` crosses into the worker. `SubprocessArtPipeStageExecutor.ApplyWorkerEnvironment` sets `PYTHONPATH/PYTHONUNBUFFERED/BLENDER_BIN` only; the stdin job spec carries `job_id` but no trace/span id. - `art_pipe` has **zero OpenTelemetry** — the actual generation work (concept/modeling/texturing/rigging/animation/export/enrichment, model inference, Blender render) emits **no spans**. In Jaeger it's one opaque `ProcessArtAssetStage` span. - `art_pipe` **doesn't log to Seq** — `logging_config.py` writes a local `logs/debug.log` with thread-local `asset_id/job_id` context. Correlation across the seam is currently by `asset_id/job_id` only, never by `trace_id`. ## Reference implementation (reuse this — don't reinvent) `spikersoft-backend/SpikerSoft.EventHandlers.ImageDescription.Python/image_description_service.py` (and `Trellis3D.Python`) already do .NET↔Python OTel correlation "and back": - OTel SDK: `TracerProvider` + `Resource(SERVICE_NAME=...)` + `BatchSpanProcessor` + `OTLPSpanExporter(endpoint=JAEGER_ENDPOINT, insecure=True)`, default `http://jaeger:4317`. - Extract: `_extract_trace_context(properties)` reads `traceparent`/`tracestate`; rebuild parent via `TraceContextTextMapPropagator().extract(carrier=...)`; `start_as_current_span(..., context=parent_context)`. - Onward hop: `_inject_workflow_trace_context(...)` re-injects `traceparent` into the next request. **Known gotchas already solved there (carry them over):** 1. **"invalid parent span" race** — default `BatchSpanProcessor` 5000ms schedule delay makes the Python child span export *before* the .NET parent lands in Jaeger. Fix: short schedule delay (~1s), as they did. 2. `traceparent` header arrives as `bytes` — decode utf-8 before use. 3. Metrics are disabled (Jaeger OTLP = traces only). ## Key difference for art_pipe (design note) The precedent's carrier is **RabbitMQ message headers**. `art_pipe` is **not** a bus consumer — the ArtPipeProcessor spawns `python -m artpipe.worker --serve` and streams jobs over **stdin/stdout** (resident serve mode, #368). So the trace-context carrier must be the **per-job stdin spec JSON** (add a `_traceparent` field) and/or the subprocess `TRACEPARENT` env var — **per job, not per process** (the resident worker serves many jobs across its lifetime; each must start a fresh span from that job's context). ## Workstreams (sub-issues) 1. **.NET side** — inject W3C `traceparent` into the worker (stdin spec + env) and add a per-stage child span. _(self-contained, backend-mergeable; no-op until #2 consumes it)_ 2. **art_pipe** — add OTel SDK + OTLP exporter, extract parent context from the job spec, span-per-stage/model-call; reuse the BatchSpanProcessor fast-export fix. 3. **art_pipe logs → Seq** — ship worker logs to Seq (CLEF) and/or stamp `trace_id` into the log context for trace↔log correlation. ## Acceptance criteria - A single Jaeger trace for one asset spans API → bus → ArtPipeProcessor → **each art_pipe stage/model call** as child spans, correctly parented (no orphans/invalid-parent). - Seq shows the .NET orchestration logs **and** art_pipe worker logs for that asset, correlated by `trace_id` (not just `asset_id`). - Works in both executor modes (subprocess + resident serve). Refs #346 (ProArt epic), #368 (resident serve), #348 (GPU worker), #389 (ArtStudioMetrics). Precedent: ImageDescription.Python / Trellis3D.Python. <!-- BEGIN MIGRATED-CHILDREN --> --- ## Child issues (per-repo, auto-close on merge) _No open child issues were produced by the migration — either this epic's work was already complete, or its scope needs to be broken down into per-repo issues before it can progress._ <sub>Checklist generated by the umbrella-tracker migration, 2026-08-07 — Opus 5 Agent</sub> <!-- END MIGRATED-CHILDREN -->
spikerj commented 2026-07-06 02:26:53 +00:00
Author
Owner
Copy link
Copy source

Workstreams filed:

  • #429 — .NET: propagate W3C traceparent into the worker + per-stage child span (start here; self-contained, backend-mergeable)
  • #430 — art_pipe: OpenTelemetry spans with parent-context extraction from the job spec (depends on #429)
  • #431 — art_pipe: ship worker logs to Seq + stamp trace_id (complements #430)

Execution order: #429 → #430 → #431. #429 is additive and inert until #430 consumes the context, so it can merge on its own without changing runtime behavior.

Workstreams filed: - **#429** — .NET: propagate W3C `traceparent` into the worker + per-stage child span _(start here; self-contained, backend-mergeable)_ - **#430** — art_pipe: OpenTelemetry spans with parent-context extraction from the job spec _(depends on #429)_ - **#431** — art_pipe: ship worker logs to Seq + stamp `trace_id` _(complements #430)_ Execution order: #429 → #430 → #431. #429 is additive and inert until #430 consumes the context, so it can merge on its own without changing runtime behavior.
spikerj commented 2026-07-08 04:29:29 +00:00
Author
Owner
Copy link
Copy source

Status roll-up — Python correlation is wired end-to-end

  • ✅ #430 — art_pipe worker OTel spans (per-job CONSUMER span re-parented from the injected _traceparent, nested model.run/preprocess). Merged (artpipe PR #7).
  • ✅ #431 — worker structured logs → Seq (stdlib CLEF over urllib), trace_id/span_id stamped from the active span. Merged (artpipe PR #8).
  • ✅ #459 — .NET ArtPipeProcessor now propagates JAEGER_ENDPOINT/SEQ_URL/SEQ_API_KEY into the worker subprocess. Merged (backend PR #183).
  • ⏳ #460 — install opentelemetry-sdk into the per-model venvs so span export actually fires. Decision-gated (which venvs / opt-in flag), so parked for a call.

Net effect on next deploy: #431's Seq log↔trace correlation activates immediately (stdlib-only — SEQ_URL alone is enough). #430's Jaeger spans are fully wired and primed; they start exporting the moment #460 lands the OTel packages in the venvs. So the epic is functionally complete except for that one venv-packaging decision.

## Status roll-up — Python correlation is wired end-to-end - ✅ **#430** — art_pipe worker OTel spans (per-job CONSUMER span re-parented from the injected `_traceparent`, nested `model.run`/`preprocess`). Merged (artpipe PR #7). - ✅ **#431** — worker structured logs → Seq (stdlib CLEF over `urllib`), `trace_id`/`span_id` stamped from the active span. Merged (artpipe PR #8). - ✅ **#459** — .NET `ArtPipeProcessor` now propagates `JAEGER_ENDPOINT`/`SEQ_URL`/`SEQ_API_KEY` into the worker subprocess. Merged (backend PR #183). - ⏳ **#460** — install `opentelemetry-sdk` into the per-model venvs so span export actually fires. **Decision-gated** (which venvs / opt-in flag), so parked for a call. **Net effect on next deploy:** #431's Seq log↔trace correlation activates immediately (stdlib-only — `SEQ_URL` alone is enough). #430's Jaeger spans are fully wired and primed; they start exporting the moment #460 lands the OTel packages in the venvs. So the epic is functionally complete except for that one venv-packaging decision.
spikerj added the epic label 2026-08-07 13:43:01 +00:00
spikerj commented 2026-08-07 14:31:07 +00:00
Author
Owner
Copy link
Copy source

Dissolved into per-repo issues as part of the umbrella-tracker breakup. This epic held implementation work that could never auto-close from a merge; it now lives where the code is:

  • Backend: spikerj/spikersoft-backend#622 — artpipe.worker.execute child span on the autotag / QR-art / safety-gate / art-variant worker lanes (only the art-asset stage lane has one today)
  • artpipe: spikerj/spikersoft-artpipe#62 — emit CLEF @tr/@sp (+ fleet log properties) so a Seq TraceId filter returns the .NET and worker logs together
  • artpipe: spikerj/spikersoft-artpipe#63 — worker OTel resource parity (host.name from NODE_HOSTNAME, real service.namespace) + dual-export spans to Seq's OTLP endpoint like the .NET fleet
  • artpipe: spikerj/spikersoft-artpipe#64 — spans inside the model run: Blender daemon renders and the nested RigNet/MDM subprocesses

Already shipped, no issue filed (verified 2026-08-07 against synced masters and the live swarm):

  • .NET → worker trace propagation — WorkerTraceContext.Inject stamps the per-job _traceparent/_tracestate in both executor modes (SubprocessArtPipeStageExecutor.cs:67, ResidentArtPipeStageExecutor.cs:178), backend PR #109. Per-job, not per-process, exactly as the epic required for the resident serve worker.
  • Stage-lane span breakdown — artpipe.stage.execute → artpipe.gpu.lease / artpipe.worker.execute / artpipe.outputs.persist, tagged with artasset.id / artasset.stage / artasset.stagerun.id / artpipe.model / artpipe.action (ArtPipeStageOrchestrator.cs:299-305, :371-378).
  • Python OTel consumption — artpipe.telemetry re-parents each job from its own _traceparent, with the reference gotchas carried over (1s BatchSpanProcessor schedule delay, bytes→utf-8 decode, traces-only, exit force-flush); nested artpipe.preprocess / artpipe.model.run (artpipe PR #7, 5797f86).
  • Worker → Seq shipping — artpipe.seq_logging, stdlib-only CLEF over urllib, env-gated, non-blocking (artpipe PR #8, 9d0650c).
  • Telemetry activation — ApplyWorkerEnvironment sets JAEGER_ENDPOINT / SEQ_URL / SEQ_API_KEY on the worker subprocess in both modes (SubprocessArtPipeStageExecutor.cs:386-397, shared by ServeWorkerProcess.cs:73), backend PR #183.
  • OTel packages in the venvs (#460's long-running blocker) — now genuinely resolved. The 2026-07-29 audit on #460 recorded that the tier-3 final images had never been rebuilt on the OTel-enabled env base (blocked on the registry read-path failures in #775). That is no longer true: running the deployed image shows the packages present —
    docker run --rm --entrypoint /bin/sh git.spikersoft.com/spikerj/artpipe-model-triposr:latest -c 'find /opt/art_pipe -name "opentelemetry*"' → opentelemetry_sdk-1.44.0 and opentelemetry_exporter_otlp_proto_grpc-1.44.0 in both /opt/art_pipe/.venv and /opt/art_pipe/models/TripoSR/venv.
  • Infrastructure wiring — complete, nothing filed. All 15 spikersoft-artpipe-* stack files join both the jaeger and seq-attachable overlays, set a distinct Deployment__Name, and pass NODE_HOSTNAME={{.Node.Hostname}}. Jaeger (jaegertracing/jaeger:2.20.0, OTLP on 4317) and Seq are both up and ingesting. No collector/stack change is needed for this epic, so no infrastructure issue was created.

Live state, for the record. The art_pipe lanes are currently idle rather than instrumented-and-silent: spikersoft-artpipe-modeling, -model-shape and -photostack are 0/1 (exited 0 during a broker outage), and the per-model services that are up report ArtPipeStageConsumer starting for stages [] with no job traffic. Consequently Jaeger holds no ProcessArtAssetStage / AutoTagPhotograph / GenerateQrArt / SafetyCheckRpc trace over a 30d lookback (SpikerSoft.EventHandlers.ArtPipeProcessor's only registered operations are GET /healthz and gpu.lease.requests/request publish), art_pipe.worker has never registered as a Jaeger service, and a Seq query for component = 'worker' returns 0 events. That is an unexercised pipeline, not broken telemetry — the .NET half is demonstrably live in both backends (ArtPipeProcessor events in Seq as recently as 2026-08-07T12:25Z; the service registered in Jaeger). The epic's end-to-end acceptance therefore still needs one real asset pushed through once the lanes are back up; that verification rides on the sibling issues rather than a ticket of its own.

The unit is tracked by the shared [ArtPipe telemetry] title prefix and by sibling cross-links in each issue. Closing here — the umbrella tracker is being emptied.

— Opus 5 Agent

Dissolved into per-repo issues as part of the umbrella-tracker breakup. This epic held implementation work that could never auto-close from a merge; it now lives where the code is: - Backend: spikerj/spikersoft-backend#622 — `artpipe.worker.execute` child span on the autotag / QR-art / safety-gate / art-variant worker lanes (only the art-asset stage lane has one today) - artpipe: spikerj/spikersoft-artpipe#62 — emit CLEF `@tr`/`@sp` (+ fleet log properties) so a Seq `TraceId` filter returns the .NET **and** worker logs together - artpipe: spikerj/spikersoft-artpipe#63 — worker OTel resource parity (`host.name` from `NODE_HOSTNAME`, real `service.namespace`) + dual-export spans to Seq's OTLP endpoint like the .NET fleet - artpipe: spikerj/spikersoft-artpipe#64 — spans inside the model run: Blender daemon renders and the nested RigNet/MDM subprocesses **Already shipped, no issue filed** (verified 2026-08-07 against synced masters and the live swarm): - **.NET → worker trace propagation** — `WorkerTraceContext.Inject` stamps the per-job `_traceparent`/`_tracestate` in *both* executor modes (`SubprocessArtPipeStageExecutor.cs:67`, `ResidentArtPipeStageExecutor.cs:178`), backend PR #109. Per-job, not per-process, exactly as the epic required for the resident serve worker. - **Stage-lane span breakdown** — `artpipe.stage.execute` → `artpipe.gpu.lease` / `artpipe.worker.execute` / `artpipe.outputs.persist`, tagged with `artasset.id` / `artasset.stage` / `artasset.stagerun.id` / `artpipe.model` / `artpipe.action` (`ArtPipeStageOrchestrator.cs:299-305`, `:371-378`). - **Python OTel consumption** — `artpipe.telemetry` re-parents each job from its own `_traceparent`, with the reference gotchas carried over (1s `BatchSpanProcessor` schedule delay, bytes→utf-8 decode, traces-only, exit force-flush); nested `artpipe.preprocess` / `artpipe.model.run` (artpipe PR #7, `5797f86`). - **Worker → Seq shipping** — `artpipe.seq_logging`, stdlib-only CLEF over `urllib`, env-gated, non-blocking (artpipe PR #8, `9d0650c`). - **Telemetry activation** — `ApplyWorkerEnvironment` sets `JAEGER_ENDPOINT` / `SEQ_URL` / `SEQ_API_KEY` on the worker subprocess in both modes (`SubprocessArtPipeStageExecutor.cs:386-397`, shared by `ServeWorkerProcess.cs:73`), backend PR #183. - **OTel packages in the venvs (#460's long-running blocker) — now genuinely resolved.** The 2026-07-29 audit on #460 recorded that the tier-3 final images had never been rebuilt on the OTel-enabled env base (blocked on the registry read-path failures in #775). That is no longer true: running the *deployed* image shows the packages present — `docker run --rm --entrypoint /bin/sh git.spikersoft.com/spikerj/artpipe-model-triposr:latest -c 'find /opt/art_pipe -name "opentelemetry*"'` → `opentelemetry_sdk-1.44.0` and `opentelemetry_exporter_otlp_proto_grpc-1.44.0` in **both** `/opt/art_pipe/.venv` and `/opt/art_pipe/models/TripoSR/venv`. - **Infrastructure wiring — complete, nothing filed.** All 15 `spikersoft-artpipe-*` stack files join both the `jaeger` and `seq-attachable` overlays, set a distinct `Deployment__Name`, and pass `NODE_HOSTNAME={{.Node.Hostname}}`. Jaeger (`jaegertracing/jaeger:2.20.0`, OTLP on 4317) and Seq are both up and ingesting. No collector/stack change is needed for this epic, so no infrastructure issue was created. **Live state, for the record.** The art_pipe lanes are currently idle rather than instrumented-and-silent: `spikersoft-artpipe-modeling`, `-model-shape` and `-photostack` are 0/1 (exited 0 during a broker outage), and the per-model services that are up report `ArtPipeStageConsumer starting for stages []` with no job traffic. Consequently Jaeger holds no `ProcessArtAssetStage` / `AutoTagPhotograph` / `GenerateQrArt` / `SafetyCheckRpc` trace over a 30d lookback (`SpikerSoft.EventHandlers.ArtPipeProcessor`'s only registered operations are `GET /healthz` and `gpu.lease.requests/request publish`), `art_pipe.worker` has never registered as a Jaeger service, and a Seq query for `component = 'worker'` returns 0 events. **That is an unexercised pipeline, not broken telemetry** — the .NET half is demonstrably live in both backends (ArtPipeProcessor events in Seq as recently as 2026-08-07T12:25Z; the service registered in Jaeger). The epic's end-to-end acceptance therefore still needs one real asset pushed through once the lanes are back up; that verification rides on the sibling issues rather than a ticket of its own. The unit is tracked by the shared `[ArtPipe telemetry]` title prefix and by sibling cross-links in each issue. Closing here — the umbrella tracker is being emptied. — Opus 5 Agent
Sign in to join this conversation.
No Branch/Tag Specified
Labels
Clear labels
agentic
Actionable surfaced by the agentic architecture & security review
 bug
Something is not working
 duplicate
This issue or pull request already exists
 enhancement
New feature
 epic
Cross-repo epic — children live in per-repo trackers
 help wanted
Need some help
 invalid
Something is wrong
 question
More information is needed
 sonarqube
Code quality issue surfaced by SonarQube (bug / code smell)
 wontfix
This won't be fixed
No labels epic
Milestone
No items
No Milestone
Projects
Clear projects
No projects
Assignees
Clear assignees
spikerj (Joseph Spiker)
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: spikerj/spikersoft-issues#428