diff --git a/.github/workflows/reusable-dispatch.yml b/.github/workflows/reusable-dispatch.yml index 2bf2eea5bb..0da12638a4 100644 --- a/.github/workflows/reusable-dispatch.yml +++ b/.github/workflows/reusable-dispatch.yml @@ -39,7 +39,9 @@ on: FULLSEND_GCP_WIF_PROVIDER: required: false FULLSEND_GCP_PROJECT_ID: - required: true + required: false + MLFLOW_OTLP_TOKEN: + required: false jobs: route: @@ -322,7 +324,7 @@ jobs: name: Triage needs: route if: needs.route.outputs.stage == 'triage' - uses: fullsend-ai/fullsend/.github/workflows/reusable-triage.yml@v0 + uses: ascerra/fullsend/.github/workflows/reusable-triage.yml@distributed-tracing with: event_type: ${{ github.event_name }} source_repo: ${{ github.repository }} @@ -332,10 +334,7 @@ jobs: gcp_region: ${{ inputs.gcp_region }} fullsend_version: ${{ inputs.fullsend_version }} - secrets: - FULLSEND_GCP_WIF_PROVIDER: ${{ secrets.FULLSEND_GCP_WIF_PROVIDER }} - - FULLSEND_GCP_PROJECT_ID: ${{ secrets.FULLSEND_GCP_PROJECT_ID }} + secrets: inherit code: name: Code diff --git a/.github/workflows/reusable-triage.yml b/.github/workflows/reusable-triage.yml index fbf0a0f3cd..7345a84f3d 100644 --- a/.github/workflows/reusable-triage.yml +++ b/.github/workflows/reusable-triage.yml @@ -30,9 +30,11 @@ on: default: 'per-org' secrets: FULLSEND_GCP_WIF_PROVIDER: - required: true + required: false FULLSEND_GCP_PROJECT_ID: - required: true + required: false + MLFLOW_OTLP_TOKEN: + required: false jobs: triage: @@ -131,10 +133,53 @@ jobs: TRIAGE_CLOUD_ML_REGION: ${{ inputs.gcp_region }} run: bash .github/scripts/setup-agent-env.sh - - name: Run triage agent + - name: Install fullsend infrastructure uses: fullsend-ai/fullsend@v0 + with: + agent: __install_only__ + version: ${{ inputs.fullsend_version }} + + - name: Checkout telemetry source + uses: actions/checkout@v6 + with: + repository: ascerra/fullsend + ref: distributed-tracing + path: .telemetry-src + + - name: Setup Go + uses: actions/setup-go@v5 + with: + go-version-file: .telemetry-src/go.mod + cache: false + + - name: Build telemetry-enabled fullsend + working-directory: .telemetry-src + run: | + set -euo pipefail + go build -o /tmp/fullsend-bin ./cmd/fullsend/ + FULLSEND_PATH="$(which fullsend)" + echo "Replacing ${FULLSEND_PATH} with telemetry-enabled build" + cp /tmp/fullsend-bin "${FULLSEND_PATH}" + fullsend --version + + - name: Run triage agent env: GITHUB_ISSUE_URL: ${{ fromJSON(inputs.event_payload).issue.html_url }} + FULLSEND_TELEMETRY: '1' + OTEL_EXPORTER_OTLP_TRACES_ENDPOINT: https://mlflow-35-212-57-52.nip.io/v1/traces + OTEL_EXPORTER_OTLP_TRACES_HEADERS: ${{ format('Authorization=Bearer {0},x-mlflow-experiment-id=0', secrets.MLFLOW_OTLP_TOKEN) }} + OTEL_SERVICE_NAME: fullsend-cli + run: | + set -euo pipefail + mkdir -p "${GITHUB_WORKSPACE}/output" + fullsend run triage \ + --fullsend-dir "${GITHUB_WORKSPACE}" \ + --output-dir "${GITHUB_WORKSPACE}/output" \ + --target-repo "${GITHUB_WORKSPACE}/target-repo" + + - name: Upload fullsend artifacts + if: always() + uses: actions/upload-artifact@v7 with: - agent: triage - version: ${{ inputs.fullsend_version }} + name: fullsend-triage + path: ${{ github.workspace }}/output diff --git a/docs/ADRs/0040-distributed-tracing-instrumentation.md b/docs/ADRs/0040-distributed-tracing-instrumentation.md new file mode 100644 index 0000000000..09cf450508 --- /dev/null +++ b/docs/ADRs/0040-distributed-tracing-instrumentation.md @@ -0,0 +1,225 @@ +--- +title: "40. Framework-native distributed tracing with OpenTelemetry" +status: Accepted +relates_to: + - operational-observability +topics: + - observability + - telemetry + - opentelemetry +--- + +# 40. Framework-native distributed tracing with OpenTelemetry + +Date: 2026-05-23 + +## Status + +Accepted + +## Context + +Fullsend agent runs are opaque. When a multi-agent pipeline dispatches a +triage agent, then a code agent, then a review agent, operators have no +structured way to understand what happened, how long each step took, or +where a failure occurred. The +[operational observability](../problems/operational-observability.md) problem +doc identifies this as a first-order concern. + +Several prior decisions set the stage for this one: + +- [ADR 0021](0021-jsonl-reasoning-trace-exposure.md) decided that JSONL + reasoning traces are exposed from sandboxes with owner-scoped storage and + credential scanning as defense-in-depth. That ADR addresses *what* traces + contain and *who* can access them; this ADR addresses *how* structured + telemetry is produced at the framework level. +- [ADR 0018](0018-scripted-pipeline-for-multi-agent-orchestration.md) + established the scripted multi-agent pipeline (triage → code → review) + whose cross-run correlation this ADR enables. +- [ADR 0022](0022-harness-level-output-schema-enforcement.md) established + structured output schemas that `run-summary.json` complements with + execution-level metadata. + +The [operational observability](../problems/operational-observability.md) +problem doc identifies several open questions that this decision partially +addresses: the bootstrapping problem (how to get observability without +deploying infrastructure first) and the need for structured traces that +support both individual-run debugging and cross-run correlation. + +### Approaches evaluated + +Four approaches were considered along two dimensions: where telemetry +originates and what infrastructure is required. + +``` + WHERE telemetry WHAT backend is needed + is produced + ┌────────────┐ ┌───────────────┐ ┌──────────────────┐ + │ No backend │ │ General OTEL │ │ LLM-aware OTEL │ + │ (files │ │ (Jaeger, │ │ (Phoenix, MLflow│ + │ only) │ │ Tempo, etc.) │ │ Langfuse) │ + ──────────────────┼────────────┼───┼───────────────┼───┼──────────────────┤ + CLI produces │ │ │ │ │ │ + spans at source │ A │ │ B │ │ B+ │ + (framework-native)│ Local │ │ OTLP export │ │ OTLP + GenAI │ + │ baseline │ │ │ │ dashboards │ + ──────────────────┼────────────┼───┼───────────────┼───┼──────────────────┤ + External tool │ │ │ │ │ │ + parses stdout │ — │ │ C │ │ D │ + after the run │ │ │ Post-hoc │ │ Post-hoc + │ + (adopter-side) │ │ │ span builder │ │ LLM platform │ + ──────────────────┴────────────┴───┴───────────────┴───┴──────────────────┘ +``` + +**A. Local baseline** — Every run writes `run-events.jsonl` (NDJSON) and +`run-summary.json` to the output directory. Zero infrastructure. Operators +`grep`, `jq`, or script against these files. + +**B. Framework-native OTLP** — Everything in A, plus spans exported via +OTLP/HTTP when `OTEL_EXPORTER_OTLP_ENDPOINT` is set. One env var turns +any general-purpose backend on. + +**B+. Framework-native + LLM backend** — Same OTLP export pointed at a +backend that understands GenAI semantic conventions. The CLI's `gen_ai.*` +span attributes light up token cost rollups, prompt/completion inspection, +and agent-specific dashboards without any CLI-side config change. + +**C. Post-hoc span builder** *(rejected)* — External tooling parses CLI +stdout after each run to construct spans. Fragile: stdout is not a stable +contract, timing is approximate, and intermediate state is lost. + +**D. Post-hoc + LLM platform** *(rejected)* — Same as C, feeding an +LLM-aware backend. The early Arize Phoenix experiment used this approach. +It proved that GenAI dashboards are valuable, but confirmed that post-hoc +parsing is the wrong instrumentation point. + +### Comparison + +| | A. Local | B / B+. Framework OTLP | C. Post-hoc | D. Post-hoc + LLM | +|------------------------------|:--------:|:----------------------:|:-----------:|:------------------:| +| Infra needed | None | OTEL backend | OTEL backend| LLM platform | +| Timing accuracy | Exact | Exact | ~Approx | ~Approx | +| Cross-run correlation | Manual | Automatic (W3C) | Manual | Manual | +| Captures intermediate state | Yes | Yes | No | No | +| Stable contract | Yes | Yes | No | No | +| GenAI dashboards | — | Yes (B+ backend) | — | Yes | +| Token/cost attribution | — | Yes (B+ backend) | — | Yes | +| Survives CLI output changes | Yes | Yes | No | No | +| Bootstrapping cost | Zero | 1 env var | Custom glue | Custom glue | + +### Recommendation + +**A + B combined** — the approach this ADR accepts. Every run always +produces local files (A). One env var enables OTLP export (B). Choosing an +LLM-aware backend (B+) activates GenAI dashboards with zero CLI changes. +This creates a zero-to-production gradient: + +``` + Day 1 Day N Day N+M + ───────────────────────────────────────────────── + run-events.jsonl + OTLP to Jaeger + MLflow/Phoenix + run-summary.json or Tempo GenAI dashboards + (grep, jq) (trace UI) (token costs, prompts) + A ──────────────► B ──────────────► B+ +``` + +Post-hoc approaches (C, D) are superseded. The early Phoenix experiment +(D) validated the value of GenAI backends, which informed the decision to +include `gen_ai.*` semantic conventions in the framework-native approach. + +See the +[Distributed Tracing admin guide](../guides/admin/distributed-tracing.md#live-deployment-example) +for a worked example with live GitHub Actions runs. + +## Decision + +**Fullsend instruments the CLI natively using OpenTelemetry with a +zero-infrastructure baseline.** + +The `internal/telemetry` package provides: + +- **Always-on local output:** Every run produces `run-events.jsonl` (NDJSON + structured events) and `run-summary.json` regardless of configuration. + No collector or backend is required. +- **Optional OTLP export:** When `OTEL_EXPORTER_OTLP_ENDPOINT` or + `FULLSEND_TELEMETRY=1` is set, spans are additionally exported via + OTLP/HTTP to any compatible backend. +- **W3C trace context propagation:** Dispatched runs inherit `TRACEPARENT` + from the parent workflow, creating cross-run trace correlation. The + `work_item_id` attribute (`owner/repo#N`) enables querying all traces + related to a single issue or PR across the full triage → code → review + pipeline. +- **Unified InstrumentedPrinter:** A single component that atomically + produces both terminal UI output and telemetry events, making it + structurally impossible to have a UI step without a corresponding span. + Early lifecycle steps (before the run directory exists) are buffered and + replayed once the recorder attaches. +- **OTEL GenAI semantic conventions:** Root and iteration spans carry + `gen_ai.operation.name`, `gen_ai.agent.name`, `gen_ai.request.model`, + and `gen_ai.system` so LLM-aware backends recognize them as agent runs. +- **Transcript-to-span promotion:** Claude Code JSONL transcripts are + parsed post-execution, and individual LLM turns are emitted as child + spans with `gen_ai.content.prompt`, `gen_ai.content.completion`, + `gen_ai.usage.input_tokens`, `gen_ai.usage.output_tokens`, tool call + metadata, and stop reason. This bridges the gap between the JSONL + reasoning traces ([ADR 0021](0021-jsonl-reasoning-trace-exposure.md)) and + structured OTEL spans. +- **SpanKind signaling:** Root span is `Consumer` when `TRACEPARENT` is + present (dispatched run), `Internal` otherwise. +- **Regression gates:** CI tests (`telemetry_lint_test.go`) enforce that + all lifecycle steps in `runAgent` use the `InstrumentedPrinter` path. + Raw `printer.StepStart/StepDone/StepFail/StepWarn` calls and the legacy + `recStep/recDone/recFail/recWarn` closures are both caught. + +### Production backend + +Traces are exported to an MLflow instance (`https://mlflow-35-212-57-52.nip.io`) +running on a GCP VM. MLflow ingests OTLP/HTTP traces and provides GenAI-aware +dashboards with token usage rollups. See +[Distributed Tracing admin guide](../guides/admin/distributed-tracing.md) +for configuration details and alternative backends. + +## Consequences + +- Operators get structured observability for free — no configuration needed + for the local baseline (`run-events.jsonl` + `run-summary.json`). This + addresses the + [bootstrapping problem](../problems/operational-observability.md) identified + in the observability problem doc: the factory gets observability before any + infrastructure is deployed. +- Any OTLP-compatible backend (Jaeger, Tempo, Phoenix, MLflow, Langfuse, + SigNoz, Honeycomb) works with a single environment variable. +- Cross-run correlation works out of the box for dispatched pipelines via + W3C `TRACEPARENT` propagation and the `work_item_id` span attribute. +- The `InstrumentedPrinter` pattern means new lifecycle steps added to the + CLI automatically appear in traces — contributors cannot accidentally + skip telemetry. +- The `gen_ai.*` attributes follow the + [OTEL GenAI semantic conventions](https://opentelemetry.io/docs/specs/semconv/gen-ai/) + which are experimental; they may change in future OTEL releases and will + need updating. +- `run-summary.json` provides a machine-stable contract (versioned via + `schema_version`) for downstream consumers — scripts, retro agents, and + dashboards can ingest it without parsing CLI stdout. + +## Related issues + +- [#294](https://github.com/fullsend-ai/fullsend/issues/294) — Define + trace granularity and retention policy (open; this ADR provides the + local-first baseline but defers retention decisions) +- [#295](https://github.com/fullsend-ai/fullsend/issues/295) — Define + quality metrics for autonomous software factory (open; traces provide + the raw data these metrics will be computed from) +- [#296](https://github.com/fullsend-ai/fullsend/issues/296) — Evaluate + Langfuse deployment threshold vs structured logging (open; this ADR's + zero-config baseline is the "structured logging" phase, with OTLP export + as the graduation path) +- [#637](https://github.com/fullsend-ai/fullsend/issues/637) — UI + monitoring/status dashboard (open; can consume `run-summary.json` and + OTLP data for agent-centric dashboards) +- [#896](https://github.com/fullsend-ai/fullsend/issues/896) — Emit + source/destination annotations for agent workflow runs (open; + complements tracing with GitHub-native resource correlation) +- [#1043](https://github.com/fullsend-ai/fullsend/issues/1043) — Add + observability for review agent re-trigger failures (open; cross-run + tracing via `TRACEPARENT` helps correlate the re-trigger chain) diff --git a/docs/architecture.md b/docs/architecture.md index 2118b3ba4b..120b4ae8c6 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -175,11 +175,12 @@ Observability is a cross-cutting concern that touches every other component. Eac **Decided:** - JSONL reasoning trace exposure: raw JSONL conversation transcripts are extracted from sandboxes and stored with owner-scoped access. Credential scanning acts as an invariant check on [ADR 0017](ADRs/0017-credential-isolation-for-sandboxed-agents.md)'s isolation model. Agents handling data from protected sources beyond the target repo can opt in to JSONL suppression via configuration ([ADR 0021](ADRs/0021-jsonl-reasoning-trace-exposure.md)). +- Distributed tracing: framework-native OpenTelemetry instrumentation with zero-configuration baseline. Every run produces `run-events.jsonl` and `run-summary.json` locally; optional OTLP export to any compatible backend. W3C trace context propagation links multi-agent pipelines into unified traces. OTEL GenAI semantic conventions enable LLM-aware backends ([ADR 0040](ADRs/0040-distributed-tracing-instrumentation.md)). **Open questions:** - What signals matter most — cost, latency, token usage, action logs, decision traces, or something else? -- How do we balance detailed tracing (useful for debugging) with the volume of data agents will produce? +- ~~How do we balance detailed tracing (useful for debugging) with the volume of data agents will produce?~~ Decided in [ADR 0040](ADRs/0040-distributed-tracing-instrumentation.md): instrument all lifecycle steps comprehensively; volume is managed by backends not by suppressing data at the source. - What is the retention and access model for agent logs? Who can see what? (JSONL trace access model decided in [ADR 0021](ADRs/0021-jsonl-reasoning-trace-exposure.md); retention policy and broader log access remain open.) - How does observability interact with the security requirement that "every action is logged, attributable, and reviewable"? (See [security-threat-model.md](problems/security-threat-model.md).) - Is there a real-time monitoring requirement (agent is stuck, agent is behaving anomalously), or is observability primarily forensic? diff --git a/docs/guides/README.md b/docs/guides/README.md index bffb989db1..58deb2ca9f 100644 --- a/docs/guides/README.md +++ b/docs/guides/README.md @@ -10,6 +10,7 @@ Guides for org administrators who install, configure, and manage fullsend. - [Installing fullsend](admin/installation.md) — Set up fullsend in a GitHub organization from scratch (see [#328](https://github.com/fullsend-ai/fullsend/pull/328)) - [Enabling fullsend on private repositories](admin/private-repositories.md) — Additional guardrails and configuration for private repos +- [Distributed tracing](admin/distributed-tracing.md) — Configure and consume structured telemetry from agent runs ## User guides diff --git a/docs/guides/admin/distributed-tracing.md b/docs/guides/admin/distributed-tracing.md new file mode 100644 index 0000000000..559cdc8e94 --- /dev/null +++ b/docs/guides/admin/distributed-tracing.md @@ -0,0 +1,282 @@ +# Distributed Tracing + +Fullsend produces structured telemetry for every agent run. This guide covers +how to configure, consume, and extend the tracing system. + +Decided in [ADR 0040](../../ADRs/0040-distributed-tracing-instrumentation.md). + +## Zero-configuration baseline + +Every `fullsend run` produces two files in the run output directory with no +configuration required: + +- **`run-events.jsonl`** — NDJSON stream of lifecycle events (step starts, + completions, failures, warnings) with timestamps, durations, and trace IDs. +- **`run-summary.json`** — Aggregated run summary including agent name, exit + code, step timings, total duration, and a W3C `traceparent` value for + downstream correlation. + +These files are always written, even when no OTLP backend is configured. + +## Enabling OTLP export + +To send spans to an OpenTelemetry-compatible backend, set one of: + +```bash +# Option 1: Set the standard OTEL endpoint (also enables telemetry implicitly) +export OTEL_EXPORTER_OTLP_ENDPOINT="http://localhost:4318" + +# Option 2: Explicit enable (uses OTEL_EXPORTER_OTLP_ENDPOINT from env) +export FULLSEND_TELEMETRY=1 +``` + +When enabled, spans are exported via OTLP/HTTP. Any backend that speaks OTLP +works: Jaeger, Grafana Tempo, Arize Phoenix, Langfuse, SigNoz, Honeycomb, etc. + +If the endpoint is unreachable, the CLI continues normally — local files are +still produced and the run is not affected. + +## Cross-run trace correlation + +Multi-agent pipelines (triage → code → review) propagate trace context +automatically via the `TRACEPARENT` environment variable (W3C Trace Context). + +When a workflow dispatches a run: + +```yaml +env: + TRACEPARENT: ${{ steps.parent.outputs.traceparent }} +``` + +The child run's root span becomes a child of the parent trace, creating a +unified view of the entire pipeline in your tracing backend. + +The `run-summary.json` includes the `traceparent` value so downstream +consumers (scripts, other agents) can continue the trace chain. + +## Span structure + +A typical agent run produces this span hierarchy: + +``` +fullsend-run (root, SpanKind=Consumer if dispatched) +├── load-harness +├── setup-sandbox +│ └── create-sandbox (gen_ai.operation.name=create_agent) +├── agent-execution.iteration-0 +│ └── (gen_ai.operation.name=invoke_agent) +├── agent-execution.iteration-1 +├── collect-artifacts +├── security-scan +└── validation +``` + +### GenAI semantic conventions + +Root and iteration spans carry [OTEL GenAI semantic convention](https://opentelemetry.io/docs/specs/semconv/gen-ai/) attributes: + +| Attribute | Example | Description | +|-----------|---------|-------------| +| `gen_ai.operation.name` | `invoke_agent` | The GenAI operation type | +| `gen_ai.agent.name` | `triage` | The agent being executed | +| `gen_ai.request.model` | `claude-sonnet-4-20250514` | The model configured in the harness | +| `gen_ai.system` | `anthropic` | The LLM provider | + +These attributes enable LLM-aware backends to recognize fullsend spans as +agent operations and surface them in GenAI-specific dashboards. + +### SpanKind + +- **Consumer**: The root span when `TRACEPARENT` is set (the run was + dispatched by an external system). +- **Internal**: The root span for local/manual invocations. + +## Custom attributes + +Every span also carries fullsend-specific attributes: + +| Attribute | Description | +|-----------|-------------| +| `fullsend.agent` | Agent name from the harness | +| `fullsend.harness` | Path to the harness YAML | +| `fullsend.model` | Model identifier | +| `fullsend.image` | Container image used | +| `fullsend.work_item_id` | Issue/PR number being addressed | + +## Architecture + +The tracing system uses an `InstrumentedPrinter` that unifies terminal output +and telemetry recording: + +``` +┌─────────────────────────────────────────┐ +│ InstrumentedPrinter │ +│ │ +│ ip.StepStart("name", "message") │ +│ │ │ │ +│ ▼ ▼ │ +│ ┌─────────────┐ ┌──────────────┐ │ +│ │ ui.Printer │ │ Recorder │ │ +│ │ (terminal) │ │ (OTEL+JSONL) │ │ +│ └─────────────┘ └──────────────┘ │ +└─────────────────────────────────────────┘ +``` + +This design ensures every step visible in the terminal is also captured in +telemetry — it is structurally impossible to have a UI step without a +corresponding trace span. + +Early lifecycle steps (before the recorder is initialized) are buffered and +replayed once the recorder attaches. + +## Extending instrumentation + +When adding new lifecycle steps to the CLI: + +```go +// Use ip.StepStart/StepDone — never call printer.StepStart directly +ip.StepStart("my-new-step", "Doing something useful", + telemetry.StringAttr("key", "value"), +) +// ... do the work ... +ip.StepDone("my-new-step", "Done", + telemetry.StringAttr("result", "success"), +) +``` + +A CI regression gate (`telemetry_lint_test.go`) ensures that raw +`printer.StepStart` calls cannot be introduced in `runAgent` — the test +will fail if someone bypasses the unified path. + +## MLflow tracing backend (production) + +Fullsend traces are exported to an MLflow instance at +`https://mlflow-35-212-57-52.nip.io`. MLflow ingests OTLP/HTTP traces and +provides GenAI-aware dashboards with automatic token usage rollups. + +### GHA workflow configuration + +Add these environment variables to workflow jobs that run `fullsend run`: + +```yaml +env: + OTEL_EXPORTER_OTLP_TRACES_ENDPOINT: "https://mlflow-35-212-57-52.nip.io/v1/traces" + OTEL_EXPORTER_OTLP_TRACES_HEADERS: "Authorization=Bearer ${{ secrets.MLFLOW_OTLP_TOKEN }},x-mlflow-experiment-id=0" +``` + +The `MLFLOW_OTLP_TOKEN` GitHub Actions secret must be set at the org or repo +level. The token value is stored in GCP Secret Manager +(`mlflow-otlp-token` in `it-gcp-konflux-dev-fullsend`). + +### MLflow UI access + +The MLflow UI is at `https://mlflow-35-212-57-52.nip.io` behind basic auth +(user: `admin`, password: same as the OTLP token). Navigate to the **Traces** +tab to view agent run traces with span hierarchies, GenAI attributes, and +token usage. + +### Infrastructure + +The MLflow instance runs on a GCP VM (`mlflow`, zone `us-east4-c`) in the +`it-gcp-konflux-dev-fullsend` project: + +- **VM**: e2-medium (2 vCPU, 4GB), Ubuntu 24.04 LTS +- **Static IP**: 35.212.57.52 +- **Stack**: MLflow + PostgreSQL + RustFS (S3-compatible artifacts) + Caddy + (TLS, auth, reverse proxy) +- **Service account**: `mlflow-vm@it-gcp-konflux-dev-fullsend.iam.gserviceaccount.com` + (logging + monitoring write only) +- **Network**: HTTPS (443) open, SSH via IAP only (35.235.240.0/20), iptables + rate limiting (30 new connections/min per source IP) +- **Auth**: Bearer token for OTLP, basic auth for UI, both enforced by Caddy + +Admin access: + +```bash +gcloud compute ssh mlflow --zone=us-east4-c --tunnel-through-iap \ + --project=it-gcp-konflux-dev-fullsend +``` + +## Live deployment example + +The [`ascerra-feature-evals/features`](https://github.com/ascerra-feature-evals/features) +repo runs a full telemetry-enabled pipeline. This section shows how the +pieces fit together in practice. + +### Trace flow across GitHub Actions + +``` + GitHub event (issue opened, PR pushed, slash command) + │ + ▼ + ┌─────────────────────────────────────────────────────────────────────┐ + │ fullsend shim (fullsend.yaml) │ + │ Routes event → reusable-dispatch.yml → reusable-{stage}.yml │ + │ Concurrency: one dispatch per issue/PR at a time │ + └──────────────────────┬──────────────────────────────────────────────┘ + │ workflow_call + ▼ + ┌──────────────────────────────────────────────────────────────────────┐ + │ Agent stage (Triage / Code / Review / Fix / Retro) │ + │ │ + │ 1. Mint scoped token (OIDC → token mint → GitHub App install token) │ + │ 2. Setup GCP + agent env │ + │ 3. Read TRACEPARENT from issue/PR (prior stage wrote it) │ + │ 4. fullsend run {stage} │ + │ ├─ FULLSEND_TELEMETRY=1 │ + │ ├─ OTEL_EXPORTER_OTLP_TRACES_ENDPOINT → MLflow │ + │ ├─ Produces run-events.jsonl + run-summary.json │ + │ └─ Exports OTEL spans with gen_ai.* attrs │ + │ 5. Post TRACEPARENT to issue/PR for next stage │ + │ 6. Export transcript → OTEL child spans (LLM turns) │ + │ 7. Upload artifacts │ + └──────────────────────┬──────────────────────────────────────────────┘ + │ workflow_run (completed) + ▼ + ┌──────────────────────────────────────────────────────────────────────┐ + │ Send Telemetry (send-telemetry.yml) │ + │ Post-hoc enrichment — reads GHA jobs API, constructs additional │ + │ OTEL spans for workflow-level timing (queue wait, setup overhead), │ + │ exports to Phoenix/MLflow. │ + └──────────────────────────────────────────────────────────────────────┘ +``` + +### Telemetry test workflows + +The repo includes standalone telemetry test workflows that build the CLI +from the `distributed-tracing` branch and run each stage with full tracing +enabled: + +- `triage-telemetry.yml` — dispatched via `workflow_dispatch` with an issue + number, runs triage with `TRACEPARENT` propagation +- `code-telemetry.yml` — same pattern for the code agent +- `review-telemetry.yml` — same pattern for the review agent + +Each workflow: + +1. Builds the telemetry-enabled `fullsend` binary from source +2. Reads `TRACEPARENT` from the issue (written by a prior stage) +3. Runs `fullsend run` with `FULLSEND_TELEMETRY=1` and + `OTEL_EXPORTER_OTLP_TRACES_ENDPOINT` pointed at MLflow +4. Posts the new `TRACEPARENT` back to the issue for the next stage +5. Exports Claude Code transcript JSONL as child OTEL spans + +### Example runs + +Recent successful runs from +[ascerra-feature-evals/features/actions](https://github.com/ascerra-feature-evals/features/actions): + +| Stage | Run ID | Link | +|-------|--------|------| +| Triage (telemetry test) | 26427579796 | [view](https://github.com/ascerra-feature-evals/features/actions/runs/26427579796) | +| Code (telemetry test) | 26427580136 | [view](https://github.com/ascerra-feature-evals/features/actions/runs/26427580136) | +| Review (via fullsend dispatch) | 26427737042 | [view](https://github.com/ascerra-feature-evals/features/actions/runs/26427737042) | +| Send Telemetry (post-hoc enrichment) | 26427875956 | [view](https://github.com/ascerra-feature-evals/features/actions/runs/26427875956) | + +## Other backends for evaluation + +| Backend | Strengths | Setup | +|---------|-----------|-------| +| [Arize Phoenix](https://phoenix.arize.com/) | LLM-native, GenAI dashboard, free OSS | `docker run -p 6006:6006 -p 4318:4318 arizephoenix/phoenix` | +| [Jaeger](https://www.jaegertracing.io/) | Mature, trace-focused UI | `docker run -p 16686:16686 -p 4318:4318 jaegertracing/jaeger` | +| [Grafana Tempo](https://grafana.com/oss/tempo/) | Integrates with Grafana dashboards | docker-compose with Tempo + Grafana | diff --git a/docs/problems/operational-observability.md b/docs/problems/operational-observability.md index 0c692f1b35..4bac81e63e 100644 --- a/docs/problems/operational-observability.md +++ b/docs/problems/operational-observability.md @@ -191,7 +191,7 @@ This works for early experimentation when the volume is low and the operators ar - What retention policy applies to traces? Indefinite retention supports audit requirements but increases storage cost and data sensitivity exposure. Time-bounded retention (e.g., 90 days) limits exposure but may lose traces needed for incident investigation. - How do we measure "is the system getting better"? What metrics constitute a meaningful quality signal for an autonomous software factory? Merge revert rate? Human override rate? Time-to-review? Cost per decision? Some composite score? The choice of metric shapes what gets optimized. - At what scale does a dedicated LLM observability platform justify its operational overhead (Postgres, ClickHouse, Redis, S3 for something like Langfuse)? Is there a threshold of agent activity below which structured logging suffices? -- How do we handle the bootstrapping problem — the factory needs observability to improve, but building the observability infrastructure is itself work that competes with building the factory? +- ~~How do we handle the bootstrapping problem — the factory needs observability to improve, but building the observability infrastructure is itself work that competes with building the factory?~~ Addressed in [ADR 0040](../ADRs/0040-distributed-tracing-instrumentation.md): zero-configuration baseline (local JSONL + summary files) eliminates infrastructure requirements for initial observability; OTLP export adds backends when the org is ready. - Should observability data feed back into agent instructions automatically (e.g., auto-adjusting prompts when false positive rates exceed a threshold), or should it only inform human-driven instruction changes? Automatic feedback creates the risk of instruction oscillation; human-only feedback is slower but more controlled. - How do we build community dashboards that are useful to contributors with different levels of technical depth — from "is the agent doing a good job on my repo" to "show me the trace of this specific review"? - What is the cost of observability itself? Storing traces, running evaluators, maintaining dashboards — this has infrastructure cost. At what scale does it pay for itself in debugging time saved and quality improvement? diff --git a/go.mod b/go.mod index 12d89c8db9..ae388c29fd 100644 --- a/go.mod +++ b/go.mod @@ -10,6 +10,10 @@ require ( github.com/pquerna/otp v1.5.0 github.com/spf13/cobra v1.10.2 github.com/stretchr/testify v1.11.1 + go.opentelemetry.io/otel v1.43.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0 + go.opentelemetry.io/otel/sdk v1.43.0 + go.opentelemetry.io/otel/trace v1.43.0 golang.org/x/crypto v0.50.0 golang.org/x/net v0.52.0 golang.org/x/oauth2 v0.36.0 @@ -19,9 +23,11 @@ require ( ) require ( - cloud.google.com/go/compute/metadata v0.3.0 // indirect + cloud.google.com/go/compute/metadata v0.9.0 // indirect github.com/aymanbagabas/go-osc52/v2 v2.0.1 // indirect github.com/boombuler/barcode v1.0.1-0.20190219062509-6c824513bacc // indirect + github.com/cenkalti/backoff/v5 v5.0.3 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/charmbracelet/colorprofile v0.4.3 // indirect github.com/charmbracelet/x/ansi v0.11.6 // indirect github.com/charmbracelet/x/cellbuf v0.0.15 // indirect @@ -35,6 +41,7 @@ require ( github.com/go-errors/errors v1.5.1 // indirect github.com/go-jose/go-jose/v3 v3.0.5 // indirect github.com/go-logr/logr v1.4.3 // indirect + github.com/go-logr/stdr v1.2.2 // indirect github.com/go-stack/stack v1.8.1 // indirect github.com/gofrs/flock v0.13.0 // indirect github.com/gomlx/exceptions v0.0.3 // indirect @@ -42,6 +49,7 @@ require ( github.com/gomlx/go-xla v0.2.2 // indirect github.com/gomlx/gomlx v0.27.3 // indirect github.com/gomlx/onnx-gomlx v0.4.2 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.28.0 // indirect github.com/inconshreveable/mousetrap v1.1.0 // indirect github.com/knights-analytics/ortgenai v0.3.0 // indirect github.com/lucasb-eyer/go-colorful v1.3.0 // indirect @@ -56,10 +64,17 @@ require ( github.com/x448/float16 v0.8.4 // indirect github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e // indirect github.com/yalue/onnxruntime_go v1.27.0 // indirect + go.opentelemetry.io/auto/sdk v1.2.1 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0 // indirect + go.opentelemetry.io/otel/metric v1.43.0 // indirect + go.opentelemetry.io/proto/otlp v1.10.0 // indirect golang.org/x/exp v0.0.0-20260410095643-746e56fc9e2f // indirect golang.org/x/image v0.39.0 // indirect golang.org/x/sync v0.20.0 // indirect golang.org/x/sys v0.43.0 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260401024825-9d38bb4040a9 // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20260401024825-9d38bb4040a9 // indirect + google.golang.org/grpc v1.80.0 // indirect google.golang.org/protobuf v1.36.11 // indirect k8s.io/klog/v2 v2.140.0 // indirect ) diff --git a/go.sum b/go.sum index cc5e6d72bc..ccce112d2b 100644 --- a/go.sum +++ b/go.sum @@ -1,5 +1,5 @@ -cloud.google.com/go/compute/metadata v0.3.0 h1:Tz+eQXMEqDIKRsmY3cHTL6FVaynIjX2QxYC4trgAKZc= -cloud.google.com/go/compute/metadata v0.3.0/go.mod h1:zFmK7XCadkQkj6TtorcaGlCW1hT1fIilQDwofLpJ20k= +cloud.google.com/go/compute/metadata v0.9.0 h1:pDUj4QMoPejqq20dK0Pg2N4yG9zIkYGdBtwLoEkH9Zs= +cloud.google.com/go/compute/metadata v0.9.0/go.mod h1:E0bWwX5wTnLPedCKqk3pJmVgCBSM6qQI1yTBdEb3C10= codeberg.org/go-fonts/liberation v0.5.0 h1:SsKoMO1v1OZmzkG2DY+7ZkCL9U+rrWI09niOLfQ5Bo0= codeberg.org/go-fonts/liberation v0.5.0/go.mod h1:zS/2e1354/mJ4pGzIIaEtm/59VFCFnYC7YV6YdGl5GU= codeberg.org/go-latex/latex v0.1.0 h1:hoGO86rIbWVyjtlDLzCqZPjNykpWQ9YuTZqAzPcfL3c= @@ -16,6 +16,10 @@ github.com/boombuler/barcode v1.0.1-0.20190219062509-6c824513bacc h1:biVzkmvwrH8 github.com/boombuler/barcode v1.0.1-0.20190219062509-6c824513bacc/go.mod h1:paBWMcWSl3LHKBqUq+rly7CNSldXjb2rDl3JlRe0mD8= github.com/campoy/embedmd v1.0.0 h1:V4kI2qTJJLf4J29RzI/MAt2c3Bl4dQSYPuflzwFH2hY= github.com/campoy/embedmd v1.0.0/go.mod h1:oxyr9RCiSXg0M3VJ3ks0UGfp98BpSSGr0kpiX3MzVl8= +github.com/cenkalti/backoff/v5 v5.0.3 h1:ZN+IMa753KfX5hd8vVaMixjnqRZ3y8CuJKRKj1xcsSM= +github.com/cenkalti/backoff/v5 v5.0.3/go.mod h1:rkhZdG3JZukswDf7f0cwqPNk4K0sa+F97BxZthm/crw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/charmbracelet/colorprofile v0.4.3 h1:QPa1IWkYI+AOB+fE+mg/5/4HRMZcaXex9t5KX76i20Q= github.com/charmbracelet/colorprofile v0.4.3/go.mod h1:/zT4BhpD5aGFpqQQqw7a+VtHCzu+zrQtt1zhMt9mR4Q= github.com/charmbracelet/lipgloss v1.1.0 h1:vYXsiLHVkK7fp74RkV7b2kq9+zDLoEU4MZoFqR/noCY= @@ -44,14 +48,19 @@ github.com/go-errors/errors v1.5.1 h1:ZwEMSLRCapFLflTpT7NKaAc7ukJ8ZPEjzlxt8rPN8b github.com/go-errors/errors v1.5.1/go.mod h1:sIVyrIiJhuEF+Pj9Ebtd6P/rEYROXFi3BopGUQ5a5Og= github.com/go-jose/go-jose/v3 v3.0.5 h1:BLLJWbC4nMZOfuPVxoZIxeYsn6Nl2r1fITaJ78UQlVQ= github.com/go-jose/go-jose/v3 v3.0.5/go.mod h1:5b+7YgP7ZICgJDBdfjZaIt+H/9L9T/YQrVfLAMboGkQ= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-stack/stack v1.8.1 h1:ntEHSVwIt7PNXNpgPmVfMrNhLtgjlmnZha2kOpuRiDw= github.com/go-stack/stack v1.8.1/go.mod h1:dcoOX6HbPZSZptuspn9bctJ+N/CnF5gGygcUP3XYfe4= github.com/gofrs/flock v0.13.0 h1:95JolYOvGMqeH31+FC7D2+uULf6mG61mEZ/A8dRYMzw= github.com/gofrs/flock v0.13.0/go.mod h1:jxeyy9R1auM5S6JYDBhDt+E2TCo7DkratH4Pgi8P+Z0= github.com/golang/freetype v0.0.0-20170609003504-e2365dfdc4a0 h1:DACJavvAHhabrF08vX0COfcOBJRhZ8lUbR+ZWIs0Y5g= github.com/golang/freetype v0.0.0-20170609003504-e2365dfdc4a0/go.mod h1:E/TSTwGwJL78qG/PmXZO1EjYhfJinVAhrmmHX6Z8B9k= +github.com/golang/protobuf v1.5.4 h1:i7eJL8qZTpSEXOPTxNKhASYpMn+8e5Q6AdndVa1dWek= +github.com/golang/protobuf v1.5.4/go.mod h1:lnTiLA8Wa4RWRcIUkrtSVa5nRhsEGBg48fD6rSs7xps= github.com/gomlx/exceptions v0.0.3 h1:HKnTgEjj4jlmhr8zVFkTP9qmV1ey7ypYYosQ8GzXWuM= github.com/gomlx/exceptions v0.0.3/go.mod h1:uHL0TQwJ0xaV2/snJOJV6hSE4yRmhhfymuYgNredGxU= github.com/gomlx/go-huggingface v0.3.5 h1:eZz1huOvfr0TW30e11TkGAUZY4Jj5Oh/g0Thz4cvu0I= @@ -67,6 +76,8 @@ github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.28.0 h1:HWRh5R2+9EifMyIHV7ZV+MIZqgz+PMpZ14Jynv3O2Zs= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.28.0/go.mod h1:JfhWUomR1baixubs02l85lZYYOm7LV6om4ceouMv45c= github.com/inconshreveable/mousetrap v1.1.0 h1:wN+x4NVGpMsO7ErUn/mUI3vEoE6Jt13X2s0bqwp9tc8= github.com/inconshreveable/mousetrap v1.1.0/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw= github.com/janpfeifer/go-benchmarks v0.1.1 h1:gLLy07/JrOKSnMWeUxSnjTdhkglgmrNR2IBDnR4kRqw= @@ -127,6 +138,26 @@ github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e/go.mod h1:RbqR21r5mrJu github.com/yalue/onnxruntime_go v1.27.0 h1:c1YSgDNtpf0WGtxj3YeRIb8VC5LmM1J+Ve3uHdteC1U= github.com/yalue/onnxruntime_go v1.27.0/go.mod h1:b4X26A8pekNb1ACJ58wAXgNKeUCGEAQ9dmACut9Sm/4= github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= +go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= +go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/otel v1.43.0 h1:mYIM03dnh5zfN7HautFE4ieIig9amkNANT+xcVxAj9I= +go.opentelemetry.io/otel v1.43.0/go.mod h1:JuG+u74mvjvcm8vj8pI5XiHy1zDeoCS2LB1spIq7Ay0= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0 h1:88Y4s2C8oTui1LGM6bTWkw0ICGcOLCAI5l6zsD1j20k= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0/go.mod h1:Vl1/iaggsuRlrHf/hfPJPvVag77kKyvrLeD10kpMl+A= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0 h1:3iZJKlCZufyRzPzlQhUIWVmfltrXuGyfjREgGP3UUjc= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.43.0/go.mod h1:/G+nUPfhq2e+qiXMGxMwumDrP5jtzU+mWN7/sjT2rak= +go.opentelemetry.io/otel/metric v1.43.0 h1:d7638QeInOnuwOONPp4JAOGfbCEpYb+K6DVWvdxGzgM= +go.opentelemetry.io/otel/metric v1.43.0/go.mod h1:RDnPtIxvqlgO8GRW18W6Z/4P462ldprJtfxHxyKd2PY= +go.opentelemetry.io/otel/sdk v1.43.0 h1:pi5mE86i5rTeLXqoF/hhiBtUNcrAGHLKQdhg4h4V9Dg= +go.opentelemetry.io/otel/sdk v1.43.0/go.mod h1:P+IkVU3iWukmiit/Yf9AWvpyRDlUeBaRg6Y+C58QHzg= +go.opentelemetry.io/otel/sdk/metric v1.43.0 h1:S88dyqXjJkuBNLeMcVPRFXpRw2fuwdvfCGLEo89fDkw= +go.opentelemetry.io/otel/sdk/metric v1.43.0/go.mod h1:C/RJtwSEJ5hzTiUz5pXF1kILHStzb9zFlIEe85bhj6A= +go.opentelemetry.io/otel/trace v1.43.0 h1:BkNrHpup+4k4w+ZZ86CZoHHEkohws8AY+WTX09nk+3A= +go.opentelemetry.io/otel/trace v1.43.0/go.mod h1:/QJhyVBUUswCphDVxq+8mld+AvhXZLhe+8WVFxiFff0= +go.opentelemetry.io/proto/otlp v1.10.0 h1:IQRWgT5srOCYfiWnpqUYz9CVmbO8bFmKcwYxpuCSL2g= +go.opentelemetry.io/proto/otlp v1.10.0/go.mod h1:/CV4QoCR/S9yaPj8utp3lvQPoqMtxXdzn7ozvvozVqk= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= go.yaml.in/yaml/v3 v3.0.4/go.mod h1:DhzuOOF2ATzADvBadXxruRBLzYTpT36CKvDb3+aBEFg= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= @@ -184,8 +215,16 @@ golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtn golang.org/x/tools v0.1.12/go.mod h1:hNGJHUnrk76NpqgfD5Aqm5Crs+Hm0VOH/i9J2+nxYbc= golang.org/x/tools v0.6.0/go.mod h1:Xwgl3UAJ/d3gWutnCtw505GrjyAbvKui8lOU390QaIU= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +gonum.org/v1/gonum v0.17.0 h1:VbpOemQlsSMrYmn7T2OUvQ4dqxQXU+ouZFQsZOx50z4= +gonum.org/v1/gonum v0.17.0/go.mod h1:El3tOrEuMpv2UdMrbNlKEh9vd86bmQ6vqIcDwxEOc1E= gonum.org/v1/plot v0.15.2 h1:Tlfh/jBk2tqjLZ4/P8ZIwGrLEWQSPDLRm/SNWKNXiGI= gonum.org/v1/plot v0.15.2/go.mod h1:DX+x+DWso3LTha+AdkJEv5Txvi+Tql3KAGkehP0/Ubg= +google.golang.org/genproto/googleapis/api v0.0.0-20260401024825-9d38bb4040a9 h1:VPWxll4HlMw1Vs/qXtN7BvhZqsS9cdAittCNvVENElA= +google.golang.org/genproto/googleapis/api v0.0.0-20260401024825-9d38bb4040a9/go.mod h1:7QBABkRtR8z+TEnmXTqIqwJLlzrZKVfAUm7tY3yGv0M= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260401024825-9d38bb4040a9 h1:m8qni9SQFH0tJc1X0vmnpw/0t+AImlSvp30sEupozUg= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260401024825-9d38bb4040a9/go.mod h1:4Hqkh8ycfw05ld/3BWL7rJOSfebL2Q+DVDeRgYgxUU8= +google.golang.org/grpc v1.80.0 h1:Xr6m2WmWZLETvUNvIUmeD5OAagMw3FiKmMlTdViWsHM= +google.golang.org/grpc v1.80.0/go.mod h1:ho/dLnxwi3EDJA4Zghp7k2Ec1+c2jqup0bFkw07bwF4= google.golang.org/protobuf v1.36.11 h1:fV6ZwhNocDyBLK0dj+fg8ektcVegBBuEolpbTQyBNVE= google.golang.org/protobuf v1.36.11/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= diff --git a/internal/cli/run.go b/internal/cli/run.go index 6615147be4..03a716af03 100644 --- a/internal/cli/run.go +++ b/internal/cli/run.go @@ -29,6 +29,8 @@ import ( "github.com/fullsend-ai/fullsend/internal/sandbox" "github.com/fullsend-ai/fullsend/internal/scaffold" "github.com/fullsend-ai/fullsend/internal/security" + "github.com/fullsend-ai/fullsend/internal/telemetry" + "go.opentelemetry.io/otel/codes" "github.com/fullsend-ai/fullsend/internal/ui" ) @@ -57,8 +59,8 @@ func newRunCmd() *cobra.Command { Args: cobra.ExactArgs(1), RunE: func(cmd *cobra.Command, args []string) error { agentName := args[0] - printer := ui.New(os.Stdout) - return runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary, envFiles, noPostScript, debugFilter, printer) + ip := telemetry.NewInstrumentedPrinter(os.Stdout) + return runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary, envFiles, noPostScript, debugFilter, ip) }, } @@ -76,11 +78,11 @@ func newRunCmd() *cobra.Command { return cmd } -func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary string, envFiles []string, noPostScript bool, debug string, printer *ui.Printer) (runErr error) { - printer.Banner() - printer.Blank() - printer.Header("Running agent: " + agentName) - printer.Blank() +func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary string, envFiles []string, noPostScript bool, debug string, ip *telemetry.InstrumentedPrinter) (runErr error) { + ip.Banner() + ip.Blank() + ip.Header("Running agent: " + agentName) + ip.Blank() // 0. Load env files before anything else so vars are available for harness expansion. for _, ef := range envFiles { @@ -89,15 +91,33 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str } } + // Initialize telemetry. Context propagation: accept TRACEPARENT from the + // environment so the caller (GitHub Actions workflow, dispatch) can link + // this run into a broader trace. + ctx := telemetry.ContextFromTraceparent(context.Background(), "") + telCfg := telemetry.ConfigFromEnv() + telCfg.Enabled = true // structured events always written; OTEL export is opt-in via endpoint + telCfg.ServiceVersion = version + tp, tpErr := telemetry.InitTracer(ctx, telCfg) + if tpErr != nil { + ip.Warn("Telemetry init failed: " + tpErr.Error()) + tp = telemetry.NoopProvider() + } + defer func() { + _ = tp.Shutdown(context.Background()) + }() + // 1. Resolve and load harness. harnessPath := filepath.Join(fullsendDir, "harness", agentName+".yaml") harnessStart := time.Now() - printer.StepStart("Loading harness: " + harnessPath) + ip.StepStart("load-harness", "Loading harness: "+harnessPath, + telemetry.StringAttr("harness.path", harnessPath), + ) - h, err := harness.Load(harnessPath) - if err != nil { - printer.StepFail("Failed to load harness") - return fmt.Errorf("loading harness: %w", err) + h, loadErr := harness.Load(harnessPath) + if loadErr != nil { + ip.StepFail("load-harness", "Failed to load harness", loadErr) + return fmt.Errorf("loading harness: %w", loadErr) } absFullsendDir, err := filepath.Abs(fullsendDir) @@ -105,12 +125,12 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str return fmt.Errorf("resolving fullsend dir: %w", err) } if err := h.ResolveRelativeTo(absFullsendDir); err != nil { - printer.StepFail("Path validation failed") + ip.StepFail("load-harness", "Path validation failed", err) return fmt.Errorf("resolving paths: %w", err) } if resolved, overridden := applySandboxImageOverride(h.Image); overridden { - printer.StepInfo(fmt.Sprintf("Image override via FULLSEND_SANDBOX_IMAGE: %s -> %s", h.Image, resolved)) + ip.StepInfo(fmt.Sprintf("Image override via FULLSEND_SANDBOX_IMAGE: %s -> %s", h.Image, resolved)) h.Image = resolved } @@ -130,132 +150,228 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str return os.LookupEnv(key) } if err := h.ValidateRunnerEnvWith(lookup); err != nil { - printer.StepFail("Environment validation failed") + ip.StepFail("load-harness", "Environment validation failed", err) return fmt.Errorf("validating env: %w", err) } for k, v := range h.RunnerEnv { h.RunnerEnv[k] = os.Expand(v, expander) } if err := h.ValidateFilesExist(); err != nil { - printer.StepFail("File validation failed") + ip.StepFail("load-harness", "File validation failed", err) return fmt.Errorf("validating files: %w", err) } - // Ensure scripts are executable. The GitHub Contents API does not - // preserve file permissions, so scripts written via admin install - // may lack the execute bit. for _, script := range h.Scripts() { if script != "" { if chmodErr := os.Chmod(script, 0o755); chmodErr != nil { - printer.StepWarn("Could not chmod " + script + ": " + chmodErr.Error()) + ip.Warn("Could not chmod " + script + ": " + chmodErr.Error()) } } } - printer.StepDone(fmt.Sprintf("Harness loaded (%.1fs)", time.Since(harnessStart).Seconds())) + ip.StepDone("load-harness", telemetry.TimedMsg("Harness loaded", time.Since(harnessStart)), + telemetry.StringAttr("harness.agent", h.Agent), + telemetry.StringAttr("harness.model", h.Model), + telemetry.StringAttr("harness.image", h.Image), + telemetry.StringAttr("harness.policy", h.Policy), + telemetry.StringAttr("harness.pre_script", h.PreScript), + telemetry.StringAttr("harness.post_script", h.PostScript), + telemetry.StringAttr("harness.timeout_minutes", fmt.Sprintf("%d", h.TimeoutMinutes)), + ) // Print plan. - printer.KeyValue("Agent", h.Agent) + ip.KeyValue("Agent", h.Agent) if h.Policy != "" { - printer.KeyValue("Policy", h.Policy) + ip.KeyValue("Policy", h.Policy) } if h.Model != "" { - printer.KeyValue("Model", h.Model) + ip.KeyValue("Model", h.Model) } if h.Image != "" { - printer.KeyValue("Image", h.Image) + ip.KeyValue("Image", h.Image) } if len(h.Providers) > 0 { - printer.KeyValue("Providers", strings.Join(h.Providers, ", ")) + ip.KeyValue("Providers", strings.Join(h.Providers, ", ")) } if len(h.Skills) > 0 { - printer.KeyValue("Skills", strings.Join(h.Skills, ", ")) + ip.KeyValue("Skills", strings.Join(h.Skills, ", ")) } if len(h.Plugins) > 0 { - printer.KeyValue("Plugins", strings.Join(h.Plugins, ", ")) + ip.KeyValue("Plugins", strings.Join(h.Plugins, ", ")) } if h.AgentInput != "" { - printer.KeyValue("Agent input", h.AgentInput) + ip.KeyValue("Agent input", h.AgentInput) } if h.PreScript != "" { - printer.KeyValue("Pre-script", h.PreScript) + ip.KeyValue("Pre-script", h.PreScript) } if h.PostScript != "" { if noPostScript { - printer.KeyValue("Post-script", h.PostScript+" (SKIPPED: --no-post-script)") + ip.KeyValue("Post-script", h.PostScript+" (SKIPPED: --no-post-script)") } else { - printer.KeyValue("Post-script", h.PostScript) + ip.KeyValue("Post-script", h.PostScript) } } if h.TimeoutMinutes > 0 { - printer.KeyValue("Timeout", fmt.Sprintf("%d minutes", h.TimeoutMinutes)) + ip.KeyValue("Timeout", fmt.Sprintf("%d minutes", h.TimeoutMinutes)) + } + ip.Blank() + + // Compute sandbox name and run directory early so the telemetry recorder + // can be initialized before any lifecycle steps. + sandboxName := fmt.Sprintf("agent-%s-%d-%d", agentName, os.Getpid(), time.Now().Unix()) + if outputBase == "" { + outputBase = filepath.Join(os.TempDir(), "fullsend") + } + runDir := filepath.Join(outputBase, sandboxName) + + // Initialize the structured event recorder and attach it to the + // InstrumentedPrinter. Any steps that occurred before this point + // (load-harness) are replayed into the recorder automatically. + // Determine root span kind: Consumer when dispatched (TRACEPARENT present), + // Internal for local invocations. + rootSpanKind := telemetry.SpanKindInternal() + if os.Getenv("TRACEPARENT") != "" { + rootSpanKind = telemetry.SpanKindConsumer() + } + + workItemID := telemetry.WorkItemIDFromEnv() + rootSpanName := agentName + "-run" + if workItemID != "" { + rootSpanName = agentName + ": " + workItemID + } + rec, runCtx, recErr := telemetry.NewRecorder(ctx, runDir, tp.Tracer, + rootSpanName, + []telemetry.Attr{ + telemetry.StringAttr("fullsend.agent", agentName), + telemetry.StringAttr("fullsend.harness", harnessPath), + telemetry.StringAttr("fullsend.model", h.Model), + telemetry.StringAttr("fullsend.image", h.Image), + telemetry.StringAttr("fullsend.work_item_id", workItemID), + telemetry.StringAttr("gen_ai.operation.name", "invoke_agent"), + telemetry.StringAttr("gen_ai.agent.name", agentName), + telemetry.StringAttr("gen_ai.request.model", h.Model), + telemetry.StringAttr("gen_ai.system", "anthropic"), + }, + rootSpanKind, + ) + if recErr != nil { + ip.Warn("Telemetry recorder init failed: " + recErr.Error()) + } + if rec != nil { + ip.AttachRecorder(rec, runCtx) + ip.AddRootEvent("run.plan", + telemetry.StringAttr("agent", h.Agent), + telemetry.StringAttr("model", h.Model), + telemetry.StringAttr("image", h.Image), + telemetry.StringAttr("sandbox.name", sandboxName), + telemetry.StringAttr("run_dir", runDir), + telemetry.StringAttr("target_repo", targetRepo), + telemetry.StringAttr("pre_script", h.PreScript), + telemetry.StringAttr("post_script", h.PostScript), + telemetry.StringAttr("timeout_minutes", fmt.Sprintf("%d", h.TimeoutMinutes)), + ) + defer func() { + exitCode := 0 + if runErr != nil { + exitCode = 1 + } + summary := telemetry.RunSummary{ + Agent: agentName, + Harness: harnessPath, + Model: h.Model, + Image: h.Image, + WorkItemID: workItemID, + StartTime: rec.StartTime(), + ExitCode: exitCode, + Attrs: map[string]string{ + "sandbox.name": sandboxName, + }, + } + if runErr != nil { + summary.Attrs["error"] = runErr.Error() + } + _ = rec.WriteSummary(summary) + if runErr != nil { + rec.SetRootStatus(codes.Error, runErr.Error()) + } else { + rec.SetRootStatus(codes.Ok, "") + } + _ = rec.Close() + }() } - printer.Blank() // 2. Check openshell availability. openshellStart := time.Now() - printer.StepStart("Checking openshell availability") + ip.StepStart("check-openshell", "Checking openshell availability") if err := sandbox.EnsureAvailable(); err != nil { - printer.StepFail("openshell not available") + ip.StepFail("check-openshell", "openshell not available", err) return fmt.Errorf("openshell is required: %w", err) } - printer.StepDone(fmt.Sprintf("openshell available (%.1fs)", time.Since(openshellStart).Seconds())) + ip.StepDone("check-openshell", telemetry.TimedMsg("openshell available", time.Since(openshellStart))) // 2a. Check that a gateway is running. gatewayStart := time.Now() - printer.StepStart("Checking gateway") + ip.StepStart("check-gateway", "Checking gateway") if err := sandbox.CheckGateway(); err != nil { - printer.StepFail("Gateway not running") + ip.StepFail("check-gateway", "Gateway not running", err) return fmt.Errorf("gateway check failed: %w", err) } - printer.StepDone(fmt.Sprintf("Gateway available (%.1fs)", time.Since(gatewayStart).Seconds())) + ip.StepDone("check-gateway", telemetry.TimedMsg("Gateway available", time.Since(gatewayStart))) // 2b. Ensure providers exist on the gateway (if any declared). if len(h.Providers) > 0 { providersDir := filepath.Join(absFullsendDir, "providers") providerDefs, err := harness.LoadProviderDefs(providersDir) if err != nil { - printer.StepFail("Failed to load provider definitions") + ip.StepFail("ensure-providers", "Failed to load provider definitions", err) return fmt.Errorf("loading provider definitions: %w", err) } for _, pd := range providerDefs { providerStart := time.Now() - printer.StepStart("Ensuring provider: " + pd.Name) + stepName := "ensure-provider." + pd.Name + ip.StepStart(stepName, "Ensuring provider: "+pd.Name) if err := sandbox.EnsureProvider(pd.Name, pd.Type, pd.Credentials, pd.Config); err != nil { - printer.StepFail("Failed to create provider " + pd.Name) + ip.StepFail(stepName, "Failed to create provider "+pd.Name, err) return fmt.Errorf("ensuring provider %q: %w", pd.Name, err) } - printer.StepDone(fmt.Sprintf("Provider ready: %s (%.1fs)", pd.Name, time.Since(providerStart).Seconds())) + ip.StepDone(stepName, telemetry.TimedMsg("Provider ready: "+pd.Name, time.Since(providerStart))) } } // 2c. Run pre-script on the host (if configured). if h.PreScript != "" { preStart := time.Now() - printer.StepStart("Running pre-script: " + h.PreScript) + ip.StepStart("pre-script", "Running pre-script: "+h.PreScript, + telemetry.StringAttr("script.path", h.PreScript), + telemetry.StringAttr("script.type", "pre"), + ) preCmd := exec.Command(h.PreScript) - preCmd.Env = append(os.Environ(), envToList(h.RunnerEnv)...) + preEnv := append(os.Environ(), envToList(h.RunnerEnv)...) + if tpEnv := telemetry.TraceparentEnvVar(ip.Context()); tpEnv != "" { + preEnv = append(preEnv, tpEnv) + } + preCmd.Env = preEnv preCmd.Stdout = os.Stdout preCmd.Stderr = os.Stderr if err := preCmd.Run(); err != nil { - printer.StepFail("Pre-script failed") + ip.StepFail("pre-script", "Pre-script failed", err) return fmt.Errorf("running pre-script: %w", err) } - printer.StepDone(fmt.Sprintf("Pre-script completed (%.1fs)", time.Since(preStart).Seconds())) + ip.StepDone("pre-script", telemetry.TimedMsg("Pre-script completed", time.Since(preStart))) } // 3. Create sandbox. - sandboxName := fmt.Sprintf("agent-%s-%d-%d", agentName, os.Getpid(), time.Now().Unix()) createStart := time.Now() - printer.StepStart("Creating sandbox: " + sandboxName) + ip.StepStart("create-sandbox", "Creating sandbox: "+sandboxName, + telemetry.StringAttr("sandbox.name", sandboxName), + telemetry.StringAttr("sandbox.image", h.Image), + telemetry.StringAttr("sandbox.policy", h.Policy), + ) readyTimeout := time.Duration(h.SandboxTimeoutSeconds) * time.Second if err := sandbox.CreateWithRetry(sandboxName, h.Providers, h.Image, h.Policy, sandbox.DefaultMaxCreateAttempts, readyTimeout); err != nil { - printer.StepFail("Failed to create sandbox") + ip.StepFail("create-sandbox", "Failed to create sandbox", err) return fmt.Errorf("creating sandbox: %w", err) } - if outputBase == "" { - outputBase = filepath.Join(os.TempDir(), "fullsend") - } - runDir := filepath.Join(outputBase, sandboxName) // validationPassed is declared here (before the post-script defer) so the // defer closure can guard on it. The post-script must only run when @@ -264,55 +380,59 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str var validationPassed bool // Post-script runs after sandbox cleanup (defers are LIFO). - // When a validation_loop is configured, the post-script only runs if - // validation passed (ADR 0022). When no validation_loop exists (e.g., - // the code agent), the post-script runs unconditionally after a - // successful agent run — the post-script itself is responsible for - // any output checks it needs. if h.PostScript != "" { defer func() { if noPostScript { - printer.StepWarn(fmt.Sprintf("Skipping post-script %s: --no-post-script", h.PostScript)) + ip.Warn(fmt.Sprintf("Skipping post-script %s: --no-post-script", h.PostScript)) return } if h.ValidationLoop != nil && !validationPassed { - printer.StepWarn("Skipping post-script: validation did not pass") + ip.Warn("Skipping post-script: validation did not pass") return } if runErr != nil { - printer.StepWarn("Skipping post-script: agent run failed") + ip.Warn("Skipping post-script: agent run failed") return } postStart := time.Now() - printer.StepStart("Running post-script: " + h.PostScript) + ip.StepStart("post-script", "Running post-script: "+h.PostScript, + telemetry.StringAttr("script.path", h.PostScript), + telemetry.StringAttr("script.type", "post"), + telemetry.StringAttr("script.working_dir", runDir), + ) postCmd := exec.Command(h.PostScript) postCmd.Dir = runDir - postCmd.Env = append(os.Environ(), envToList(h.RunnerEnv)...) + postEnv := append(os.Environ(), envToList(h.RunnerEnv)...) + if tpEnv := telemetry.TraceparentEnvVar(ip.Context()); tpEnv != "" { + postEnv = append(postEnv, tpEnv) + } + postCmd.Env = postEnv postCmd.Stdout = os.Stdout postCmd.Stderr = os.Stderr if err := postCmd.Run(); err != nil { - printer.StepFail("Post-script failed: " + err.Error()) + ip.StepFail("post-script", "Post-script failed: "+err.Error(), err) if runErr == nil { runErr = fmt.Errorf("post-script %s failed: %w", h.PostScript, err) } } else { - printer.StepDone(fmt.Sprintf("Post-script completed (%.1fs)", time.Since(postStart).Seconds())) + ip.StepDone("post-script", telemetry.TimedMsg("Post-script completed", time.Since(postStart))) } }() } defer func() { - // Collect OpenShell logs before sandbox deletion for post-mortem debugging. - collectOpenshellLogs(sandboxName, runDir, printer) + collectOpenshellLogs(sandboxName, runDir, ip) cleanupStart := time.Now() - printer.StepStart("Cleaning up sandbox") + ip.StepStart("delete-sandbox", "Cleaning up sandbox", + telemetry.StringAttr("sandbox.name", sandboxName), + ) if err := sandbox.Delete(sandboxName); err != nil { - printer.StepWarn("Sandbox cleanup failed: " + err.Error()) + ip.StepWarn("delete-sandbox", "Sandbox cleanup failed: "+err.Error()) } else { - printer.StepDone(fmt.Sprintf("Sandbox deleted (%.1fs)", time.Since(cleanupStart).Seconds())) + ip.StepDone("delete-sandbox", telemetry.TimedMsg("Sandbox deleted", time.Since(cleanupStart))) } }() - printer.StepDone(fmt.Sprintf("Sandbox created (%.1fs)", time.Since(createStart).Seconds())) + ip.StepDone("create-sandbox", telemetry.TimedMsg("Sandbox created", time.Since(createStart)), telemetry.StringAttr("sandbox.name", sandboxName)) // 4. Resolve target repo path (needed by bootstrap for env vars). repoSrc, err := filepath.Abs(targetRepo) @@ -324,21 +444,28 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str // 7. Bootstrap sandbox. bootstrapStart := time.Now() - printer.StepStart("Bootstrapping sandbox") + ip.StepStart("bootstrap-sandbox", "Bootstrapping sandbox", + telemetry.StringAttr("sandbox.name", sandboxName), + telemetry.StringAttr("sandbox.repo_dir", repoDir), + ) if err := bootstrapSandbox(sandboxName, repoDir, fullsendBinary, h); err != nil { - printer.StepFail("Failed to bootstrap sandbox") + ip.StepFail("bootstrap-sandbox", "Failed to bootstrap sandbox", err) return err } - printer.StepDone(fmt.Sprintf("Sandbox bootstrapped (%.1fs)", time.Since(bootstrapStart).Seconds())) + ip.StepDone("bootstrap-sandbox", telemetry.TimedMsg("Sandbox bootstrapped", time.Since(bootstrapStart))) // 8. Make project code available (copy repo root into a named subdirectory). copyStart := time.Now() - printer.StepStart("Copying project code into sandbox") + ip.StepStart("upload-target-repo", "Copying project code into sandbox", + telemetry.StringAttr("repo.source", repoSrc), + telemetry.StringAttr("repo.name", repoName), + telemetry.StringAttr("repo.sandbox_path", repoDir), + ) if err := sandbox.UploadDir(sandboxName, repoSrc, repoDir); err != nil { - printer.StepFail("Failed to copy project code") + ip.StepFail("upload-target-repo", "Failed to copy project code", err) return fmt.Errorf("copying project code: %w", err) } - printer.StepDone(fmt.Sprintf("Project code copied to %s/ (%.1fs)", repoName, time.Since(copyStart).Seconds())) + ip.StepDone("upload-target-repo", telemetry.TimedMsg(fmt.Sprintf("Project code copied to %s/", repoName), time.Since(copyStart)), telemetry.StringAttr("repo.name", repoName)) // 8a. Inject org-level AGENTS.md if the target repo does not have one. // The scaffold ships a default AGENTS.md with baseline behavioral @@ -349,14 +476,13 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str orgAgentsMD := filepath.Join(absFullsendDir, "AGENTS.md") if _, err := os.Stat(orgAgentsMD); err == nil { if err := sandbox.Upload(sandboxName, orgAgentsMD, repoDir+"/AGENTS.md"); err != nil { - printer.StepWarn("Could not inject org AGENTS.md: " + err.Error()) + ip.Warn("Could not inject org AGENTS.md: " + err.Error()) } else { - // Hide the injected file from git status so agents don't stage it. excludeCmd := fmt.Sprintf("echo 'AGENTS.md' >> %s/.git/info/exclude", repoDir) if _, _, _, err := sandbox.Exec(sandboxName, excludeCmd, 5*time.Second); err != nil { - printer.StepWarn("Could not add AGENTS.md to git exclude: " + err.Error()) + ip.Warn("Could not add AGENTS.md to git exclude: " + err.Error()) } - printer.StepDone("Injected org-level AGENTS.md (target repo has none)") + ip.StepInfo("Injected org-level AGENTS.md (target repo has none)") } } } @@ -364,70 +490,80 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str // 8b. Copy agent-input files (if configured). if h.AgentInput != "" { inputStart := time.Now() - printer.StepStart("Copying agent-input files into sandbox") + ip.StepStart("upload-agent-input", "Copying agent-input files into sandbox") remoteInput := fmt.Sprintf("%s/agent-input", sandbox.SandboxWorkspace) mkInputCmd := fmt.Sprintf("mkdir -p %s", remoteInput) if _, _, _, err := sandbox.Exec(sandboxName, mkInputCmd, 10*time.Second); err != nil { return fmt.Errorf("creating agent-input dir in sandbox: %w", err) } if err := sandbox.Upload(sandboxName, h.AgentInput+"/.", remoteInput+"/"); err != nil { - printer.StepFail("Failed to copy agent-input files") + ip.StepFail("upload-agent-input", "Failed to copy agent-input files", err) return fmt.Errorf("copying agent-input files: %w", err) } - printer.StepDone(fmt.Sprintf("Agent-input files copied (%.1fs)", time.Since(inputStart).Seconds())) + ip.StepDone("upload-agent-input", telemetry.TimedMsg("Agent-input files copied", time.Since(inputStart))) } - // 8c. Host-side scan (Path A): scan the target repo's context files - // (CLAUDE.md, AGENTS.md, SKILL.md, etc.) before the agent processes them. - // The target branch may contain attacker-controlled files from a PR. + // 8c. Host-side scan (Path A): scan the target repo's context files. if h.SecurityEnabled() { - printer.StepStart("Scanning target repo context files") + ip.StepStart("scan-host-context", "Scanning target repo context files", + telemetry.StringAttr("scan.target", repoSrc), + telemetry.StringAttr("scan.type", "host-context"), + ) findings := scanRepoContextFiles(repoSrc) if security.HasCriticalFindings(findings) { if h.FailModeClosed() { - printer.StepFail("BLOCKED: critical injection findings in target repo context files") + ip.StepFail("scan-host-context", "BLOCKED: critical injection findings in target repo context files", fmt.Errorf("critical injection findings")) return fmt.Errorf("target repo context scan blocked: critical injection findings") } - printer.StepWarn("Target repo has critical injection findings (fail_mode: open)") + ip.StepWarn("scan-host-context", "Target repo has critical injection findings (fail_mode: open)") } else if len(findings) > 0 { - printer.StepWarn(fmt.Sprintf("Target repo context scan: %d finding(s)", len(findings))) + ip.StepWarn("scan-host-context", fmt.Sprintf("Target repo context scan: %d finding(s)", len(findings))) } else { - printer.StepDone("Target repo context files clean") + ip.StepDone("scan-host-context", "Target repo context files clean", + telemetry.StringAttr("scan.findings_count", "0"), + ) } } // 9a. Generate trace ID for security finding correlation. traceID := security.GenerateTraceID() - printer.KeyValue("Trace ID", traceID) + ip.KeyValue("Trace ID", traceID) if err := injectTraceID(sandboxName, traceID); err != nil { - printer.StepWarn("Could not inject trace ID into sandbox: " + err.Error()) + ip.Warn("Could not inject trace ID into sandbox: " + err.Error()) } // 9b. Pre-agent security scan (sandbox-internal, Path B). - // Scans context files (CLAUDE.md, AGENTS.md, .cursorrules, agent defs, - // SKILL.md) that were just copied into the sandbox. if h.SecurityEnabled() { - printer.StepStart("Running pre-agent security scan") + ip.StepStart("scan-pre-agent", "Running pre-agent security scan", + telemetry.StringAttr("scan.type", "pre-agent"), + telemetry.StringAttr("scan.sandbox", sandboxName), + ) scanCmd := buildScanContextCommand(repoDir, traceID) stdout, stderr, exitCode, execErr := sandbox.Exec(sandboxName, scanCmd, 60*time.Second) if execErr != nil { - printer.StepFail("Security scan failed: " + execErr.Error()) if h.FailModeClosed() { + ip.StepFail("scan-pre-agent", "Security scan failed: "+execErr.Error(), execErr) return fmt.Errorf("pre-agent security scan failed: %w", execErr) } - printer.StepWarn("Continuing despite scan failure (fail_mode: open)") + ip.StepWarn("scan-pre-agent", "Continuing despite scan failure (fail_mode: open)") } else if exitCode != 0 { - printer.StepWarn("Security scan findings:\n" + stdout) + ip.AddEvent("scan-pre-agent", "scan.findings", telemetry.StringAttr("stdout", stdout)) + if stderr != "" { + ip.AddEvent("scan-pre-agent", "scan.stderr", telemetry.StringAttr("stderr", stderr)) + } + ip.Warn("Security scan findings:\n" + stdout) if stderr != "" { - printer.StepWarn("Scan stderr: " + stderr) + ip.Warn("Scan stderr: " + stderr) } if h.FailModeClosed() { - printer.StepFail("BLOCKED: pre-agent scan detected critical findings") + ip.StepFail("scan-pre-agent", "BLOCKED: pre-agent scan detected critical findings", fmt.Errorf("critical findings detected")) return fmt.Errorf("pre-agent security scan blocked: critical findings detected") } - printer.StepWarn("Continuing despite findings (fail_mode: open)") + ip.StepWarn("scan-pre-agent", "Continuing despite findings (fail_mode: open)") } else { - printer.StepDone("Pre-agent scan passed") + ip.StepDone("scan-pre-agent", "Pre-agent scan passed", + telemetry.StringAttr("scan.exit_code", "0"), + ) } } @@ -458,13 +594,13 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str if oidcURL := os.Getenv("FULLSEND_GCP_OIDC_URL"); oidcURL != "" { oidcAuth, err := readOIDCAuthFile(os.Getenv("FULLSEND_GCP_OIDC_AUTH_FILE")) if err != nil { - printer.StepWarn("OIDC token refresh disabled: " + err.Error()) + ip.Warn("OIDC token refresh disabled: " + err.Error()) } else { - printer.StepDone("OIDC token refresh enabled (WIF mode)") + ip.StepInfo("OIDC token refresh enabled (WIF mode)") oidcWg.Add(1) go func() { defer oidcWg.Done() - runOIDCRefresh(oidcCtx, sandboxName, oidcURL, oidcAuth, printer) + runOIDCRefresh(oidcCtx, sandboxName, oidcURL, oidcAuth, ip.Printer()) }() } } @@ -488,8 +624,8 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str } if maxIterations > 1 { - printer.Blank() - printer.Header(fmt.Sprintf("Iteration %d of %d", iteration, maxIterations)) + ip.Blank() + ip.Header(fmt.Sprintf("Iteration %d of %d", iteration, maxIterations)) } // Clear sandbox-side output and transcripts so the next iteration starts fresh. @@ -497,85 +633,108 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str clearCmd := fmt.Sprintf("rm -rf %s/output/* %s/*.jsonl", sandbox.SandboxWorkspace, sandbox.SandboxClaudeConfig) if _, _, _, clearErr := sandbox.Exec(sandboxName, clearCmd, 10*time.Second); clearErr != nil { - printer.StepWarn("Failed to clear sandbox output: " + clearErr.Error()) + ip.Warn("Failed to clear sandbox output: " + clearErr.Error()) } } // 9a. Run agent. - printer.StepStart("Running agent") - printer.Blank() + iterStep := fmt.Sprintf("agent-execution.iteration-%d", iteration) + ip.StepStart(iterStep, "Running agent", + telemetry.StringAttr("gen_ai.operation.name", "invoke_agent"), + telemetry.StringAttr("gen_ai.agent.name", agentName), + telemetry.StringAttr("gen_ai.request.model", h.Model), + telemetry.StringAttr("iteration", fmt.Sprintf("%d", iteration)), + telemetry.StringAttr("max_iterations", fmt.Sprintf("%d", maxIterations)), + telemetry.StringAttr("timeout", timeout.String()), + telemetry.StringAttr("sandbox.name", sandboxName), + telemetry.StringAttr("command", claudeCmd), + ) + ip.Blank() agentStart := time.Now() heartbeatDone := make(chan struct{}) - go runHeartbeat(printer, agentStart, timeout, heartbeatDone) + go runHeartbeat(ip.Printer(), agentStart, timeout, heartbeatDone) var metrics RunMetrics - exitCode, runErr := runAgentWithProgress(sandboxName, claudeCmd, timeout, printer, agentStart, &metrics) + exitCode, runErr := runAgentWithProgress(sandboxName, claudeCmd, timeout, ip.Printer(), agentStart, &metrics) close(heartbeatDone) if runErr != nil { - printer.StepFail("Agent execution failed") + ip.StepFail(iterStep, "Agent execution failed", runErr) return fmt.Errorf("running agent (iteration %d): %w", iteration, runErr) } lastExitCode = exitCode - printer.Blank() - // Non-zero exit is a warning, not a failure — the validation loop is the success gate. + ip.Blank() if exitCode == 0 { - printer.StepDone(fmt.Sprintf("Agent exited with code %d (%.1fs)", exitCode, time.Since(agentStart).Seconds())) + ip.StepDone(iterStep, telemetry.TimedMsg(fmt.Sprintf("Agent exited with code %d", exitCode), time.Since(agentStart)), telemetry.StringAttr("exit_code", fmt.Sprintf("%d", exitCode))) } else { - printer.StepWarn(fmt.Sprintf("Agent exited with code %d", exitCode)) + ip.StepWarn(iterStep, fmt.Sprintf("Agent exited with code %d (exit_code=%d)", exitCode, exitCode)) } // 9b. Extract output files. extractStart := time.Now() - printer.StepStart("Extracting output files") + ip.StepStart("extract-output", "Extracting output files", + telemetry.StringAttr("output.destination", iterOutputDir), + ) remoteSrc := fmt.Sprintf("%s/output", sandbox.SandboxWorkspace) extracted, extractErr := sandbox.ExtractOutputFiles(sandboxName, remoteSrc, iterOutputDir) if extractErr != nil { - printer.StepWarn("Failed to extract output files: " + extractErr.Error()) + ip.StepWarn("extract-output", "Failed to extract output files: "+extractErr.Error()) } else if len(extracted) == 0 { - printer.StepInfo("No output files found") + ip.StepDone("extract-output", "No output files found", + telemetry.StringAttr("output.file_count", "0"), + ) } else { for _, f := range extracted { - printer.StepInfo(f) + ip.StepInfo(f) } - printer.StepDone(fmt.Sprintf("Extracted %d output file(s) (%.1fs)", len(extracted), time.Since(extractStart).Seconds())) + ip.StepDone("extract-output", telemetry.TimedMsg(fmt.Sprintf("Extracted %d output file(s)", len(extracted)), time.Since(extractStart)), + telemetry.StringAttr("output.file_count", fmt.Sprintf("%d", len(extracted))), + telemetry.StringAttr("output.files", strings.Join(extracted, ", ")), + ) } // 9c. Extract transcripts for this iteration. transcriptStart := time.Now() - printer.StepStart("Extracting transcripts") + ip.StepStart("extract-transcripts", "Extracting transcripts", + telemetry.StringAttr("transcripts.destination", iterTranscriptDir), + ) if err := sandbox.ExtractTranscripts(sandboxName, agentName, iterTranscriptDir); err != nil { - printer.StepWarn("Failed to extract transcripts: " + err.Error()) + ip.StepWarn("extract-transcripts", "Failed to extract transcripts: "+err.Error()) } else { - printer.StepDone(fmt.Sprintf("Transcripts extracted (%.1fs)", time.Since(transcriptStart).Seconds())) + ip.StepDone("extract-transcripts", telemetry.TimedMsg("Transcripts extracted", time.Since(transcriptStart)), + telemetry.StringAttr("transcripts.directory", iterTranscriptDir), + ) } // Extract debug log if --debug was enabled. if debug != "" { debugDst := filepath.Join(iterDir, claudeDebugLog) if err := sandbox.DownloadFile(sandboxName, sandbox.SandboxWorkspace+"/"+claudeDebugLog, debugDst); err != nil { - printer.StepWarn("Failed to extract debug log: " + err.Error()) + ip.Warn("Failed to extract debug log: " + err.Error()) } else { - printer.StepInfo("Extracted claude-debug.log") + ip.StepInfo("Extracted claude-debug.log") } } - // 9d. Extract target repo back to host. SafeDownload removes dangerous - // symlinks (absolute or repo-escaping) and .git/hooks/ to prevent sandbox escape. + // 9d. Extract target repo back to host. if clearErr := os.RemoveAll(repoSrc); clearErr != nil { return fmt.Errorf("clearing local repo %s before extraction: %w", repoSrc, clearErr) } repoExtractStart := time.Now() - printer.StepStart("Extracting target repo") + ip.StepStart("extract-target-repo", "Extracting target repo", + telemetry.StringAttr("repo.sandbox_path", repoDir), + telemetry.StringAttr("repo.local_path", repoSrc), + ) if err := sandbox.SafeDownload(sandboxName, repoDir, repoSrc); err != nil { if es := extractTranscriptErrors(iterTranscriptDir); len(es) > 0 { emitTranscriptErrors(os.Stderr, es) } + ip.StepFail("extract-target-repo", "Failed to extract target repo", err) return fmt.Errorf("extracting target repo (iteration %d): %w", iteration, err) } - printer.StepDone(fmt.Sprintf("Target repo extracted to %s (%.1fs)", repoSrc, time.Since(repoExtractStart).Seconds())) + ip.StepDone("extract-target-repo", telemetry.TimedMsg(fmt.Sprintf("Target repo extracted to %s", repoSrc), time.Since(repoExtractStart))) // 9e. Run validation. if h.ValidationLoop == nil { @@ -583,7 +742,11 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str } valStart := time.Now() - printer.StepStart("Running validation: " + h.ValidationLoop.Script) + ip.StepStart("validation", "Running validation: "+h.ValidationLoop.Script, + telemetry.StringAttr("validation.script", h.ValidationLoop.Script), + telemetry.StringAttr("validation.iteration", fmt.Sprintf("%d", iteration)), + telemetry.StringAttr("validation.working_dir", iterDir), + ) valCmd := exec.Command(h.ValidationLoop.Script) valCmd.Dir = iterDir valCmd.Env = append(os.Environ(), @@ -595,64 +758,104 @@ func runAgent(agentName, fullsendDir, outputBase, targetRepo, fullsendBinary str valOut, valErr := valCmd.CombinedOutput() if valErr == nil { - printer.StepDone(fmt.Sprintf("Validation passed: %s (%.1fs)", strings.TrimSpace(string(valOut)), time.Since(valStart).Seconds())) + ip.StepDone("validation", telemetry.TimedMsg("Validation passed: "+strings.TrimSpace(string(valOut)), time.Since(valStart)), + telemetry.StringAttr("validation.result", "passed"), + telemetry.StringAttr("validation.output", strings.TrimSpace(string(valOut))), + ) validationPassed = true break } - printer.StepFail("Validation failed: " + strings.TrimSpace(string(valOut))) + ip.AddEvent("validation", "validation.output", + telemetry.StringAttr("output", strings.TrimSpace(string(valOut))), + ) + ip.StepFail("validation", "Validation failed: "+strings.TrimSpace(string(valOut)), valErr) if iteration < maxIterations { - printer.StepInfo(fmt.Sprintf("Will retry (%d iterations remaining)", maxIterations-iteration)) + ip.StepInfo(fmt.Sprintf("Will retry (%d iterations remaining)", maxIterations-iteration)) } } - // 9e-bis. Surface transcript errors in workflow logs (GitHub Actions). - // When the agent exits non-zero, parse transcript JSONL files and emit - // ::error:: annotations so operators can diagnose failures without - // downloading artifacts. See #704. + // Surface transcript errors in workflow logs (GitHub Actions). if lastExitCode != 0 { lastIterDir := filepath.Join(runDir, fmt.Sprintf("iteration-%d", runCount)) lastTranscriptDir := filepath.Join(lastIterDir, "transcripts") if errorSummaries := extractTranscriptErrors(lastTranscriptDir); len(errorSummaries) > 0 { - printer.StepWarn(fmt.Sprintf("Found %d transcript error(s) — emitting to workflow log", len(errorSummaries))) + ip.Warn(fmt.Sprintf("Found %d transcript error(s) — emitting to workflow log", len(errorSummaries))) emitTranscriptErrors(os.Stderr, errorSummaries) } } // 9f. Post-agent output scan — redact secrets from extracted output. if h.SecurityEnabled() { - printer.StepStart("Running post-agent output scan") - if err := scanOutputFiles(runDir, traceID, printer); err != nil { - printer.StepWarn("Output scan error: " + err.Error()) + ip.StepStart("scan-post-agent", "Running post-agent output scan") + if err := scanOutputFiles(runDir, traceID, ip); err != nil { + ip.StepWarn("scan-post-agent", "Output scan error: "+err.Error()) + } else { + ip.StepDone("scan-post-agent", "Post-agent output scan complete") } - // Extract sandbox-side security findings for audit trail. findingsDir := filepath.Join(runDir, "security") if err := os.MkdirAll(findingsDir, 0o755); err == nil { remoteFindingsDir := sandbox.SandboxWorkspace + "/.security/" if dlErr := sandbox.Download(sandboxName, remoteFindingsDir, findingsDir); dlErr != nil { - printer.StepInfo("No sandbox security findings to extract") + ip.StepInfo("No sandbox security findings to extract") + } else { + ip.StepInfo("Security findings extracted") + } + } + } + + // Enrich the deferred summary with data only available at this point. + // The defer block above handles WriteSummary + Close for all exit paths. + if rec != nil { + rec.SetSummaryFields(func(s *telemetry.RunSummary) { + s.SecurityTraceID = traceID + s.ExitCode = lastExitCode + s.Iterations = runCount + if h.ValidationLoop != nil { + s.Validation = &telemetry.ValidationResult{ + Configured: true, + Passed: validationPassed, + Iterations: runCount, + } + if validationPassed { + s.Validation.Status = telemetry.StatusOK + } else { + s.Validation.Status = telemetry.StatusError + } + } + }) + rec.SetRootAttribute("fullsend.iterations", fmt.Sprintf("%d", runCount)) + rec.SetRootAttribute("fullsend.exit_code", fmt.Sprintf("%d", lastExitCode)) + if h.ValidationLoop != nil { + if validationPassed { + rec.SetRootAttribute("fullsend.validation", "passed") } else { - printer.StepDone("Security findings extracted") + rec.SetRootAttribute("fullsend.validation", "failed") } } } - // 10. Print results. - printer.Blank() - printer.Header("Results") - printer.KeyValue("Run directory", runDir) - printer.KeyValue("Agent exit code", fmt.Sprintf("%d", lastExitCode)) - printer.KeyValue("Agent runs", fmt.Sprintf("%d", runCount)) - printer.KeyValue("Trace ID", traceID) + // Print results. + ip.Blank() + ip.Header("Results") + ip.KeyValue("Run directory", runDir) + ip.KeyValue("Agent exit code", fmt.Sprintf("%d", lastExitCode)) + ip.KeyValue("Agent runs", fmt.Sprintf("%d", runCount)) + ip.KeyValue("Trace ID", traceID) + if tp != nil && tp.Tracer != nil { + if otelTraceID := telemetry.Traceparent(ip.Context()); otelTraceID != "" { + ip.KeyValue("Traceparent", otelTraceID) + } + } if h.ValidationLoop != nil { if validationPassed { - printer.KeyValue("Validation", "passed") + ip.KeyValue("Validation", "passed") } else { - printer.KeyValue("Validation", "failed") + ip.KeyValue("Validation", "failed") } } - printer.Blank() + ip.Blank() if h.ValidationLoop != nil && !validationPassed { return fmt.Errorf("validation failed after %d iteration(s)", runCount) @@ -1234,18 +1437,18 @@ func buildScanContextCommand(repoDir, traceID string) string { // collectOpenshellLogs extracts OpenShell logs (sandbox and gateway sources) // into /logs/ before sandbox deletion. Failures are warned but never // block the run — log collection is best-effort. -func collectOpenshellLogs(sandboxName, runDir string, printer *ui.Printer) { +func collectOpenshellLogs(sandboxName, runDir string, ip *telemetry.InstrumentedPrinter) { if runDir == "" { return } logsDir := filepath.Join(runDir, "logs") if err := os.MkdirAll(logsDir, 0o755); err != nil { - printer.StepWarn("Failed to create logs directory: " + err.Error()) + ip.Warn("Failed to create logs directory: " + err.Error()) return } - printer.StepStart("Collecting OpenShell logs") + ip.StepStart("collect-logs", "Collecting OpenShell logs") collected := 0 sources := []struct { @@ -1259,19 +1462,21 @@ func collectOpenshellLogs(sandboxName, runDir string, printer *ui.Printer) { for _, src := range sources { output, err := sandbox.CollectLogs(sandboxName, src.name) if err != nil { - printer.StepWarn(fmt.Sprintf("Could not collect %s logs: %s", src.name, err.Error())) + ip.Warn(fmt.Sprintf("Could not collect %s logs: %s", src.name, err.Error())) continue } logPath := filepath.Join(logsDir, src.file) if err := os.WriteFile(logPath, []byte(output), 0o644); err != nil { - printer.StepWarn(fmt.Sprintf("Could not write %s: %s", src.file, err.Error())) + ip.Warn(fmt.Sprintf("Could not write %s: %s", src.file, err.Error())) continue } collected++ } if collected > 0 { - printer.StepDone(fmt.Sprintf("Collected %d OpenShell log source(s) to %s", collected, logsDir)) + ip.StepDone("collect-logs", fmt.Sprintf("Collected %d OpenShell log source(s) to %s", collected, logsDir)) + } else { + ip.StepWarn("collect-logs", "No OpenShell logs collected") } } @@ -1396,9 +1601,9 @@ func scanRepoContextFiles(repoDir string) []security.Finding { // scanOutputFiles runs the secret redactor on extracted output files, // recursively walking all subdirectories (iteration-N/output/, etc.). -func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { +func scanOutputFiles(outputDir, traceID string, ip *telemetry.InstrumentedPrinter) error { if _, err := os.Stat(outputDir); os.IsNotExist(err) { - printer.StepInfo("No output files to scan") + ip.StepInfo("No output files to scan") return nil } @@ -1408,10 +1613,9 @@ func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { err := filepath.WalkDir(outputDir, func(path string, d os.DirEntry, err error) error { if err != nil { - return nil // skip unreadable entries + return nil } if d.IsDir() { - // Skip the security findings directory itself. if d.Name() == "security" { return filepath.SkipDir } @@ -1420,7 +1624,7 @@ func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { content, readErr := os.ReadFile(path) if readErr != nil { relPath, _ := filepath.Rel(outputDir, path) - printer.StepWarn(fmt.Sprintf("Could not read %s: %v", relPath, readErr)) + ip.Warn(fmt.Sprintf("Could not read %s: %v", relPath, readErr)) return nil } @@ -1429,7 +1633,7 @@ func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { redacted += len(result.Findings) relPath, _ := filepath.Rel(outputDir, path) for _, f := range result.Findings { - printer.StepWarn(fmt.Sprintf("Redacted [%s] in %s: %s", f.Name, relPath, f.Detail)) + ip.Warn(fmt.Sprintf("Redacted [%s] in %s: %s", f.Name, relPath, f.Detail)) security.AppendFinding(findingsPath, security.TracedFinding{ TraceID: traceID, @@ -1439,7 +1643,7 @@ func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { }) } if writeErr := os.WriteFile(path, []byte(result.Sanitized), 0o644); writeErr != nil { - printer.StepWarn(fmt.Sprintf("Could not write redacted %s: %v", relPath, writeErr)) + ip.Warn(fmt.Sprintf("Could not write redacted %s: %v", relPath, writeErr)) } } return nil @@ -1449,9 +1653,9 @@ func scanOutputFiles(outputDir, traceID string, printer *ui.Printer) error { } if redacted > 0 { - printer.StepWarn(fmt.Sprintf("Redacted %d secret(s) from output files", redacted)) + ip.Warn(fmt.Sprintf("Redacted %d secret(s) from output files", redacted)) } else { - printer.StepDone("Output files clean — no secrets found") + ip.StepInfo("Output files clean — no secrets found") } return nil } diff --git a/internal/cli/run_test.go b/internal/cli/run_test.go index ca05647f52..2e2d0292cb 100644 --- a/internal/cli/run_test.go +++ b/internal/cli/run_test.go @@ -23,6 +23,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/fullsend-ai/fullsend/internal/telemetry" "github.com/fullsend-ai/fullsend/internal/ui" ) @@ -335,8 +336,8 @@ func TestBuildScanContextCommand_SourcesEnv(t *testing.T) { func TestCollectOpenshellLogs_EmptyRunDir(t *testing.T) { // Should be a no-op when runDir is empty — no panic, no error. - printer := ui.New(io.Discard) - collectOpenshellLogs("test-sandbox", "", printer) + ip := telemetry.NewInstrumentedPrinter(io.Discard) + collectOpenshellLogs("test-sandbox", "", ip) } func TestCollectOpenshellLogs_CreatesLogsDir(t *testing.T) { @@ -347,8 +348,8 @@ func TestCollectOpenshellLogs_CreatesLogsDir(t *testing.T) { runDir := filepath.Join(tmpDir, "run") require.NoError(t, os.MkdirAll(runDir, 0o755)) - printer := ui.New(io.Discard) - collectOpenshellLogs("nonexistent-sandbox", runDir, printer) + ip := telemetry.NewInstrumentedPrinter(io.Discard) + collectOpenshellLogs("nonexistent-sandbox", runDir, ip) // The logs directory should be created even if collection fails. logsDir := filepath.Join(runDir, "logs") diff --git a/internal/cli/telemetry_lint_test.go b/internal/cli/telemetry_lint_test.go new file mode 100644 index 0000000000..b5c19ef285 --- /dev/null +++ b/internal/cli/telemetry_lint_test.go @@ -0,0 +1,100 @@ +package cli + +import ( + "os" + "regexp" + "strings" + "testing" +) + +// TestNoRawPrinterStepCalls ensures that run.go does not call +// printer.StepStart/StepDone/StepFail/StepWarn directly within +// runAgent(). All lifecycle step output must go through the +// InstrumentedPrinter (ip.StepStart etc.) so that every printed +// step is automatically captured as a telemetry event. +// +// Helper functions that accept *ui.Printer as a parameter (like +// runHeartbeat, runOIDCRefresh) are exempt — they handle progress +// indicators, not lifecycle steps. +func TestNoRawPrinterStepCalls(t *testing.T) { + data, err := os.ReadFile("run.go") + if err != nil { + t.Fatalf("reading run.go: %v", err) + } + source := string(data) + + // Extract the runAgent function body (from signature to next top-level func). + startIdx := strings.Index(source, "func runAgent(") + if startIdx == -1 { + t.Fatal("could not find runAgent function") + } + + // Find the end of runAgent — the next top-level "func " at column 0. + body := source[startIdx:] + endIdx := strings.Index(body[1:], "\nfunc ") + if endIdx == -1 { + body = body[1:] + } else { + body = body[:endIdx+1] + } + + // These patterns indicate raw printer usage that bypasses telemetry. + forbidden := []*regexp.Regexp{ + regexp.MustCompile(`printer\.StepStart\(`), + regexp.MustCompile(`printer\.StepDone\(`), + regexp.MustCompile(`printer\.StepFail\(`), + regexp.MustCompile(`printer\.StepWarn\(`), + } + + for _, re := range forbidden { + matches := re.FindAllStringIndex(body, -1) + if len(matches) > 0 { + for _, m := range matches { + line := 1 + strings.Count(body[:m[0]], "\n") + t.Errorf("run.go:runAgent: raw %s call at line ~%d — use ip.StepStart/StepDone/StepFail/StepWarn instead", + re.String(), line) + } + } + } +} + +// TestNoRecStepHelperCalls ensures the old recStep/recDone/recFail/recWarn +// closure pattern has been fully removed from runAgent. +func TestNoRecStepHelperCalls(t *testing.T) { + data, err := os.ReadFile("run.go") + if err != nil { + t.Fatalf("reading run.go: %v", err) + } + source := string(data) + + startIdx := strings.Index(source, "func runAgent(") + if startIdx == -1 { + t.Fatal("could not find runAgent function") + } + + body := source[startIdx:] + endIdx := strings.Index(body[1:], "\nfunc ") + if endIdx == -1 { + body = body[1:] + } else { + body = body[:endIdx+1] + } + + forbidden := []*regexp.Regexp{ + regexp.MustCompile(`recStep\(`), + regexp.MustCompile(`recDone\(`), + regexp.MustCompile(`recFail\(`), + regexp.MustCompile(`recWarn\(`), + } + + for _, re := range forbidden { + matches := re.FindAllStringIndex(body, -1) + if len(matches) > 0 { + for _, m := range matches { + line := 1 + strings.Count(body[:m[0]], "\n") + t.Errorf("run.go:runAgent: old %s helper at line ~%d — this pattern is replaced by ip.StepStart/StepDone/StepFail/StepWarn", + re.String(), line) + } + } + } +} diff --git a/internal/sandbox/sandbox.go b/internal/sandbox/sandbox.go index 1df64674af..7551ff40a5 100644 --- a/internal/sandbox/sandbox.go +++ b/internal/sandbox/sandbox.go @@ -250,17 +250,25 @@ func createOnce(name string, providers []string, image, policy string, timeout t out, err := cmd.CombinedOutput() if err != nil { - check := exec.CommandContext(ctx, "openshell", "sandbox", "get", name) + // Use a fresh context for the existence check — the create context + // may have expired while the sandbox was still initializing. + getCtx, getCancel := context.WithTimeout(context.Background(), 10*time.Second) + defer getCancel() + check := exec.CommandContext(getCtx, "openshell", "sandbox", "get", name) if checkErr := check.Run(); checkErr != nil { return fmt.Errorf("sandbox create failed: %s", string(out)) } } // Wait for sandbox to be fully ready (image pull can take a while). + // Use a fresh context so we get the full ready timeout even if the + // create command consumed most of the original context. + readyCtx, readyCancel := context.WithTimeout(context.Background(), timeout+readyCtxBuffer) + defer readyCancel() deadline := time.Now().Add(timeout) var lastOutput, lastStderr string for time.Now().Before(deadline) { - check := exec.CommandContext(ctx, "openshell", "sandbox", "get", name) + check := exec.CommandContext(readyCtx, "openshell", "sandbox", "get", name) var stdoutBuf, stderrBuf strings.Builder check.Stdout = &stdoutBuf check.Stderr = &stderrBuf diff --git a/internal/telemetry/event.go b/internal/telemetry/event.go new file mode 100644 index 0000000000..eaf5eaeb3f --- /dev/null +++ b/internal/telemetry/event.go @@ -0,0 +1,101 @@ +package telemetry + +import "time" + +const SchemaVersion = "1" + +// RunEvent is a single lifecycle event emitted to run-events.jsonl. +// Designed with OTEL span semantics so events can be promoted to spans +// without schema changes. +type RunEvent struct { + Timestamp time.Time `json:"ts"` + Event string `json:"event"` + Step string `json:"step"` + DurationMs *int64 `json:"duration_ms,omitempty"` + Status string `json:"status,omitempty"` + Error string `json:"error,omitempty"` + Attrs map[string]string `json:"attrs,omitempty"` + TraceID string `json:"trace_id,omitempty"` + SpanID string `json:"span_id,omitempty"` + ParentID string `json:"parent_span_id,omitempty"` +} + +// Event type constants. +const ( + EventStepStart = "step.start" + EventStepDone = "step.done" + EventStepFail = "step.fail" + EventStepWarn = "step.warn" + EventRunStart = "run.start" + EventRunDone = "run.done" +) + +// Status constants. +const ( + StatusOK = "ok" + StatusError = "error" + StatusWarning = "warning" + StatusSkipped = "skipped" +) + +// RunSummary is the top-level metadata written to run-summary.json at the +// end of an agent run. It provides a machine-stable contract for downstream +// consumers to ingest without parsing CLI stdout. +type RunSummary struct { + SchemaVersion string `json:"schema_version"` + Agent string `json:"agent"` + Harness string `json:"harness"` + Model string `json:"model,omitempty"` + Image string `json:"image,omitempty"` + WorkItemID string `json:"work_item_id,omitempty"` + TraceID string `json:"trace_id,omitempty"` + SecurityTraceID string `json:"security_trace_id,omitempty"` + Traceparent string `json:"traceparent,omitempty"` + StartTime time.Time `json:"start_time"` + EndTime time.Time `json:"end_time"` + DurationMs int64 `json:"duration_ms"` + ExitCode int `json:"exit_code"` + Iterations int `json:"iterations"` + Validation *ValidationResult `json:"validation,omitempty"` + Steps []StepSummary `json:"steps"` + Attrs map[string]string `json:"attrs,omitempty"` +} + +// ValidationResult captures the outcome of the validation loop. +type ValidationResult struct { + Configured bool `json:"configured"` + Passed bool `json:"passed"` + Iterations int `json:"iterations"` + Status string `json:"status"` +} + +// StepSummary captures the outcome of a single lifecycle step. +type StepSummary struct { + Name string `json:"name"` + Status string `json:"status"` + DurationMs int64 `json:"duration_ms"` + Error string `json:"error,omitempty"` +} + +// Attr is a key-value attribute pair passed to recorder methods. +type Attr struct { + Key string + Value string +} + +// StringAttr creates an Attr. +func StringAttr(key, value string) Attr { + return Attr{Key: key, Value: value} +} + +// attrsToMap converts a slice of Attr to a map. +func attrsToMap(attrs []Attr) map[string]string { + if len(attrs) == 0 { + return nil + } + m := make(map[string]string, len(attrs)) + for _, a := range attrs { + m[a.Key] = a.Value + } + return m +} diff --git a/internal/telemetry/instrumented.go b/internal/telemetry/instrumented.go new file mode 100644 index 0000000000..e62432363b --- /dev/null +++ b/internal/telemetry/instrumented.go @@ -0,0 +1,212 @@ +package telemetry + +import ( + "context" + "fmt" + "io" + "time" + + "github.com/fullsend-ai/fullsend/internal/ui" +) + +// InstrumentedPrinter unifies terminal output (ui.Printer) and structured +// telemetry recording (Recorder) into a single call site. Every printed +// lifecycle step is automatically recorded as a telemetry event and OTEL +// span. This makes it structurally impossible to print a step without +// tracing it. +// +// The recorder may be attached after construction (via AttachRecorder) +// to handle the bootstrapping period where the printer is needed before +// the run directory exists. Steps started before the recorder is attached +// are captured as buffered entries and replayed once the recorder becomes +// available. +type InstrumentedPrinter struct { + printer *ui.Printer + rec *Recorder + ctx context.Context + buffered []bufferedStep +} + +type bufferedStep struct { + name string + start time.Time + done bool + fail error + warn string + attrs []Attr +} + +// NewInstrumentedPrinter creates an InstrumentedPrinter that writes styled +// output to w. The recorder is not yet attached — call AttachRecorder once +// the run directory and tracer are available. +func NewInstrumentedPrinter(w io.Writer) *InstrumentedPrinter { + return &InstrumentedPrinter{ + printer: ui.New(w), + ctx: context.Background(), + } +} + +// AttachRecorder connects the telemetry recorder and replays any buffered +// steps that occurred before the recorder was available. +func (ip *InstrumentedPrinter) AttachRecorder(rec *Recorder, ctx context.Context) { + ip.rec = rec + ip.ctx = ctx + ip.replayBuffered() +} + +// Recorder returns the underlying Recorder (may be nil before AttachRecorder). +func (ip *InstrumentedPrinter) Recorder() *Recorder { + return ip.rec +} + +// Context returns the current run context (root span context after attach). +func (ip *InstrumentedPrinter) Context() context.Context { + return ip.ctx +} + +// StepStart prints a step-in-progress marker and records a telemetry event. +func (ip *InstrumentedPrinter) StepStart(name, msg string, attrs ...Attr) { + ip.printer.StepStart(msg) + if ip.rec != nil { + ip.rec.StepStart(ip.ctx, name, attrs...) + } else { + ip.buffered = append(ip.buffered, bufferedStep{name: name, start: time.Now(), attrs: attrs}) + } +} + +// StepDone prints a success marker and records step completion. +func (ip *InstrumentedPrinter) StepDone(name, msg string, attrs ...Attr) { + ip.printer.StepDone(msg) + if ip.rec != nil { + ip.rec.StepDone(name, attrs...) + } else { + ip.markBuffered(name, func(b *bufferedStep) { b.done = true; b.attrs = append(b.attrs, attrs...) }) + } +} + +// StepFail prints a failure marker and records the step as failed. +func (ip *InstrumentedPrinter) StepFail(name, msg string, err error) { + ip.printer.StepFail(msg) + if ip.rec != nil { + ip.rec.StepFail(name, err) + } else { + ip.markBuffered(name, func(b *bufferedStep) { b.fail = err }) + } +} + +// StepWarn prints a warning marker and records the step with a warning. +func (ip *InstrumentedPrinter) StepWarn(name, msg string) { + ip.printer.StepWarn(msg) + if ip.rec != nil { + ip.rec.StepWarn(name, msg) + } else { + ip.markBuffered(name, func(b *bufferedStep) { b.warn = msg }) + } +} + +// StepInfo prints indented informational text (no telemetry event). +func (ip *InstrumentedPrinter) StepInfo(text string) { + ip.printer.StepInfo(text) +} + +// AddEvent attaches a log-style event to the currently-open step span. +// This is the standard OTEL mechanism for adding context to spans and +// appears in all backends (Jaeger, Phoenix, Tempo) under "Events" or "Logs". +func (ip *InstrumentedPrinter) AddEvent(stepName, eventName string, attrs ...Attr) { + if ip.rec != nil { + ip.rec.AddEvent(stepName, eventName, attrs...) + } +} + +// AddRootEvent attaches an event directly to the root span. +func (ip *InstrumentedPrinter) AddRootEvent(eventName string, attrs ...Attr) { + if ip.rec != nil { + ip.rec.AddRootEvent(eventName, attrs...) + } +} + +// Warn prints a standalone warning not associated with a step lifecycle. +// Use for informational warnings that aren't closing a span. +func (ip *InstrumentedPrinter) Warn(msg string) { + ip.printer.StepWarn(msg) +} + +// Printer returns the underlying ui.Printer for helpers that only need +// informational output (heartbeats, progress parsing) without step lifecycles. +func (ip *InstrumentedPrinter) Printer() *ui.Printer { + return ip.printer +} + +// Banner prints the fullsend brand banner. +func (ip *InstrumentedPrinter) Banner() { + ip.printer.Banner() +} + +// Header prints a section header. +func (ip *InstrumentedPrinter) Header(text string) { + ip.printer.Header(text) +} + +// KeyValue prints a key-value pair. +func (ip *InstrumentedPrinter) KeyValue(key, value string) { + ip.printer.KeyValue(key, value) +} + +// Summary prints a bordered summary box. +func (ip *InstrumentedPrinter) Summary(title string, items []string) { + ip.printer.Summary(title, items) +} + +// ErrorBox prints an error-styled bordered box. +func (ip *InstrumentedPrinter) ErrorBox(title, detail string) { + ip.printer.ErrorBox(title, detail) +} + +// Heartbeat prints a periodic progress line. +func (ip *InstrumentedPrinter) Heartbeat(text string) { + ip.printer.Heartbeat(text) +} + +// Blank prints an empty line. +func (ip *InstrumentedPrinter) Blank() { + ip.printer.Blank() +} + +// Raw writes text directly without styling. +func (ip *InstrumentedPrinter) Raw(text string) { + ip.printer.Raw(text) +} + +// PRLink prints a pull request link. +func (ip *InstrumentedPrinter) PRLink(repo, url string) { + ip.printer.PRLink(repo, url) +} + +// TimedMsg formats a message with elapsed seconds appended. +func TimedMsg(base string, d time.Duration) string { + return fmt.Sprintf("%s (%.1fs)", base, d.Seconds()) +} + +func (ip *InstrumentedPrinter) replayBuffered() { + for _, b := range ip.buffered { + ip.rec.StepStart(ip.ctx, b.name, b.attrs...) + switch { + case b.fail != nil: + ip.rec.StepFail(b.name, b.fail) + case b.warn != "": + ip.rec.StepWarn(b.name, b.warn) + case b.done: + ip.rec.StepDone(b.name, b.attrs...) + } + } + ip.buffered = nil +} + +func (ip *InstrumentedPrinter) markBuffered(name string, fn func(*bufferedStep)) { + for i := len(ip.buffered) - 1; i >= 0; i-- { + if ip.buffered[i].name == name { + fn(&ip.buffered[i]) + return + } + } +} diff --git a/internal/telemetry/instrumented_test.go b/internal/telemetry/instrumented_test.go new file mode 100644 index 0000000000..2578df7624 --- /dev/null +++ b/internal/telemetry/instrumented_test.go @@ -0,0 +1,290 @@ +package telemetry + +import ( + "bytes" + "context" + "encoding/json" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/attribute" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" +) + +func TestInstrumentedPrinter_StepStartDone(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + ip.StepStart("my-step", "Doing something") + ip.StepDone("my-step", "Done doing something") + require.NoError(t, rec.Close()) + + output := buf.String() + assert.Contains(t, output, "Doing something") + assert.Contains(t, output, "Done doing something") + + events := readEvents(t, filepath.Join(dir, "run-events.jsonl")) + stepStarts := filterEvents(events, EventStepStart, "my-step") + stepDones := filterEvents(events, EventStepDone, "my-step") + assert.Len(t, stepStarts, 1) + assert.Len(t, stepDones, 1) +} + +func TestInstrumentedPrinter_StepFail(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + ip.StepStart("failing-step", "About to fail") + ip.StepFail("failing-step", "It failed", assert.AnError) + require.NoError(t, rec.Close()) + + events := readEvents(t, filepath.Join(dir, "run-events.jsonl")) + fails := filterEvents(events, EventStepFail, "failing-step") + assert.Len(t, fails, 1) + assert.Equal(t, StatusError, fails[0].Status) + assert.Contains(t, fails[0].Error, "assert.AnError") +} + +func TestInstrumentedPrinter_StepWarn(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + ip.StepStart("warn-step", "Trying something risky") + ip.StepWarn("warn-step", "It kinda worked") + require.NoError(t, rec.Close()) + + events := readEvents(t, filepath.Join(dir, "run-events.jsonl")) + warns := filterEvents(events, EventStepWarn, "warn-step") + assert.Len(t, warns, 1) + assert.Equal(t, StatusWarning, warns[0].Status) +} + +func TestInstrumentedPrinter_BufferReplay(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + // Steps before recorder is attached get buffered. + ip.StepStart("early-step", "Loading config") + ip.StepDone("early-step", "Config loaded") + ip.StepStart("fail-early", "Validating") + ip.StepFail("fail-early", "Validation failed", assert.AnError) + + // Now attach the recorder — buffered steps should replay. + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + // Additional step after attach. + ip.StepStart("late-step", "Running agent") + ip.StepDone("late-step", "Agent done") + require.NoError(t, rec.Close()) + + events := readEvents(t, filepath.Join(dir, "run-events.jsonl")) + + // All three steps should be in the JSONL: early-step, fail-early, late-step. + earlyStarts := filterEvents(events, EventStepStart, "early-step") + earlyDones := filterEvents(events, EventStepDone, "early-step") + failStarts := filterEvents(events, EventStepStart, "fail-early") + failFails := filterEvents(events, EventStepFail, "fail-early") + lateStarts := filterEvents(events, EventStepStart, "late-step") + lateDones := filterEvents(events, EventStepDone, "late-step") + + assert.Len(t, earlyStarts, 1, "buffered step.start should replay") + assert.Len(t, earlyDones, 1, "buffered step.done should replay") + assert.Len(t, failStarts, 1, "buffered fail step.start should replay") + assert.Len(t, failFails, 1, "buffered step.fail should replay") + assert.Len(t, lateStarts, 1, "post-attach step.start should record") + assert.Len(t, lateDones, 1, "post-attach step.done should record") +} + +func TestInstrumentedPrinter_NoRecorder(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + // Without attaching a recorder, steps should still print (no panic). + ip.StepStart("orphan-step", "Doing work") + ip.StepDone("orphan-step", "Work done") + ip.StepFail("other-step", "Oops", assert.AnError) + ip.StepWarn("yet-another", "Hmm") + ip.Warn("Standalone warning") + + output := buf.String() + assert.Contains(t, output, "Doing work") + assert.Contains(t, output, "Work done") + assert.Contains(t, output, "Oops") + assert.Contains(t, output, "Standalone warning") +} + +func TestInstrumentedPrinter_WarnDoesNotCreateSpan(t *testing.T) { + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + ip.Warn("standalone warning that is not a step") + require.NoError(t, rec.Close()) + + events := readEvents(t, filepath.Join(dir, "run-events.jsonl")) + // Only run.start and run.done — no step events from Warn(). + for _, e := range events { + if e.Event == EventStepStart || e.Event == EventStepDone || e.Event == EventStepFail || e.Event == EventStepWarn { + t.Errorf("Warn() should not produce step events, got %s for step %q", e.Event, e.Step) + } + } +} + +func TestInstrumentedPrinter_AttrsFlowToOTELSpan(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + tracer := tp.Tracer("test") + + var buf bytes.Buffer + ip := NewInstrumentedPrinter(&buf) + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, tracer, "test-run", + []Attr{StringAttr("gen_ai.agent.name", "triage")}, + ) + require.NoError(t, err) + ip.AttachRecorder(rec, ctx) + + ip.StepStart("sandbox-create", "Creating sandbox", + StringAttr("sandbox.image", "ubuntu:22.04"), + ) + ip.StepDone("sandbox-create", "Sandbox ready", + StringAttr("sandbox.name", "fs-abc123"), + StringAttr("exit_code", "0"), + ) + require.NoError(t, rec.Close()) + require.NoError(t, tp.ForceFlush(context.Background())) + + spans := exporter.GetSpans() + + // Find the sandbox-create span. + var found *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "sandbox-create" { + found = &spans[i] + break + } + } + require.NotNil(t, found, "sandbox-create span should exist") + + attrMap := make(map[string]string) + for _, a := range found.Attributes { + if a.Value.Type() == attribute.STRING { + attrMap[string(a.Key)] = a.Value.AsString() + } + } + + assert.Equal(t, "ubuntu:22.04", attrMap["sandbox.image"], "StepStart attr should appear on span") + assert.Equal(t, "fs-abc123", attrMap["sandbox.name"], "StepDone attr should appear on span") + assert.Equal(t, "0", attrMap["exit_code"], "StepDone attr should appear on span") +} + +func TestRecorder_RootSpanKind(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + tracer := tp.Tracer("test") + + dir := t.TempDir() + rec, _, err := NewRecorder(context.Background(), dir, tracer, "consumer-run", + []Attr{StringAttr("test", "1")}, + SpanKindConsumer(), + ) + require.NoError(t, err) + require.NoError(t, rec.Close()) + require.NoError(t, tp.ForceFlush(context.Background())) + + spans := exporter.GetSpans() + var root *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "consumer-run" { + root = &spans[i] + break + } + } + require.NotNil(t, root, "root span should exist") + assert.Equal(t, trace.SpanKindConsumer, root.SpanKind, "root span should have SpanKindConsumer") +} + +func TestRecorder_RootSpanKindDefault(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + tracer := tp.Tracer("test") + + dir := t.TempDir() + rec, _, err := NewRecorder(context.Background(), dir, tracer, "internal-run", nil) + require.NoError(t, err) + require.NoError(t, rec.Close()) + require.NoError(t, tp.ForceFlush(context.Background())) + + spans := exporter.GetSpans() + var root *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "internal-run" { + root = &spans[i] + break + } + } + require.NotNil(t, root, "root span should exist") + assert.Equal(t, trace.SpanKindInternal, root.SpanKind, "default root span should be SpanKindInternal") +} + +func TestTimedMsg(t *testing.T) { + msg := TimedMsg("Operation complete", 3500000000) // 3.5 seconds as Duration + assert.Equal(t, "Operation complete (3.5s)", msg) +} + +// --- helpers --- + +func readEvents(t *testing.T, path string) []RunEvent { + t.Helper() + data, err := os.ReadFile(path) + require.NoError(t, err) + var events []RunEvent + for _, line := range strings.Split(strings.TrimSpace(string(data)), "\n") { + if line == "" { + continue + } + var e RunEvent + require.NoError(t, json.Unmarshal([]byte(line), &e)) + events = append(events, e) + } + return events +} + +func filterEvents(events []RunEvent, eventType, step string) []RunEvent { + var out []RunEvent + for _, e := range events { + if e.Event == eventType && e.Step == step { + out = append(out, e) + } + } + return out +} diff --git a/internal/telemetry/otel.go b/internal/telemetry/otel.go new file mode 100644 index 0000000000..10c1395073 --- /dev/null +++ b/internal/telemetry/otel.go @@ -0,0 +1,125 @@ +package telemetry + +import ( + "context" + "fmt" + "os" + "time" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" + "go.opentelemetry.io/otel/trace" +) + +const ( + serviceName = "fullsend-cli" + shutdownTimeout = 5 * time.Second +) + +// Config controls telemetry initialization. +type Config struct { + // Enabled turns telemetry on. When false, a noop tracer is returned + // and no events file is written to disk. + Enabled bool + + // OTLPEndpoint is the OTLP HTTP endpoint (e.g. "localhost:4318"). + // When empty, the SDK reads OTEL_EXPORTER_OTLP_ENDPOINT from the + // environment. When neither is set, spans are exported only to the + // run-events.jsonl file (no network export). + OTLPEndpoint string + + // ServiceVersion is the fullsend CLI version string. + ServiceVersion string +} + +// ConfigFromEnv builds a Config from environment variables. +// Telemetry is enabled when FULLSEND_TELEMETRY=1 or when +// OTEL_EXPORTER_OTLP_ENDPOINT / OTEL_EXPORTER_OTLP_TRACES_ENDPOINT +// is set (opt-in via either mechanism). +func ConfigFromEnv() Config { + endpoint := os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT") + tracesEndpoint := os.Getenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") + explicit := os.Getenv("FULLSEND_TELEMETRY") + return Config{ + Enabled: explicit == "1" || explicit == "true" || endpoint != "" || tracesEndpoint != "", + OTLPEndpoint: endpoint, + } +} + +// TracerProvider holds the initialized OTEL provider and its shutdown function. +type TracerProvider struct { + provider *sdktrace.TracerProvider + Tracer trace.Tracer +} + +// Shutdown flushes remaining spans and releases resources. +func (tp *TracerProvider) Shutdown(ctx context.Context) error { + if tp == nil || tp.provider == nil { + return nil + } + shutdownCtx, cancel := context.WithTimeout(ctx, shutdownTimeout) + defer cancel() + return tp.provider.Shutdown(shutdownCtx) +} + +// NoopProvider returns a TracerProvider with a noop tracer. Used as a safe +// fallback when initialization fails. +func NoopProvider() *TracerProvider { + return &TracerProvider{Tracer: trace.NewNoopTracerProvider().Tracer(serviceName)} +} + +// InitTracer sets up an OTEL TracerProvider. When the config has an OTLP +// endpoint (explicit or via env), spans are exported over HTTP. When no +// endpoint is configured, the tracer still produces valid trace/span IDs +// for the events file — consumers get structured telemetry without +// running a collector. +func InitTracer(ctx context.Context, cfg Config) (*TracerProvider, error) { + if !cfg.Enabled { + return &TracerProvider{Tracer: trace.NewNoopTracerProvider().Tracer(serviceName)}, nil + } + + res, err := resource.New(ctx, + resource.WithAttributes( + semconv.ServiceName(serviceName), + semconv.ServiceVersion(cfg.ServiceVersion), + ), + ) + if err != nil { + return nil, fmt.Errorf("creating OTEL resource: %w", err) + } + + var opts []sdktrace.TracerProviderOption + opts = append(opts, sdktrace.WithResource(res)) + + // When an OTLP endpoint is available, configure the HTTP exporter. + // If the endpoint comes from OTEL_EXPORTER_OTLP_ENDPOINT (the standard + // env var), let the SDK read it directly — it expects a full URL + // (e.g. "http://localhost:4318") and handles scheme/path parsing. + // WithEndpoint() expects bare host:port and would break with a scheme. + if cfg.OTLPEndpoint != "" || os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT") != "" || os.Getenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") != "" { + exporter, err := otlptracehttp.New(ctx) + if err != nil { + return nil, fmt.Errorf("creating OTLP exporter: %w", err) + } + opts = append(opts, sdktrace.WithBatcher(exporter)) + } else { + // No collector configured. Use a simple syncer that drops spans. + // The structured events file (run-events.jsonl) is the primary + // output in this mode — it captures trace/span IDs from the SDK + // so consumers can correlate without running a collector. + opts = append(opts, sdktrace.WithSampler(sdktrace.AlwaysSample())) + } + + tp := sdktrace.NewTracerProvider(opts...) + otel.SetTracerProvider(tp) + otel.SetTextMapPropagator(propagation.TraceContext{}) + + return &TracerProvider{ + provider: tp, + Tracer: tp.Tracer(serviceName), + }, nil +} diff --git a/internal/telemetry/otel_test.go b/internal/telemetry/otel_test.go new file mode 100644 index 0000000000..4fa8df9097 --- /dev/null +++ b/internal/telemetry/otel_test.go @@ -0,0 +1,105 @@ +package telemetry + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/trace" +) + +func TestInitTracer_Disabled(t *testing.T) { + tp, err := InitTracer(context.Background(), Config{Enabled: false}) + require.NoError(t, err) + require.NotNil(t, tp) + require.NotNil(t, tp.Tracer) + + // Noop tracer should not produce valid span contexts. + ctx, span := tp.Tracer.Start(context.Background(), "test") + defer span.End() + sc := trace.SpanContextFromContext(ctx) + assert.False(t, sc.IsValid()) + + assert.NoError(t, tp.Shutdown(context.Background())) +} + +func TestInitTracer_EnabledNoEndpoint(t *testing.T) { + // Enabled without an endpoint — should still create a real tracer + // that produces valid trace IDs for the events file. + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "") + tp, err := InitTracer(context.Background(), Config{ + Enabled: true, + ServiceVersion: "test", + }) + require.NoError(t, err) + require.NotNil(t, tp) + + ctx, span := tp.Tracer.Start(context.Background(), "test") + defer span.End() + sc := trace.SpanContextFromContext(ctx) + assert.True(t, sc.IsValid()) + + assert.NoError(t, tp.Shutdown(context.Background())) +} + +func TestConfigFromEnv_Defaults(t *testing.T) { + t.Setenv("FULLSEND_TELEMETRY", "") + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "") + t.Setenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "") + cfg := ConfigFromEnv() + assert.False(t, cfg.Enabled) +} + +func TestConfigFromEnv_TelemetryFlag(t *testing.T) { + t.Setenv("FULLSEND_TELEMETRY", "1") + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "") + t.Setenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "") + cfg := ConfigFromEnv() + assert.True(t, cfg.Enabled) +} + +func TestConfigFromEnv_OTLPEndpoint(t *testing.T) { + t.Setenv("FULLSEND_TELEMETRY", "") + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://localhost:4318") + t.Setenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "") + cfg := ConfigFromEnv() + assert.True(t, cfg.Enabled) + assert.Equal(t, "http://localhost:4318", cfg.OTLPEndpoint) +} + +func TestConfigFromEnv_TracesEndpoint(t *testing.T) { + t.Setenv("FULLSEND_TELEMETRY", "") + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "") + t.Setenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "https://mlflow.example.com/v1/traces") + cfg := ConfigFromEnv() + assert.True(t, cfg.Enabled, "traces-specific endpoint should enable telemetry") +} + +func TestTracerProvider_ShutdownNil(t *testing.T) { + var tp *TracerProvider + assert.NoError(t, tp.Shutdown(context.Background())) +} + +func TestInitTracer_UnreachableEndpoint_StillWorks(t *testing.T) { + // Simulates a misconfigured endpoint. The exporter will fail to + // connect but the SDK should still produce valid trace/span IDs + // so local files remain useful. + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://192.0.2.1:4318") // RFC 5737 TEST-NET + tp, err := InitTracer(context.Background(), Config{ + Enabled: true, + OTLPEndpoint: "http://192.0.2.1:4318", + ServiceVersion: "test", + }) + require.NoError(t, err) + require.NotNil(t, tp) + + ctx, span := tp.Tracer.Start(context.Background(), "test-op") + sc := trace.SpanContextFromContext(ctx) + assert.True(t, sc.IsValid(), "should produce valid span context even with unreachable endpoint") + span.End() + + // Shutdown may return a timeout error when the endpoint is unreachable — + // the important thing is it doesn't panic or block indefinitely. + _ = tp.Shutdown(context.Background()) +} diff --git a/internal/telemetry/propagation.go b/internal/telemetry/propagation.go new file mode 100644 index 0000000000..5b31fd3213 --- /dev/null +++ b/internal/telemetry/propagation.go @@ -0,0 +1,141 @@ +package telemetry + +import ( + "context" + "fmt" + "os" + "regexp" + "strings" + + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/trace" +) + +var reTraceparent = regexp.MustCompile( + `^00-[a-f0-9]{32}-[a-f0-9]{16}-[a-f0-9]{2}$`, +) + +// Traceparent formats a W3C traceparent header from the span context. +// Returns empty string if the span context is invalid. +func Traceparent(ctx context.Context) string { + sc := trace.SpanContextFromContext(ctx) + if !sc.IsValid() { + return "" + } + flags := "00" + if sc.IsSampled() { + flags = "01" + } + return fmt.Sprintf("00-%s-%s-%s", + sc.TraceID().String(), + sc.SpanID().String(), + flags, + ) +} + +// TraceparentEnvVar returns the TRACEPARENT=... string suitable for injection +// into a subprocess environment. Returns empty string if the context carries +// no valid span. +func TraceparentEnvVar(ctx context.Context) string { + tp := Traceparent(ctx) + if tp == "" { + return "" + } + return "TRACEPARENT=" + tp +} + +// IsValidTraceparent checks whether a string is a well-formed W3C traceparent. +func IsValidTraceparent(tp string) bool { + return reTraceparent.MatchString(tp) +} + +// ContextFromTraceparent extracts trace context from a TRACEPARENT env var +// or explicit value and returns a context with the remote span context set. +// Falls back to checking the TRACEPARENT environment variable if value is empty. +func ContextFromTraceparent(ctx context.Context, value string) context.Context { + if value == "" { + value = os.Getenv("TRACEPARENT") + } + if value == "" || !IsValidTraceparent(value) { + return ctx + } + carrier := propagation.MapCarrier{"traceparent": value} + prop := propagation.TraceContext{} + return prop.Extract(ctx, carrier) +} + +// WorkItemID constructs a canonical work-item identifier from a repo and +// issue/PR number. This is the framework-level convention for cross-run +// correlation: every trace carries this as a span attribute so consumers +// can query for all traces related to a work item at read time. +// +// Format: "owner/repo#123" +func WorkItemID(repo string, number int) string { + if repo == "" || number <= 0 { + return "" + } + return fmt.Sprintf("%s#%d", repo, number) +} + +// WorkItemIDFromEnv attempts to construct a work_item_id from standard +// environment variables set by fullsend dispatch workflows. +func WorkItemIDFromEnv() string { + repo := os.Getenv("FULLSEND_SOURCE_REPO") + if repo == "" { + repo = os.Getenv("GITHUB_REPOSITORY") + } + + // Try issue number first, then PR number. Validate that the value + // looks numeric to avoid producing IDs like "owner/repo#not-a-number". + for _, key := range []string{ + "FULLSEND_ISSUE_NUMBER", + "GITHUB_ISSUE_NUMBER", + "FULLSEND_PR_NUMBER", + } { + if num := os.Getenv(key); num != "" && isNumeric(num) { + if repo != "" { + return repo + "#" + num + } + } + } + + // Fall back to URL-based extraction. + for _, key := range []string{"GITHUB_ISSUE_URL", "GITHUB_PR_URL", "ORIGINATING_URL"} { + if u := os.Getenv(key); u != "" { + if wid := workItemFromURL(u); wid != "" { + return wid + } + } + } + return "" +} + +func isNumeric(s string) bool { + for _, c := range s { + if c < '0' || c > '9' { + return false + } + } + return len(s) > 0 +} + +// workItemFromURL extracts "owner/repo#N" from a GitHub issue or PR URL. +func workItemFromURL(u string) string { + // Expected: https://github.com/owner/repo/issues/123 + // or: https://github.com/owner/repo/pull/123 + parts := strings.Split(strings.TrimRight(u, "/"), "/") + if len(parts) < 5 { + return "" + } + n := len(parts) + number := parts[n-1] + kind := parts[n-2] // "issues" or "pull" + if kind != "issues" && kind != "pull" { + return "" + } + if !isNumeric(number) { + return "" + } + repo := parts[n-4] + "/" + parts[n-3] + return repo + "#" + number +} diff --git a/internal/telemetry/propagation_test.go b/internal/telemetry/propagation_test.go new file mode 100644 index 0000000000..974b8e61e6 --- /dev/null +++ b/internal/telemetry/propagation_test.go @@ -0,0 +1,67 @@ +package telemetry + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestIsValidTraceparent(t *testing.T) { + tests := []struct { + input string + valid bool + }{ + {"00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01", true}, + {"00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-00", true}, + {"", false}, + {"not-a-traceparent", false}, + {"00-INVALID-00f067aa0ba902b7-01", false}, + {"01-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01", false}, // wrong version + } + + for _, tc := range tests { + assert.Equal(t, tc.valid, IsValidTraceparent(tc.input), "input: %q", tc.input) + } +} + +func TestContextFromTraceparent(t *testing.T) { + tp := "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" + ctx := ContextFromTraceparent(context.Background(), tp) + require.NotNil(t, ctx) + + result := Traceparent(ctx) + // The extracted context should produce a valid traceparent with same trace ID. + assert.Contains(t, result, "4bf92f3577b34da6a3ce929d0e0e4736") +} + +func TestContextFromTraceparent_Empty(t *testing.T) { + ctx := ContextFromTraceparent(context.Background(), "") + result := Traceparent(ctx) + assert.Empty(t, result) +} + +func TestWorkItemID(t *testing.T) { + assert.Equal(t, "owner/repo#42", WorkItemID("owner/repo", 42)) + assert.Equal(t, "", WorkItemID("", 42)) + assert.Equal(t, "", WorkItemID("owner/repo", 0)) + assert.Equal(t, "", WorkItemID("owner/repo", -1)) +} + +func TestWorkItemFromURL(t *testing.T) { + tests := []struct { + url string + expect string + }{ + {"https://github.com/org/repo/issues/123", "org/repo#123"}, + {"https://github.com/org/repo/pull/456", "org/repo#456"}, + {"https://github.com/org/repo/issues/123/", "org/repo#123"}, + {"https://not-github.com/too/short", ""}, + {"https://github.com/org/repo/actions/runs/123", ""}, + } + + for _, tc := range tests { + assert.Equal(t, tc.expect, workItemFromURL(tc.url), "url: %s", tc.url) + } +} diff --git a/internal/telemetry/recorder.go b/internal/telemetry/recorder.go new file mode 100644 index 0000000000..0113ca39c5 --- /dev/null +++ b/internal/telemetry/recorder.go @@ -0,0 +1,440 @@ +package telemetry + +import ( + "context" + "encoding/json" + "fmt" + "os" + "path/filepath" + "sync" + "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" +) + +const ( + eventsFile = "run-events.jsonl" + summaryFile = "run-summary.json" +) + +// Recorder captures structured lifecycle events alongside OTEL spans. +// It writes events to run-events.jsonl as they occur (crash-safe) and +// produces a run-summary.json at close. When an OTEL tracer is configured, +// each step also produces an OTEL span. +// +// All methods are safe for concurrent use. +type Recorder struct { + mu sync.Mutex + dir string + file *os.File + enc *json.Encoder + tracer trace.Tracer + rootCtx context.Context + rootSpan trace.Span + spans map[string]spanEntry + steps []StepSummary + start time.Time + closed bool + summaryEnrich func(*RunSummary) // optional enrichment callback set before Close +} + +type spanEntry struct { + span trace.Span + ctx context.Context + start time.Time +} + +// RecorderOption configures optional behavior for NewRecorder. +type RecorderOption func(*recorderConfig) + +type recorderConfig struct { + spanKind trace.SpanKind +} + +// WithSpanKind sets the OTEL SpanKind on the root span. +func WithSpanKind(kind trace.SpanKind) RecorderOption { + return func(c *recorderConfig) { c.spanKind = kind } +} + +// SpanKindInternal returns a RecorderOption for SpanKindInternal (default). +func SpanKindInternal() RecorderOption { + return WithSpanKind(trace.SpanKindInternal) +} + +// SpanKindConsumer returns a RecorderOption for SpanKindConsumer +// (use when this run was dispatched by an external system). +func SpanKindConsumer() RecorderOption { + return WithSpanKind(trace.SpanKindConsumer) +} + +// NewRecorder creates a Recorder that writes structured events to outputDir. +// The tracer may be nil (noop); OTEL span creation is skipped in that case. +// The returned context carries the root span for the run. +func NewRecorder(ctx context.Context, outputDir string, tracer trace.Tracer, runName string, attrs []Attr, opts ...RecorderOption) (*Recorder, context.Context, error) { + cfg := &recorderConfig{spanKind: trace.SpanKindInternal} + for _, o := range opts { + o(cfg) + } + + if err := os.MkdirAll(outputDir, 0o755); err != nil { + return nil, ctx, fmt.Errorf("creating telemetry dir: %w", err) + } + + f, err := os.OpenFile(filepath.Join(outputDir, eventsFile), + os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644) + if err != nil { + return nil, ctx, fmt.Errorf("opening events file: %w", err) + } + + r := &Recorder{ + dir: outputDir, + file: f, + enc: json.NewEncoder(f), + tracer: tracer, + spans: make(map[string]spanEntry), + start: time.Now(), + } + + var rootCtx context.Context + if tracer != nil { + var rootSpan trace.Span + otelAttrs := attrsToOTEL(attrs) + rootCtx, rootSpan = tracer.Start(ctx, runName, + trace.WithAttributes(otelAttrs...), + trace.WithSpanKind(cfg.spanKind), + ) + r.rootCtx = rootCtx + r.rootSpan = rootSpan + } else { + rootCtx = ctx + r.rootCtx = ctx + } + + r.record(RunEvent{ + Timestamp: time.Now().UTC(), + Event: EventRunStart, + Step: runName, + Attrs: attrsToMap(attrs), + TraceID: r.traceID(), + }) + + return r, rootCtx, nil +} + +// StepStart records the beginning of a lifecycle step. +// Returns a context that may carry a child span. +func (r *Recorder) StepStart(ctx context.Context, name string, attrs ...Attr) context.Context { + r.mu.Lock() + defer r.mu.Unlock() + + now := time.Now() + event := RunEvent{ + Timestamp: now.UTC(), + Event: EventStepStart, + Step: name, + Attrs: attrsToMap(attrs), + TraceID: r.traceID(), + } + + var stepCtx context.Context + if r.tracer != nil { + parentCtx := r.rootCtx + if ctx != nil { + parentCtx = ctx + } + otelAttrs := attrsToOTEL(attrs) + var span trace.Span + stepCtx, span = r.tracer.Start(parentCtx, name, trace.WithAttributes(otelAttrs...)) + r.spans[name] = spanEntry{span: span, ctx: stepCtx, start: now} + event.SpanID = span.SpanContext().SpanID().String() + if parentSC := trace.SpanContextFromContext(parentCtx); parentSC.IsValid() { + event.ParentID = parentSC.SpanID().String() + } + } else { + stepCtx = ctx + } + + r.recordLocked(event) + return stepCtx +} + +// StepDone records successful completion of a lifecycle step. +func (r *Recorder) StepDone(name string, attrs ...Attr) { + r.mu.Lock() + defer r.mu.Unlock() + + now := time.Now() + event := RunEvent{ + Timestamp: now.UTC(), + Event: EventStepDone, + Step: name, + Status: StatusOK, + Attrs: attrsToMap(attrs), + TraceID: r.traceID(), + } + + if entry, ok := r.spans[name]; ok { + dur := now.Sub(entry.start).Milliseconds() + event.DurationMs = &dur + event.SpanID = entry.span.SpanContext().SpanID().String() + for _, a := range attrs { + entry.span.SetAttributes(attribute.String(a.Key, a.Value)) + } + entry.span.SetStatus(codes.Ok, "") + entry.span.End() + delete(r.spans, name) + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusOK, DurationMs: dur}) + } else { + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusOK}) + } + + r.recordLocked(event) +} + +// StepFail records a failed lifecycle step. +func (r *Recorder) StepFail(name string, err error, attrs ...Attr) { + r.mu.Lock() + defer r.mu.Unlock() + + now := time.Now() + errMsg := "" + if err != nil { + errMsg = err.Error() + } + + event := RunEvent{ + Timestamp: now.UTC(), + Event: EventStepFail, + Step: name, + Status: StatusError, + Error: errMsg, + Attrs: attrsToMap(attrs), + TraceID: r.traceID(), + } + + if entry, ok := r.spans[name]; ok { + dur := now.Sub(entry.start).Milliseconds() + event.DurationMs = &dur + event.SpanID = entry.span.SpanContext().SpanID().String() + if err != nil { + entry.span.RecordError(err) + } + entry.span.SetStatus(codes.Error, errMsg) + entry.span.End() + delete(r.spans, name) + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusError, DurationMs: dur, Error: errMsg}) + } else { + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusError, Error: errMsg}) + } + + r.recordLocked(event) +} + +// StepWarn records a step that completed with warnings. +func (r *Recorder) StepWarn(name string, detail string) { + r.mu.Lock() + defer r.mu.Unlock() + + event := RunEvent{ + Timestamp: time.Now().UTC(), + Event: EventStepWarn, + Step: name, + Status: StatusWarning, + Error: detail, + TraceID: r.traceID(), + } + + if entry, ok := r.spans[name]; ok { + dur := time.Since(entry.start).Milliseconds() + event.DurationMs = &dur + event.SpanID = entry.span.SpanContext().SpanID().String() + entry.span.SetStatus(codes.Ok, detail) + entry.span.End() + delete(r.spans, name) + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusWarning, DurationMs: dur}) + } else { + r.steps = append(r.steps, StepSummary{Name: name, Status: StatusWarning}) + } + + r.recordLocked(event) +} + +// AddEvent attaches a named event (log line) to a currently-open step span. +// If the step has no open span, the event is attached to the root span. +// This uses OTEL's span.AddEvent which appears as "Events" in any backend. +func (r *Recorder) AddEvent(stepName, eventName string, attrs ...Attr) { + r.mu.Lock() + defer r.mu.Unlock() + + var span trace.Span + if entry, ok := r.spans[stepName]; ok { + span = entry.span + } else if r.rootSpan != nil { + span = r.rootSpan + } + if span != nil { + otelAttrs := attrsToOTEL(attrs) + span.AddEvent(eventName, trace.WithAttributes(otelAttrs...)) + } +} + +// AddRootEvent attaches an event to the root span directly. +func (r *Recorder) AddRootEvent(eventName string, attrs ...Attr) { + r.mu.Lock() + defer r.mu.Unlock() + + if r.rootSpan != nil { + otelAttrs := attrsToOTEL(attrs) + r.rootSpan.AddEvent(eventName, trace.WithAttributes(otelAttrs...)) + } +} + +// Context returns the root span context for propagation to subprocesses. +func (r *Recorder) Context() context.Context { + return r.rootCtx +} + +// StartTime returns when the recorder was created. +func (r *Recorder) StartTime() time.Time { + return r.start +} + +// SetSummaryFields registers a function that will be called to enrich the +// RunSummary before WriteSummary writes it to disk. This allows the caller +// to set fields that are only known at the end of the run (exit code, +// validation status) while the defer block handles the actual write. +func (r *Recorder) SetSummaryFields(fn func(*RunSummary)) { + r.mu.Lock() + defer r.mu.Unlock() + r.summaryEnrich = fn +} + +// SetRootStatus sets the status on the root span. +func (r *Recorder) SetRootStatus(code codes.Code, description string) { + r.mu.Lock() + defer r.mu.Unlock() + if r.rootSpan != nil { + r.rootSpan.SetStatus(code, description) + } +} + +// SetRootAttribute sets a string attribute on the root span. +func (r *Recorder) SetRootAttribute(key, value string) { + r.mu.Lock() + defer r.mu.Unlock() + if r.rootSpan != nil { + r.rootSpan.SetAttributes(attribute.String(key, value)) + } +} + +// Steps returns the accumulated step summaries. +func (r *Recorder) Steps() []StepSummary { + r.mu.Lock() + defer r.mu.Unlock() + out := make([]StepSummary, len(r.steps)) + copy(out, r.steps) + return out +} + +// WriteSummary writes the run-summary.json file. If SetSummaryFields was +// called, the enrichment function is applied before writing. +func (r *Recorder) WriteSummary(summary RunSummary) error { + r.mu.Lock() + defer r.mu.Unlock() + + if r.summaryEnrich != nil { + r.summaryEnrich(&summary) + } + + summary.SchemaVersion = SchemaVersion + summary.Steps = make([]StepSummary, len(r.steps)) + copy(summary.Steps, r.steps) + summary.DurationMs = time.Since(r.start).Milliseconds() + if summary.EndTime.IsZero() { + summary.EndTime = time.Now().UTC() + } + if summary.TraceID == "" { + summary.TraceID = r.traceID() + } + if summary.Traceparent == "" { + summary.Traceparent = Traceparent(r.rootCtx) + } + + data, err := json.MarshalIndent(summary, "", " ") + if err != nil { + return fmt.Errorf("marshaling run summary: %w", err) + } + path := filepath.Join(r.dir, summaryFile) + if err := os.WriteFile(path, data, 0o644); err != nil { + return fmt.Errorf("writing run summary: %w", err) + } + return nil +} + +// Close ends the root span, writes a run.done event, and closes the events file. +func (r *Recorder) Close() error { + r.mu.Lock() + defer r.mu.Unlock() + + if r.closed { + return nil + } + + // End any orphaned step spans. + for name, entry := range r.spans { + entry.span.SetStatus(codes.Error, "step not completed before recorder close") + entry.span.End() + delete(r.spans, name) + } + + dur := time.Since(r.start).Milliseconds() + r.recordLocked(RunEvent{ + Timestamp: time.Now().UTC(), + Event: EventRunDone, + DurationMs: &dur, + TraceID: r.traceID(), + }) + + r.closed = true + + if r.rootSpan != nil { + r.rootSpan.End() + } + + return r.file.Close() +} + +func (r *Recorder) record(event RunEvent) { + r.mu.Lock() + defer r.mu.Unlock() + r.recordLocked(event) +} + +func (r *Recorder) recordLocked(event RunEvent) { + if r.enc != nil && !r.closed { + _ = r.enc.Encode(event) // best-effort; telemetry must not break the run + } +} + +func (r *Recorder) traceID() string { + if r.rootSpan != nil { + sc := r.rootSpan.SpanContext() + if sc.IsValid() { + return sc.TraceID().String() + } + } + return "" +} + +func attrsToOTEL(attrs []Attr) []attribute.KeyValue { + if len(attrs) == 0 { + return nil + } + out := make([]attribute.KeyValue, len(attrs)) + for i, a := range attrs { + out[i] = attribute.String(a.Key, a.Value) + } + return out +} diff --git a/internal/telemetry/recorder_test.go b/internal/telemetry/recorder_test.go new file mode 100644 index 0000000000..9b05cce9f7 --- /dev/null +++ b/internal/telemetry/recorder_test.go @@ -0,0 +1,145 @@ +package telemetry + +import ( + "bufio" + "context" + "encoding/json" + "errors" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +func TestRecorder_WritesEvents(t *testing.T) { + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", + []Attr{StringAttr("agent", "triage")}) + require.NoError(t, err) + require.NotNil(t, rec) + require.NotNil(t, ctx) + + rec.StepStart(ctx, "load-harness", StringAttr("path", "/foo/bar.yaml")) + rec.StepDone("load-harness", StringAttr("duration", "1.2s")) + rec.StepStart(ctx, "create-sandbox") + rec.StepFail("create-sandbox", errors.New("timeout")) + require.NoError(t, rec.Close()) + + data, err := os.ReadFile(filepath.Join(dir, eventsFile)) + require.NoError(t, err) + + var events []RunEvent + scanner := bufio.NewScanner(strings.NewReader(string(data))) + for scanner.Scan() { + line := scanner.Text() + if line == "" { + continue + } + var e RunEvent + require.NoError(t, json.Unmarshal([]byte(line), &e)) + events = append(events, e) + } + + require.Len(t, events, 6) // run.start, step.start, step.done, step.start, step.fail, run.done + assert.Equal(t, EventRunStart, events[0].Event) + assert.Equal(t, EventStepStart, events[1].Event) + assert.Equal(t, "load-harness", events[1].Step) + assert.Equal(t, "/foo/bar.yaml", events[1].Attrs["path"]) + assert.Equal(t, EventStepDone, events[2].Event) + assert.Equal(t, StatusOK, events[2].Status) + assert.Equal(t, EventStepStart, events[3].Event) + assert.Equal(t, "create-sandbox", events[3].Step) + assert.Equal(t, EventStepFail, events[4].Event) + assert.Equal(t, StatusError, events[4].Status) + assert.Equal(t, "timeout", events[4].Error) + assert.Equal(t, EventRunDone, events[5].Event) +} + +func TestRecorder_WriteSummary(t *testing.T) { + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + + rec.StepStart(ctx, "bootstrap") + rec.StepDone("bootstrap") + + err = rec.WriteSummary(RunSummary{ + Agent: "triage", + Harness: "harness/triage.yaml", + SecurityTraceID: "abc-123", + ExitCode: 0, + Iterations: 1, + }) + require.NoError(t, err) + require.NoError(t, rec.Close()) + + data, err := os.ReadFile(filepath.Join(dir, summaryFile)) + require.NoError(t, err) + + var summary RunSummary + require.NoError(t, json.Unmarshal(data, &summary)) + assert.Equal(t, SchemaVersion, summary.SchemaVersion) + assert.Equal(t, "triage", summary.Agent) + assert.Equal(t, "abc-123", summary.SecurityTraceID) + assert.Len(t, summary.Steps, 1) + assert.Equal(t, "bootstrap", summary.Steps[0].Name) + assert.Equal(t, StatusOK, summary.Steps[0].Status) +} + +func TestRecorder_StepWarn(t *testing.T) { + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + + rec.StepStart(ctx, "scan") + rec.StepWarn("scan", "3 findings") + require.NoError(t, rec.Close()) + + steps := rec.Steps() + require.Len(t, steps, 1) + assert.Equal(t, StatusWarning, steps[0].Status) +} + +func TestRecorder_DoubleClose(t *testing.T) { + dir := t.TempDir() + rec, _, err := NewRecorder(context.Background(), dir, nil, "test-run", nil) + require.NoError(t, err) + + require.NoError(t, rec.Close()) + require.NoError(t, rec.Close()) +} + +func TestRecorder_SummaryIncludesTraceparent(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + tracer := tp.Tracer("test") + + dir := t.TempDir() + rec, _, err := NewRecorder(context.Background(), dir, tracer, "test-run", nil) + require.NoError(t, err) + + err = rec.WriteSummary(RunSummary{ + Agent: "triage", + Harness: "harness/triage.yaml", + ExitCode: 0, + }) + require.NoError(t, err) + require.NoError(t, rec.Close()) + + data, err := os.ReadFile(filepath.Join(dir, summaryFile)) + require.NoError(t, err) + + var summary RunSummary + require.NoError(t, json.Unmarshal(data, &summary)) + + assert.NotEmpty(t, summary.TraceID, "TraceID should be populated with a real tracer") + assert.NotEmpty(t, summary.Traceparent, "Traceparent should be populated with a real tracer") + assert.True(t, IsValidTraceparent(summary.Traceparent), + "Traceparent %q should be valid W3C format", summary.Traceparent) +} + diff --git a/internal/telemetry/transcript.go b/internal/telemetry/transcript.go new file mode 100644 index 0000000000..e3d749f778 --- /dev/null +++ b/internal/telemetry/transcript.go @@ -0,0 +1,277 @@ +package telemetry + +import ( + "bufio" + "bytes" + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" +) + +const ( + maxContentLength = 4096 + maxTranscriptLineSize = 2 * 1024 * 1024 // 2MB per line +) + +// transcriptMessage is a minimal representation of a Claude Code JSONL event. +type transcriptMessage struct { + Type string `json:"type"` + Role string `json:"role,omitempty"` + Message json.RawMessage `json:"message,omitempty"` + Content json.RawMessage `json:"content,omitempty"` + Model string `json:"model,omitempty"` + StopReason string `json:"stop_reason,omitempty"` + Usage *tokenUsage `json:"usage,omitempty"` + Timestamp string `json:"timestamp,omitempty"` +} + +type tokenUsage struct { + InputTokens int `json:"input_tokens"` + OutputTokens int `json:"output_tokens"` +} + +// contentBlock is a block inside a message content array. +type contentBlock struct { + Type string `json:"type"` + Text string `json:"text,omitempty"` + Name string `json:"name,omitempty"` + Input json.RawMessage `json:"input,omitempty"` +} + +// LLMInteraction represents a single prompt→completion exchange extracted +// from a transcript, ready to be emitted as an OTEL span. +type LLMInteraction struct { + Input string + Output string + Model string + StopReason string + InputTokens int + OutputTokens int + ToolCalls []ToolCall + Timestamp time.Time +} + +// ToolCall represents a tool invocation within an LLM response. +type ToolCall struct { + Name string + Input string +} + +// ParseTranscriptInteractions reads a Claude Code JSONL transcript and +// extracts LLM interactions (prompt/completion pairs) suitable for creating +// child spans. Returns nil if the file cannot be parsed. +func ParseTranscriptInteractions(path string) []LLMInteraction { + f, err := os.Open(path) + if err != nil { + return nil + } + defer f.Close() + + scanner := bufio.NewScanner(f) + scanner.Buffer(make([]byte, 0, 64*1024), maxTranscriptLineSize) + + var interactions []LLMInteraction + var pendingInput string + + for scanner.Scan() { + line := scanner.Bytes() + if len(line) == 0 { + continue + } + + var msg transcriptMessage + if err := json.Unmarshal(line, &msg); err != nil { + continue + } + + switch msg.Type { + case "human", "user": + pendingInput = extractContent(msg.Content, msg.Message) + + case "assistant": + output, tools := extractAssistantContent(msg.Content, msg.Message) + interaction := LLMInteraction{ + Input: truncateContent(pendingInput), + Output: truncateContent(output), + Model: msg.Model, + StopReason: msg.StopReason, + ToolCalls: tools, + } + if msg.Usage != nil { + interaction.InputTokens = msg.Usage.InputTokens + interaction.OutputTokens = msg.Usage.OutputTokens + } + if msg.Timestamp != "" { + if t, err := time.Parse(time.RFC3339, msg.Timestamp); err == nil { + interaction.Timestamp = t + } + } + interactions = append(interactions, interaction) + pendingInput = "" + } + } + + return interactions +} + +// EmitTranscriptSpans creates child spans under the given parent step for +// each LLM interaction found in JSONL files within transcriptDir. +func EmitTranscriptSpans(r *Recorder, parentStepName, transcriptDir, model string) { + if r == nil || r.tracer == nil { + return + } + + entries, err := os.ReadDir(transcriptDir) + if err != nil { + return + } + + r.mu.Lock() + parentEntry, hasParent := r.spans[parentStepName] + r.mu.Unlock() + + var parentCtx = r.rootCtx + if hasParent { + parentCtx = parentEntry.ctx + } + + for _, entry := range entries { + if entry.IsDir() || !strings.HasSuffix(entry.Name(), ".jsonl") { + continue + } + path := filepath.Join(transcriptDir, entry.Name()) + interactions := ParseTranscriptInteractions(path) + + for i, ix := range interactions { + spanName := fmt.Sprintf("llm.turn.%d", i+1) + attrs := []attribute.KeyValue{ + attribute.String("gen_ai.operation.name", "chat"), + attribute.String("gen_ai.system", "anthropic"), + attribute.String("gen_ai.content.prompt", ix.Input), + attribute.String("gen_ai.content.completion", ix.Output), + } + if ix.Model != "" { + attrs = append(attrs, attribute.String("gen_ai.response.model", ix.Model)) + } else if model != "" { + attrs = append(attrs, attribute.String("gen_ai.request.model", model)) + } + if ix.StopReason != "" { + attrs = append(attrs, attribute.String("gen_ai.response.finish_reasons", ix.StopReason)) + } + if ix.InputTokens > 0 { + attrs = append(attrs, attribute.Int("gen_ai.usage.input_tokens", ix.InputTokens)) + } + if ix.OutputTokens > 0 { + attrs = append(attrs, attribute.Int("gen_ai.usage.output_tokens", ix.OutputTokens)) + } + if len(ix.ToolCalls) > 0 { + var names []string + for _, tc := range ix.ToolCalls { + names = append(names, tc.Name) + } + attrs = append(attrs, attribute.String("tool_calls", strings.Join(names, ", "))) + attrs = append(attrs, attribute.Int("tool_call_count", len(ix.ToolCalls))) + } + + _, span := r.tracer.Start(parentCtx, spanName, trace.WithAttributes(attrs...)) + span.End() + } + } +} + +func extractContent(content json.RawMessage, message json.RawMessage) string { + if len(content) > 0 { + return parseContentField(content) + } + if len(message) > 0 { + return parseContentField(message) + } + return "" +} + +func extractAssistantContent(content json.RawMessage, message json.RawMessage) (string, []ToolCall) { + raw := content + if len(raw) == 0 { + raw = message + } + if len(raw) == 0 { + return "", nil + } + + // Try as string first. + var s string + if json.Unmarshal(raw, &s) == nil { + return s, nil + } + + // Try as array of content blocks. + var blocks []contentBlock + if json.Unmarshal(raw, &blocks) == nil { + var textParts []string + var tools []ToolCall + for _, b := range blocks { + switch b.Type { + case "text": + if b.Text != "" { + textParts = append(textParts, b.Text) + } + case "tool_use": + input := string(b.Input) + if len(input) > 512 { + input = input[:512] + "..." + } + tools = append(tools, ToolCall{Name: b.Name, Input: input}) + } + } + return strings.Join(textParts, "\n"), tools + } + + return string(raw), nil +} + +func parseContentField(raw json.RawMessage) string { + // Try as string. + var s string + if json.Unmarshal(raw, &s) == nil { + return s + } + + // Try as array of content blocks. + var blocks []contentBlock + if json.Unmarshal(raw, &blocks) == nil { + var parts []string + for _, b := range blocks { + if b.Type == "text" && b.Text != "" { + parts = append(parts, b.Text) + } + } + return strings.Join(parts, "\n") + } + + // Try as object with "content" field. + var obj struct { + Content json.RawMessage `json:"content"` + } + if json.Unmarshal(raw, &obj) == nil && len(obj.Content) > 0 { + return parseContentField(obj.Content) + } + + // Fallback: return raw (truncated) if it looks like a useful string. + if len(raw) < 200 && !bytes.HasPrefix(raw, []byte("{")) { + return string(raw) + } + return "" +} + +func truncateContent(s string) string { + if len(s) <= maxContentLength { + return s + } + return s[:maxContentLength] + "… (truncated)" +} diff --git a/internal/telemetry/transcript_test.go b/internal/telemetry/transcript_test.go new file mode 100644 index 0000000000..e6ae136f4d --- /dev/null +++ b/internal/telemetry/transcript_test.go @@ -0,0 +1,112 @@ +package telemetry + +import ( + "context" + "os" + "path/filepath" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +func TestParseTranscriptInteractions_Basic(t *testing.T) { + dir := t.TempDir() + transcript := `{"type":"human","content":"Fix the bug in auth.go"} +{"type":"assistant","content":[{"type":"text","text":"I'll fix that bug now."}],"model":"claude-sonnet-4-20250514","usage":{"input_tokens":150,"output_tokens":42}} +{"type":"human","content":"Now add a test for it"} +{"type":"assistant","content":[{"type":"text","text":"Here's the test:"},{"type":"tool_use","name":"write_file","input":{"path":"auth_test.go"}}],"model":"claude-sonnet-4-20250514","stop_reason":"end_turn","usage":{"input_tokens":300,"output_tokens":85}} +` + path := filepath.Join(dir, "transcript.jsonl") + require.NoError(t, os.WriteFile(path, []byte(transcript), 0o644)) + + interactions := ParseTranscriptInteractions(path) + require.Len(t, interactions, 2) + + assert.Equal(t, "Fix the bug in auth.go", interactions[0].Input) + assert.Equal(t, "I'll fix that bug now.", interactions[0].Output) + assert.Equal(t, "claude-sonnet-4-20250514", interactions[0].Model) + assert.Equal(t, 150, interactions[0].InputTokens) + assert.Equal(t, 42, interactions[0].OutputTokens) + + assert.Equal(t, "Now add a test for it", interactions[1].Input) + assert.Contains(t, interactions[1].Output, "Here's the test:") + assert.Equal(t, "end_turn", interactions[1].StopReason) + assert.Len(t, interactions[1].ToolCalls, 1) + assert.Equal(t, "write_file", interactions[1].ToolCalls[0].Name) +} + +func TestParseTranscriptInteractions_EmptyFile(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "empty.jsonl") + require.NoError(t, os.WriteFile(path, []byte(""), 0o644)) + + interactions := ParseTranscriptInteractions(path) + assert.Empty(t, interactions) +} + +func TestParseTranscriptInteractions_NoAssistant(t *testing.T) { + dir := t.TempDir() + transcript := `{"type":"human","content":"Hello"} +{"type":"result","is_error":true,"result":"timeout"} +` + path := filepath.Join(dir, "no-assistant.jsonl") + require.NoError(t, os.WriteFile(path, []byte(transcript), 0o644)) + + interactions := ParseTranscriptInteractions(path) + assert.Empty(t, interactions) +} + +func TestEmitTranscriptSpans_CreatesChildSpans(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + tracer := tp.Tracer("test") + + dir := t.TempDir() + rec, ctx, err := NewRecorder(context.Background(), dir, tracer, "test-run", nil) + require.NoError(t, err) + + // Start a parent step (simulating an iteration). + rec.StepStart(ctx, "agent-execution.iteration-1") + + // Write a transcript file. + transcriptDir := filepath.Join(dir, "transcripts") + require.NoError(t, os.MkdirAll(transcriptDir, 0o755)) + transcript := `{"type":"human","content":"What is 2+2?"} +{"type":"assistant","content":[{"type":"text","text":"The answer is 4."}],"model":"claude-sonnet-4-20250514","usage":{"input_tokens":10,"output_tokens":8}} +` + require.NoError(t, os.WriteFile( + filepath.Join(transcriptDir, "session.jsonl"), + []byte(transcript), 0o644)) + + EmitTranscriptSpans(rec, "agent-execution.iteration-1", transcriptDir, "claude-sonnet-4-20250514") + + rec.StepDone("agent-execution.iteration-1") + require.NoError(t, rec.Close()) + require.NoError(t, tp.ForceFlush(context.Background())) + + spans := exporter.GetSpans() + + // Find the LLM turn span. + var llmSpan *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "llm.turn.1" { + llmSpan = &spans[i] + break + } + } + require.NotNil(t, llmSpan, "llm.turn.1 span should exist") + + attrMap := make(map[string]string) + for _, a := range llmSpan.Attributes { + attrMap[string(a.Key)] = a.Value.Emit() + } + + assert.Equal(t, "What is 2+2?", attrMap["gen_ai.content.prompt"]) + assert.Equal(t, "The answer is 4.", attrMap["gen_ai.content.completion"]) + assert.Equal(t, "chat", attrMap["gen_ai.operation.name"]) + assert.Equal(t, "anthropic", attrMap["gen_ai.system"]) + assert.Equal(t, "claude-sonnet-4-20250514", attrMap["gen_ai.response.model"]) +}