diff --git a/README.md b/README.md index bde0a9a3..ff3c39c9 100644 --- a/README.md +++ b/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 diff --git a/docs/observability.md b/docs/observability.md index f42a95b7..2736ea17 100644 --- a/docs/observability.md +++ b/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: diff --git a/pkg/leeway/build.go b/pkg/leeway/build.go index baccce87..4153352b 100644 --- a/pkg/leeway/build.go +++ b/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 { diff --git a/pkg/leeway/gotest_trace.go b/pkg/leeway/gotest_trace.go index 9e4abc46..d93cddd5 100644 --- a/pkg/leeway/gotest_trace.go +++ b/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"), diff --git a/pkg/leeway/gotest_trace_test.go b/pkg/leeway/gotest_trace_test.go index c67b3833..678b2a4d 100644 --- a/pkg/leeway/gotest_trace_test.go +++ b/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} diff --git a/pkg/leeway/reporter.go b/pkg/leeway/reporter.go index d5f3d2d5..4142190c 100644 --- a/pkg/leeway/reporter.go +++ b/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 diff --git a/pkg/leeway/reporter_otel_phase_test.go b/pkg/leeway/reporter_otel_phase_test.go new file mode 100644 index 00000000..8b68c396 --- /dev/null +++ b/pkg/leeway/reporter_otel_phase_test.go @@ -0,0 +1,329 @@ +package leeway + +import ( + "context" + "fmt" + "testing" + "time" + + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +func TestOTelReporter_PhaseSpans(t *testing.T) { + // Create in-memory exporter for testing + exporter := tracetest.NewInMemoryExporter() + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + ) + defer func() { + _ = tp.Shutdown(context.Background()) + }() + + tracer := tp.Tracer("test") + reporter := NewOTelReporter(tracer, context.Background()) + + // Create test package + pkg := &Package{ + C: &Component{ + Name: "test-component", + W: &Workspace{ + Origin: "/workspace", + }, + }, + PackageInternal: PackageInternal{ + Name: "test-package", + Type: GenericPackage, + }, + } + + // Start build and package + status := map[*Package]PackageBuildStatus{ + pkg: PackageNotBuiltYet, + } + reporter.BuildStarted(pkg, status) + reporter.PackageBuildStarted(pkg, "/tmp/build") + + // Simulate phase execution + phases := []PackageBuildPhase{ + PackageBuildPhasePrep, + PackageBuildPhaseBuild, + PackageBuildPhaseTest, + } + + for _, phase := range phases { + reporter.PackageBuildPhaseStarted(pkg, phase) + time.Sleep(10 * time.Millisecond) // Simulate work + reporter.PackageBuildPhaseFinished(pkg, phase, nil) + } + + // Finish package and build + rep := &PackageBuildReport{ + phaseEnter: make(map[PackageBuildPhase]time.Time), + phaseDone: make(map[PackageBuildPhase]time.Time), + Phases: phases, + Error: nil, + } + reporter.PackageBuildFinished(pkg, rep) + reporter.BuildFinished(pkg, nil) + + // Verify spans were created + spans := exporter.GetSpans() + if len(spans) < 5 { // build + package + 3 phases + t.Fatalf("Expected at least 5 spans (build + package + 3 phases), got %d", len(spans)) + } + + // Count phase spans + phaseSpanCount := 0 + for _, span := range spans { + if span.Name == "leeway.phase" { + phaseSpanCount++ + + // Verify phase has name attribute + hasPhaseNameAttr := false + for _, attr := range span.Attributes { + if string(attr.Key) == "leeway.phase.name" { + hasPhaseNameAttr = true + phaseName := attr.Value.AsString() + if phaseName != string(PackageBuildPhasePrep) && + phaseName != string(PackageBuildPhaseBuild) && + phaseName != string(PackageBuildPhaseTest) { + t.Errorf("Unexpected phase name: %s", phaseName) + } + } + } + if !hasPhaseNameAttr { + t.Error("Expected 'leeway.phase.name' attribute in phase span") + } + + // Verify status is OK + if span.Status.Code != codes.Ok { + t.Errorf("Expected phase span status OK, got %v", span.Status.Code) + } + } + } + + if phaseSpanCount != 3 { + t.Errorf("Expected 3 phase spans, got %d", phaseSpanCount) + } +} + +func TestOTelReporter_PhaseSpanWithError(t *testing.T) { + // Create in-memory exporter for testing + exporter := tracetest.NewInMemoryExporter() + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + ) + defer func() { + _ = tp.Shutdown(context.Background()) + }() + + tracer := tp.Tracer("test") + reporter := NewOTelReporter(tracer, context.Background()) + + // Create test package + pkg := &Package{ + C: &Component{ + Name: "test-component", + W: &Workspace{ + Origin: "/workspace", + }, + }, + PackageInternal: PackageInternal{ + Name: "test-package", + Type: GenericPackage, + }, + } + + // Start build and package + status := map[*Package]PackageBuildStatus{ + pkg: PackageNotBuiltYet, + } + reporter.BuildStarted(pkg, status) + reporter.PackageBuildStarted(pkg, "/tmp/build") + + // Simulate phase with error + reporter.PackageBuildPhaseStarted(pkg, PackageBuildPhaseBuild) + buildErr := fmt.Errorf("build failed") + reporter.PackageBuildPhaseFinished(pkg, PackageBuildPhaseBuild, buildErr) + + // Finish package and build + rep := &PackageBuildReport{ + phaseEnter: make(map[PackageBuildPhase]time.Time), + phaseDone: make(map[PackageBuildPhase]time.Time), + Phases: []PackageBuildPhase{PackageBuildPhaseBuild}, + Error: buildErr, + } + reporter.PackageBuildFinished(pkg, rep) + reporter.BuildFinished(pkg, buildErr) + + // Verify spans were created + spans := exporter.GetSpans() + + // Find phase span + var phaseSpan *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "leeway.phase" { + phaseSpan = &spans[i] + break + } + } + + if phaseSpan == nil { + t.Fatal("Expected to find phase span") + } + + // Verify error status + if phaseSpan.Status.Code != codes.Error { + t.Errorf("Expected phase span status Error, got %v", phaseSpan.Status.Code) + } + + // Verify error was recorded + if len(phaseSpan.Events) == 0 { + t.Error("Expected error event to be recorded in phase span") + } +} + +func TestOTelReporter_PhaseSpanHierarchy(t *testing.T) { + // Create in-memory exporter for testing + exporter := tracetest.NewInMemoryExporter() + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + ) + defer func() { + _ = tp.Shutdown(context.Background()) + }() + + tracer := tp.Tracer("test") + reporter := NewOTelReporter(tracer, context.Background()) + + // Create test package + pkg := &Package{ + C: &Component{ + Name: "test-component", + W: &Workspace{ + Origin: "/workspace", + }, + }, + PackageInternal: PackageInternal{ + Name: "test-package", + Type: GenericPackage, + }, + } + + // Start build and package + status := map[*Package]PackageBuildStatus{ + pkg: PackageNotBuiltYet, + } + reporter.BuildStarted(pkg, status) + reporter.PackageBuildStarted(pkg, "/tmp/build") + + // Execute phase + reporter.PackageBuildPhaseStarted(pkg, PackageBuildPhaseBuild) + reporter.PackageBuildPhaseFinished(pkg, PackageBuildPhaseBuild, nil) + + // Finish package and build + rep := &PackageBuildReport{ + phaseEnter: make(map[PackageBuildPhase]time.Time), + phaseDone: make(map[PackageBuildPhase]time.Time), + Phases: []PackageBuildPhase{PackageBuildPhaseBuild}, + Error: nil, + } + reporter.PackageBuildFinished(pkg, rep) + reporter.BuildFinished(pkg, nil) + + // Verify span hierarchy + spans := exporter.GetSpans() + + var buildSpan, packageSpan, phaseSpan *tracetest.SpanStub + for i := range spans { + switch spans[i].Name { + case "leeway.build": + buildSpan = &spans[i] + case "leeway.package": + packageSpan = &spans[i] + case "leeway.phase": + phaseSpan = &spans[i] + } + } + + if buildSpan == nil { + t.Fatal("Expected to find build span") + } + if packageSpan == nil { + t.Fatal("Expected to find package span") + } + if phaseSpan == nil { + t.Fatal("Expected to find phase span") + } + + // Verify parent-child relationships + // Package span should be child of build span + if packageSpan.Parent.TraceID() != buildSpan.SpanContext.TraceID() { + t.Error("Package span should have same trace ID as build span") + } + if packageSpan.Parent.SpanID() != buildSpan.SpanContext.SpanID() { + t.Error("Package span should be child of build span") + } + + // Phase span should be child of package span + if phaseSpan.Parent.TraceID() != packageSpan.SpanContext.TraceID() { + t.Error("Phase span should have same trace ID as package span") + } + if phaseSpan.Parent.SpanID() != packageSpan.SpanContext.SpanID() { + t.Error("Phase span should be child of package span") + } +} + +func TestOTelReporter_PhaseAwareInterface(t *testing.T) { + // Verify OTelReporter implements PhaseAwareReporter + var _ PhaseAwareReporter = (*OTelReporter)(nil) + + // Verify NoopReporter does NOT implement PhaseAwareReporter + var noop Reporter = &NoopReporter{} + if _, ok := noop.(PhaseAwareReporter); ok { + t.Error("NoopReporter should not implement PhaseAwareReporter") + } +} + +func TestOTelReporter_PhaseWithoutPackageContext(t *testing.T) { + // Create in-memory exporter for testing + exporter := tracetest.NewInMemoryExporter() + tp := trace.NewTracerProvider( + trace.WithSyncer(exporter), + ) + defer func() { + _ = tp.Shutdown(context.Background()) + }() + + tracer := tp.Tracer("test") + reporter := NewOTelReporter(tracer, context.Background()) + + // Create test package + pkg := &Package{ + C: &Component{ + Name: "test-component", + W: &Workspace{ + Origin: "/workspace", + }, + }, + PackageInternal: PackageInternal{ + Name: "test-package", + Type: GenericPackage, + }, + } + + // Try to start phase without starting package first + // This should not panic and should log a warning + reporter.PackageBuildPhaseStarted(pkg, PackageBuildPhaseBuild) + reporter.PackageBuildPhaseFinished(pkg, PackageBuildPhaseBuild, nil) + + // Verify no phase spans were created + spans := exporter.GetSpans() + for _, span := range spans { + if span.Name == "leeway.phase" { + t.Error("Phase span should not be created without package context") + } + } +} diff --git a/pkg/leeway/reporter_otel_test.go b/pkg/leeway/reporter_otel_test.go index a82336d8..c66bb9e4 100644 --- a/pkg/leeway/reporter_otel_test.go +++ b/pkg/leeway/reporter_otel_test.go @@ -820,6 +820,14 @@ func TestOTelReporter_PhaseDurations(t *testing.T) { reporter.BuildStarted(pkg, status) reporter.PackageBuildStarted(pkg, "/tmp/build") + // Simulate phase execution with actual phase spans + phases := []PackageBuildPhase{PackageBuildPhasePrep, PackageBuildPhaseBuild, PackageBuildPhaseTest} + for _, phase := range phases { + reporter.PackageBuildPhaseStarted(pkg, phase) + time.Sleep(10 * time.Millisecond) // Simulate work + reporter.PackageBuildPhaseFinished(pkg, phase, nil) + } + // Create report with phase durations now := time.Now() rep := &PackageBuildReport{ @@ -833,52 +841,41 @@ func TestOTelReporter_PhaseDurations(t *testing.T) { PackageBuildPhaseBuild: now.Add(300 * time.Millisecond), PackageBuildPhaseTest: now.Add(500 * time.Millisecond), }, - Phases: []PackageBuildPhase{PackageBuildPhasePrep, PackageBuildPhaseBuild, PackageBuildPhaseTest}, + Phases: phases, } reporter.PackageBuildFinished(pkg, rep) reporter.BuildFinished(pkg, nil) // Verify spans were created spans := exporter.GetSpans() - if len(spans) < 2 { - t.Fatalf("Expected at least 2 spans, got %d", len(spans)) - } - - // Find package span - var packageSpan *tracetest.SpanStub - for i := range spans { - if spans[i].Name == "leeway.package" { - packageSpan = &spans[i] - break - } - } - - if packageSpan == nil { - t.Fatal("Expected to find package span") + if len(spans) < 5 { // build + package + 3 phases + t.Fatalf("Expected at least 5 spans, got %d", len(spans)) } - // Verify phase duration attributes exist + // Verify phase spans exist (durations are now in nested spans, not attributes) expectedPhases := []string{"prep", "build", "test"} foundPhases := make(map[string]bool) - for _, attr := range packageSpan.Attributes { - key := string(attr.Key) - if strings.HasPrefix(key, "leeway.package.phase.") && strings.HasSuffix(key, ".duration_ms") { - phase := strings.TrimPrefix(key, "leeway.package.phase.") - phase = strings.TrimSuffix(phase, ".duration_ms") - foundPhases[phase] = true - - // Verify duration is reasonable (should be around 100-200ms for each phase) - duration := attr.Value.AsInt64() - if duration < 50 || duration > 300 { - t.Errorf("Phase '%s' duration %dms seems unreasonable", phase, duration) + for _, span := range spans { + if span.Name == "leeway.phase" { + for _, attr := range span.Attributes { + if string(attr.Key) == "leeway.phase.name" { + phaseName := attr.Value.AsString() + foundPhases[phaseName] = true + + // Verify span has reasonable duration + duration := span.EndTime.Sub(span.StartTime) + if duration < 5*time.Millisecond || duration > 100*time.Millisecond { + t.Errorf("Phase '%s' duration %v seems unreasonable", phaseName, duration) + } + } } } } for _, phase := range expectedPhases { if !foundPhases[phase] { - t.Errorf("Expected phase duration attribute for '%s' not found", phase) + t.Errorf("Expected phase span for '%s' not found", phase) } } } diff --git a/pkg/leeway/reporter_test.go b/pkg/leeway/reporter_test.go index 618a657a..8676ea27 100644 --- a/pkg/leeway/reporter_test.go +++ b/pkg/leeway/reporter_test.go @@ -7,11 +7,15 @@ import ( "time" "github.com/google/go-cmp/cmp" + "github.com/gookit/color" ) func TestConsoleReporter(t *testing.T) { t.Parallel() + // Disable colors for consistent test output across environments. + color.Enable = false + type Expectation struct { Output string }