Merge pull request #323 from gitpod-io/wv/add-phase-spans-otel

feat: add nested phase spans for OpenTelemetry tracing

Author: WVerlaek

README.md

@@ -611,6 +611,25 @@ export OTEL_EXPORTER_OTLP_HEADERS="x-honeycomb-team=YOUR_API_KEY"
 leeway build :my-package
 ```
 
+The OpenTelemetry SDK automatically reads standard `OTEL_EXPORTER_OTLP_*` environment variables.
+
+## Span Hierarchy
+
+Leeway creates a nested span hierarchy for detailed build timeline visualization:
+
+```
+leeway.build (root)
+├── leeway.package (component:package-1)
+│   ├── leeway.phase (prep)
+│   ├── leeway.phase (build)
+│   └── leeway.phase (test)
+└── leeway.package (component:package-2)
+    ├── leeway.phase (prep)
+    └── leeway.phase (build)
+```
+
+Each phase span captures timing, status, and errors for individual build phases (prep, pull, lint, test, build, package).
+
 See [docs/observability.md](docs/observability.md) for configuration, examples, and span attributes.
 
 # Provenance (SLSA) - EXPERIMENTAL

docs/observability.md

@@ -19,14 +19,24 @@ OpenTelemetry tracing in leeway captures:
 ```
 Root Span (leeway.build)
 ├── Package Span 1 (leeway.package)
+│   ├── Phase Span (leeway.phase: prep)
+│   ├── Phase Span (leeway.phase: pull)
+│   ├── Phase Span (leeway.phase: lint)
+│   ├── Phase Span (leeway.phase: test)
+│   ├── Phase Span (leeway.phase: build)
+│   └── Phase Span (leeway.phase: package)
 ├── Package Span 2 (leeway.package)
+│   ├── Phase Span (leeway.phase: prep)
+│   └── Phase Span (leeway.phase: build)
 └── Package Span N (leeway.package)
