fix(telemetry): harden export lifecycle and log correlation

Author: LauJosefsen

actions/runner.go

@@ -40,7 +40,6 @@ func RunActions(ctx context.Context, cfg *config.GitteConfig, st *state.GitteSta
 	view := newView(mode, infos, actionOrder, runCancel, retryCh, cfg.QuickSolve.GitClean.Exclude)
 
 	tracker := telemetry.NewActionTracker(ctx)
-	reg := telemetry.NewSpanRegistry()
 
 	onStart := func(name string) {
 		tracker.OnStart(name)
@@ -72,7 +71,7 @@ func RunActions(ctx context.Context, cfg *config.GitteConfig, st *state.GitteSta
 	var retrySet map[string]struct{} // nil on first run
 	var runErr error
 	for {
-		tasks := buildExecutorTasks(cfg, st, cwd, keys, tracker, reg)
+		tasks := buildExecutorTasks(cfg, st, cwd, keys, tracker)
 
 		// Strip needs from explicitly retried tasks so they run immediately.
 		if retrySet != nil {
@@ -114,7 +113,7 @@ func RunActions(ctx context.Context, cfg *config.GitteConfig, st *state.GitteSta
 			exec.WithPreCompleted(succeeded, failed)
 		}
 
-		exec.WithOutputHandler(telemetry.LogOutputHandler(view.Handler(), reg))
+		exec.WithOutputHandler(view.Handler())
 		exec.WithRetryChannel(retryCh)
 
 		runErr = exec.Execute(runCtx)
@@ -208,7 +207,7 @@ func buildTaskInfos(cfg *config.GitteConfig, st *state.GitteState, cwd string, k
 }
 
 // buildExecutorTasks constructs executor.Task list from keys.
-func buildExecutorTasks(cfg *config.GitteConfig, st *state.GitteState, cwd string, keys []GroupKeyWithDeps, tracker *telemetry.ActionTracker, reg *telemetry.SpanRegistry) []executor.Task {
+func buildExecutorTasks(cfg *config.GitteConfig, st *state.GitteState, cwd string, keys []GroupKeyWithDeps, tracker *telemetry.ActionTracker) []executor.Task {
 	tasks := make([]executor.Task, 0, len(keys))
 	searchFors := cfg.SearchFor
 
@@ -253,7 +252,7 @@ func buildExecutorTasks(cfg *config.GitteConfig, st *state.GitteState, cwd strin
 			Needs: needNames,
 			Retry: retryConfig,
 			ExecuteFn: func(ctx context.Context, tName string, handler executor.OutputHandler) error {
-				return runGroupTask(ctx, cfg, st, cwd, proj, key.Project, tName, cmds, allSearchFors, handler, tracker, reg)
+				return runGroupTask(ctx, cfg, st, cwd, proj, key.Project, tName, cmds, allSearchFors, handler, tracker)
 			},
 		})
 	}
@@ -285,38 +284,28 @@ func runGroupTask(
 	searchFors []config.SearchFor,
 	handler executor.OutputHandler,
 	tracker *telemetry.ActionTracker,
-	reg *telemetry.SpanRegistry,
 ) (err error) {
 	actionCtx := tracker.ActionContext(telemetry.ActionOf(taskName))
 	// Parent the task span under the action span, but keep running under the
 	// executor's incoming (cancellable) context so cancellation still propagates
 	// to the command — attach the span to ctx rather than replacing ctx.
 	_, span := telemetry.Tracer().Start(actionCtx, "action.run "+taskName)
 	ctx = trace.ContextWithSpan(ctx, span)
-	reg.Set(taskName, span.SpanContext())
-	setActionAttrs(span, taskName, projName, strings.Join(cmds, " "))
-	if feats := enabledFeaturesForProject(cfg, st, projName, proj); len(feats) > 0 {
-		span.SetAttributes(attribute.StringSlice("gitte.features", feats))
-	}
-	if env := injectedEnv(cfg, st, projName, proj); len(env) > 0 {
-		keys := make([]string, 0, len(env))
-		for k := range env {
-			keys = append(keys, k)
-		}
-		sort.Strings(keys)
-		kvs := make([]string, 0, len(keys))
-		for _, k := range keys {
-			kvs = append(kvs, k+"="+env[k])
-		}
-		span.SetAttributes(attribute.StringSlice("gitte.env", kvs))
-	}
+	handler = telemetry.LogOutputHandler(handler)
+	setTaskTelemetryAttrs(span, cfg, st, projName, proj, taskName, cmds)
 	defer func() {
+		if recovered := recover(); recovered != nil {
+			panicErr := fmt.Errorf("panic: %v", recovered)
+			span.RecordError(panicErr)
+			span.SetStatus(codes.Error, panicErr.Error())
+			span.End()
+			panic(recovered)
+		}
 		if err != nil {
 			span.RecordError(err)
 			span.SetStatus(codes.Error, err.Error())
 		}
 		span.End()
-		reg.Delete(taskName)
 	}()
 
 	if len(cmds) == 0 {
@@ -348,18 +337,51 @@ func runGroupTask(
 		return err
 	}
 
-	span.SetAttributes(attribute.Int("gitte.exit_code", res.ExitCode))
+	if span.IsRecording() {
+		span.SetAttributes(attribute.Int("gitte.exit_code", res.ExitCode))
+		if res.ExitCode != 0 {
+			if tail := outputTail(res.Stderr, res.Stdout); tail != "" {
+				span.SetAttributes(attribute.String("gitte.error_tail", tail))
+			}
+		}
+	}
 
 	if res.ExitCode != 0 {
-		if tail := outputTail(res.Stderr, res.Stdout); tail != "" {
-			span.SetAttributes(attribute.String("gitte.error_tail", tail))
-		}
 		return fmt.Errorf("command exited with code %d", res.ExitCode)
 	}
 
 	return nil
 }
 
+func setTaskTelemetryAttrs(
+	span trace.Span,
+	cfg *config.GitteConfig,
+	st *state.GitteState,
+	projName string,
+	proj config.ProjectConfig,
+	taskName string,
+	cmds []string,
+) {
+	if span.IsRecording() {
+		setActionAttrs(span, taskName, projName, strings.Join(cmds, " "))
+		if feats := enabledFeaturesForProject(cfg, st, projName, proj); len(feats) > 0 {
+			span.SetAttributes(attribute.StringSlice("gitte.features", feats))
+		}
+		if env := injectedEnv(cfg, st, projName, proj); len(env) > 0 {
+			keys := make([]string, 0, len(env))
+			for k := range env {
+				keys = append(keys, k)
+			}
+			sort.Strings(keys)
+			kvs := make([]string, 0, len(keys))
+			for _, k := range keys {
+				kvs = append(kvs, k+"="+env[k])
+			}
+			span.SetAttributes(attribute.StringSlice("gitte.env", kvs))
+		}
+	}
+}
+
 // errorTailBytes caps how much trailing command output is attached to a failed
 // task span via the gitte.error_tail attribute.
 const errorTailBytes = 4096

actions/telemetry_test.go

@@ -4,9 +4,11 @@ import (
 	"context"
 	"testing"
 
+	"github.com/cego/gitte/config"
 	"go.opentelemetry.io/otel"
 	sdktrace "go.opentelemetry.io/otel/sdk/trace"
 	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+	"go.opentelemetry.io/otel/trace/noop"
 )
 
 func TestSetActionAttrs(t *testing.T) {
@@ -35,3 +37,10 @@ func TestSetActionAttrs(t *testing.T) {
 		t.Fatalf("attrs = %+v", got)
 	}
 }
+
+func TestSetTaskTelemetryAttrs_SkipsWorkForNonRecordingSpan(t *testing.T) {
+	_, span := noop.NewTracerProvider().Tracer("test").Start(context.Background(), "task")
+	// nil config/state would panic in feature and environment resolution. A
+	// non-recording span must return before touching either dependency.
+	setTaskTelemetryAttrs(span, nil, nil, "project", config.ProjectConfig{}, "project:up:default", []string{"true"})
+}

cmd/root.go

@@ -36,7 +36,7 @@ var (
 	globalCtx    context.Context
 	globalCancel context.CancelFunc
 
-	globalTelemetryShutdown func()
+	globalTelemetryShutdown func(context.Context)
 	globalRootSpan          trace.Span
 )
 
@@ -86,8 +86,7 @@ func Execute() {
 			globalCancel()
 		}
 	}()
-	err := rootCmd.Execute()
-	finishTelemetry(err)
+	err := executeRoot()
 	if err != nil {
 		if output.DetectMode(flagNoTTY) == output.ModePlain {
 			fmt.Fprintln(os.Stderr, "error:", err)
@@ -98,6 +97,25 @@ func Execute() {
 	}
 }
 
+// executeRoot guarantees telemetry finalization for both returned errors and
+// panics. A panic is recorded as an error before being re-thrown so callers keep
+// the normal panic behavior and stack output.
+func executeRoot() (err error) {
+	return runWithTelemetry(rootCmd.Execute)
+}
+
+func runWithTelemetry(run func() error) (err error) {
+	defer func() {
+		if recovered := recover(); recovered != nil {
+			panicErr := fmt.Errorf("panic: %v", recovered)
+			finishTelemetry(panicErr)
+			panic(recovered)
+		}
+		finishTelemetry(err)
+	}()
+	return run()
+}
+
 // finishTelemetry records the final command status on the root span and flushes
 // pending spans. Safe to call when telemetry was never initialized (e.g.
 // completion commands or an early config failure), where the handles remain nil.
@@ -112,7 +130,9 @@ func finishTelemetry(err error) {
 		globalRootSpan.End()
 	}
 	if globalTelemetryShutdown != nil {
-		globalTelemetryShutdown()
+		shutdownCtx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
+		defer stop()
+		globalTelemetryShutdown(shutdownCtx)
 	}
 }
 

cmd/root_telemetry_test.go

@@ -0,0 +1,56 @@
+package cmd
+
+import (
+	"context"
+	"testing"
+
+	"go.opentelemetry.io/otel/codes"
+	sdktrace "go.opentelemetry.io/otel/sdk/trace"
+	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+)
+
+func TestRunWithTelemetry_RecordsAndFlushesPanicThenRepanics(t *testing.T) {
+	exporter := tracetest.NewInMemoryExporter()
+	provider := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter))
+	t.Cleanup(func() { _ = provider.Shutdown(context.Background()) })
+
+	_, span := provider.Tracer("test").Start(context.Background(), "gitte test")
+	previousSpan := globalRootSpan
+	previousShutdown := globalTelemetryShutdown
+	globalRootSpan = span
+	shutdownCalled := false
+	globalTelemetryShutdown = func(context.Context) { shutdownCalled = true }
+	t.Cleanup(func() {
+		globalRootSpan = previousSpan
+		globalTelemetryShutdown = previousShutdown
+	})
+
+	var recovered any
+	func() {
+		defer func() { recovered = recover() }()
+		_ = runWithTelemetry(func() error { panic("boom") })
+	}()
+
+	if recovered != "boom" {
+		t.Fatalf("recovered panic = %v, want boom", recovered)
+	}
+	if !shutdownCalled {
+		t.Fatal("telemetry shutdown was not called")
+	}
+	spans := exporter.GetSpans()
+	if len(spans) != 1 {
+		t.Fatalf("exported %d spans, want 1", len(spans))
+	}
+	if spans[0].Status.Code != codes.Error {
+		t.Fatalf("root span status = %v, want error", spans[0].Status.Code)
+	}
+	foundException := false
+	for _, event := range spans[0].Events {
+		if event.Name == "exception" {
+			foundException = true
+		}
+	}
+	if !foundException {
+		t.Fatal("panic was not sent as an exception event")
+	}
+}

config/startup_checks.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"io"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -18,7 +19,7 @@ type StartupCheck interface {
 	GetType() string
 	GetHint() string
 	GetNeeds() []string
-	Check(ctx context.Context, cwd string) error
+	Check(ctx context.Context, cwd string, stdout, stderr io.Writer) error
 }
 
 // BaseStartupCheck holds common fields for all check types
@@ -44,14 +45,18 @@ type ShellStartupCheck struct {
 	Script           string `yaml:"script"`
 }
 
-func (s *ShellStartupCheck) Check(ctx context.Context, cwd string) error {
+func (s *ShellStartupCheck) Check(ctx context.Context, cwd string, stdout, stderr io.Writer) error {
 	cmd := exec.CommandContext(ctx, s.Shell, "-c", s.Script) //nolint:gosec
 	cmd.Dir = cwd
-	var stderr bytes.Buffer
-	cmd.Stderr = &stderr
+	var stderrBuf bytes.Buffer
+	if stderr == nil {
+		stderr = io.Discard
+	}
+	cmd.Stdout = stdout
+	cmd.Stderr = io.MultiWriter(stderr, &stderrBuf)
 	if err := cmd.Run(); err != nil {
 		if exitErr, ok := err.(*exec.ExitError); ok {
-			stderrStr := strings.TrimSpace(stderr.String())
+			stderrStr := strings.TrimSpace(stderrBuf.String())
 			if stderrStr != "" {
 				return fmt.Errorf("shell script exited with code %d: %s", exitErr.ExitCode(), stderrStr)
 			}
@@ -68,12 +73,14 @@ type CommandStartupCheck struct {
 	Command          []string `yaml:"cmd"`
 }
 
-func (s *CommandStartupCheck) Check(ctx context.Context, cwd string) error {
+func (s *CommandStartupCheck) Check(ctx context.Context, cwd string, stdout, stderr io.Writer) error {
 	if len(s.Command) == 0 {
 		return fmt.Errorf("command check has no command")
 	}
 	cmd := exec.CommandContext(ctx, s.Command[0], s.Command[1:]...) //nolint:gosec
 	cmd.Dir = cwd
+	cmd.Stdout = stdout
+	cmd.Stderr = stderr
 	if err := cmd.Run(); err != nil {
 		if exitErr, ok := err.(*exec.ExitError); ok {
 			return fmt.Errorf("command exited with code %d", exitErr.ExitCode())
@@ -90,7 +97,7 @@ type YamlPathPresentStartupCheck struct {
 	File             string `yaml:"file"`
 }
 
-func (s *YamlPathPresentStartupCheck) Check(_ context.Context, _ string) error {
+func (s *YamlPathPresentStartupCheck) Check(_ context.Context, _ string, _, _ io.Writer) error {
 	path, err := goyaml.PathString(s.Path)
 	if err != nil {
 		return fmt.Errorf("invalid yaml path: %w", err)

executor/executor.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"runtime/debug"
 	"strconv"
 	"strings"
 	"time"
@@ -244,7 +245,7 @@ func (e *Executor) startReadyTasks(ctx context.Context, completionCh chan<- Comm
 			}
 
 			handler := ToChannelOutputHandler{OutputCh: outputCh}
-			err := r.task.ExecuteFn(ctx, r.task.Name, handler)
+			err := executeTask(ctx, r.task, handler)
 			elapsed := time.Since(r.startedAt)
 
 			if err != nil {
@@ -276,6 +277,15 @@ func (e *Executor) startReadyTasks(ctx context.Context, completionCh chan<- Comm
 	return nil
 }
 
+func executeTask(ctx context.Context, task Task, handler OutputHandler) (err error) {
+	defer func() {
+		if recovered := recover(); recovered != nil {
+			err = &PanicError{Task: task.Name, Value: recovered, Stack: debug.Stack()}
+		}
+	}()
+	return task.ExecuteFn(ctx, task.Name, handler)
+}
+
 // resetForRetry re-queues the named failed tasks and cascades to any skipped dependents.
 // Returns the number of tasks reset (caller must decrement its finished counter by this amount).
 func (e *Executor) resetForRetry(names []string) int {