From 0b0e817ca5e064346f64c1048ac191fc1183a6ee Mon Sep 17 00:00:00 2001 From: Julien Neuhart Date: Tue, 2 Jun 2026 18:59:33 +0200 Subject: [PATCH] feat(gotenberg): wrap Cmd.Exec in a process.exec client span --- pkg/gotenberg/cmd.go | 52 +++++++++++++++ pkg/gotenberg/cmd_test.go | 136 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 188 insertions(+) create mode 100644 pkg/gotenberg/cmd_test.go diff --git a/pkg/gotenberg/cmd.go b/pkg/gotenberg/cmd.go index 3a0d2f2..ea97ac9 100644 --- a/pkg/gotenberg/cmd.go +++ b/pkg/gotenberg/cmd.go @@ -8,8 +8,14 @@ import ( "io" "log/slog" "os/exec" + "path/filepath" "strings" "syscall" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + semconv "go.opentelemetry.io/otel/semconv/v1.41.0" + "go.opentelemetry.io/otel/trace" ) // Cmd wraps an [exec.Cmd]. @@ -92,11 +98,44 @@ func (cmd *Cmd) Wait() error { // Exec executes the command and waits for its completion or until the context // is done. In any case, it kills the unix process and all its children. +// +// When the context carries an active trace span, Exec records a +// "process.exec" client span around the execution. It is the single +// instrumentation point for every short-lived external binary (soffice, pdftk, +// qpdf, exiftool, pdfcpu). The span is skipped when there is no active parent, +// so process starts performed off the request path do not emit orphan roots. func (cmd *Cmd) Exec() (int, error) { if cmd.ctx == nil { return 10, errors.New("nil context") } + var span trace.Span + if trace.SpanContextFromContext(cmd.ctx).IsValid() { + _, span = Tracer().Start(cmd.ctx, "process.exec", + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(semconv.ProcessExecutableName(filepath.Base(cmd.process.Path))), + ) + defer span.End() + } + + code, err := cmd.exec() + + if span != nil { + span.SetAttributes(attribute.Int("process.exit.code", code)) + if err != nil { + span.RecordError(err) + span.SetStatus(codes.Error, err.Error()) + span.SetAttributes(semconv.ErrorTypeKey.String(execErrorType(cmd.ctx))) + } else { + span.SetStatus(codes.Ok, "") + } + } + + return code, err +} + +// exec runs the command and returns its exit code and error. +func (cmd *Cmd) exec() (int, error) { err := cmd.Start() if err != nil { if cmd.process.ProcessState == nil { @@ -138,6 +177,19 @@ func (cmd *Cmd) Exec() (int, error) { } } +// execErrorType maps an execution failure to a bounded semconv error.type +// value. +func execErrorType(ctx context.Context) string { + switch { + case errors.Is(ctx.Err(), context.DeadlineExceeded): + return "context_deadline_exceeded" + case errors.Is(ctx.Err(), context.Canceled): + return "context_canceled" + default: + return "process_error" + } +} + // pipeOutput creates logs entries according to the process stdout and stderr. // It does nothing if the logging level is not debug. func (cmd *Cmd) pipeOutput() error { diff --git a/pkg/gotenberg/cmd_test.go b/pkg/gotenberg/cmd_test.go new file mode 100644 index 0000000..0bdadbc --- /dev/null +++ b/pkg/gotenberg/cmd_test.go @@ -0,0 +1,136 @@ +package gotenberg + +import ( + "context" + "log/slog" + "testing" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +func newTestSpanRecorder(t *testing.T) *tracetest.SpanRecorder { + t.Helper() + recorder := tracetest.NewSpanRecorder() + provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(recorder)) + previous := otel.GetTracerProvider() + otel.SetTracerProvider(provider) + t.Cleanup(func() { otel.SetTracerProvider(previous) }) + return recorder +} + +func findSpan(recorder *tracetest.SpanRecorder, name string) sdktrace.ReadOnlySpan { + for _, s := range recorder.Ended() { + if s.Name() == name { + return s + } + } + return nil +} + +func spanAttr(span sdktrace.ReadOnlySpan, key string) (attribute.Value, bool) { + for _, kv := range span.Attributes() { + if string(kv.Key) == key { + return kv.Value, true + } + } + return attribute.Value{}, false +} + +func TestCmd_Exec_NilContext(t *testing.T) { + cmd := Command(slog.New(slog.DiscardHandler), "true") + + code, err := cmd.Exec() + if err == nil { + t.Error("expected an error for a nil context") + } + if code != 10 { + t.Errorf("expected code 10, got %d", code) + } +} + +func TestCmd_Exec_NoParentSpanProducesNoSpan(t *testing.T) { + recorder := newTestSpanRecorder(t) + + cmd, err := CommandContext(context.Background(), slog.New(slog.DiscardHandler), "sh", "-c", "exit 0") + if err != nil { + t.Fatalf("create command: %v", err) + } + + code, err := cmd.Exec() + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if code != 0 { + t.Errorf("expected code 0, got %d", code) + } + if n := len(recorder.Ended()); n != 0 { + t.Errorf("expected no span without an active parent, got %d", n) + } +} + +func TestCmd_Exec_RecordsSpanOnSuccess(t *testing.T) { + recorder := newTestSpanRecorder(t) + + ctx, parent := otel.Tracer("test").Start(context.Background(), "parent") + cmd, err := CommandContext(ctx, slog.New(slog.DiscardHandler), "sh", "-c", "exit 0") + if err != nil { + t.Fatalf("create command: %v", err) + } + + code, err := cmd.Exec() + parent.End() + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if code != 0 { + t.Errorf("expected code 0, got %d", code) + } + + span := findSpan(recorder, "process.exec") + if span == nil { + t.Fatal("expected a process.exec span to be recorded") + } + if span.Status().Code != codes.Ok { + t.Errorf("expected status Ok, got %v", span.Status().Code) + } + if name, ok := spanAttr(span, "process.executable.name"); !ok || name.AsString() != "sh" { + t.Errorf("expected process.executable.name=sh, got %q (present=%t)", name.AsString(), ok) + } + if exit, ok := spanAttr(span, "process.exit.code"); !ok || exit.AsInt64() != 0 { + t.Errorf("expected process.exit.code=0, got %d (present=%t)", exit.AsInt64(), ok) + } +} + +func TestCmd_Exec_RecordsSpanOnError(t *testing.T) { + recorder := newTestSpanRecorder(t) + + ctx, parent := otel.Tracer("test").Start(context.Background(), "parent") + cmd, err := CommandContext(ctx, slog.New(slog.DiscardHandler), "sh", "-c", "exit 3") + if err != nil { + t.Fatalf("create command: %v", err) + } + + code, err := cmd.Exec() + parent.End() + if err == nil { + t.Error("expected an error for a non-zero exit code") + } + if code != 3 { + t.Errorf("expected exit code 3, got %d", code) + } + + span := findSpan(recorder, "process.exec") + if span == nil { + t.Fatal("expected a process.exec span to be recorded") + } + if span.Status().Code != codes.Error { + t.Errorf("expected status Error, got %v", span.Status().Code) + } + if et, ok := spanAttr(span, "error.type"); !ok || et.AsString() != "process_error" { + t.Errorf("expected error.type=process_error, got %q (present=%t)", et.AsString(), ok) + } +}