+    └── ...
 ```
 
 - **Root Span**: Created when `BuildStarted` is called, represents the entire build operation
 - **Package Spans**: Created for each package being built, as children of the root span
+- **Phase Spans**: Created for each build phase (prep, pull, lint, test, build, package) as children of package spans
 
-Build phase durations (prep, pull, lint, test, build, package) are captured as attributes on package spans, not as separate spans. This design provides lower overhead and simpler hierarchy while maintaining visibility into phase-level performance.
+Phase spans provide detailed timeline visualization and capture individual phase errors. Only phases with commands are executed and create spans.
 
 ### Context Propagation
 
@@ -35,6 +45,7 @@ Leeway supports W3C Trace Context propagation, allowing builds to be part of lar
 1. **Parent Context**: Accepts `traceparent` and `tracestate` headers from upstream systems
 2. **Root Context**: Creates a root span linked to the parent context
 3. **Package Context**: Each package span is a child of the root span
+4. **Phase Context**: Each phase span is a child of its package span
 
 ## Configuration
 
@@ -109,11 +120,24 @@ leeway build :my-package
 | `leeway.package.builddir` | string | Build directory | `"/tmp/leeway/build/..."` |
 | `leeway.package.last_phase` | string | Last completed phase | `"build"` |
 | `leeway.package.duration_ms` | int64 | Total build duration (ms) | `15234` |
-| `leeway.package.phase.{phase}.duration_ms` | int64 | Phase duration (ms) | `5432` |
 | `leeway.package.test.coverage_percentage` | int | Test coverage % | `85` |
 | `leeway.package.test.functions_with_test` | int | Functions with tests | `42` |
 | `leeway.package.test.functions_without_test` | int | Functions without tests | `8` |
 
+### Phase Span Attributes
+
+Phase spans are created for each build phase (prep, pull, lint, test, build, package) that has commands to execute.
+
+| Attribute | Type | Description | Example |
+|-----------|------|-------------|---------|
+| `leeway.phase.name` | string | Phase name | `"prep"`, `"build"`, `"test"`, etc. |
+
+**Span Status:**
+- `OK`: Phase completed successfully
+- `ERROR`: Phase failed (error details in span events)
+
+**Span Duration:** The span's start and end times capture the phase execution duration automatically.
+
 ### GitHub Actions Attributes
 
 When running in GitHub Actions (`GITHUB_ACTIONS=true`), the following attributes are added to the root span:

pkg/leeway/build.go

@@ -1262,12 +1262,19 @@ func (p *Package) build(buildctx *buildContext) (err error) {
 	// Generate SBOM if enabled (after packaging - written alongside artifact)
 	// SBOM files are stored outside the tar.gz to maintain artifact determinism.
 	if p.C.W.SBOM.Enabled {
+		if par, ok := buildctx.Reporter.(PhaseAwareReporter); ok {
+			par.PackageBuildPhaseStarted(p, PackageBuildPhaseSBOM)
+		}
 		pkgRep.phaseEnter[PackageBuildPhaseSBOM] = time.Now()
 		pkgRep.Phases = append(pkgRep.Phases, PackageBuildPhaseSBOM)
-		if err := writeSBOMToCache(buildctx, p, builddir); err != nil {
-			return err
-		}
+		sbomErr := writeSBOMToCache(buildctx, p, builddir)
 		pkgRep.phaseDone[PackageBuildPhaseSBOM] = time.Now()
+		if par, ok := buildctx.Reporter.(PhaseAwareReporter); ok {
+			par.PackageBuildPhaseFinished(p, PackageBuildPhaseSBOM, sbomErr)
+		}
+		if sbomErr != nil {
+			return sbomErr
+		}
 	}
 
 	// Register newly built package
@@ -1365,6 +1372,11 @@ func executeBuildPhase(buildctx *buildContext, p *Package, builddir string, bld
 		return nil
 	}
 
+	// Notify phase-aware reporters
+	if par, ok := buildctx.Reporter.(PhaseAwareReporter); ok {
+		par.PackageBuildPhaseStarted(p, phase)
+	}
+
 	if phase != PackageBuildPhasePrep {
 		pkgRep.phaseEnter[phase] = time.Now()
 		pkgRep.Phases = append(pkgRep.Phases, phase)
@@ -1375,6 +1387,11 @@ func executeBuildPhase(buildctx *buildContext, p *Package, builddir string, bld
 	err := executeCommandsForPackage(buildctx, p, builddir, cmds)
 	pkgRep.phaseDone[phase] = time.Now()
 
+	// Notify phase-aware reporters
+	if par, ok := buildctx.Reporter.(PhaseAwareReporter); ok {
+		par.PackageBuildPhaseFinished(p, phase, err)
+	}
+
 	return err
 }
 
@@ -3153,7 +3170,7 @@ func runGoTestWithTracing(buildctx *buildContext, p *Package, env []string, cwd,
 	}
 
 	// Create tracer and parse output
-	goTracer := NewGoTestTracer(tracer, parentCtx)
+	goTracer := NewGoTestTracer(tracer, parentCtx, p.FullName())
 	outputWriter := &reporterStream{R: buildctx.Reporter, P: p, IsErr: false}
 
 	if err := goTracer.parseJSONOutput(stdout, outputWriter); err != nil {

pkg/leeway/gotest_trace.go

@@ -35,19 +35,21 @@ type testSpanData struct {
 
 // GoTestTracer handles parsing Go test JSON output and creating OpenTelemetry spans
 type GoTestTracer struct {
-	tracer    trace.Tracer
-	parentCtx context.Context
+	tracer        trace.Tracer
+	parentCtx     context.Context
+	leewayPkgName string
 
 	mu    sync.Mutex
 	spans map[string]*testSpanData // key: "package/testname" or just "package" for package-level
 }
 
 // NewGoTestTracer creates a new GoTestTracer that will create spans as children of the given context
-func NewGoTestTracer(tracer trace.Tracer, parentCtx context.Context) *GoTestTracer {
+func NewGoTestTracer(tracer trace.Tracer, parentCtx context.Context, leewayPkgName string) *GoTestTracer {
 	return &GoTestTracer{
-		tracer:    tracer,
-		parentCtx: parentCtx,
-		spans:     make(map[string]*testSpanData),
+		tracer:        tracer,
+		parentCtx:     parentCtx,
+		leewayPkgName: leewayPkgName,
+		spans:         make(map[string]*testSpanData),
 	}
 }
 
@@ -163,6 +165,7 @@ func (t *GoTestTracer) handleRun(event *goTestEvent) {
 	)
 
 	span.SetAttributes(
+		attribute.String("leeway.package.name", t.leewayPkgName),
 		attribute.String("test.name", event.Test),
 		attribute.String("test.package", event.Package),
 		attribute.String("test.framework", "go"),
@@ -193,6 +196,7 @@ func (t *GoTestTracer) handlePackageStart(event *goTestEvent) {
 	)
 
 	span.SetAttributes(
+		attribute.String("leeway.package.name", t.leewayPkgName),
 		attribute.String("test.package", event.Package),
 		attribute.String("test.framework", "go"),
 		attribute.String("test.scope", "package"),

pkg/leeway/gotest_trace_test.go

@@ -24,7 +24,7 @@ func TestGoTestTracer_ParseJSONOutput(t *testing.T) {
 	ctx, parentSpan := tracer.Start(context.Background(), "parent")
 	defer parentSpan.End()
 
-	goTracer := NewGoTestTracer(tracer, ctx)
+	goTracer := NewGoTestTracer(tracer, ctx, "test:pkg")
 
 	// Simulate go test -json output
 	jsonOutput := `{"Time":"2024-01-01T10:00:00Z","Action":"start","Package":"example.com/pkg"}
@@ -123,7 +123,7 @@ func TestGoTestTracer_ParallelTests(t *testing.T) {
 	ctx, parentSpan := tracer.Start(context.Background(), "parent")
 	defer parentSpan.End()
 
-	goTracer := NewGoTestTracer(tracer, ctx)
+	goTracer := NewGoTestTracer(tracer, ctx, "test:pkg")
 
 	// Simulate parallel test execution with pause/cont events
 	jsonOutput := `{"Time":"2024-01-01T10:00:00Z","Action":"run","Package":"example.com/pkg","Test":"TestParallel"}
@@ -167,7 +167,7 @@ func TestGoTestTracer_ParallelTests(t *testing.T) {
 
 func TestGoTestTracer_NoTracer(t *testing.T) {
 	// Test that nil tracer doesn't panic
-	goTracer := NewGoTestTracer(nil, context.Background())
+	goTracer := NewGoTestTracer(nil, context.Background(), "test:pkg")
 
 	jsonOutput := `{"Time":"2024-01-01T10:00:00Z","Action":"run","Package":"example.com/pkg","Test":"TestOne"}
 {"Time":"2024-01-01T10:00:00.100Z","Action":"pass","Package":"example.com/pkg","Test":"TestOne","Elapsed":0.1}

pkg/leeway/reporter.go

@@ -52,6 +52,17 @@ type Reporter interface {
 	PackageBuildFinished(pkg *Package, rep *PackageBuildReport)
 }
 
+// PhaseAwareReporter is an optional interface that reporters can implement
+// to receive phase-level notifications for creating nested spans or tracking.
+// This follows the Go pattern of optional interfaces (like io.Closer, io.Seeker).
+type PhaseAwareReporter interface {
+	Reporter
+	// PackageBuildPhaseStarted is called when a build phase starts
+	PackageBuildPhaseStarted(pkg *Package, phase PackageBuildPhase)
+	// PackageBuildPhaseFinished is called when a build phase completes
+	PackageBuildPhaseFinished(pkg *Package, phase PackageBuildPhase, err error)
+}
+
 type PackageBuildReport struct {
 	phaseEnter map[PackageBuildPhase]time.Time
 	phaseDone  map[PackageBuildPhase]time.Time
@@ -544,7 +555,26 @@ func (cr CompositeReporter) PackageBuildStarted(pkg *Package, builddir string) {
 	}
 }
 
+// PackageBuildPhaseStarted implements PhaseAwareReporter
+func (cr CompositeReporter) PackageBuildPhaseStarted(pkg *Package, phase PackageBuildPhase) {
+	for _, r := range cr {
+		if par, ok := r.(PhaseAwareReporter); ok {
+			par.PackageBuildPhaseStarted(pkg, phase)
+		}
+	}
+}
+
+// PackageBuildPhaseFinished implements PhaseAwareReporter
+func (cr CompositeReporter) PackageBuildPhaseFinished(pkg *Package, phase PackageBuildPhase, err error) {
+	for _, r := range cr {
+		if par, ok := r.(PhaseAwareReporter); ok {
+			par.PackageBuildPhaseFinished(pkg, phase, err)
+		}
+	}
+}
+
 var _ Reporter = CompositeReporter{}
+var _ PhaseAwareReporter = CompositeReporter{}
 
 type NoopReporter struct{}
 
@@ -701,6 +731,8 @@ type OTelReporter struct {
 	rootSpan     trace.Span
 	packageCtxs  map[string]context.Context
 	packageSpans map[string]trace.Span
+	phaseSpans   map[string]trace.Span   // key: "packageName:phaseName"
+	phaseCtxs    map[string]context.Context // key: "packageName:phaseName"
 	mu           sync.RWMutex
 }
 
@@ -714,6 +746,8 @@ func NewOTelReporter(tracer trace.Tracer, parentCtx context.Context) *OTelReport
 		parentCtx:    parentCtx,
 		packageCtxs:  make(map[string]context.Context),
 		packageSpans: make(map[string]trace.Span),
+		phaseSpans:   make(map[string]trace.Span),
+		phaseCtxs:    make(map[string]context.Context),
 	}
 }
 
@@ -866,16 +900,6 @@ func (r *OTelReporter) PackageBuildFinished(pkg *Package, rep *PackageBuildRepor
 		attribute.Int64("leeway.package.duration_ms", rep.TotalTime().Milliseconds()),
 	)
 
-	// Add phase durations
-	for _, phase := range rep.Phases {
-		duration := rep.PhaseDuration(phase)
-		if duration >= 0 {
-			span.SetAttributes(
-				attribute.Int64(fmt.Sprintf("leeway.package.phase.%s.duration_ms", phase), duration.Milliseconds()),
-			)
-		}
-	}
-
 	// Add test coverage if available
 	if rep.TestCoverageAvailable {
 		span.SetAttributes(
@@ -901,6 +925,71 @@ func (r *OTelReporter) PackageBuildFinished(pkg *Package, rep *PackageBuildRepor
 	delete(r.packageCtxs, pkgName)
 }
 
+// PackageBuildPhaseStarted implements PhaseAwareReporter
+func (r *OTelReporter) PackageBuildPhaseStarted(pkg *Package, phase PackageBuildPhase) {
+	if r.tracer == nil {
+		return
+	}
+
+	r.mu.Lock()
+	defer r.mu.Unlock()
+
+	pkgName := pkg.FullName()
+	packageCtx, ok := r.packageCtxs[pkgName]
+	if !ok {
+		log.WithField("package", pkgName).Warn("PackageBuildPhaseStarted called without package context")
+		return
+	}
+
+	// Create phase span as child of package span
+	phaseKey := fmt.Sprintf("%s:%s", pkgName, phase)
+	phaseCtx, span := r.tracer.Start(packageCtx, "leeway.phase",
+		trace.WithSpanKind(trace.SpanKindInternal),
+	)
+
+	// Add phase attributes
+	span.SetAttributes(
+		attribute.String("leeway.package.name", pkgName),
+		attribute.String("leeway.phase.name", string(phase)),
+	)
+
+	r.phaseSpans[phaseKey] = span
+	r.phaseCtxs[phaseKey] = phaseCtx
+}
+
+// PackageBuildPhaseFinished implements PhaseAwareReporter
+func (r *OTelReporter) PackageBuildPhaseFinished(pkg *Package, phase PackageBuildPhase, err error) {
+	if r.tracer == nil {
+		return
+	}
+
+	r.mu.Lock()
+	defer r.mu.Unlock()
+
+	pkgName := pkg.FullName()
+	phaseKey := fmt.Sprintf("%s:%s", pkgName, phase)
+	span, ok := r.phaseSpans[phaseKey]
+	if !ok {
+		log.WithField("package", pkgName).WithField("phase", phase).Warn("PackageBuildPhaseFinished called without corresponding PackageBuildPhaseStarted")
+		return
+	}
+
+	// Set error status if phase failed
+	if err != nil {
+		span.RecordError(err)
+		span.SetStatus(codes.Error, err.Error())
+	} else {
+		span.SetStatus(codes.Ok, "phase completed successfully")
+	}
+
+	// End span
+	span.End()
+
+	// Clean up
+	delete(r.phaseSpans, phaseKey)
+	delete(r.phaseCtxs, phaseKey)
+}
+
 // addGitHubAttributes adds GitHub Actions context attributes to the span
 func (r *OTelReporter) addGitHubAttributes(span trace.Span) {
 	// Check if running in GitHub Actions
@@ -945,7 +1034,8 @@ func (r *OTelReporter) addGitHubAttributes(span trace.Span) {
 }
 
 // GetPackageContext returns the tracing context for a package build.
-// This can be used to create child spans for operations within the package build.
+// If a phase is currently active, returns the phase context so child spans
+// are nested under the phase. Otherwise returns the package context.
 // Returns nil if no context is available for the package.
 func (r *OTelReporter) GetPackageContext(pkg *Package) context.Context {
 	if r.tracer == nil {
@@ -956,6 +1046,15 @@ func (r *OTelReporter) GetPackageContext(pkg *Package) context.Context {
 	defer r.mu.RUnlock()
 
 	pkgName := pkg.FullName()
+
+	// Check for active phase context first
+	for key, ctx := range r.phaseCtxs {
+		if len(key) > len(pkgName) && key[:len(pkgName)] == pkgName && key[len(pkgName)] == ':' {
+			return ctx
+		}
+	}
+
+	// Fall back to package context
 	ctx, ok := r.packageCtxs[pkgName]
 	if !ok {
 		return nil