From 54897fbe6357f95c05c9cfb9c53b0d7b05502053 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Mon, 1 Jun 2026 13:58:01 +1000 Subject: [PATCH 01/13] Spike OTLP job log export --- agent/agent_configuration.go | 1 + agent/job_runner.go | 12 ++ agent/otlp_job_logger.go | 231 ++++++++++++++++++++++++++++++++ agent/otlp_job_logger_test.go | 241 ++++++++++++++++++++++++++++++++++ agent/run_job.go | 6 + clicommand/agent_start.go | 7 + go.mod | 4 + go.sum | 10 ++ 8 files changed, 512 insertions(+) create mode 100644 agent/otlp_job_logger.go create mode 100644 agent/otlp_job_logger_test.go diff --git a/agent/agent_configuration.go b/agent/agent_configuration.go index 64a87e8d86..96395aff59 100644 --- a/agent/agent_configuration.go +++ b/agent/agent_configuration.go @@ -66,6 +66,7 @@ type AgentConfiguration struct { EnableJobLogTmpfile bool JobLogPath string WriteJobLogsToStdout bool + JobLogsOTLP bool LogFormat string Shell string HooksShell string diff --git a/agent/job_runner.go b/agent/job_runner.go index c95d55c8c8..a6532b928f 100644 --- a/agent/job_runner.go +++ b/agent/job_runner.go @@ -125,6 +125,9 @@ type JobRunner struct { // jobLogs is an io.Writer that sends data to the job logs jobLogs io.Writer + // jobLogsOTLP exports job log lines to an OTLP logs endpoint when enabled. + jobLogsOTLP *OTLPJobLogger + // Job cancellation control cancelLock sync.Mutex // prevent concurrent calls to Cancel @@ -262,6 +265,15 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c } pr, pw := io.Pipe() + if conf.AgentConfiguration.JobLogsOTLP { + jobLogsOTLP, err := NewOTLPJobLogger(ctx, conf) + if err != nil { + r.agentLogger.Warnf("Failed to initialize OTLP job log exporter: %v", err) + } else { + r.jobLogsOTLP = jobLogsOTLP + allWriters = append(allWriters, jobLogsOTLP) + } + } switch { case conf.AgentConfiguration.ANSITimestamps: diff --git a/agent/otlp_job_logger.go b/agent/otlp_job_logger.go new file mode 100644 index 0000000000..ab6fe1c7b3 --- /dev/null +++ b/agent/otlp_job_logger.go @@ -0,0 +1,231 @@ +package agent + +import ( + "bytes" + "context" + "fmt" + "os" + "strings" + "sync" + "time" + + "github.com/buildkite/agent/v3/version" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" + otellog "go.opentelemetry.io/otel/log" + "go.opentelemetry.io/otel/propagation" + sdklog "go.opentelemetry.io/otel/sdk/log" + "go.opentelemetry.io/otel/sdk/resource" + semconv "go.opentelemetry.io/otel/semconv/v1.4.0" +) + +// OTLPJobLogger satisfies io.WriteCloser and emits job output as OpenTelemetry +// log records. It line-buffers process output so each emitted OTLP record can +// carry a native timestamp instead of encoding timestamps into the log body. +type OTLPJobLogger struct { + ctx context.Context + log otellog.Logger + provider *sdklog.LoggerProvider + attrs []otellog.KeyValue + + mu sync.Mutex + buf []byte + currentPhase string + currentHook string + currentHookScope string + currentHookPlugin string +} + +func NewOTLPJobLogger(ctx context.Context, conf JobRunnerConfig) (*OTLPJobLogger, error) { + protocol := os.Getenv("OTEL_EXPORTER_OTLP_LOGS_PROTOCOL") + if protocol == "" { + protocol = os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL") + } + if protocol == "" { + protocol = "grpc" + } + + var exporter sdklog.Exporter + var err error + switch protocol { + case "grpc": + exporter, err = otlploggrpc.New(ctx) + case "http/protobuf", "http": + exporter, err = otlploghttp.New(ctx) + default: + return nil, fmt.Errorf("unsupported OTLP logs protocol: %s", protocol) + } + if err != nil { + return nil, fmt.Errorf("creating OTLP log exporter: %w", err) + } + + serviceName := conf.AgentConfiguration.TracingServiceName + if serviceName == "" { + serviceName = "buildkite-agent" + } + resources := resource.NewWithAttributes(semconv.SchemaURL, + semconv.ServiceNameKey.String(serviceName), + semconv.ServiceVersionKey.String(version.Version()), + semconv.DeploymentEnvironmentKey.String("ci"), + ) + provider := sdklog.NewLoggerProvider( + sdklog.WithProcessor(sdklog.NewBatchProcessor(exporter)), + sdklog.WithResource(resources), + ) + log := provider.Logger( + "buildkite-agent", + otellog.WithInstrumentationVersion(version.Version()), + otellog.WithSchemaURL(semconv.SchemaURL), + ) + + return newOTLPJobLoggerWithLogger(contextWithJobTraceparent(ctx, conf.Job.TraceParent, conf.Job.TraceState), log, provider, otlpJobLogAttributes(conf)), nil +} + +func newOTLPJobLoggerWithLogger(ctx context.Context, log otellog.Logger, provider *sdklog.LoggerProvider, attrs []otellog.KeyValue) *OTLPJobLogger { + return &OTLPJobLogger{ + ctx: ctx, + log: log, + provider: provider, + attrs: attrs, + } +} + +func (l *OTLPJobLogger) Write(data []byte) (int, error) { + l.mu.Lock() + defer l.mu.Unlock() + + origLen := len(data) + for len(data) > 0 { + i := bytes.IndexByte(data, '\n') + if i < 0 { + l.buf = append(l.buf, data...) + return origLen, nil + } + + line := append(l.buf, data[:i]...) + line = bytes.TrimSuffix(line, []byte{'\r'}) + l.emit(string(line)) + l.buf = l.buf[:0] + data = data[i+1:] + } + + return origLen, nil +} + +func (l *OTLPJobLogger) Close(context.Context) error { + l.mu.Lock() + if len(l.buf) > 0 { + l.emit(string(l.buf)) + l.buf = l.buf[:0] + } + l.mu.Unlock() + + if l.provider == nil { + return nil + } + + flushCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + flushErr := l.provider.ForceFlush(flushCtx) + shutdownErr := l.provider.Shutdown(flushCtx) + if flushErr != nil { + return flushErr + } + return shutdownErr +} + +func (l *OTLPJobLogger) emit(line string) { + l.updateScope(line) + + now := time.Now() + attrs := append([]otellog.KeyValue{}, l.attrs...) + if l.currentPhase != "" { + attrs = append(attrs, otellog.String("buildkite.phase", l.currentPhase)) + } + if l.currentHook != "" { + attrs = append(attrs, + otellog.String("buildkite.hook.name", l.currentHook), + otellog.String("buildkite.hook.scope", l.currentHookScope), + ) + if l.currentHookPlugin != "" { + attrs = append(attrs, otellog.String("buildkite.hook.plugin", l.currentHookPlugin)) + } + } + + var record otellog.Record + record.SetTimestamp(now) + record.SetObservedTimestamp(now) + record.SetSeverity(otellog.SeverityInfo) + record.SetSeverityText("INFO") + record.SetBody(otellog.StringValue(line)) + record.AddAttributes(attrs...) + l.log.Emit(l.ctx, record) +} + +func (l *OTLPJobLogger) updateScope(line string) { + if strings.Contains(line, "Running commands") || strings.Contains(line, "Running script") { + l.currentPhase = "command" + l.currentHook = "" + l.currentHookScope = "" + l.currentHookPlugin = "" + return + } + + i := strings.Index(line, "Running ") + if i < 0 { + return + } + rest := strings.TrimSpace(line[i+len("Running "):]) + rest = strings.TrimSuffix(rest, "\r") + rest = strings.TrimSuffix(rest, " hook") + fields := strings.Fields(rest) + if len(fields) < 2 || !isKnownHook(fields[len(fields)-1]) { + return + } + + l.currentPhase = "hook" + l.currentHookScope = fields[0] + l.currentHook = fields[len(fields)-1] + l.currentHookPlugin = strings.Join(fields[1:len(fields)-1], " ") +} + +func isKnownHook(name string) bool { + switch name { + case "environment", "pre-checkout", "post-checkout", "pre-command", "command", "post-command", "pre-artifact", "post-artifact", "pre-exit": + return true + default: + return false + } +} + +func contextWithJobTraceparent(ctx context.Context, traceparent, tracestate string) context.Context { + if traceparent == "" { + return ctx + } + carrier := propagation.MapCarrier{"traceparent": traceparent} + if tracestate != "" { + carrier["tracestate"] = tracestate + } + return propagation.TraceContext{}.Extract(ctx, carrier) +} + +func otlpJobLogAttributes(conf JobRunnerConfig) []otellog.KeyValue { + job := conf.Job + env := job.Env + attrs := []otellog.KeyValue{ + otellog.String("source", "job"), + otellog.String("buildkite.organization.slug", env["BUILDKITE_ORGANIZATION_SLUG"]), + otellog.String("buildkite.pipeline.slug", env["BUILDKITE_PIPELINE_SLUG"]), + otellog.String("buildkite.branch", env["BUILDKITE_BRANCH"]), + otellog.String("buildkite.queue", env["BUILDKITE_AGENT_META_DATA_QUEUE"]), + otellog.String("buildkite.agent", env["BUILDKITE_AGENT_NAME"]), + otellog.String("buildkite.agent.id", env["BUILDKITE_AGENT_ID"]), + otellog.String("buildkite.build.id", env["BUILDKITE_BUILD_ID"]), + otellog.String("buildkite.build.number", env["BUILDKITE_BUILD_NUMBER"]), + otellog.String("buildkite.job.id", job.ID), + otellog.String("buildkite.job.label", env["BUILDKITE_LABEL"]), + otellog.String("buildkite.job.key", env["BUILDKITE_STEP_KEY"]), + } + + return attrs +} diff --git a/agent/otlp_job_logger_test.go b/agent/otlp_job_logger_test.go new file mode 100644 index 0000000000..12d028a77c --- /dev/null +++ b/agent/otlp_job_logger_test.go @@ -0,0 +1,241 @@ +package agent + +import ( + "context" + "sync" + "testing" + "time" + + "github.com/buildkite/agent/v3/api" + "go.opentelemetry.io/otel/log" + sdklog "go.opentelemetry.io/otel/sdk/log" +) + +type otlpJobLogTestExporter struct { + mu sync.Mutex + records []sdklog.Record +} + +func (e *otlpJobLogTestExporter) Export(_ context.Context, records []sdklog.Record) error { + e.mu.Lock() + defer e.mu.Unlock() + for _, record := range records { + e.records = append(e.records, record.Clone()) + } + return nil +} + +func (e *otlpJobLogTestExporter) Shutdown(context.Context) error { + return nil +} + +func (e *otlpJobLogTestExporter) ForceFlush(context.Context) error { + return nil +} + +func (e *otlpJobLogTestExporter) Records() []sdklog.Record { + e.mu.Lock() + defer e.mu.Unlock() + records := make([]sdklog.Record, len(e.records)) + copy(records, e.records) + return records +} + +func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + conf := JobRunnerConfig{ + Job: &api.Job{ + ID: "job-123", + Env: map[string]string{ + "BUILDKITE_ORGANIZATION_SLUG": "my-org", + "BUILDKITE_PIPELINE_SLUG": "my-pipeline", + "BUILDKITE_BRANCH": "main", + "BUILDKITE_AGENT_META_DATA_QUEUE": "default", + "BUILDKITE_AGENT_NAME": "agent-1", + "BUILDKITE_AGENT_ID": "agent-id-1", + "BUILDKITE_BUILD_ID": "build-456", + "BUILDKITE_BUILD_NUMBER": "42", + "BUILDKITE_BUILD_URL": "https://buildkite.com/my-org/my-pipeline/builds/42", + "BUILDKITE_LABEL": "Test", + "BUILDKITE_STEP_KEY": "test", + }, + TraceParent: "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", + }, + } + logger := newOTLPJobLoggerWithLogger( + contextWithJobTraceparent(context.Background(), conf.Job.TraceParent, conf.Job.TraceState), + provider.Logger("test"), + provider, + otlpJobLogAttributes(conf), + ) + + if _, err := logger.Write([]byte("first line\nsecond line\n")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + + records := exporter.Records() + if got, want := len(records), 2; got != want { + t.Fatalf("record count = %d, want %d", got, want) + } + if got, want := records[0].Body().AsString(), "first line"; got != want { + t.Errorf("record body = %q, want %q", got, want) + } + if records[0].Timestamp().IsZero() { + t.Errorf("record timestamp is zero") + } + if records[0].ObservedTimestamp().IsZero() { + t.Errorf("record observed timestamp is zero") + } + if got, want := records[0].Severity(), log.SeverityInfo; got != want { + t.Errorf("record severity = %v, want %v", got, want) + } + if got, want := records[0].TraceID().String(), "abcdef1234567890abcdef1234567890"; got != want { + t.Errorf("record trace ID = %q, want %q", got, want) + } + if got, want := records[0].SpanID().String(), "1234567890abcdef"; got != want { + t.Errorf("record span ID = %q, want %q", got, want) + } + + attrs := recordAttributes(records[0]) + for key, want := range map[string]string{ + "source": "job", + "buildkite.organization.slug": "my-org", + "buildkite.pipeline.slug": "my-pipeline", + "buildkite.branch": "main", + "buildkite.queue": "default", + "buildkite.agent": "agent-1", + "buildkite.agent.id": "agent-id-1", + "buildkite.build.id": "build-456", + "buildkite.build.number": "42", + "buildkite.job.id": "job-123", + "buildkite.job.label": "Test", + "buildkite.job.key": "test", + } { + if got := attrs[key]; got != want { + t.Errorf("attribute %s = %q, want %q", key, got, want) + } + } + for _, key := range []string{"buildkite.build.url", "buildkite.job.url", "trace_id", "span_id"} { + if got := attrs[key]; got != "" { + t.Errorf("attribute %s = %q, want empty", key, got) + } + } +} + +func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + + if _, err := logger.Write([]byte("partial")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + if got := len(exporter.Records()); got != 0 { + t.Fatalf("record count before close = %d, want 0", got) + } + if err := logger.Close(context.Background()); err != nil { + t.Fatalf("logger.Close() = %v", err) + } + records := exporter.Records() + if got, want := len(records), 1; got != want { + t.Fatalf("record count after close = %d, want %d", got, want) + } + if got, want := records[0].Body().AsString(), "partial"; got != want { + t.Errorf("record body = %q, want %q", got, want) + } +} + +func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + + before := time.Now() + if _, err := logger.Write([]byte("hello from the command\n")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + records := exporter.Records() + if got, want := records[0].Body().AsString(), "hello from the command"; got != want { + t.Errorf("record body = %q, want %q", got, want) + } + if records[0].Timestamp().Before(before) { + t.Errorf("record timestamp = %v, want after %v", records[0].Timestamp(), before) + } +} + +func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + + if _, err := logger.Write([]byte("~~~ Running repository post-command hook\nhook output\n~~~ Running commands\ncommand output\n")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + + records := exporter.Records() + if got, want := len(records), 4; got != want { + t.Fatalf("record count = %d, want %d", got, want) + } + + hookAttrs := recordAttributes(records[1]) + for key, want := range map[string]string{ + "buildkite.phase": "hook", + "buildkite.hook.name": "post-command", + "buildkite.hook.scope": "repository", + } { + if got := hookAttrs[key]; got != want { + t.Errorf("hook output attribute %s = %q, want %q", key, got, want) + } + } + + commandAttrs := recordAttributes(records[3]) + if got, want := commandAttrs["buildkite.phase"], "command"; got != want { + t.Errorf("command output buildkite.phase = %q, want %q", got, want) + } + if got := commandAttrs["buildkite.hook.name"]; got != "" { + t.Errorf("command output buildkite.hook.name = %q, want empty", got) + } +} + +func TestOTLPJobLoggerAddsPluginHookScopeFromHeaders(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + + if _, err := logger.Write([]byte("~~~ Running plugin docker#v5.12.0 pre-command hook\nplugin output\n")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + + records := exporter.Records() + attrs := recordAttributes(records[1]) + for key, want := range map[string]string{ + "buildkite.phase": "hook", + "buildkite.hook.name": "pre-command", + "buildkite.hook.scope": "plugin", + "buildkite.hook.plugin": "docker#v5.12.0", + } { + if got := attrs[key]; got != want { + t.Errorf("plugin hook output attribute %s = %q, want %q", key, got, want) + } + } +} + +func recordAttributes(record sdklog.Record) map[string]string { + attrs := map[string]string{} + record.WalkAttributes(func(kv log.KeyValue) bool { + attrs[kv.Key] = kv.Value.AsString() + return true + }) + return attrs +} diff --git a/agent/run_job.go b/agent/run_job.go index 5df596409d..c76e657aa4 100644 --- a/agent/run_job.go +++ b/agent/run_job.go @@ -420,6 +420,12 @@ func (r *JobRunner) cleanup(ctx context.Context, wg *sync.WaitGroup, exit core.P r.agentLogger.Debugf("[JobRunner] Waiting for all other routines to finish") wg.Wait() + if r.jobLogsOTLP != nil { + if err := r.jobLogsOTLP.Close(ctx); err != nil { + r.agentLogger.Warnf("Failed to flush OTLP job logs: %v", err) + } + } + // Remove the env file, if any for _, f := range []*os.File{r.envShellFile, r.envJSONFile} { if f == nil { diff --git a/clicommand/agent_start.go b/clicommand/agent_start.go index a040434911..d32837cef6 100644 --- a/clicommand/agent_start.go +++ b/clicommand/agent_start.go @@ -127,6 +127,7 @@ type AgentStartConfig struct { LogFormat string `cli:"log-format"` WriteJobLogsToStdout bool `cli:"write-job-logs-to-stdout"` + JobLogsOTLP bool `cli:"job-logs-otlp"` DisableWarningsFor []string `cli:"disable-warnings-for" normalize:"list"` BuildPath string `cli:"build-path" normalize:"filepath" validate:"required"` @@ -439,6 +440,11 @@ var AgentStartCommand = cli.Command{ Usage: "Writes job logs to the agent process' stdout. This simplifies log collection if running agents in Docker (default: false)", EnvVar: "BUILDKITE_WRITE_JOB_LOGS_TO_STDOUT", }, + cli.BoolFlag{ + Name: "job-logs-otlp", + Usage: "Export job logs directly to an OTLP logs endpoint using OpenTelemetry log records (default: false)", + EnvVar: "BUILDKITE_JOB_LOGS_OTLP", + }, cli.StringFlag{ Name: "shell", Value: DefaultShell(), @@ -1109,6 +1115,7 @@ var AgentStartCommand = cli.Command{ EnableJobLogTmpfile: cfg.EnableJobLogTmpfile, JobLogPath: cfg.JobLogPath, WriteJobLogsToStdout: cfg.WriteJobLogsToStdout, + JobLogsOTLP: cfg.JobLogsOTLP, LogFormat: cfg.LogFormat, Shell: cfg.Shell, HooksShell: cfg.HooksShell, diff --git a/go.mod b/go.mod index ead6ec30f6..ab746a57c0 100644 --- a/go.mod +++ b/go.mod @@ -57,9 +57,13 @@ require ( go.opentelemetry.io/contrib/propagators/jaeger v1.44.0 go.opentelemetry.io/contrib/propagators/ot v1.44.0 go.opentelemetry.io/otel v1.44.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.20.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.44.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0 + go.opentelemetry.io/otel/log v0.20.0 go.opentelemetry.io/otel/sdk v1.44.0 + go.opentelemetry.io/otel/sdk/log v0.20.0 go.opentelemetry.io/otel/trace v1.44.0 golang.org/x/crypto v0.53.0 golang.org/x/net v0.56.0 diff --git a/go.sum b/go.sum index 6a6d90d4fc..d4d1b39171 100644 --- a/go.sum +++ b/go.sum @@ -477,16 +477,26 @@ go.opentelemetry.io/contrib/propagators/ot v1.44.0 h1:JLTPenzmPtLp5ODPntAA5JhxVu go.opentelemetry.io/contrib/propagators/ot v1.44.0/go.mod h1:8zr0bHgwkoQXucBK39/H4QphmLf1lSen1Z7FPDZD5Uc= go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0 h1:rydZ9sxbcFdm/oWrVyfLTjHIygMgv0bEeMd+3B/BvoM= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0/go.mod h1:earQ25dooT0Hhspq59DZ8YCC50jWfOlFEeWoxy/P444= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.20.0 h1:owlhcJ3QO3X0YTDTCcDZ4V+6aVDkWbNmBoQ5NUp7Oww= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.20.0/go.mod h1:MP4eemTiI9zC8fgg+DYynhYDYf3ba72S376TvP+Ye0Q= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0 h1:4YsVu3B8+3qtWYYrsUYgn0OG78pN0rnNPRGX4SbokQI= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0/go.mod h1:+wnlSn0mD1ADVMe3v9Z/WIaiz6q6gL2J/ejaAmdmv80= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.44.0 h1:qazEJlUOQzhCpzQpFETGby7EdqjI1wsd0W+6Gg1SCTU= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.44.0/go.mod h1:fOD2Yefuxixkx3ahVNf0O/PERb6r4OlbxfATVnYvzCo= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0 h1:lgh3PiVrRUWMLOVSkQicxzZll5NjF1r+AtsX1XRIHw0= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0/go.mod h1:5Cnhth3m/AgOeTgE3ex12pPmiu/gGtZit03kSzx9X7s= +go.opentelemetry.io/otel/log v0.20.0 h1:/5i0vuHxCLWUfChWG41K9wkM0jafruPw9NU1/RCJirs= +go.opentelemetry.io/otel/log v0.20.0/go.mod h1:wOcMcjsZpG8x7Bak7IhSi/lg8wscV2C1VdrKCLPlt0E= go.opentelemetry.io/otel/metric v1.44.0 h1:1w0gILTcHdr3YI+ixLyjemwrVnsMURbTZFrSYCdDdmc= go.opentelemetry.io/otel/metric v1.44.0/go.mod h1:8O7hanEPBNgEMmybD3s2VBKcgWOCsA6tzHBPODAiquo= go.opentelemetry.io/otel/sdk v1.44.0 h1:nHYwb9lK+fJPU/dnT6s7W7Z8itMWyqrnVfbheVYrZ58= go.opentelemetry.io/otel/sdk v1.44.0/go.mod h1:Osuydd3Se74nqjAKxid74N5eC+jfEqfTegHRnq58oK0= +go.opentelemetry.io/otel/sdk/log v0.20.0 h1:vM3xI7TQgKPiSghe6urZtAkyFY7SodrSpC83CffDFuY= +go.opentelemetry.io/otel/sdk/log v0.20.0/go.mod h1:Knej2nmsTUzN79T2eeXdRsjjPcoxoq2pUyUHz9TFyyU= +go.opentelemetry.io/otel/sdk/log/logtest v0.20.0 h1:OqdRZ1guyzamK3M6LlRsmGqRrjkHWw6WZOKKli5ELpg= +go.opentelemetry.io/otel/sdk/log/logtest v0.20.0/go.mod h1:PuMIlm7zAt7c3z8zfOI5ox4iT1Z87We+PF6YoINux/M= go.opentelemetry.io/otel/sdk/metric v1.44.0 h1:3LlKgI+VjbVsjNRFZJZAJ30WjXC5VkNRks6si09iEfI= go.opentelemetry.io/otel/sdk/metric v1.44.0/go.mod h1:5B5pMARnXxKhltooO4xUuCBorl65a4EpnTalObqOigA= go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= From acc6ea386258dd6107deb3262c6ee7aa0b57eeb2 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Mon, 1 Jun 2026 14:14:52 +1000 Subject: [PATCH 02/13] Add OTLP job log trace fields --- agent/job_runner.go | 32 ++++++--- agent/otlp_job_logger.go | 58 ++++++++++++--- agent/otlp_job_logger_test.go | 131 +++++++++++++++++++++++++++++++++- agent/run_job.go | 2 +- clicommand/agent_start.go | 2 +- 5 files changed, 204 insertions(+), 21 deletions(-) diff --git a/agent/job_runner.go b/agent/job_runner.go index a6532b928f..c6dcd9f8d3 100644 --- a/agent/job_runner.go +++ b/agent/job_runner.go @@ -160,7 +160,7 @@ type jobProcess interface { } // Initializes the job runner -func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, conf JobRunnerConfig) (*JobRunner, error) { +func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, conf JobRunnerConfig) (_ *JobRunner, err error) { // If the accept response has a token attached, we should use that instead of the Agent Access Token that // our current apiClient is using if conf.Job.Token != "" { @@ -176,7 +176,15 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c client: &core.Client{APIClient: apiClient, Logger: l}, } - var err error + defer func() { + if err != nil && r.jobLogsOTLP != nil { + if closeErr := r.jobLogsOTLP.Close(); closeErr != nil { + r.agentLogger.Warnf("Failed to close OTLP job log exporter after job runner initialization error: %v", closeErr) + } + r.jobLogsOTLP = nil + } + }() + r.VerificationFailureBehavior, err = r.normalizeVerificationBehavior(conf.AgentConfiguration.VerificationFailureBehaviour) if err != nil { return nil, fmt.Errorf("setting no signature behavior: %w", err) @@ -226,6 +234,16 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c // BUILDKITE_AGENT_JOB_TIMEOUT_FILE env var. r.jobTimeoutFilePath = jobTimeoutFilePath(r.conf.Job.ID, conf.KubernetesExec) + var jobLogsOTLP *OTLPJobLogger + if conf.AgentConfiguration.JobLogsOTLP { + jobLogsOTLP, err = NewOTLPJobLogger(ctx, conf) + if err != nil { + r.agentLogger.Warnf("Failed to initialize OTLP job log exporter: %v", err) + } else { + r.jobLogsOTLP = jobLogsOTLP + } + } + env, err := r.createEnvironment(ctx) if err != nil { return nil, err @@ -265,14 +283,8 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c } pr, pw := io.Pipe() - if conf.AgentConfiguration.JobLogsOTLP { - jobLogsOTLP, err := NewOTLPJobLogger(ctx, conf) - if err != nil { - r.agentLogger.Warnf("Failed to initialize OTLP job log exporter: %v", err) - } else { - r.jobLogsOTLP = jobLogsOTLP - allWriters = append(allWriters, jobLogsOTLP) - } + if jobLogsOTLP != nil { + allWriters = append(allWriters, jobLogsOTLP) } switch { diff --git a/agent/otlp_job_logger.go b/agent/otlp_job_logger.go index ab6fe1c7b3..aef6f2b8d1 100644 --- a/agent/otlp_job_logger.go +++ b/agent/otlp_job_logger.go @@ -9,7 +9,10 @@ import ( "sync" "time" + "github.com/buildkite/agent/v3/tracetools" "github.com/buildkite/agent/v3/version" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" otellog "go.opentelemetry.io/otel/log" @@ -17,6 +20,7 @@ import ( sdklog "go.opentelemetry.io/otel/sdk/log" "go.opentelemetry.io/otel/sdk/resource" semconv "go.opentelemetry.io/otel/semconv/v1.4.0" + "go.opentelemetry.io/otel/trace" ) // OTLPJobLogger satisfies io.WriteCloser and emits job output as OpenTelemetry @@ -26,6 +30,7 @@ type OTLPJobLogger struct { ctx context.Context log otellog.Logger provider *sdklog.LoggerProvider + span trace.Span attrs []otellog.KeyValue mu sync.Mutex @@ -78,10 +83,14 @@ func NewOTLPJobLogger(ctx context.Context, conf JobRunnerConfig) (*OTLPJobLogger otellog.WithSchemaURL(semconv.SchemaURL), ) - return newOTLPJobLoggerWithLogger(contextWithJobTraceparent(ctx, conf.Job.TraceParent, conf.Job.TraceState), log, provider, otlpJobLogAttributes(conf)), nil + logCtx, span := otlpJobLogContext(ctx, conf) + logger := newOTLPJobLoggerWithLogger(logCtx, log, provider, otlpJobLogAttributes(conf)) + logger.span = span + return logger, nil } func newOTLPJobLoggerWithLogger(ctx context.Context, log otellog.Logger, provider *sdklog.LoggerProvider, attrs []otellog.KeyValue) *OTLPJobLogger { + ctx = context.WithoutCancel(ctx) return &OTLPJobLogger{ ctx: ctx, log: log, @@ -112,7 +121,7 @@ func (l *OTLPJobLogger) Write(data []byte) (int, error) { return origLen, nil } -func (l *OTLPJobLogger) Close(context.Context) error { +func (l *OTLPJobLogger) Close() error { l.mu.Lock() if len(l.buf) > 0 { l.emit(string(l.buf)) @@ -120,6 +129,10 @@ func (l *OTLPJobLogger) Close(context.Context) error { } l.mu.Unlock() + if l.span != nil { + l.span.End() + } + if l.provider == nil { return nil } @@ -163,7 +176,18 @@ func (l *OTLPJobLogger) emit(line string) { } func (l *OTLPJobLogger) updateScope(line string) { - if strings.Contains(line, "Running commands") || strings.Contains(line, "Running script") { + header := ansiColourRE.ReplaceAllString(line, "") + if !headerRE.MatchString(header) { + return + } + + parts := strings.Fields(header) + if len(parts) < 2 { + return + } + rest := strings.TrimSpace(strings.TrimPrefix(header, parts[0])) + + if strings.Contains(rest, "Running commands") || strings.Contains(rest, "Running script") { l.currentPhase = "command" l.currentHook = "" l.currentHookScope = "" @@ -171,14 +195,14 @@ func (l *OTLPJobLogger) updateScope(line string) { return } - i := strings.Index(line, "Running ") + i := strings.Index(rest, "Running ") if i < 0 { return } - rest := strings.TrimSpace(line[i+len("Running "):]) - rest = strings.TrimSuffix(rest, "\r") - rest = strings.TrimSuffix(rest, " hook") - fields := strings.Fields(rest) + hook := strings.TrimSpace(rest[i+len("Running "):]) + hook = strings.TrimSuffix(hook, "\r") + hook = strings.TrimSuffix(hook, " hook") + fields := strings.Fields(hook) if len(fields) < 2 || !isKnownHook(fields[len(fields)-1]) { return } @@ -209,6 +233,24 @@ func contextWithJobTraceparent(ctx context.Context, traceparent, tracestate stri return propagation.TraceContext{}.Extract(ctx, carrier) } +func otlpJobLogContext(ctx context.Context, conf JobRunnerConfig) (context.Context, trace.Span) { + if conf.AgentConfiguration.TracingBackend != tracetools.BackendOpenTelemetry || !conf.AgentConfiguration.TracingPropagateTraceparent { + return ctx, nil + } + ctx = contextWithJobTraceparent(ctx, conf.Job.TraceParent, conf.Job.TraceState) + if trace.SpanContextFromContext(ctx).IsValid() { + return ctx, nil + } + + ctx, span := otel.Tracer( + "buildkite-agent", + trace.WithInstrumentationVersion(version.Version()), + trace.WithSchemaURL(semconv.SchemaURL), + ).Start(ctx, "job.logs", trace.WithAttributes(attribute.String("buildkite.job.id", conf.Job.ID))) + + return ctx, span +} + func otlpJobLogAttributes(conf JobRunnerConfig) []otellog.KeyValue { job := conf.Job env := job.Env diff --git a/agent/otlp_job_logger_test.go b/agent/otlp_job_logger_test.go index 12d028a77c..fa94d2e32c 100644 --- a/agent/otlp_job_logger_test.go +++ b/agent/otlp_job_logger_test.go @@ -7,8 +7,12 @@ import ( "time" "github.com/buildkite/agent/v3/api" + "github.com/buildkite/agent/v3/tracetools" + "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/log" sdklog "go.opentelemetry.io/otel/sdk/log" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + oteltrace "go.opentelemetry.io/otel/trace" ) type otlpJobLogTestExporter struct { @@ -125,6 +129,52 @@ func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { } } +func TestOTLPJobLogContextCreatesTraceparentForBootstrapWhenServerDoesNotProvideOne(t *testing.T) { + oldTracerProvider := otel.GetTracerProvider() + tracerProvider := sdktrace.NewTracerProvider() + otel.SetTracerProvider(tracerProvider) + t.Cleanup(func() { + otel.SetTracerProvider(oldTracerProvider) + _ = tracerProvider.Shutdown(context.Background()) + }) + + conf := JobRunnerConfig{ + AgentConfiguration: AgentConfiguration{ + TracingBackend: tracetools.BackendOpenTelemetry, + TracingPropagateTraceparent: true, + }, + Job: &api.Job{ + ID: "job-123", + Env: map[string]string{}, + }, + } + + ctx, span := otlpJobLogContext(context.Background(), conf) + if span == nil { + t.Fatalf("otlpJobLogContext() span = nil, want fallback span") + } + t.Cleanup(func() { span.End() }) + + sc := oteltrace.SpanContextFromContext(ctx) + if !sc.IsValid() { + t.Fatalf("SpanContextFromContext(ctx).IsValid() = false, want true") + } + if got := conf.Job.TraceParent; got != "" { + t.Errorf("conf.Job.TraceParent = %q, want empty", got) + } + if got := conf.Job.TraceState; got != "" { + t.Errorf("conf.Job.TraceState = %q, want empty", got) + } + + logger := newOTLPJobLoggerWithLogger(ctx, nil, nil, otlpJobLogAttributes(conf)) + attrs := keyValues(logger.attrs) + for _, key := range []string{"trace_id", "span_id"} { + if got := attrs[key]; got != "" { + t.Errorf("attribute %s = %q, want empty", key, got) + } + } +} + func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { t.Parallel() @@ -138,7 +188,7 @@ func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { if got := len(exporter.Records()); got != 0 { t.Fatalf("record count before close = %d, want 0", got) } - if err := logger.Close(context.Background()); err != nil { + if err := logger.Close(); err != nil { t.Fatalf("logger.Close() = %v", err) } records := exporter.Records() @@ -150,6 +200,29 @@ func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { } } +func TestOTLPJobLoggerDetachesEmitContextFromCancellation(t *testing.T) { + t.Parallel() + + ctx := contextWithJobTraceparent( + context.Background(), + "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", + "", + ) + ctx, cancel := context.WithCancel(ctx) + cancel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(ctx, provider.Logger("test"), provider, nil) + + if err := logger.ctx.Err(); err != nil { + t.Fatalf("logger ctx error = %v, want nil", err) + } + if got, want := oteltrace.SpanContextFromContext(logger.ctx).TraceID().String(), "abcdef1234567890abcdef1234567890"; got != want { + t.Fatalf("logger ctx trace ID = %q, want %q", got, want) + } +} + func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { t.Parallel() @@ -170,6 +243,29 @@ func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { } } +func TestOTLPJobLogContextDoesNotAcceptTraceparentWithoutPropagateOptIn(t *testing.T) { + t.Parallel() + + conf := JobRunnerConfig{ + AgentConfiguration: AgentConfiguration{ + TracingBackend: tracetools.BackendOpenTelemetry, + }, + Job: &api.Job{ + ID: "job-123", + Env: map[string]string{}, + TraceParent: "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", + }, + } + + ctx, span := otlpJobLogContext(context.Background(), conf) + if span != nil { + t.Fatalf("otlpJobLogContext() span = %v, want nil", span) + } + if sc := oteltrace.SpanContextFromContext(ctx); sc.IsValid() { + t.Fatalf("SpanContextFromContext(ctx).IsValid() = true, want false") + } +} + func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { t.Parallel() @@ -231,6 +327,31 @@ func TestOTLPJobLoggerAddsPluginHookScopeFromHeaders(t *testing.T) { } } +func TestOTLPJobLoggerDoesNotUpdateScopeFromOrdinaryOutput(t *testing.T) { + t.Parallel() + + exporter := &otlpJobLogTestExporter{} + provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) + logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + + if _, err := logger.Write([]byte("Running plugin docker#v5.12.0 pre-command hook\nordinary output\n")); err != nil { + t.Fatalf("logger.Write() = %v", err) + } + + records := exporter.Records() + if got, want := len(records), 2; got != want { + t.Fatalf("record count = %d, want %d", got, want) + } + for i, record := range records { + attrs := recordAttributes(record) + for _, key := range []string{"buildkite.phase", "buildkite.hook.name", "buildkite.hook.scope", "buildkite.hook.plugin"} { + if got := attrs[key]; got != "" { + t.Errorf("record %d attribute %s = %q, want empty", i, key, got) + } + } + } +} + func recordAttributes(record sdklog.Record) map[string]string { attrs := map[string]string{} record.WalkAttributes(func(kv log.KeyValue) bool { @@ -239,3 +360,11 @@ func recordAttributes(record sdklog.Record) map[string]string { }) return attrs } + +func keyValues(kvs []log.KeyValue) map[string]string { + attrs := map[string]string{} + for _, kv := range kvs { + attrs[kv.Key] = kv.Value.AsString() + } + return attrs +} diff --git a/agent/run_job.go b/agent/run_job.go index c76e657aa4..c90bb1aa1c 100644 --- a/agent/run_job.go +++ b/agent/run_job.go @@ -421,7 +421,7 @@ func (r *JobRunner) cleanup(ctx context.Context, wg *sync.WaitGroup, exit core.P wg.Wait() if r.jobLogsOTLP != nil { - if err := r.jobLogsOTLP.Close(ctx); err != nil { + if err := r.jobLogsOTLP.Close(); err != nil { r.agentLogger.Warnf("Failed to flush OTLP job logs: %v", err) } } diff --git a/clicommand/agent_start.go b/clicommand/agent_start.go index d32837cef6..3198ec9824 100644 --- a/clicommand/agent_start.go +++ b/clicommand/agent_start.go @@ -442,7 +442,7 @@ var AgentStartCommand = cli.Command{ }, cli.BoolFlag{ Name: "job-logs-otlp", - Usage: "Export job logs directly to an OTLP logs endpoint using OpenTelemetry log records (default: false)", + Usage: "Export job logs directly as OpenTelemetry log records using the OTEL_EXPORTER_OTLP_LOGS_* / OTEL_EXPORTER_OTLP_* environment configuration (default: false)", EnvVar: "BUILDKITE_JOB_LOGS_OTLP", }, cli.StringFlag{ From 2e528956c9bd71c61e3047f3bd67704d9a12d372 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sun, 7 Jun 2026 16:25:54 +1000 Subject: [PATCH 03/13] Correlate OTLP job logs without backend propagation --- agent/job_runner.go | 35 +++--- agent/otlp_job_logger.go | 48 +------- agent/otlp_job_logger_test.go | 109 ++---------------- clicommand/bootstrap.go | 8 +- internal/job/config.go | 9 +- internal/job/executor.go | 36 +++++- internal/job/executor_test.go | 42 +++++++ internal/job/otlp_job_logger.go | 189 ++++++++++++++++++++++++++++++++ internal/job/tracing.go | 7 +- internal/shell/shell.go | 44 +++++++- internal/shell/shell_test.go | 25 +++++ 11 files changed, 379 insertions(+), 173 deletions(-) create mode 100644 internal/job/otlp_job_logger.go diff --git a/agent/job_runner.go b/agent/job_runner.go index c6dcd9f8d3..f3f98f2d91 100644 --- a/agent/job_runner.go +++ b/agent/job_runner.go @@ -26,6 +26,7 @@ import ( "github.com/buildkite/agent/v3/logger" "github.com/buildkite/agent/v3/metrics" "github.com/buildkite/agent/v3/status" + "github.com/buildkite/agent/v3/tracetools" "github.com/buildkite/roko" "github.com/buildkite/shellwords" ) @@ -235,7 +236,7 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c r.jobTimeoutFilePath = jobTimeoutFilePath(r.conf.Job.ID, conf.KubernetesExec) var jobLogsOTLP *OTLPJobLogger - if conf.AgentConfiguration.JobLogsOTLP { + if conf.AgentConfiguration.JobLogsOTLP && conf.AgentConfiguration.TracingBackend != tracetools.BackendOpenTelemetry { jobLogsOTLP, err = NewOTLPJobLogger(ctx, conf) if err != nil { r.agentLogger.Warnf("Failed to initialize OTLP job log exporter: %v", err) @@ -733,25 +734,29 @@ BUILDKITE_AGENT_JWKS_KEY_ID` setEnv("BUILDKITE_TRACING_BACKEND", r.conf.AgentConfiguration.TracingBackend) setEnv("BUILDKITE_TRACING_SERVICE_NAME", r.conf.AgentConfiguration.TracingServiceName) - // Buildkite backend can provide a traceparent property on the job - // which can be propagated to the job tracing if OpenTelemetry is used - // - // https://www.w3.org/TR/trace-context/#traceparent-header - if r.conf.Job.TraceParent != "" { - setEnv("BUILDKITE_TRACING_TRACEPARENT", r.conf.Job.TraceParent) - } - // Buildkite backend may also provide a tracestate property on the job, - // which carries vendor-specific trace context alongside the traceparent. - // - // https://www.w3.org/TR/trace-context/#tracestate-header - if r.conf.Job.TraceState != "" { - setEnv("BUILDKITE_TRACING_TRACESTATE", r.conf.Job.TraceState) - } if r.conf.AgentConfiguration.TracingPropagateTraceparent { + // Buildkite backend can provide a traceparent property on the job + // which can be propagated to the job tracing if OpenTelemetry is used. + // + // https://www.w3.org/TR/trace-context/#traceparent-header + if r.conf.Job.TraceParent != "" { + setEnv("BUILDKITE_TRACING_TRACEPARENT", r.conf.Job.TraceParent) + } + // Buildkite backend may also provide a tracestate property on the job, + // which carries vendor-specific trace context alongside traceparent. + // + // https://www.w3.org/TR/trace-context/#tracestate-header + if r.conf.Job.TraceState != "" { + setEnv("BUILDKITE_TRACING_TRACESTATE", r.conf.Job.TraceState) + } setEnv("BUILDKITE_TRACING_PROPAGATE_TRACEPARENT", "true") } } + if r.conf.AgentConfiguration.JobLogsOTLP { + setEnv("BUILDKITE_JOB_LOGS_OTLP", "true") + } + setEnv("BUILDKITE_AGENT_DISABLE_WARNINGS_FOR", strings.Join(r.conf.AgentConfiguration.DisableWarningsFor, ",")) // see documentation for BuildkiteMessageMax diff --git a/agent/otlp_job_logger.go b/agent/otlp_job_logger.go index aef6f2b8d1..c2ecce7aa4 100644 --- a/agent/otlp_job_logger.go +++ b/agent/otlp_job_logger.go @@ -9,18 +9,13 @@ import ( "sync" "time" - "github.com/buildkite/agent/v3/tracetools" "github.com/buildkite/agent/v3/version" - "go.opentelemetry.io/otel" - "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" otellog "go.opentelemetry.io/otel/log" - "go.opentelemetry.io/otel/propagation" sdklog "go.opentelemetry.io/otel/sdk/log" "go.opentelemetry.io/otel/sdk/resource" semconv "go.opentelemetry.io/otel/semconv/v1.4.0" - "go.opentelemetry.io/otel/trace" ) // OTLPJobLogger satisfies io.WriteCloser and emits job output as OpenTelemetry @@ -30,7 +25,6 @@ type OTLPJobLogger struct { ctx context.Context log otellog.Logger provider *sdklog.LoggerProvider - span trace.Span attrs []otellog.KeyValue mu sync.Mutex @@ -83,10 +77,7 @@ func NewOTLPJobLogger(ctx context.Context, conf JobRunnerConfig) (*OTLPJobLogger otellog.WithSchemaURL(semconv.SchemaURL), ) - logCtx, span := otlpJobLogContext(ctx, conf) - logger := newOTLPJobLoggerWithLogger(logCtx, log, provider, otlpJobLogAttributes(conf)) - logger.span = span - return logger, nil + return newOTLPJobLoggerWithLogger(ctx, log, provider, otlpJobLogAttributes(conf)), nil } func newOTLPJobLoggerWithLogger(ctx context.Context, log otellog.Logger, provider *sdklog.LoggerProvider, attrs []otellog.KeyValue) *OTLPJobLogger { @@ -129,10 +120,6 @@ func (l *OTLPJobLogger) Close() error { } l.mu.Unlock() - if l.span != nil { - l.span.End() - } - if l.provider == nil { return nil } @@ -189,8 +176,8 @@ func (l *OTLPJobLogger) updateScope(line string) { if strings.Contains(rest, "Running commands") || strings.Contains(rest, "Running script") { l.currentPhase = "command" - l.currentHook = "" - l.currentHookScope = "" + l.currentHook = "command" + l.currentHookScope = "default" l.currentHookPlugin = "" return } @@ -222,35 +209,6 @@ func isKnownHook(name string) bool { } } -func contextWithJobTraceparent(ctx context.Context, traceparent, tracestate string) context.Context { - if traceparent == "" { - return ctx - } - carrier := propagation.MapCarrier{"traceparent": traceparent} - if tracestate != "" { - carrier["tracestate"] = tracestate - } - return propagation.TraceContext{}.Extract(ctx, carrier) -} - -func otlpJobLogContext(ctx context.Context, conf JobRunnerConfig) (context.Context, trace.Span) { - if conf.AgentConfiguration.TracingBackend != tracetools.BackendOpenTelemetry || !conf.AgentConfiguration.TracingPropagateTraceparent { - return ctx, nil - } - ctx = contextWithJobTraceparent(ctx, conf.Job.TraceParent, conf.Job.TraceState) - if trace.SpanContextFromContext(ctx).IsValid() { - return ctx, nil - } - - ctx, span := otel.Tracer( - "buildkite-agent", - trace.WithInstrumentationVersion(version.Version()), - trace.WithSchemaURL(semconv.SchemaURL), - ).Start(ctx, "job.logs", trace.WithAttributes(attribute.String("buildkite.job.id", conf.Job.ID))) - - return ctx, span -} - func otlpJobLogAttributes(conf JobRunnerConfig) []otellog.KeyValue { job := conf.Job env := job.Env diff --git a/agent/otlp_job_logger_test.go b/agent/otlp_job_logger_test.go index fa94d2e32c..053fb6dae4 100644 --- a/agent/otlp_job_logger_test.go +++ b/agent/otlp_job_logger_test.go @@ -7,12 +7,8 @@ import ( "time" "github.com/buildkite/agent/v3/api" - "github.com/buildkite/agent/v3/tracetools" - "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/log" sdklog "go.opentelemetry.io/otel/sdk/log" - sdktrace "go.opentelemetry.io/otel/sdk/trace" - oteltrace "go.opentelemetry.io/otel/trace" ) type otlpJobLogTestExporter struct { @@ -66,11 +62,10 @@ func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { "BUILDKITE_LABEL": "Test", "BUILDKITE_STEP_KEY": "test", }, - TraceParent: "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", }, } logger := newOTLPJobLoggerWithLogger( - contextWithJobTraceparent(context.Background(), conf.Job.TraceParent, conf.Job.TraceState), + context.Background(), provider.Logger("test"), provider, otlpJobLogAttributes(conf), @@ -96,11 +91,11 @@ func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { if got, want := records[0].Severity(), log.SeverityInfo; got != want { t.Errorf("record severity = %v, want %v", got, want) } - if got, want := records[0].TraceID().String(), "abcdef1234567890abcdef1234567890"; got != want { - t.Errorf("record trace ID = %q, want %q", got, want) + if records[0].TraceID().IsValid() { + t.Errorf("record trace ID = %q, want invalid", records[0].TraceID().String()) } - if got, want := records[0].SpanID().String(), "1234567890abcdef"; got != want { - t.Errorf("record span ID = %q, want %q", got, want) + if records[0].SpanID().IsValid() { + t.Errorf("record span ID = %q, want invalid", records[0].SpanID().String()) } attrs := recordAttributes(records[0]) @@ -129,52 +124,6 @@ func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { } } -func TestOTLPJobLogContextCreatesTraceparentForBootstrapWhenServerDoesNotProvideOne(t *testing.T) { - oldTracerProvider := otel.GetTracerProvider() - tracerProvider := sdktrace.NewTracerProvider() - otel.SetTracerProvider(tracerProvider) - t.Cleanup(func() { - otel.SetTracerProvider(oldTracerProvider) - _ = tracerProvider.Shutdown(context.Background()) - }) - - conf := JobRunnerConfig{ - AgentConfiguration: AgentConfiguration{ - TracingBackend: tracetools.BackendOpenTelemetry, - TracingPropagateTraceparent: true, - }, - Job: &api.Job{ - ID: "job-123", - Env: map[string]string{}, - }, - } - - ctx, span := otlpJobLogContext(context.Background(), conf) - if span == nil { - t.Fatalf("otlpJobLogContext() span = nil, want fallback span") - } - t.Cleanup(func() { span.End() }) - - sc := oteltrace.SpanContextFromContext(ctx) - if !sc.IsValid() { - t.Fatalf("SpanContextFromContext(ctx).IsValid() = false, want true") - } - if got := conf.Job.TraceParent; got != "" { - t.Errorf("conf.Job.TraceParent = %q, want empty", got) - } - if got := conf.Job.TraceState; got != "" { - t.Errorf("conf.Job.TraceState = %q, want empty", got) - } - - logger := newOTLPJobLoggerWithLogger(ctx, nil, nil, otlpJobLogAttributes(conf)) - attrs := keyValues(logger.attrs) - for _, key := range []string{"trace_id", "span_id"} { - if got := attrs[key]; got != "" { - t.Errorf("attribute %s = %q, want empty", key, got) - } - } -} - func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { t.Parallel() @@ -203,12 +152,7 @@ func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { func TestOTLPJobLoggerDetachesEmitContextFromCancellation(t *testing.T) { t.Parallel() - ctx := contextWithJobTraceparent( - context.Background(), - "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", - "", - ) - ctx, cancel := context.WithCancel(ctx) + ctx, cancel := context.WithCancel(context.Background()) cancel() exporter := &otlpJobLogTestExporter{} @@ -218,9 +162,6 @@ func TestOTLPJobLoggerDetachesEmitContextFromCancellation(t *testing.T) { if err := logger.ctx.Err(); err != nil { t.Fatalf("logger ctx error = %v, want nil", err) } - if got, want := oteltrace.SpanContextFromContext(logger.ctx).TraceID().String(), "abcdef1234567890abcdef1234567890"; got != want { - t.Fatalf("logger ctx trace ID = %q, want %q", got, want) - } } func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { @@ -243,29 +184,6 @@ func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { } } -func TestOTLPJobLogContextDoesNotAcceptTraceparentWithoutPropagateOptIn(t *testing.T) { - t.Parallel() - - conf := JobRunnerConfig{ - AgentConfiguration: AgentConfiguration{ - TracingBackend: tracetools.BackendOpenTelemetry, - }, - Job: &api.Job{ - ID: "job-123", - Env: map[string]string{}, - TraceParent: "00-abcdef1234567890abcdef1234567890-1234567890abcdef-01", - }, - } - - ctx, span := otlpJobLogContext(context.Background(), conf) - if span != nil { - t.Fatalf("otlpJobLogContext() span = %v, want nil", span) - } - if sc := oteltrace.SpanContextFromContext(ctx); sc.IsValid() { - t.Fatalf("SpanContextFromContext(ctx).IsValid() = true, want false") - } -} - func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { t.Parallel() @@ -297,8 +215,11 @@ func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { if got, want := commandAttrs["buildkite.phase"], "command"; got != want { t.Errorf("command output buildkite.phase = %q, want %q", got, want) } - if got := commandAttrs["buildkite.hook.name"]; got != "" { - t.Errorf("command output buildkite.hook.name = %q, want empty", got) + if got, want := commandAttrs["buildkite.hook.name"], "command"; got != want { + t.Errorf("command output buildkite.hook.name = %q, want %q", got, want) + } + if got, want := commandAttrs["buildkite.hook.scope"], "default"; got != want { + t.Errorf("command output buildkite.hook.scope = %q, want %q", got, want) } } @@ -360,11 +281,3 @@ func recordAttributes(record sdklog.Record) map[string]string { }) return attrs } - -func keyValues(kvs []log.KeyValue) map[string]string { - attrs := map[string]string{} - for _, kv := range kvs { - attrs[kv.Key] = kv.Value.AsString() - } - return attrs -} diff --git a/clicommand/bootstrap.go b/clicommand/bootstrap.go index e1c32ff30a..2bfdcdb7a7 100644 --- a/clicommand/bootstrap.go +++ b/clicommand/bootstrap.go @@ -117,6 +117,7 @@ type BootstrapConfig struct { TracingPropagateTraceparent bool `cli:"tracing-propagate-traceparent"` TraceContextEncoding string `cli:"trace-context-encoding"` NoJobAPI bool `cli:"no-job-api"` + JobLogsOTLP bool `cli:"job-logs-otlp"` DisableWarningsFor []string `cli:"disable-warnings-for" normalize:"list"` CheckoutAttempts int `cli:"checkout-attempts"` } @@ -367,12 +368,16 @@ var BootstrapCommand = cli.Command{ Usage: "Accept traceparent from Buildkite control plane (default: false)", EnvVar: "BUILDKITE_TRACING_PROPAGATE_TRACEPARENT", }, - cli.BoolFlag{ Name: "no-job-api", Usage: "Disables the Job API, which gives commands in jobs some abilities to introspect and mutate the state of the job (default: false)", EnvVar: "BUILDKITE_AGENT_NO_JOB_API", }, + cli.BoolFlag{ + Name: "job-logs-otlp", + EnvVar: "BUILDKITE_JOB_LOGS_OTLP", + Hidden: true, + }, cli.StringSliceFlag{ Name: "disable-warnings-for", Usage: "A list of warning IDs to disable", @@ -508,6 +513,7 @@ var BootstrapCommand = cli.Command{ TracingTraceState: cfg.TracingTraceState, TracingPropagateTraceparent: cfg.TracingPropagateTraceparent, JobAPI: !cfg.NoJobAPI, + JobLogsOTLP: cfg.JobLogsOTLP, DisabledWarnings: cfg.DisableWarningsFor, Secrets: cfg.Secrets, CheckoutAttempts: cfg.CheckoutAttempts, diff --git a/internal/job/config.go b/internal/job/config.go index 3e88c572d0..68b3ee1dda 100644 --- a/internal/job/config.go +++ b/internal/job/config.go @@ -206,9 +206,9 @@ type ExecutorConfig struct { TracingTraceParent string // W3C tracestate accompanying TracingTraceParent. Plumbed through to the - // bootstrap environment whenever the server provides a value, but only - // attached to the OTel span context when TracingPropagateTraceparent is - // enabled (same opt-in gate as TracingTraceParent). + // bootstrap environment and attached to the OTel span context only when + // TracingPropagateTraceparent is enabled (same opt-in gate as + // TracingTraceParent). TracingTraceState string // Accept traceparent context from Buildkite control plane @@ -220,6 +220,9 @@ type ExecutorConfig struct { // Whether to start the JobAPI JobAPI bool + // Whether to emit visible job process output as OTLP log records. + JobLogsOTLP bool + // The warnings that have been disabled by the user DisabledWarnings []string diff --git a/internal/job/executor.go b/internal/job/executor.go index 71613e885d..5eee8575a9 100644 --- a/internal/job/executor.go +++ b/internal/job/executor.go @@ -156,6 +156,20 @@ func (e *Executor) Run(ctx context.Context) (exitCode int) { // Create an empty env for us to keep track of our env changes in e.shell.Env = env.FromSlice(os.Environ()) + if e.JobLogsOTLP && e.TracingBackend == tracetools.BackendOpenTelemetry { + jobLogger, err := newOTLPJobLogger(ctx, e) + if err != nil { + e.shell.Warningf("Failed to initialize OTLP job log exporter: %v", err) + } else { + e.shell.SetOutputInterceptor(jobLogger.Wrap) + defer func() { + if err := jobLogger.Close(); err != nil { + e.shell.Warningf("Failed to close OTLP job log exporter: %v", err) + } + }() + } + } + // Initialize the job API, iff the experiment is enabled. Noop otherwise if e.JobAPI { cleanup, err := e.startJobAPI() @@ -361,6 +375,18 @@ type HookConfig struct { PluginName string } +func hookLogAttributes(hookCfg HookConfig) map[string]string { + attrs := map[string]string{ + "buildkite.phase": "hook", + "buildkite.hook.name": hookCfg.Name, + "buildkite.hook.scope": hookCfg.Scope, + } + if hookCfg.PluginName != "" { + attrs["buildkite.hook.plugin"] = hookCfg.PluginName + } + return attrs +} + func (e *Executor) tracingImplementationSpecificHookScope(scope string) string { if e.TracingBackend != tracetools.BackendDatadog { return scope @@ -463,7 +489,7 @@ func (e *Executor) runUnwrappedHook(ctx context.Context, _ string, hookCfg HookC environ.Set("BUILDKITE_HOOK_PATH", hookCfg.Path) environ.Set("BUILDKITE_HOOK_SCOPE", hookCfg.Scope) - if err := e.shell.Command(hookCfg.Path).Run(ctx, shell.WithExtraEnv(environ)); err != nil { + if err := e.shell.Command(hookCfg.Path).Run(ctx, shell.WithExtraEnv(environ), shell.WithOutputAttributes(hookLogAttributes(hookCfg))); err != nil { return err } // Passing an empty env changes through because in polyglot hook we can't detect @@ -572,7 +598,7 @@ func (e *Executor) runWrappedShellScriptHook(ctx context.Context, hookName strin if err != nil { return err } - return script.Run(ctx, shell.ShowPrompt(false), shell.WithExtraEnv(hookCfg.Env)) + return script.Run(ctx, shell.ShowPrompt(false), shell.WithExtraEnv(hookCfg.Env), shell.WithOutputAttributes(hookLogAttributes(hookCfg))) }() if err != nil { exitCode := shell.ExitCode(err) @@ -1299,7 +1325,11 @@ func (e *Executor) defaultCommandPhase(ctx context.Context) (retErr error) { e.shell.Promptf("%s", cmdToExec) } - err = e.shell.Command(cmd[0], cmd[1:]...).Run(ctx, shell.ShowPrompt(false)) + err = e.shell.Command(cmd[0], cmd[1:]...).Run(ctx, shell.ShowPrompt(false), shell.WithOutputAttributes(map[string]string{ + "buildkite.phase": "command", + "buildkite.hook.name": "command", + "buildkite.hook.scope": "default", + })) return err } diff --git a/internal/job/executor_test.go b/internal/job/executor_test.go index d319ebfee8..d306b1758e 100644 --- a/internal/job/executor_test.go +++ b/internal/job/executor_test.go @@ -11,6 +11,7 @@ import ( "github.com/buildkite/agent/v3/tracetools" "github.com/google/go-cmp/cmp" "github.com/opentracing/opentracing-go" + "go.opentelemetry.io/otel/trace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/opentracer" ) @@ -107,6 +108,47 @@ func TestStartTracing_Datadog(t *testing.T) { stopper() } +func TestContextWithTraceparentIfEnabledDoesNotAcceptServerTraceparentWithoutPropagation(t *testing.T) { + t.Parallel() + + sh, err := shell.New(shell.WithLogger(shell.DiscardLogger)) + if err != nil { + t.Fatalf("shell.New() error = %v", err) + } + e := New(ExecutorConfig{ + TracingTraceParent: "00-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-bbbbbbbbbbbbbbbb-01", + }) + e.shell = sh + + ctx := e.contextWithTraceparentIfEnabled(context.Background()) + if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { + t.Fatalf("SpanContextFromContext(ctx).IsValid() = true, want false") + } +} + +func TestContextWithTraceparentIfEnabledAcceptsServerTraceparentWithPropagation(t *testing.T) { + t.Parallel() + + sh, err := shell.New(shell.WithLogger(shell.DiscardLogger)) + if err != nil { + t.Fatalf("shell.New() error = %v", err) + } + e := New(ExecutorConfig{ + TracingPropagateTraceparent: true, + TracingTraceParent: "00-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-bbbbbbbbbbbbbbbb-01", + }) + e.shell = sh + + ctx := e.contextWithTraceparentIfEnabled(context.Background()) + sc := trace.SpanContextFromContext(ctx) + if !sc.IsValid() { + t.Fatalf("SpanContextFromContext(ctx).IsValid() = false, want true") + } + if got, want := sc.TraceID().String(), "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"; got != want { + t.Fatalf("SpanContextFromContext(ctx).TraceID() = %q, want %q", got, want) + } +} + // newCancelTestExecutor returns an Executor whose shell.Env starts empty, // suitable for exercising Cancel without depending on the host environment. func newCancelTestExecutor(t *testing.T) *Executor { diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go new file mode 100644 index 0000000000..6e4075cea2 --- /dev/null +++ b/internal/job/otlp_job_logger.go @@ -0,0 +1,189 @@ +package job + +import ( + "bytes" + "context" + "fmt" + "io" + "os" + "sync" + "time" + + "github.com/buildkite/agent/v3/version" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" + otellog "go.opentelemetry.io/otel/log" + sdklog "go.opentelemetry.io/otel/sdk/log" + "go.opentelemetry.io/otel/sdk/resource" + semconv "go.opentelemetry.io/otel/semconv/v1.4.0" +) + +type otlpJobLogger struct { + log otellog.Logger + provider *sdklog.LoggerProvider + attrs []otellog.KeyValue +} + +func newOTLPJobLogger(ctx context.Context, e *Executor) (*otlpJobLogger, error) { + protocol := os.Getenv("OTEL_EXPORTER_OTLP_LOGS_PROTOCOL") + if protocol == "" { + protocol = os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL") + } + if protocol == "" { + protocol = "grpc" + } + + var exporter sdklog.Exporter + var err error + switch protocol { + case "grpc": + exporter, err = otlploggrpc.New(ctx) + case "http/protobuf", "http": + exporter, err = otlploghttp.New(ctx) + default: + return nil, fmt.Errorf("unsupported OTLP logs protocol: %s", protocol) + } + if err != nil { + return nil, fmt.Errorf("creating OTLP log exporter: %w", err) + } + + serviceName := e.TracingServiceName + if serviceName == "" { + serviceName = "buildkite-agent" + } + resources := resource.NewWithAttributes(semconv.SchemaURL, + semconv.ServiceNameKey.String(serviceName), + semconv.ServiceVersionKey.String(version.Version()), + semconv.DeploymentEnvironmentKey.String("ci"), + ) + provider := sdklog.NewLoggerProvider( + sdklog.WithProcessor(sdklog.NewBatchProcessor(exporter)), + sdklog.WithResource(resources), + ) + + return &otlpJobLogger{ + log: provider.Logger( + "buildkite-agent", + otellog.WithInstrumentationVersion(version.Version()), + otellog.WithSchemaURL(semconv.SchemaURL), + ), + provider: provider, + attrs: otlpJobAttributes(e), + }, nil +} + +func (l *otlpJobLogger) Wrap(ctx context.Context, out io.Writer, attrs map[string]string) io.Writer { + return &otlpJobLogWriter{ + ctx: context.WithoutCancel(ctx), + out: out, + log: l.log, + attrs: appendLogAttrs(l.attrs, attrs), + } +} + +func (l *otlpJobLogger) Close() error { + if l.provider == nil { + return nil + } + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + flushErr := l.provider.ForceFlush(ctx) + shutdownErr := l.provider.Shutdown(ctx) + if flushErr != nil { + return flushErr + } + return shutdownErr +} + +type otlpJobLogWriter struct { + mu sync.Mutex + ctx context.Context + out io.Writer + log otellog.Logger + attrs []otellog.KeyValue + buf []byte +} + +func (w *otlpJobLogWriter) Write(data []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + + n, err := w.out.Write(data) + origLen := len(data) + for len(data) > 0 { + i := bytes.IndexByte(data, '\n') + if i < 0 { + w.buf = append(w.buf, data...) + return n, err + } + + line := append(w.buf, data[:i]...) + line = bytes.TrimSuffix(line, []byte{'\r'}) + w.emit(string(line)) + w.buf = w.buf[:0] + data = data[i+1:] + } + + return origLen, err +} + +func (w *otlpJobLogWriter) Flush() { + w.mu.Lock() + defer w.mu.Unlock() + if len(w.buf) == 0 { + return + } + w.emit(string(w.buf)) + w.buf = w.buf[:0] +} + +func (w *otlpJobLogWriter) emit(line string) { + now := time.Now() + + var record otellog.Record + record.SetTimestamp(now) + record.SetObservedTimestamp(now) + record.SetSeverity(otellog.SeverityInfo) + record.SetSeverityText("INFO") + record.SetBody(otellog.StringValue(line)) + record.AddAttributes(w.attrs...) + w.log.Emit(w.ctx, record) +} + +func otlpJobAttributes(e *Executor) []otellog.KeyValue { + buildID, _ := e.shell.Env.Get("BUILDKITE_BUILD_ID") + buildNumber, _ := e.shell.Env.Get("BUILDKITE_BUILD_NUMBER") + branch, _ := e.shell.Env.Get("BUILDKITE_BRANCH") + label, _ := e.shell.Env.Get("BUILDKITE_LABEL") + stepKey, _ := e.shell.Env.Get("BUILDKITE_STEP_KEY") + agentID, _ := e.shell.Env.Get("BUILDKITE_AGENT_ID") + + return []otellog.KeyValue{ + otellog.String("source", "job"), + otellog.String("buildkite.organization.slug", e.OrganizationSlug), + otellog.String("buildkite.pipeline.slug", e.PipelineSlug), + otellog.String("buildkite.branch", branch), + otellog.String("buildkite.queue", e.Queue), + otellog.String("buildkite.agent", e.AgentName), + otellog.String("buildkite.agent.id", agentID), + otellog.String("buildkite.build.id", buildID), + otellog.String("buildkite.build.number", buildNumber), + otellog.String("buildkite.job.id", e.JobID), + otellog.String("buildkite.job.label", label), + otellog.String("buildkite.job.key", stepKey), + } +} + +func appendLogAttrs(base []otellog.KeyValue, attrs map[string]string) []otellog.KeyValue { + if len(attrs) == 0 { + return base + } + out := append([]otellog.KeyValue{}, base...) + for key, value := range attrs { + if value != "" { + out = append(out, otellog.String(key, value)) + } + } + return out +} diff --git a/internal/job/tracing.go b/internal/job/tracing.go index e89f3b3743..c33dee7c2a 100644 --- a/internal/job/tracing.go +++ b/internal/job/tracing.go @@ -211,17 +211,14 @@ func (e *Executor) contextWithTraceparentIfEnabled(ctx context.Context) context. return ctx } - carrier := propagation.MapCarrier{ - "traceparent": e.TracingTraceParent, - } + carrier := propagation.MapCarrier{"traceparent": e.TracingTraceParent} // W3C tracestate is optional and only meaningful alongside traceparent. // The OTel TraceContext propagator already tolerates a missing key, so // this guard is purely to keep the carrier minimal. if e.TracingTraceState != "" { carrier["tracestate"] = e.TracingTraceState } - - return otel.GetTextMapPropagator().Extract(ctx, carrier) + return propagation.TraceContext{}.Extract(ctx, carrier) } func GenericTracingExtras(e *Executor, env *env.Environment) map[string]any { diff --git a/internal/shell/shell.go b/internal/shell/shell.go index bd3bd79c4b..d1bc172ebf 100644 --- a/internal/shell/shell.go +++ b/internal/shell/shell.go @@ -81,6 +81,8 @@ type Shell struct { // Defaults to [os.Stdout]. stdout io.Writer + outputInterceptor OutputInterceptor + // How to encode trace contexts. traceContextCodec tracetools.Codec @@ -90,14 +92,23 @@ type Shell struct { type NewShellOpt = func(*Shell) +type OutputInterceptor func(context.Context, io.Writer, map[string]string) io.Writer + func WithCommandLog(log *[][]string) NewShellOpt { return func(s *Shell) { s.commandLog = log } } func WithDebug(d bool) NewShellOpt { return func(s *Shell) { s.debug = d } } func WithDryRun(d bool) NewShellOpt { return func(s *Shell) { s.dryRun = d } } func WithEnv(e *env.Environment) NewShellOpt { return func(s *Shell) { s.Env = e } } func WithLogger(l Logger) NewShellOpt { return func(s *Shell) { s.Logger = l } } -func WithPTY(pty bool) NewShellOpt { return func(s *Shell) { s.pty = pty } } -func WithStdout(w io.Writer) NewShellOpt { return func(s *Shell) { s.stdout = w } } -func WithWD(wd string) NewShellOpt { return func(s *Shell) { s.wd = wd } } +func WithOutputInterceptor(i OutputInterceptor) NewShellOpt { + return func(s *Shell) { s.outputInterceptor = i } +} +func WithPTY(pty bool) NewShellOpt { return func(s *Shell) { s.pty = pty } } +func WithStdout(w io.Writer) NewShellOpt { return func(s *Shell) { s.stdout = w } } +func WithWD(wd string) NewShellOpt { return func(s *Shell) { s.wd = wd } } + +func (s *Shell) SetOutputInterceptor(i OutputInterceptor) { + s.outputInterceptor = i +} func WithInterruptSignal(sig process.Signal) NewShellOpt { return func(s *Shell) { s.interruptSignal = sig } @@ -161,6 +172,7 @@ func (s *Shell) CloneWithStdin(r io.Reader) *Shell { Env: s.Env, stdin: r, // our new stdin stdout: s.stdout, + outputInterceptor: s.outputInterceptor, wd: s.wd, interruptSignal: s.interruptSignal, signalGracePeriod: s.signalGracePeriod, @@ -482,6 +494,27 @@ func (c Command) Run(ctx context.Context, opts ...RunCommandOpt) error { }() } + var flushers []interface{ Flush() } + if c.shell.outputInterceptor != nil { + if cfg.captureStdout == nil && stdout != nil && stdout != io.Discard { + stdout = c.shell.outputInterceptor(ctx, stdout, cfg.outputAttrs) + if f, ok := stdout.(interface{ Flush() }); ok { + flushers = append(flushers, f) + } + } + if stderr != nil && stderr != io.Discard { + stderr = c.shell.outputInterceptor(ctx, stderr, cfg.outputAttrs) + if f, ok := stderr.(interface{ Flush() }); ok { + flushers = append(flushers, f) + } + } + } + defer func() { + for _, f := range flushers { + f.Flush() + } + }() + cmdCfg.Started = cfg.started cmdCfg.Done = cfg.done @@ -507,6 +540,7 @@ type runConfig struct { started chan struct{} done chan struct{} extraEnv *env.Environment + outputAttrs map[string]string smells map[string]bool } @@ -530,6 +564,10 @@ func ShowPrompt(show bool) RunCommandOpt { return func(c *runConfig) { c.showPro // WithExtraEnv can be used to set additional env vars for this run. func WithExtraEnv(e *env.Environment) RunCommandOpt { return func(c *runConfig) { c.extraEnv = e } } +func WithOutputAttributes(attrs map[string]string) RunCommandOpt { + return func(c *runConfig) { c.outputAttrs = attrs } +} + // WithStarted provides a channel that is closed after the command has started. func WithStarted(started chan struct{}) RunCommandOpt { return func(c *runConfig) { c.started = started } diff --git a/internal/shell/shell_test.go b/internal/shell/shell_test.go index 9c9ff1271f..e5e740e187 100644 --- a/internal/shell/shell_test.go +++ b/internal/shell/shell_test.go @@ -143,6 +143,31 @@ func TestRunWithStdin(t *testing.T) { } } +func TestCloneWithStdinPreservesOutputInterceptor(t *testing.T) { + t.Parallel() + + out := &bytes.Buffer{} + intercepted := &bytes.Buffer{} + sh := newShellForTest(t, + shell.WithStdout(out), + shell.WithPTY(false), + shell.WithOutputInterceptor(func(_ context.Context, downstream io.Writer, _ map[string]string) io.Writer { + return io.MultiWriter(downstream, intercepted) + }), + ) + + cmd := sh.CloneWithStdin(strings.NewReader("hello stdin")).Command("tr", "hs", "HS") + if err := cmd.Run(t.Context()); err != nil { + t.Fatalf(`sh.CloneWithStdin("hello stdin").Command("tr", "hs", "HS").Run(ctx) error = %v`, err) + } + if got, want := out.String(), "Hello Stdin"; got != want { + t.Errorf("stdout = %q, want %q", got, want) + } + if got, want := intercepted.String(), "Hello Stdin"; got != want { + t.Errorf("intercepted stdout = %q, want %q", got, want) + } +} + func TestContextCancelInterrupts(t *testing.T) { t.Parallel() From 9649d5cc2ccfc899028e7722e849234d430b8145 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 10:34:14 +1000 Subject: [PATCH 04/13] Add missing context import in executor_test.go Amp-Thread-ID: https://ampcode.com/threads/T-019ebe62-7ccf-774b-ba96-19d000353bdb Co-authored-by: Amp --- internal/job/executor_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/internal/job/executor_test.go b/internal/job/executor_test.go index d306b1758e..0d7689e596 100644 --- a/internal/job/executor_test.go +++ b/internal/job/executor_test.go @@ -1,6 +1,7 @@ package job import ( + "context" "os" "path/filepath" "reflect" From e30fc1094f0f832e79e20f3ad7f231e49d13c639 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 10:45:47 +1000 Subject: [PATCH 05/13] Use t.Context() in tests to satisfy usetesting linter Amp-Thread-ID: https://ampcode.com/threads/T-019ebe62-7ccf-774b-ba96-19d000353bdb Co-authored-by: Amp --- agent/otlp_job_logger_test.go | 14 +++++++------- internal/job/executor_test.go | 5 ++--- 2 files changed, 9 insertions(+), 10 deletions(-) diff --git a/agent/otlp_job_logger_test.go b/agent/otlp_job_logger_test.go index 053fb6dae4..0db00698a2 100644 --- a/agent/otlp_job_logger_test.go +++ b/agent/otlp_job_logger_test.go @@ -65,7 +65,7 @@ func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { }, } logger := newOTLPJobLoggerWithLogger( - context.Background(), + t.Context(), provider.Logger("test"), provider, otlpJobLogAttributes(conf), @@ -129,7 +129,7 @@ func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { exporter := &otlpJobLogTestExporter{} provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) if _, err := logger.Write([]byte("partial")); err != nil { t.Fatalf("logger.Write() = %v", err) @@ -152,7 +152,7 @@ func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { func TestOTLPJobLoggerDetachesEmitContextFromCancellation(t *testing.T) { t.Parallel() - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithCancel(t.Context()) cancel() exporter := &otlpJobLogTestExporter{} @@ -169,7 +169,7 @@ func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { exporter := &otlpJobLogTestExporter{} provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) before := time.Now() if _, err := logger.Write([]byte("hello from the command\n")); err != nil { @@ -189,7 +189,7 @@ func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { exporter := &otlpJobLogTestExporter{} provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) if _, err := logger.Write([]byte("~~~ Running repository post-command hook\nhook output\n~~~ Running commands\ncommand output\n")); err != nil { t.Fatalf("logger.Write() = %v", err) @@ -228,7 +228,7 @@ func TestOTLPJobLoggerAddsPluginHookScopeFromHeaders(t *testing.T) { exporter := &otlpJobLogTestExporter{} provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) if _, err := logger.Write([]byte("~~~ Running plugin docker#v5.12.0 pre-command hook\nplugin output\n")); err != nil { t.Fatalf("logger.Write() = %v", err) @@ -253,7 +253,7 @@ func TestOTLPJobLoggerDoesNotUpdateScopeFromOrdinaryOutput(t *testing.T) { exporter := &otlpJobLogTestExporter{} provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(context.Background(), provider.Logger("test"), provider, nil) + logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) if _, err := logger.Write([]byte("Running plugin docker#v5.12.0 pre-command hook\nordinary output\n")); err != nil { t.Fatalf("logger.Write() = %v", err) diff --git a/internal/job/executor_test.go b/internal/job/executor_test.go index 0d7689e596..6dd245db17 100644 --- a/internal/job/executor_test.go +++ b/internal/job/executor_test.go @@ -1,7 +1,6 @@ package job import ( - "context" "os" "path/filepath" "reflect" @@ -121,7 +120,7 @@ func TestContextWithTraceparentIfEnabledDoesNotAcceptServerTraceparentWithoutPro }) e.shell = sh - ctx := e.contextWithTraceparentIfEnabled(context.Background()) + ctx := e.contextWithTraceparentIfEnabled(t.Context()) if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { t.Fatalf("SpanContextFromContext(ctx).IsValid() = true, want false") } @@ -140,7 +139,7 @@ func TestContextWithTraceparentIfEnabledAcceptsServerTraceparentWithPropagation( }) e.shell = sh - ctx := e.contextWithTraceparentIfEnabled(context.Background()) + ctx := e.contextWithTraceparentIfEnabled(t.Context()) sc := trace.SpanContextFromContext(ctx) if !sc.IsValid() { t.Fatalf("SpanContextFromContext(ctx).IsValid() = false, want true") From 58eaa351cf878672492668b442a1a812f14b04e6 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 13:56:41 +1000 Subject: [PATCH 06/13] Consolidate OTLP job logs into bootstrap-only Previously OTLP job log export was split across the process boundary: the agent process emitted records when tracing was not OpenTelemetry, and the bootstrap process emitted them when it was. That produced two near-identical implementations, a duplicated buildkite.* attribute schema, and two different sources of phase/hook truth (brittle log-text regex parsing in the agent vs structured HookConfig in the bootstrap). The same --job-logs-otlp flag also yielded materially different output depending on the unrelated tracing backend. Make the bootstrap process the single home for OTLP job log export: - Remove the agent-side emitter (agent/otlp_job_logger.go) and its wiring in job_runner.go / run_job.go. - Activate the bootstrap OTLP logger whenever --job-logs-otlp is set, regardless of tracing backend. Records are trace-correlated when OpenTelemetry tracing is enabled and uncorrelated otherwise. The agent still propagates BUILDKITE_JOB_LOGS_OTLP to the bootstrap. Amp-Thread-ID: https://ampcode.com/threads/T-019ebf08-2dbd-710f-ad6d-5bc1c842bb0a Co-authored-by: Amp --- agent/job_runner.go | 29 +--- agent/otlp_job_logger.go | 231 --------------------------- agent/otlp_job_logger_test.go | 283 ---------------------------------- agent/run_job.go | 6 - internal/job/executor.go | 7 +- 5 files changed, 8 insertions(+), 548 deletions(-) delete mode 100644 agent/otlp_job_logger.go delete mode 100644 agent/otlp_job_logger_test.go diff --git a/agent/job_runner.go b/agent/job_runner.go index f3f98f2d91..023ca08488 100644 --- a/agent/job_runner.go +++ b/agent/job_runner.go @@ -26,7 +26,6 @@ import ( "github.com/buildkite/agent/v3/logger" "github.com/buildkite/agent/v3/metrics" "github.com/buildkite/agent/v3/status" - "github.com/buildkite/agent/v3/tracetools" "github.com/buildkite/roko" "github.com/buildkite/shellwords" ) @@ -126,9 +125,6 @@ type JobRunner struct { // jobLogs is an io.Writer that sends data to the job logs jobLogs io.Writer - // jobLogsOTLP exports job log lines to an OTLP logs endpoint when enabled. - jobLogsOTLP *OTLPJobLogger - // Job cancellation control cancelLock sync.Mutex // prevent concurrent calls to Cancel @@ -161,7 +157,7 @@ type jobProcess interface { } // Initializes the job runner -func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, conf JobRunnerConfig) (_ *JobRunner, err error) { +func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, conf JobRunnerConfig) (*JobRunner, error) { // If the accept response has a token attached, we should use that instead of the Agent Access Token that // our current apiClient is using if conf.Job.Token != "" { @@ -177,15 +173,7 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c client: &core.Client{APIClient: apiClient, Logger: l}, } - defer func() { - if err != nil && r.jobLogsOTLP != nil { - if closeErr := r.jobLogsOTLP.Close(); closeErr != nil { - r.agentLogger.Warnf("Failed to close OTLP job log exporter after job runner initialization error: %v", closeErr) - } - r.jobLogsOTLP = nil - } - }() - + var err error r.VerificationFailureBehavior, err = r.normalizeVerificationBehavior(conf.AgentConfiguration.VerificationFailureBehaviour) if err != nil { return nil, fmt.Errorf("setting no signature behavior: %w", err) @@ -235,16 +223,6 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c // BUILDKITE_AGENT_JOB_TIMEOUT_FILE env var. r.jobTimeoutFilePath = jobTimeoutFilePath(r.conf.Job.ID, conf.KubernetesExec) - var jobLogsOTLP *OTLPJobLogger - if conf.AgentConfiguration.JobLogsOTLP && conf.AgentConfiguration.TracingBackend != tracetools.BackendOpenTelemetry { - jobLogsOTLP, err = NewOTLPJobLogger(ctx, conf) - if err != nil { - r.agentLogger.Warnf("Failed to initialize OTLP job log exporter: %v", err) - } else { - r.jobLogsOTLP = jobLogsOTLP - } - } - env, err := r.createEnvironment(ctx) if err != nil { return nil, err @@ -284,9 +262,6 @@ func NewJobRunner(ctx context.Context, l logger.Logger, apiClient *api.Client, c } pr, pw := io.Pipe() - if jobLogsOTLP != nil { - allWriters = append(allWriters, jobLogsOTLP) - } switch { case conf.AgentConfiguration.ANSITimestamps: diff --git a/agent/otlp_job_logger.go b/agent/otlp_job_logger.go deleted file mode 100644 index c2ecce7aa4..0000000000 --- a/agent/otlp_job_logger.go +++ /dev/null @@ -1,231 +0,0 @@ -package agent - -import ( - "bytes" - "context" - "fmt" - "os" - "strings" - "sync" - "time" - - "github.com/buildkite/agent/v3/version" - "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" - "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" - otellog "go.opentelemetry.io/otel/log" - sdklog "go.opentelemetry.io/otel/sdk/log" - "go.opentelemetry.io/otel/sdk/resource" - semconv "go.opentelemetry.io/otel/semconv/v1.4.0" -) - -// OTLPJobLogger satisfies io.WriteCloser and emits job output as OpenTelemetry -// log records. It line-buffers process output so each emitted OTLP record can -// carry a native timestamp instead of encoding timestamps into the log body. -type OTLPJobLogger struct { - ctx context.Context - log otellog.Logger - provider *sdklog.LoggerProvider - attrs []otellog.KeyValue - - mu sync.Mutex - buf []byte - currentPhase string - currentHook string - currentHookScope string - currentHookPlugin string -} - -func NewOTLPJobLogger(ctx context.Context, conf JobRunnerConfig) (*OTLPJobLogger, error) { - protocol := os.Getenv("OTEL_EXPORTER_OTLP_LOGS_PROTOCOL") - if protocol == "" { - protocol = os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL") - } - if protocol == "" { - protocol = "grpc" - } - - var exporter sdklog.Exporter - var err error - switch protocol { - case "grpc": - exporter, err = otlploggrpc.New(ctx) - case "http/protobuf", "http": - exporter, err = otlploghttp.New(ctx) - default: - return nil, fmt.Errorf("unsupported OTLP logs protocol: %s", protocol) - } - if err != nil { - return nil, fmt.Errorf("creating OTLP log exporter: %w", err) - } - - serviceName := conf.AgentConfiguration.TracingServiceName - if serviceName == "" { - serviceName = "buildkite-agent" - } - resources := resource.NewWithAttributes(semconv.SchemaURL, - semconv.ServiceNameKey.String(serviceName), - semconv.ServiceVersionKey.String(version.Version()), - semconv.DeploymentEnvironmentKey.String("ci"), - ) - provider := sdklog.NewLoggerProvider( - sdklog.WithProcessor(sdklog.NewBatchProcessor(exporter)), - sdklog.WithResource(resources), - ) - log := provider.Logger( - "buildkite-agent", - otellog.WithInstrumentationVersion(version.Version()), - otellog.WithSchemaURL(semconv.SchemaURL), - ) - - return newOTLPJobLoggerWithLogger(ctx, log, provider, otlpJobLogAttributes(conf)), nil -} - -func newOTLPJobLoggerWithLogger(ctx context.Context, log otellog.Logger, provider *sdklog.LoggerProvider, attrs []otellog.KeyValue) *OTLPJobLogger { - ctx = context.WithoutCancel(ctx) - return &OTLPJobLogger{ - ctx: ctx, - log: log, - provider: provider, - attrs: attrs, - } -} - -func (l *OTLPJobLogger) Write(data []byte) (int, error) { - l.mu.Lock() - defer l.mu.Unlock() - - origLen := len(data) - for len(data) > 0 { - i := bytes.IndexByte(data, '\n') - if i < 0 { - l.buf = append(l.buf, data...) - return origLen, nil - } - - line := append(l.buf, data[:i]...) - line = bytes.TrimSuffix(line, []byte{'\r'}) - l.emit(string(line)) - l.buf = l.buf[:0] - data = data[i+1:] - } - - return origLen, nil -} - -func (l *OTLPJobLogger) Close() error { - l.mu.Lock() - if len(l.buf) > 0 { - l.emit(string(l.buf)) - l.buf = l.buf[:0] - } - l.mu.Unlock() - - if l.provider == nil { - return nil - } - - flushCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) - defer cancel() - flushErr := l.provider.ForceFlush(flushCtx) - shutdownErr := l.provider.Shutdown(flushCtx) - if flushErr != nil { - return flushErr - } - return shutdownErr -} - -func (l *OTLPJobLogger) emit(line string) { - l.updateScope(line) - - now := time.Now() - attrs := append([]otellog.KeyValue{}, l.attrs...) - if l.currentPhase != "" { - attrs = append(attrs, otellog.String("buildkite.phase", l.currentPhase)) - } - if l.currentHook != "" { - attrs = append(attrs, - otellog.String("buildkite.hook.name", l.currentHook), - otellog.String("buildkite.hook.scope", l.currentHookScope), - ) - if l.currentHookPlugin != "" { - attrs = append(attrs, otellog.String("buildkite.hook.plugin", l.currentHookPlugin)) - } - } - - var record otellog.Record - record.SetTimestamp(now) - record.SetObservedTimestamp(now) - record.SetSeverity(otellog.SeverityInfo) - record.SetSeverityText("INFO") - record.SetBody(otellog.StringValue(line)) - record.AddAttributes(attrs...) - l.log.Emit(l.ctx, record) -} - -func (l *OTLPJobLogger) updateScope(line string) { - header := ansiColourRE.ReplaceAllString(line, "") - if !headerRE.MatchString(header) { - return - } - - parts := strings.Fields(header) - if len(parts) < 2 { - return - } - rest := strings.TrimSpace(strings.TrimPrefix(header, parts[0])) - - if strings.Contains(rest, "Running commands") || strings.Contains(rest, "Running script") { - l.currentPhase = "command" - l.currentHook = "command" - l.currentHookScope = "default" - l.currentHookPlugin = "" - return - } - - i := strings.Index(rest, "Running ") - if i < 0 { - return - } - hook := strings.TrimSpace(rest[i+len("Running "):]) - hook = strings.TrimSuffix(hook, "\r") - hook = strings.TrimSuffix(hook, " hook") - fields := strings.Fields(hook) - if len(fields) < 2 || !isKnownHook(fields[len(fields)-1]) { - return - } - - l.currentPhase = "hook" - l.currentHookScope = fields[0] - l.currentHook = fields[len(fields)-1] - l.currentHookPlugin = strings.Join(fields[1:len(fields)-1], " ") -} - -func isKnownHook(name string) bool { - switch name { - case "environment", "pre-checkout", "post-checkout", "pre-command", "command", "post-command", "pre-artifact", "post-artifact", "pre-exit": - return true - default: - return false - } -} - -func otlpJobLogAttributes(conf JobRunnerConfig) []otellog.KeyValue { - job := conf.Job - env := job.Env - attrs := []otellog.KeyValue{ - otellog.String("source", "job"), - otellog.String("buildkite.organization.slug", env["BUILDKITE_ORGANIZATION_SLUG"]), - otellog.String("buildkite.pipeline.slug", env["BUILDKITE_PIPELINE_SLUG"]), - otellog.String("buildkite.branch", env["BUILDKITE_BRANCH"]), - otellog.String("buildkite.queue", env["BUILDKITE_AGENT_META_DATA_QUEUE"]), - otellog.String("buildkite.agent", env["BUILDKITE_AGENT_NAME"]), - otellog.String("buildkite.agent.id", env["BUILDKITE_AGENT_ID"]), - otellog.String("buildkite.build.id", env["BUILDKITE_BUILD_ID"]), - otellog.String("buildkite.build.number", env["BUILDKITE_BUILD_NUMBER"]), - otellog.String("buildkite.job.id", job.ID), - otellog.String("buildkite.job.label", env["BUILDKITE_LABEL"]), - otellog.String("buildkite.job.key", env["BUILDKITE_STEP_KEY"]), - } - - return attrs -} diff --git a/agent/otlp_job_logger_test.go b/agent/otlp_job_logger_test.go deleted file mode 100644 index 0db00698a2..0000000000 --- a/agent/otlp_job_logger_test.go +++ /dev/null @@ -1,283 +0,0 @@ -package agent - -import ( - "context" - "sync" - "testing" - "time" - - "github.com/buildkite/agent/v3/api" - "go.opentelemetry.io/otel/log" - sdklog "go.opentelemetry.io/otel/sdk/log" -) - -type otlpJobLogTestExporter struct { - mu sync.Mutex - records []sdklog.Record -} - -func (e *otlpJobLogTestExporter) Export(_ context.Context, records []sdklog.Record) error { - e.mu.Lock() - defer e.mu.Unlock() - for _, record := range records { - e.records = append(e.records, record.Clone()) - } - return nil -} - -func (e *otlpJobLogTestExporter) Shutdown(context.Context) error { - return nil -} - -func (e *otlpJobLogTestExporter) ForceFlush(context.Context) error { - return nil -} - -func (e *otlpJobLogTestExporter) Records() []sdklog.Record { - e.mu.Lock() - defer e.mu.Unlock() - records := make([]sdklog.Record, len(e.records)) - copy(records, e.records) - return records -} - -func TestOTLPJobLoggerEmitsStructuredLineRecords(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - conf := JobRunnerConfig{ - Job: &api.Job{ - ID: "job-123", - Env: map[string]string{ - "BUILDKITE_ORGANIZATION_SLUG": "my-org", - "BUILDKITE_PIPELINE_SLUG": "my-pipeline", - "BUILDKITE_BRANCH": "main", - "BUILDKITE_AGENT_META_DATA_QUEUE": "default", - "BUILDKITE_AGENT_NAME": "agent-1", - "BUILDKITE_AGENT_ID": "agent-id-1", - "BUILDKITE_BUILD_ID": "build-456", - "BUILDKITE_BUILD_NUMBER": "42", - "BUILDKITE_BUILD_URL": "https://buildkite.com/my-org/my-pipeline/builds/42", - "BUILDKITE_LABEL": "Test", - "BUILDKITE_STEP_KEY": "test", - }, - }, - } - logger := newOTLPJobLoggerWithLogger( - t.Context(), - provider.Logger("test"), - provider, - otlpJobLogAttributes(conf), - ) - - if _, err := logger.Write([]byte("first line\nsecond line\n")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - - records := exporter.Records() - if got, want := len(records), 2; got != want { - t.Fatalf("record count = %d, want %d", got, want) - } - if got, want := records[0].Body().AsString(), "first line"; got != want { - t.Errorf("record body = %q, want %q", got, want) - } - if records[0].Timestamp().IsZero() { - t.Errorf("record timestamp is zero") - } - if records[0].ObservedTimestamp().IsZero() { - t.Errorf("record observed timestamp is zero") - } - if got, want := records[0].Severity(), log.SeverityInfo; got != want { - t.Errorf("record severity = %v, want %v", got, want) - } - if records[0].TraceID().IsValid() { - t.Errorf("record trace ID = %q, want invalid", records[0].TraceID().String()) - } - if records[0].SpanID().IsValid() { - t.Errorf("record span ID = %q, want invalid", records[0].SpanID().String()) - } - - attrs := recordAttributes(records[0]) - for key, want := range map[string]string{ - "source": "job", - "buildkite.organization.slug": "my-org", - "buildkite.pipeline.slug": "my-pipeline", - "buildkite.branch": "main", - "buildkite.queue": "default", - "buildkite.agent": "agent-1", - "buildkite.agent.id": "agent-id-1", - "buildkite.build.id": "build-456", - "buildkite.build.number": "42", - "buildkite.job.id": "job-123", - "buildkite.job.label": "Test", - "buildkite.job.key": "test", - } { - if got := attrs[key]; got != want { - t.Errorf("attribute %s = %q, want %q", key, got, want) - } - } - for _, key := range []string{"buildkite.build.url", "buildkite.job.url", "trace_id", "span_id"} { - if got := attrs[key]; got != "" { - t.Errorf("attribute %s = %q, want empty", key, got) - } - } -} - -func TestOTLPJobLoggerFlushesPartialLineOnClose(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) - - if _, err := logger.Write([]byte("partial")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - if got := len(exporter.Records()); got != 0 { - t.Fatalf("record count before close = %d, want 0", got) - } - if err := logger.Close(); err != nil { - t.Fatalf("logger.Close() = %v", err) - } - records := exporter.Records() - if got, want := len(records), 1; got != want { - t.Fatalf("record count after close = %d, want %d", got, want) - } - if got, want := records[0].Body().AsString(), "partial"; got != want { - t.Errorf("record body = %q, want %q", got, want) - } -} - -func TestOTLPJobLoggerDetachesEmitContextFromCancellation(t *testing.T) { - t.Parallel() - - ctx, cancel := context.WithCancel(t.Context()) - cancel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(ctx, provider.Logger("test"), provider, nil) - - if err := logger.ctx.Err(); err != nil { - t.Fatalf("logger ctx error = %v, want nil", err) - } -} - -func TestOTLPJobLoggerPreservesBodyWithoutTimestampPrefix(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) - - before := time.Now() - if _, err := logger.Write([]byte("hello from the command\n")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - records := exporter.Records() - if got, want := records[0].Body().AsString(), "hello from the command"; got != want { - t.Errorf("record body = %q, want %q", got, want) - } - if records[0].Timestamp().Before(before) { - t.Errorf("record timestamp = %v, want after %v", records[0].Timestamp(), before) - } -} - -func TestOTLPJobLoggerAddsCurrentHookScopeFromHeaders(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) - - if _, err := logger.Write([]byte("~~~ Running repository post-command hook\nhook output\n~~~ Running commands\ncommand output\n")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - - records := exporter.Records() - if got, want := len(records), 4; got != want { - t.Fatalf("record count = %d, want %d", got, want) - } - - hookAttrs := recordAttributes(records[1]) - for key, want := range map[string]string{ - "buildkite.phase": "hook", - "buildkite.hook.name": "post-command", - "buildkite.hook.scope": "repository", - } { - if got := hookAttrs[key]; got != want { - t.Errorf("hook output attribute %s = %q, want %q", key, got, want) - } - } - - commandAttrs := recordAttributes(records[3]) - if got, want := commandAttrs["buildkite.phase"], "command"; got != want { - t.Errorf("command output buildkite.phase = %q, want %q", got, want) - } - if got, want := commandAttrs["buildkite.hook.name"], "command"; got != want { - t.Errorf("command output buildkite.hook.name = %q, want %q", got, want) - } - if got, want := commandAttrs["buildkite.hook.scope"], "default"; got != want { - t.Errorf("command output buildkite.hook.scope = %q, want %q", got, want) - } -} - -func TestOTLPJobLoggerAddsPluginHookScopeFromHeaders(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) - - if _, err := logger.Write([]byte("~~~ Running plugin docker#v5.12.0 pre-command hook\nplugin output\n")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - - records := exporter.Records() - attrs := recordAttributes(records[1]) - for key, want := range map[string]string{ - "buildkite.phase": "hook", - "buildkite.hook.name": "pre-command", - "buildkite.hook.scope": "plugin", - "buildkite.hook.plugin": "docker#v5.12.0", - } { - if got := attrs[key]; got != want { - t.Errorf("plugin hook output attribute %s = %q, want %q", key, got, want) - } - } -} - -func TestOTLPJobLoggerDoesNotUpdateScopeFromOrdinaryOutput(t *testing.T) { - t.Parallel() - - exporter := &otlpJobLogTestExporter{} - provider := sdklog.NewLoggerProvider(sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter))) - logger := newOTLPJobLoggerWithLogger(t.Context(), provider.Logger("test"), provider, nil) - - if _, err := logger.Write([]byte("Running plugin docker#v5.12.0 pre-command hook\nordinary output\n")); err != nil { - t.Fatalf("logger.Write() = %v", err) - } - - records := exporter.Records() - if got, want := len(records), 2; got != want { - t.Fatalf("record count = %d, want %d", got, want) - } - for i, record := range records { - attrs := recordAttributes(record) - for _, key := range []string{"buildkite.phase", "buildkite.hook.name", "buildkite.hook.scope", "buildkite.hook.plugin"} { - if got := attrs[key]; got != "" { - t.Errorf("record %d attribute %s = %q, want empty", i, key, got) - } - } - } -} - -func recordAttributes(record sdklog.Record) map[string]string { - attrs := map[string]string{} - record.WalkAttributes(func(kv log.KeyValue) bool { - attrs[kv.Key] = kv.Value.AsString() - return true - }) - return attrs -} diff --git a/agent/run_job.go b/agent/run_job.go index c90bb1aa1c..5df596409d 100644 --- a/agent/run_job.go +++ b/agent/run_job.go @@ -420,12 +420,6 @@ func (r *JobRunner) cleanup(ctx context.Context, wg *sync.WaitGroup, exit core.P r.agentLogger.Debugf("[JobRunner] Waiting for all other routines to finish") wg.Wait() - if r.jobLogsOTLP != nil { - if err := r.jobLogsOTLP.Close(); err != nil { - r.agentLogger.Warnf("Failed to flush OTLP job logs: %v", err) - } - } - // Remove the env file, if any for _, f := range []*os.File{r.envShellFile, r.envJSONFile} { if f == nil { diff --git a/internal/job/executor.go b/internal/job/executor.go index 5eee8575a9..80f98e95bb 100644 --- a/internal/job/executor.go +++ b/internal/job/executor.go @@ -156,7 +156,12 @@ func (e *Executor) Run(ctx context.Context) (exitCode int) { // Create an empty env for us to keep track of our env changes in e.shell.Env = env.FromSlice(os.Environ()) - if e.JobLogsOTLP && e.TracingBackend == tracetools.BackendOpenTelemetry { + // OTLP job log export lives entirely in the bootstrap process, which is the + // single home for this feature. When OpenTelemetry tracing is enabled, the + // per-command emit context carries the active hook/command span, so log + // records are trace-correlated. With tracing disabled, records are still + // emitted but remain uncorrelated. + if e.JobLogsOTLP { jobLogger, err := newOTLPJobLogger(ctx, e) if err != nil { e.shell.Warningf("Failed to initialize OTLP job log exporter: %v", err) From 890ee3662857baf5d289c8c9d8d09cbcdb9cff54 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 14:17:18 +1000 Subject: [PATCH 07/13] Redact secrets in OTLP job log records The bootstrap OTLP job log writer wrapped the shell's stdout writer, which is itself the secret redactor. Because the OTLP writer sat upstream of the redactor, it emitted raw pre-redaction bytes to the OTLP backend while the customer-facing job log was correctly redacted. Confirmed live against a local ClickStack: a redacted env var appeared verbatim in OTLP records. Route the OTLP copy through its own replacer.Replacer seeded with the live needle set from the job's redactor Mux, so OTLP records carry the same [REDACTED] markers as the job log. Streaming redaction also handles secrets split across multiple writes. - Add replacer.Mux.Needles() to expose the current needle set. - Split otlpJobLogWriter into a tee that feeds a redactor whose downstream is a line-buffering OTLP emitter. - Add regression tests for inline and split-across-writes secrets. Amp-Thread-ID: https://ampcode.com/threads/T-019ebf08-2dbd-710f-ad6d-5bc1c842bb0a Co-authored-by: Amp --- internal/job/otlp_job_logger.go | 91 ++++++++++++++------- internal/job/otlp_job_logger_test.go | 115 +++++++++++++++++++++++++++ internal/replacer/mux.go | 10 +++ 3 files changed, 188 insertions(+), 28 deletions(-) create mode 100644 internal/job/otlp_job_logger_test.go diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index 6e4075cea2..e6f2bd37c7 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -9,6 +9,8 @@ import ( "sync" "time" + "github.com/buildkite/agent/v3/internal/redact" + "github.com/buildkite/agent/v3/internal/replacer" "github.com/buildkite/agent/v3/version" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" @@ -19,9 +21,10 @@ import ( ) type otlpJobLogger struct { - log otellog.Logger - provider *sdklog.LoggerProvider - attrs []otellog.KeyValue + log otellog.Logger + provider *sdklog.LoggerProvider + attrs []otellog.KeyValue + redactors *replacer.Mux } func newOTLPJobLogger(ctx context.Context, e *Executor) (*otlpJobLogger, error) { @@ -67,18 +70,28 @@ func newOTLPJobLogger(ctx context.Context, e *Executor) (*otlpJobLogger, error) otellog.WithInstrumentationVersion(version.Version()), otellog.WithSchemaURL(semconv.SchemaURL), ), - provider: provider, - attrs: otlpJobAttributes(e), + provider: provider, + attrs: otlpJobAttributes(e), + redactors: e.redactors, }, nil } func (l *otlpJobLogger) Wrap(ctx context.Context, out io.Writer, attrs map[string]string) io.Writer { - return &otlpJobLogWriter{ + emitter := &otlpLineEmitter{ ctx: context.WithoutCancel(ctx), - out: out, log: l.log, attrs: appendLogAttrs(l.attrs, attrs), } + // Redact OTLP output using the same secret needles as the job-log + // redactor, so secrets never reach the OTLP backend. A fresh per-command + // Replacer feeds the line emitter; it is seeded with the needles known at + // the time the command starts (which already include env-, secret- and Job + // API-derived needles added during earlier phases). + return &otlpJobLogWriter{ + out: out, + redactor: replacer.New(emitter, l.redactors.Needles(), redact.Redacted), + emitter: emitter, + } } func (l *otlpJobLogger) Close() error { @@ -96,13 +109,14 @@ func (l *otlpJobLogger) Close() error { return shutdownErr } +// otlpJobLogWriter tees process output to the normal (already redacting) job-log +// writer and to a redacting OTLP line emitter, so OTLP records carry the same +// redacted content as the customer-facing job log. type otlpJobLogWriter struct { - mu sync.Mutex - ctx context.Context - out io.Writer - log otellog.Logger - attrs []otellog.KeyValue - buf []byte + mu sync.Mutex + out io.Writer + redactor *replacer.Replacer + emitter *otlpLineEmitter } func (w *otlpJobLogWriter) Write(data []byte) (int, error) { @@ -110,35 +124,56 @@ func (w *otlpJobLogWriter) Write(data []byte) (int, error) { defer w.mu.Unlock() n, err := w.out.Write(data) + // Feed the OTLP copy through the redactor, which streams redacted bytes to + // the line emitter. Errors here must not affect the primary job log. + _, _ = w.redactor.Write(data) + return n, err +} + +func (w *otlpJobLogWriter) Flush() { + w.mu.Lock() + defer w.mu.Unlock() + _ = w.redactor.Flush() + w.emitter.flush() +} + +// otlpLineEmitter line-buffers (already redacted) output and emits each line as +// an OpenTelemetry log record with a native timestamp. +type otlpLineEmitter struct { + ctx context.Context + log otellog.Logger + attrs []otellog.KeyValue + buf []byte +} + +func (e *otlpLineEmitter) Write(data []byte) (int, error) { origLen := len(data) for len(data) > 0 { i := bytes.IndexByte(data, '\n') if i < 0 { - w.buf = append(w.buf, data...) - return n, err + e.buf = append(e.buf, data...) + return origLen, nil } - line := append(w.buf, data[:i]...) + line := append(e.buf, data[:i]...) line = bytes.TrimSuffix(line, []byte{'\r'}) - w.emit(string(line)) - w.buf = w.buf[:0] + e.emit(string(line)) + e.buf = e.buf[:0] data = data[i+1:] } - return origLen, err + return origLen, nil } -func (w *otlpJobLogWriter) Flush() { - w.mu.Lock() - defer w.mu.Unlock() - if len(w.buf) == 0 { +func (e *otlpLineEmitter) flush() { + if len(e.buf) == 0 { return } - w.emit(string(w.buf)) - w.buf = w.buf[:0] + e.emit(string(e.buf)) + e.buf = e.buf[:0] } -func (w *otlpJobLogWriter) emit(line string) { +func (e *otlpLineEmitter) emit(line string) { now := time.Now() var record otellog.Record @@ -147,8 +182,8 @@ func (w *otlpJobLogWriter) emit(line string) { record.SetSeverity(otellog.SeverityInfo) record.SetSeverityText("INFO") record.SetBody(otellog.StringValue(line)) - record.AddAttributes(w.attrs...) - w.log.Emit(w.ctx, record) + record.AddAttributes(e.attrs...) + e.log.Emit(e.ctx, record) } func otlpJobAttributes(e *Executor) []otellog.KeyValue { diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go new file mode 100644 index 0000000000..bf839f3dca --- /dev/null +++ b/internal/job/otlp_job_logger_test.go @@ -0,0 +1,115 @@ +package job + +import ( + "bytes" + "context" + "strings" + "sync" + "testing" + + "github.com/buildkite/agent/v3/internal/redact" + "github.com/buildkite/agent/v3/internal/replacer" + otellog "go.opentelemetry.io/otel/log" + "go.opentelemetry.io/otel/log/embedded" +) + +// captureLogger is a minimal otellog.Logger that records emitted record bodies. +type captureLogger struct { + embedded.Logger + mu sync.Mutex + bodies []string + lastKVs map[string]string +} + +func (c *captureLogger) Emit(_ context.Context, r otellog.Record) { + c.mu.Lock() + defer c.mu.Unlock() + c.bodies = append(c.bodies, r.Body().AsString()) + c.lastKVs = map[string]string{} + r.WalkAttributes(func(kv otellog.KeyValue) bool { + c.lastKVs[string(kv.Key)] = kv.Value.AsString() + return true + }) +} + +func (c *captureLogger) Enabled(context.Context, otellog.EnabledParameters) bool { return true } + +func newTestOTLPJobLogger(log otellog.Logger, needles ...string) *otlpJobLogger { + mux := replacer.NewMux(replacer.New(nil, needles, redact.Redacted)) + return &otlpJobLogger{ + log: log, + attrs: []otellog.KeyValue{otellog.String("source", "job")}, + redactors: mux, + } +} + +// TestOTLPJobLoggerRedactsSecrets ensures OTLP log records never carry secret +// values, matching the redaction applied to the customer-facing job log. +func TestOTLPJobLoggerRedactsSecrets(t *testing.T) { + t.Parallel() + + const secret = "supersekret-value" + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap, secret) + + var downstream bytes.Buffer + w := l.Wrap(t.Context(), &downstream, map[string]string{"buildkite.phase": "command"}) + + if _, err := w.Write([]byte("before " + secret + " after\n")); err != nil { + t.Fatalf("Write() error = %v", err) + } + if f, ok := w.(interface{ Flush() }); ok { + f.Flush() + } + + cap.mu.Lock() + defer cap.mu.Unlock() + + if len(cap.bodies) != 1 { + t.Fatalf("emitted %d records, want 1: %q", len(cap.bodies), cap.bodies) + } + body := cap.bodies[0] + if strings.Contains(body, secret) { + t.Errorf("OTLP record body leaked secret: %q", body) + } + if !strings.Contains(body, "[REDACTED]") { + t.Errorf("OTLP record body = %q, want it to contain [REDACTED]", body) + } + if got := cap.lastKVs["buildkite.phase"]; got != "command" { + t.Errorf("buildkite.phase attribute = %q, want %q", got, "command") + } +} + +// TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites ensures a secret that is +// split across multiple Write calls is still redacted in the OTLP output. +func TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites(t *testing.T) { + t.Parallel() + + const secret = "supersekret-value" + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap, secret) + + w := l.Wrap(t.Context(), &bytes.Buffer{}, nil) + + // Split the secret across writes and withhold the trailing newline so the + // line is only emitted on Flush. + if _, err := w.Write([]byte("start super")); err != nil { + t.Fatalf("Write() error = %v", err) + } + if _, err := w.Write([]byte("sekret-value end\n")); err != nil { + t.Fatalf("Write() error = %v", err) + } + if f, ok := w.(interface{ Flush() }); ok { + f.Flush() + } + + cap.mu.Lock() + defer cap.mu.Unlock() + + if len(cap.bodies) != 1 { + t.Fatalf("emitted %d records, want 1: %q", len(cap.bodies), cap.bodies) + } + if body := cap.bodies[0]; strings.Contains(body, secret) { + t.Errorf("OTLP record body leaked secret split across writes: %q", body) + } +} diff --git a/internal/replacer/mux.go b/internal/replacer/mux.go index 28b7fa4305..3353798370 100644 --- a/internal/replacer/mux.go +++ b/internal/replacer/mux.go @@ -37,6 +37,16 @@ func (m *Mux) Append(r *Replacer) { m.underlying = append(m.underlying, r) } +// Needles returns the current set of needles (secrets). All replacers in a Mux +// are kept in sync by Add/Reset, so the needles of the first replacer are +// representative of the whole Mux. Returns nil if the Mux is empty. +func (m *Mux) Needles() []string { + if len(m.underlying) == 0 { + return nil + } + return m.underlying[0].Needles() +} + // Flush flushes all replacers. func (m *Mux) Flush() error { errs := make([]error, 0, len(m.underlying)) From adaaefd12b2e8177c80ffe40002c34f53246a66e Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 15:36:33 +1000 Subject: [PATCH 08/13] Mirror bootstrap control output into OTLP job logs Tee the redacted shell logger output (section headers, prompts, comments, warnings) into the OTLP exporter so exported records match the downloadable Buildkite job log and the UI stream. Previously only child-process output was mirrored, so OTLP destinations were missing the control lines customers see. Amp-Thread-ID: https://ampcode.com/threads/T-019ebf08-2dbd-710f-ad6d-5bc1c842bb0a Co-authored-by: Amp --- internal/job/executor.go | 52 +++++++++++++++++++++++++++- internal/job/otlp_job_logger.go | 37 +++++++++++++++++++- internal/job/otlp_job_logger_test.go | 46 ++++++++++++++++++++++++ 3 files changed, 133 insertions(+), 2 deletions(-) diff --git a/internal/job/executor.go b/internal/job/executor.go index 80f98e95bb..87a875d3de 100644 --- a/internal/job/executor.go +++ b/internal/job/executor.go @@ -78,6 +78,42 @@ type Executor struct { // can consume out-of-band requests made by hooks, such as a working // directory set by an unwrapped hook via the /workdir endpoint. jobAPI *jobapi.Server + + // loggerTee carries the redacted shell logger output (section headers, + // prompts, comments, warnings) to stderr and, when OTLP job logging is + // enabled, mirrors it into the OTLP exporter so the exported records match + // the customer-facing Buildkite job log. + loggerTee *teeWriter +} + +// teeWriter writes to a primary writer and, when configured, also to a +// secondary writer. The secondary sink can be attached after construction, +// which lets the executor mirror already-redacted shell logger output into the +// OTLP exporter once it has been initialised. +type teeWriter struct { + mu sync.Mutex + primary io.Writer + secondary io.Writer +} + +func (w *teeWriter) Write(p []byte) (int, error) { + w.mu.Lock() + secondary := w.secondary + w.mu.Unlock() + + n, err := w.primary.Write(p) + if secondary != nil { + // The secondary sink is best-effort: failures must not affect the + // primary (customer-facing) job log output. + _, _ = secondary.Write(p) + } + return n, err +} + +func (w *teeWriter) setSecondary(secondary io.Writer) { + w.mu.Lock() + w.secondary = secondary + w.mu.Unlock() } // New returns a new executor instance @@ -167,7 +203,16 @@ func (e *Executor) Run(ctx context.Context) (exitCode int) { e.shell.Warningf("Failed to initialize OTLP job log exporter: %v", err) } else { e.shell.SetOutputInterceptor(jobLogger.Wrap) + // Mirror the redacted shell logger control output (section headers, + // prompts, comments, warnings) into OTLP so the exported records + // match the downloadable Buildkite job log and the UI stream. + if e.loggerTee != nil { + e.loggerTee.setSecondary(jobLogger.controlWriter()) + } defer func() { + if e.loggerTee != nil { + e.loggerTee.setSecondary(nil) + } if err := jobLogger.Close(); err != nil { e.shell.Warningf("Failed to close OTLP job log exporter: %v", err) } @@ -1433,7 +1478,12 @@ func (e *Executor) setupRedactors(log shell.Logger, environ *env.Environment, st stdoutRedactor := replacer.New(stdout, needles, redact.Redacted) e.redactors.Append(stdoutRedactor) - loggerRedactor := replacer.New(stderr, needles, redact.Redacted) + // The shell logger writes through this redactor into loggerTee, whose + // primary sink is stderr. When OTLP job logging is enabled, a secondary + // sink is attached so the same already-redacted control output is mirrored + // into the OTLP exporter. + e.loggerTee = &teeWriter{primary: stderr} + loggerRedactor := replacer.New(e.loggerTee, needles, redact.Redacted) e.redactors.Append(loggerRedactor) logger := shell.NewWriterLogger(loggerRedactor, true, e.DisabledWarnings) diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index e6f2bd37c7..1535cadac0 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -25,6 +25,11 @@ type otlpJobLogger struct { provider *sdklog.LoggerProvider attrs []otellog.KeyValue redactors *replacer.Mux + + // control mirrors bootstrap-generated control output (section headers, + // prompts, comments, warnings) into OTLP so the exported records match the + // Buildkite job log stream. It is created lazily by controlWriter. + control *otlpLineEmitter } func newOTLPJobLogger(ctx context.Context, e *Executor) (*otlpJobLogger, error) { @@ -94,7 +99,28 @@ func (l *otlpJobLogger) Wrap(ctx context.Context, out io.Writer, attrs map[strin } } +// controlWriter returns an io.Writer that mirrors bootstrap control output +// (section headers, prompts, comments, warnings) into OTLP as log records, so +// the exported records contain the same lines a customer sees in the Buildkite +// UI. It is fed post-redaction bytes from the shell logger's redactor, so it +// does not redact again. Lines carry the base job attributes but no per-hook +// phase or span context (control output is bootstrap narration, not the output +// of a specific traced hook/command). +func (l *otlpJobLogger) controlWriter() io.Writer { + if l.control == nil { + l.control = &otlpLineEmitter{ + ctx: context.Background(), + log: l.log, + attrs: l.attrs, + } + } + return l.control +} + func (l *otlpJobLogger) Close() error { + if l.control != nil { + l.control.flush() + } if l.provider == nil { return nil } @@ -138,15 +164,21 @@ func (w *otlpJobLogWriter) Flush() { } // otlpLineEmitter line-buffers (already redacted) output and emits each line as -// an OpenTelemetry log record with a native timestamp. +// an OpenTelemetry log record with a native timestamp. Write and flush are +// guarded by mu because control output may be written from multiple goroutines +// (e.g. the cancellation handler emitting a comment). type otlpLineEmitter struct { ctx context.Context log otellog.Logger attrs []otellog.KeyValue + mu sync.Mutex buf []byte } func (e *otlpLineEmitter) Write(data []byte) (int, error) { + e.mu.Lock() + defer e.mu.Unlock() + origLen := len(data) for len(data) > 0 { i := bytes.IndexByte(data, '\n') @@ -166,6 +198,9 @@ func (e *otlpLineEmitter) Write(data []byte) (int, error) { } func (e *otlpLineEmitter) flush() { + e.mu.Lock() + defer e.mu.Unlock() + if len(e.buf) == 0 { return } diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go index bf839f3dca..22b09bbfb9 100644 --- a/internal/job/otlp_job_logger_test.go +++ b/internal/job/otlp_job_logger_test.go @@ -80,6 +80,52 @@ func TestOTLPJobLoggerRedactsSecrets(t *testing.T) { } } +// TestOTLPJobLoggerControlWriter ensures bootstrap control output (section +// headers, prompts, comments) written through the control writer is emitted as +// OTLP log records, giving parity with the downloadable Buildkite job log. +func TestOTLPJobLoggerControlWriter(t *testing.T) { + t.Parallel() + + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap) + + w := l.controlWriter() + if _, err := w.Write([]byte("~~~ Running commands\n$ echo hello\n")); err != nil { + t.Fatalf("Write() error = %v", err) + } + // A line without a trailing newline should only be emitted on Close/flush. + if _, err := w.Write([]byte("# trailing comment")); err != nil { + t.Fatalf("Write() error = %v", err) + } + if err := l.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + + cap.mu.Lock() + defer cap.mu.Unlock() + + want := []string{"~~~ Running commands", "$ echo hello", "# trailing comment"} + if len(cap.bodies) != len(want) { + t.Fatalf("emitted %d records, want %d: %q", len(cap.bodies), len(want), cap.bodies) + } + for i, line := range want { + if cap.bodies[i] != line { + t.Errorf("record[%d] = %q, want %q", i, cap.bodies[i], line) + } + } +} + +// TestOTLPJobLoggerControlWriterReused ensures repeated controlWriter calls +// return the same emitter so all control output shares one line buffer. +func TestOTLPJobLoggerControlWriterReused(t *testing.T) { + t.Parallel() + + l := newTestOTLPJobLogger(&captureLogger{}) + if l.controlWriter() != l.controlWriter() { + t.Error("controlWriter() returned different writers; want a single shared emitter") + } +} + // TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites ensures a secret that is // split across multiple Write calls is still redacted in the OTLP output. func TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites(t *testing.T) { From a0a42244865c6279fcf9d0740db42dbaab410924 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Sat, 13 Jun 2026 16:06:16 +1000 Subject: [PATCH 09/13] Harden OTLP job log redaction and control tee lifecycle Address adversarial review findings: - Sync the per-command OTLP redactor with the live redactor Mux on each write so secrets added mid-command (e.g. via the Job API) are redacted in OTLP output, not just secrets known when the command writer was created. - Hold the teeWriter lock across the whole write so detaching the OTLP control sink cannot race with an in-flight write, preventing control output from landing on the emitter after it has been flushed and the provider shut down. Amp-Thread-ID: https://ampcode.com/threads/T-019ebf08-2dbd-710f-ad6d-5bc1c842bb0a Co-authored-by: Amp --- internal/job/executor.go | 11 +++++---- internal/job/otlp_job_logger.go | 14 ++++++++++-- internal/job/otlp_job_logger_test.go | 34 ++++++++++++++++++++++++++++ 3 files changed, 53 insertions(+), 6 deletions(-) diff --git a/internal/job/executor.go b/internal/job/executor.go index 87a875d3de..8adbf89839 100644 --- a/internal/job/executor.go +++ b/internal/job/executor.go @@ -97,15 +97,18 @@ type teeWriter struct { } func (w *teeWriter) Write(p []byte) (int, error) { + // Hold the lock for the whole write so that detaching the secondary sink + // (setSecondary(nil), called before the OTLP exporter is flushed and shut + // down) cannot complete while a write is still in flight. This guarantees + // no control output lands on the OTLP emitter after it has been flushed. w.mu.Lock() - secondary := w.secondary - w.mu.Unlock() + defer w.mu.Unlock() n, err := w.primary.Write(p) - if secondary != nil { + if w.secondary != nil { // The secondary sink is best-effort: failures must not affect the // primary (customer-facing) job log output. - _, _ = secondary.Write(p) + _, _ = w.secondary.Write(p) } return n, err } diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index 1535cadac0..1eb807c58e 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -90,10 +90,12 @@ func (l *otlpJobLogger) Wrap(ctx context.Context, out io.Writer, attrs map[strin // Redact OTLP output using the same secret needles as the job-log // redactor, so secrets never reach the OTLP backend. A fresh per-command // Replacer feeds the line emitter; it is seeded with the needles known at - // the time the command starts (which already include env-, secret- and Job - // API-derived needles added during earlier phases). + // the time the command starts and kept in sync on every write with the + // live redactor Mux (see otlpJobLogWriter.Write), so secrets added mid + // command (e.g. via the Job API) are also redacted here. return &otlpJobLogWriter{ out: out, + live: l.redactors, redactor: replacer.New(emitter, l.redactors.Needles(), redact.Redacted), emitter: emitter, } @@ -141,6 +143,7 @@ func (l *otlpJobLogger) Close() error { type otlpJobLogWriter struct { mu sync.Mutex out io.Writer + live *replacer.Mux redactor *replacer.Replacer emitter *otlpLineEmitter } @@ -150,6 +153,13 @@ func (w *otlpJobLogWriter) Write(data []byte) (int, error) { defer w.mu.Unlock() n, err := w.out.Write(data) + // Keep the OTLP redactor's needles in sync with the live job redactor + // before redacting, so secrets added mid-command (e.g. via the Job API) + // are redacted in OTLP output too. Replacer.Add deduplicates, so re-adding + // the full needle set each write is safe. + if w.live != nil { + w.redactor.Add(w.live.Needles()...) + } // Feed the OTLP copy through the redactor, which streams redacted bytes to // the line emitter. Errors here must not affect the primary job log. _, _ = w.redactor.Write(data) diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go index 22b09bbfb9..f537698168 100644 --- a/internal/job/otlp_job_logger_test.go +++ b/internal/job/otlp_job_logger_test.go @@ -80,6 +80,40 @@ func TestOTLPJobLoggerRedactsSecrets(t *testing.T) { } } +// TestOTLPJobLoggerRedactsNeedlesAddedMidStream ensures a secret added to the +// live redactor Mux after the command writer is created (e.g. via the Job API) +// is still redacted in OTLP output, not just secrets known at writer creation. +func TestOTLPJobLoggerRedactsNeedlesAddedMidStream(t *testing.T) { + t.Parallel() + + cap := &captureLogger{} + // Start with no needles, matching a command that adds a secret at runtime. + l := newTestOTLPJobLogger(cap) + + w := l.Wrap(t.Context(), &bytes.Buffer{}, nil) + + const secret = "late-bound-secret" + // Secret added to the live Mux after the writer was created. + l.redactors.Add(secret) + + if _, err := w.Write([]byte("value " + secret + " end\n")); err != nil { + t.Fatalf("Write() error = %v", err) + } + if f, ok := w.(interface{ Flush() }); ok { + f.Flush() + } + + cap.mu.Lock() + defer cap.mu.Unlock() + + if len(cap.bodies) != 1 { + t.Fatalf("emitted %d records, want 1: %q", len(cap.bodies), cap.bodies) + } + if body := cap.bodies[0]; strings.Contains(body, secret) { + t.Errorf("OTLP record body leaked mid-stream secret: %q", body) + } +} + // TestOTLPJobLoggerControlWriter ensures bootstrap control output (section // headers, prompts, comments) written through the control writer is emitted as // OTLP log records, giving parity with the downloadable Buildkite job log. From d7322f4914f1d85b2f90f3c14404619b47c3dab1 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Wed, 15 Jul 2026 09:30:12 +1000 Subject: [PATCH 10/13] Address OTLP job log review feedback --- agent/job_runner.go | 7 +++-- internal/job/otlp_job_logger.go | 41 ++++++++++++++++++++++++---- internal/job/otlp_job_logger_test.go | 33 ++++++++++++++++++++++ internal/shell/shell.go | 33 ++++++++++++++++++---- internal/shell/shell_test.go | 39 ++++++++++++++++++++++++++ 5 files changed, 139 insertions(+), 14 deletions(-) diff --git a/agent/job_runner.go b/agent/job_runner.go index 023ca08488..e893548840 100644 --- a/agent/job_runner.go +++ b/agent/job_runner.go @@ -728,9 +728,10 @@ BUILDKITE_AGENT_JWKS_KEY_ID` } } - if r.conf.AgentConfiguration.JobLogsOTLP { - setEnv("BUILDKITE_JOB_LOGS_OTLP", "true") - } + // This is an agent-operator setting, not a pipeline setting. Always + // overwrite the job-provided value so a pipeline cannot enable OTLP export + // or choose its destination when the agent operator has not opted in. + setEnv("BUILDKITE_JOB_LOGS_OTLP", fmt.Sprint(r.conf.AgentConfiguration.JobLogsOTLP)) setEnv("BUILDKITE_AGENT_DISABLE_WARNINGS_FOR", strings.Join(r.conf.AgentConfiguration.DisableWarningsFor, ",")) diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index 1eb807c58e..88cb73fba8 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -20,6 +20,11 @@ import ( semconv "go.opentelemetry.io/otel/semconv/v1.4.0" ) +// Keep newline-free output bounded while retaining normal line-oriented +// records. This matches the maximum chunk size used by common log shippers and +// avoids buffering an arbitrarily large process write until command exit. +const otlpLogRecordMaxBytes = 64 * 1024 + type otlpJobLogger struct { log otellog.Logger provider *sdklog.LoggerProvider @@ -65,7 +70,9 @@ func newOTLPJobLogger(ctx context.Context, e *Executor) (*otlpJobLogger, error) semconv.DeploymentEnvironmentKey.String("ci"), ) provider := sdklog.NewLoggerProvider( - sdklog.WithProcessor(sdklog.NewBatchProcessor(exporter)), + // Job logs must not be silently dropped when the SDK batch queue fills. + // Back-pressure the command output on the exporter instead. + sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter)), sdklog.WithResource(resources), ) @@ -193,13 +200,15 @@ func (e *otlpLineEmitter) Write(data []byte) (int, error) { for len(data) > 0 { i := bytes.IndexByte(data, '\n') if i < 0 { - e.buf = append(e.buf, data...) + e.appendChunks(data) return origLen, nil } - line := append(e.buf, data[:i]...) - line = bytes.TrimSuffix(line, []byte{'\r'}) - e.emit(string(line)) + emittedChunk := e.appendChunks(data[:i]) + e.buf = bytes.TrimSuffix(e.buf, []byte{'\r'}) + if len(e.buf) > 0 || !emittedChunk { + e.emit(string(e.buf)) + } e.buf = e.buf[:0] data = data[i+1:] } @@ -207,6 +216,28 @@ func (e *otlpLineEmitter) Write(data []byte) (int, error) { return origLen, nil } +func (e *otlpLineEmitter) appendChunks(data []byte) bool { + emitted := false + for len(data) > 0 { + // Keep one full chunk buffered until we see either more data or a line + // terminator. This lets Write strip a trailing carriage return when a + // CRLF sequence arrives across separate writes without exceeding the + // memory bound. + if len(e.buf) == otlpLogRecordMaxBytes { + e.emit(string(e.buf)) + e.buf = e.buf[:0] + emitted = true + } + remaining := otlpLogRecordMaxBytes - len(e.buf) + if remaining > len(data) { + remaining = len(data) + } + e.buf = append(e.buf, data[:remaining]...) + data = data[remaining:] + } + return emitted +} + func (e *otlpLineEmitter) flush() { e.mu.Lock() defer e.mu.Unlock() diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go index f537698168..9d054ec59d 100644 --- a/internal/job/otlp_job_logger_test.go +++ b/internal/job/otlp_job_logger_test.go @@ -193,3 +193,36 @@ func TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites(t *testing.T) { t.Errorf("OTLP record body leaked secret split across writes: %q", body) } } + +func TestOTLPJobLoggerChunksUnterminatedOutput(t *testing.T) { + t.Parallel() + + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap) + w := l.Wrap(t.Context(), &bytes.Buffer{}, nil) + line := strings.Repeat("x", otlpLogRecordMaxBytes*2+17) + + if _, err := w.Write([]byte(line)); err != nil { + t.Fatalf("Write() error = %v", err) + } + + cap.mu.Lock() + if got, want := len(cap.bodies), 2; got != want { + cap.mu.Unlock() + t.Fatalf("records before Flush = %d, want %d", got, want) + } + cap.mu.Unlock() + + if f, ok := w.(interface{ Flush() }); ok { + f.Flush() + } + + cap.mu.Lock() + defer cap.mu.Unlock() + if got, want := len(cap.bodies), 3; got != want { + t.Fatalf("records after Flush = %d, want %d", got, want) + } + if got := strings.Join(cap.bodies, ""); got != line { + t.Errorf("rejoined record bodies differ from input: got %d bytes, want %d", len(got), len(line)) + } +} diff --git a/internal/shell/shell.go b/internal/shell/shell.go index d1bc172ebf..83a00fad4a 100644 --- a/internal/shell/shell.go +++ b/internal/shell/shell.go @@ -13,6 +13,7 @@ import ( "os/exec" "path" "path/filepath" + "reflect" "runtime" "strings" "sync/atomic" @@ -496,16 +497,28 @@ func (c Command) Run(ctx context.Context, opts ...RunCommandOpt) error { var flushers []interface{ Flush() } if c.shell.outputInterceptor != nil { - if cfg.captureStdout == nil && stdout != nil && stdout != io.Discard { + // stdout and stderr normally share the same downstream job-log writer. + // Preserve that shared stream through the interceptor as well so + // stateful processing such as redaction can match values split across + // writes to the two file descriptors. + if cfg.captureStdout == nil && sameWriter(stdout, stderr) && stdout != nil && stdout != io.Discard { stdout = c.shell.outputInterceptor(ctx, stdout, cfg.outputAttrs) + stderr = stdout if f, ok := stdout.(interface{ Flush() }); ok { flushers = append(flushers, f) } - } - if stderr != nil && stderr != io.Discard { - stderr = c.shell.outputInterceptor(ctx, stderr, cfg.outputAttrs) - if f, ok := stderr.(interface{ Flush() }); ok { - flushers = append(flushers, f) + } else { + if cfg.captureStdout == nil && stdout != nil && stdout != io.Discard { + stdout = c.shell.outputInterceptor(ctx, stdout, cfg.outputAttrs) + if f, ok := stdout.(interface{ Flush() }); ok { + flushers = append(flushers, f) + } + } + if stderr != nil && stderr != io.Discard { + stderr = c.shell.outputInterceptor(ctx, stderr, cfg.outputAttrs) + if f, ok := stderr.(interface{ Flush() }); ok { + flushers = append(flushers, f) + } } } } @@ -521,6 +534,14 @@ func (c Command) Run(ctx context.Context, opts ...RunCommandOpt) error { return c.shell.executeCommand(ctx, cmdCfg, stdout, stderr, pty) } +func sameWriter(a, b io.Writer) bool { + if a == nil || b == nil { + return a == nil && b == nil + } + av, bv := reflect.ValueOf(a), reflect.ValueOf(b) + return av.Type() == bv.Type() && av.Comparable() && av.Interface() == bv.Interface() +} + // RunAndCaptureStdout is Run, but automatically sets options: // * ShowPrompt(false) (overridable) // * CaptureStdout() (not overridable) diff --git a/internal/shell/shell_test.go b/internal/shell/shell_test.go index e5e740e187..7831d76282 100644 --- a/internal/shell/shell_test.go +++ b/internal/shell/shell_test.go @@ -168,6 +168,45 @@ func TestCloneWithStdinPreservesOutputInterceptor(t *testing.T) { } } +func TestRunSharesOutputInterceptorForCombinedStdoutAndStderr(t *testing.T) { + t.Parallel() + + proxy, err := bintest.CompileProxy("combined-output") + if err != nil { + t.Fatalf("bintest.CompileProxy(combined-output) error = %v", err) + } + defer func() { + if err := proxy.Close(); err != nil { + t.Errorf("proxy.Close() error = %v", err) + } + }() + + out := &bytes.Buffer{} + interceptorCalls := 0 + sh := newShellForTest(t, + shell.WithStdout(out), + shell.WithPTY(false), + shell.WithOutputInterceptor(func(_ context.Context, downstream io.Writer, _ map[string]string) io.Writer { + interceptorCalls++ + return downstream + }), + ) + + go func() { + call := <-proxy.Ch + _, _ = io.WriteString(call.Stdout, "stdout") + _, _ = io.WriteString(call.Stderr, "stderr") + call.Exit(0) + }() + + if err := sh.Command(proxy.Path).Run(t.Context()); err != nil { + t.Fatalf("Command.Run() error = %v", err) + } + if got, want := interceptorCalls, 1; got != want { + t.Errorf("output interceptor calls = %d, want %d for shared stdout/stderr", got, want) + } +} + func TestContextCancelInterrupts(t *testing.T) { t.Parallel() From feca6a348e0fe056bdc75d51f2f9399274147c94 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Wed, 15 Jul 2026 12:40:45 +1000 Subject: [PATCH 11/13] Share OTLP redaction through string search --- internal/shell/shell.go | 46 ++++++++++++++++++++---------------- internal/shell/shell_test.go | 24 ++++++++++++++++--- 2 files changed, 46 insertions(+), 24 deletions(-) diff --git a/internal/shell/shell.go b/internal/shell/shell.go index 83a00fad4a..1fbbd2e992 100644 --- a/internal/shell/shell.go +++ b/internal/shell/shell.go @@ -474,27 +474,6 @@ func (c Command) Run(ctx context.Context, opts ...RunCommandOpt) error { stderr = io.Discard } - // If we're performing a string search, wrap the current stdout and stderr - // in olfactors, and report which ones were detected through the map. - if cfg.smells != nil { - smells := make([]string, 0, len(cfg.smells)) - for s := range cfg.smells { - smells = append(smells, s) - } - so, o1 := olfactor.New(stdout, smells) - se, o2 := olfactor.New(stderr, smells) - stdout, stderr = so, se - - defer func() { - for _, smelt := range o1.AllSmelt() { - cfg.smells[smelt] = true - } - for _, smelt := range o2.AllSmelt() { - cfg.smells[smelt] = true - } - }() - } - var flushers []interface{ Flush() } if c.shell.outputInterceptor != nil { // stdout and stderr normally share the same downstream job-log writer. @@ -522,6 +501,31 @@ func (c Command) Run(ctx context.Context, opts ...RunCommandOpt) error { } } } + + // If we're performing a string search, wrap the intercepted stdout and + // stderr in olfactors and report which ones were detected through the map. + // Interception must happen first: olfactor uses separate wrappers for each + // stream, which would otherwise hide that both ultimately share the same + // job-log writer and incorrectly split stateful processing such as OTLP + // redaction. + if cfg.smells != nil { + smells := make([]string, 0, len(cfg.smells)) + for s := range cfg.smells { + smells = append(smells, s) + } + so, o1 := olfactor.New(stdout, smells) + se, o2 := olfactor.New(stderr, smells) + stdout, stderr = so, se + + defer func() { + for _, smelt := range o1.AllSmelt() { + cfg.smells[smelt] = true + } + for _, smelt := range o2.AllSmelt() { + cfg.smells[smelt] = true + } + }() + } defer func() { for _, f := range flushers { f.Flush() diff --git a/internal/shell/shell_test.go b/internal/shell/shell_test.go index 7831d76282..5c9108f217 100644 --- a/internal/shell/shell_test.go +++ b/internal/shell/shell_test.go @@ -11,6 +11,7 @@ import ( "path/filepath" "runtime" "strings" + "sync" "syscall" "testing" "time" @@ -22,6 +23,17 @@ import ( "github.com/google/go-cmp/cmp" ) +type synchronizedWriter struct { + mu sync.Mutex + out io.Writer +} + +func (w *synchronizedWriter) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.out.Write(p) +} + func TestRunAndCaptureWithTTY(t *testing.T) { t.Parallel() @@ -183,12 +195,13 @@ func TestRunSharesOutputInterceptorForCombinedStdoutAndStderr(t *testing.T) { out := &bytes.Buffer{} interceptorCalls := 0 + smelled := map[string]bool{"stdout": false, "stderr": false} sh := newShellForTest(t, shell.WithStdout(out), shell.WithPTY(false), shell.WithOutputInterceptor(func(_ context.Context, downstream io.Writer, _ map[string]string) io.Writer { interceptorCalls++ - return downstream + return &synchronizedWriter{out: downstream} }), ) @@ -199,11 +212,16 @@ func TestRunSharesOutputInterceptorForCombinedStdoutAndStderr(t *testing.T) { call.Exit(0) }() - if err := sh.Command(proxy.Path).Run(t.Context()); err != nil { + if err := sh.Command(proxy.Path).Run(t.Context(), shell.WithStringSearch(smelled)); err != nil { t.Fatalf("Command.Run() error = %v", err) } if got, want := interceptorCalls, 1; got != want { - t.Errorf("output interceptor calls = %d, want %d for shared stdout/stderr", got, want) + t.Errorf("output interceptor calls = %d, want %d for shared stdout/stderr with string search", got, want) + } + for output, found := range smelled { + if !found { + t.Errorf("WithStringSearch did not find %q", output) + } } } From 0e5c4c945ac5ccbbb26e583b397733e13e18f30b Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Wed, 15 Jul 2026 12:53:00 +1000 Subject: [PATCH 12/13] Preserve OTLP redaction across commands --- internal/job/otlp_job_logger.go | 117 +++++++++++++++++++++------ internal/job/otlp_job_logger_test.go | 44 ++++++++++ 2 files changed, 136 insertions(+), 25 deletions(-) diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index 88cb73fba8..3cc1831dbf 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -6,6 +6,7 @@ import ( "fmt" "io" "os" + "reflect" "sync" "time" @@ -30,6 +31,8 @@ type otlpJobLogger struct { provider *sdklog.LoggerProvider attrs []otellog.KeyValue redactors *replacer.Mux + streamsMu sync.Mutex + streams []*otlpJobLogStream // control mirrors bootstrap-generated control output (section headers, // prompts, comments, warnings) into OTLP so the exported records match the @@ -94,17 +97,33 @@ func (l *otlpJobLogger) Wrap(ctx context.Context, out io.Writer, attrs map[strin log: l.log, attrs: appendLogAttrs(l.attrs, attrs), } - // Redact OTLP output using the same secret needles as the job-log - // redactor, so secrets never reach the OTLP backend. A fresh per-command - // Replacer feeds the line emitter; it is seeded with the needles known at - // the time the command starts and kept in sync on every write with the - // live redactor Mux (see otlpJobLogWriter.Write), so secrets added mid - // command (e.g. via the Job API) are also redacted here. + + // Keep one redaction stream for each shared downstream job-log writer. The + // visible job-log redactor also persists across command boundaries, so OTLP + // must retain partial matches across Wrap calls to avoid leaking fragments + // of a secret split between two commands. + l.streamsMu.Lock() + var stream *otlpJobLogStream + for _, candidate := range l.streams { + if sameOTLPWriter(candidate.out, out) { + stream = candidate + break + } + } + if stream == nil { + stream = &otlpJobLogStream{out: out, live: l.redactors} + stream.redactor = replacer.New( + otlpRedactedWriter{stream: stream}, + l.redactors.Needles(), + redact.Redacted, + ) + l.streams = append(l.streams, stream) + } + l.streamsMu.Unlock() + return &otlpJobLogWriter{ - out: out, - live: l.redactors, - redactor: replacer.New(emitter, l.redactors.Needles(), redact.Redacted), - emitter: emitter, + stream: stream, + emitter: emitter, } } @@ -130,6 +149,12 @@ func (l *otlpJobLogger) Close() error { if l.control != nil { l.control.flush() } + l.streamsMu.Lock() + streams := append([]*otlpJobLogStream(nil), l.streams...) + l.streamsMu.Unlock() + for _, stream := range streams { + stream.flush() + } if l.provider == nil { return nil } @@ -148,38 +173,80 @@ func (l *otlpJobLogger) Close() error { // writer and to a redacting OTLP line emitter, so OTLP records carry the same // redacted content as the customer-facing job log. type otlpJobLogWriter struct { - mu sync.Mutex - out io.Writer - live *replacer.Mux - redactor *replacer.Replacer - emitter *otlpLineEmitter + stream *otlpJobLogStream + emitter *otlpLineEmitter } func (w *otlpJobLogWriter) Write(data []byte) (int, error) { - w.mu.Lock() - defer w.mu.Unlock() + w.stream.mu.Lock() + defer w.stream.mu.Unlock() - n, err := w.out.Write(data) + n, err := w.stream.out.Write(data) // Keep the OTLP redactor's needles in sync with the live job redactor // before redacting, so secrets added mid-command (e.g. via the Job API) // are redacted in OTLP output too. Replacer.Add deduplicates, so re-adding // the full needle set each write is safe. - if w.live != nil { - w.redactor.Add(w.live.Needles()...) + if w.stream.live != nil { + w.stream.redactor.Add(w.stream.live.Needles()...) } // Feed the OTLP copy through the redactor, which streams redacted bytes to - // the line emitter. Errors here must not affect the primary job log. - _, _ = w.redactor.Write(data) + // this command's line emitter. Errors here must not affect the primary job + // log. The stream retains partial redaction matches for the next command. + w.stream.emitter = w.emitter + _, _ = w.stream.redactor.Write(data) return n, err } func (w *otlpJobLogWriter) Flush() { - w.mu.Lock() - defer w.mu.Unlock() - _ = w.redactor.Flush() + w.stream.mu.Lock() + defer w.stream.mu.Unlock() + // Flush this command's complete line data, but deliberately do not flush + // the shared redactor: it may be withholding the prefix of a secret that + // continues in the next command. w.emitter.flush() } +// otlpJobLogStream owns redaction state shared by command writers that feed the +// same downstream job-log stream. +type otlpJobLogStream struct { + mu sync.Mutex + out io.Writer + live *replacer.Mux + redactor *replacer.Replacer + emitter *otlpLineEmitter +} + +func (s *otlpJobLogStream) flush() { + s.mu.Lock() + defer s.mu.Unlock() + _ = s.redactor.Flush() + if s.emitter != nil { + s.emitter.flush() + } +} + +// otlpRedactedWriter routes bytes released by the persistent redactor to the +// emitter for the command whose write released them. Its stream mutex is held +// by all callers. +type otlpRedactedWriter struct { + stream *otlpJobLogStream +} + +func (w otlpRedactedWriter) Write(data []byte) (int, error) { + if w.stream.emitter == nil { + return len(data), nil + } + return w.stream.emitter.Write(data) +} + +func sameOTLPWriter(a, b io.Writer) bool { + if a == nil || b == nil { + return a == nil && b == nil + } + av, bv := reflect.ValueOf(a), reflect.ValueOf(b) + return av.Type() == bv.Type() && av.Comparable() && av.Interface() == bv.Interface() +} + // otlpLineEmitter line-buffers (already redacted) output and emits each line as // an OpenTelemetry log record with a native timestamp. Write and flush are // guarded by mu because control output may be written from multiple goroutines diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go index 9d054ec59d..c37d382858 100644 --- a/internal/job/otlp_job_logger_test.go +++ b/internal/job/otlp_job_logger_test.go @@ -194,6 +194,50 @@ func TestOTLPJobLoggerRedactsSecretsSplitAcrossWrites(t *testing.T) { } } +// TestOTLPJobLoggerRedactsSecretsSplitAcrossCommands ensures the OTLP redactor +// retains partial matches across wrappers for sequential commands that share +// the same downstream job-log stream. +func TestOTLPJobLoggerRedactsSecretsSplitAcrossCommands(t *testing.T) { + t.Parallel() + + const secret = "supersekret-value" + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap, secret) + var downstream bytes.Buffer + + first := l.Wrap(t.Context(), &downstream, map[string]string{"buildkite.phase": "checkout"}) + if _, err := first.Write([]byte("start super")); err != nil { + t.Fatalf("first Write() error = %v", err) + } + if f, ok := first.(interface{ Flush() }); ok { + f.Flush() + } + + second := l.Wrap(t.Context(), &downstream, map[string]string{"buildkite.phase": "command"}) + if _, err := second.Write([]byte("sekret-value end\n")); err != nil { + t.Fatalf("second Write() error = %v", err) + } + if f, ok := second.(interface{ Flush() }); ok { + f.Flush() + } + if err := l.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + + cap.mu.Lock() + defer cap.mu.Unlock() + body := strings.Join(cap.bodies, "") + if strings.Contains(body, secret) || strings.Contains(body, "super") || strings.Contains(body, "sekret-value") { + t.Errorf("OTLP records leaked secret fragments across commands: %q", cap.bodies) + } + if !strings.Contains(body, "[REDACTED]") { + t.Errorf("OTLP records = %q, want them to contain [REDACTED]", cap.bodies) + } + if got := downstream.String(); got != "start "+secret+" end\n" { + t.Errorf("downstream = %q, want unmodified command output", got) + } +} + func TestOTLPJobLoggerChunksUnterminatedOutput(t *testing.T) { t.Parallel() From 6dc004a527d271e15b0910e2d30fd15e7cfce0e5 Mon Sep 17 00:00:00 2001 From: Chris Atkins Date: Wed, 15 Jul 2026 13:02:21 +1000 Subject: [PATCH 13/13] Align OTLP redaction flush boundaries --- internal/job/executor.go | 19 ++++++++++-- internal/job/otlp_job_logger.go | 20 +++++++++---- internal/job/otlp_job_logger_test.go | 44 ++++++++++++++++++++++++++++ 3 files changed, 75 insertions(+), 8 deletions(-) diff --git a/internal/job/executor.go b/internal/job/executor.go index 8adbf89839..da10d945e6 100644 --- a/internal/job/executor.go +++ b/internal/job/executor.go @@ -74,6 +74,11 @@ type Executor struct { // In order for the latter to happen, a reference is passed into the the Job API server as well redactors *replacer.Mux + // otlpJobLogger retains the OTLP redaction streams while job log export is + // enabled. Executor redactor flush boundaries must flush these streams too + // so OTLP and the customer-facing job log have identical stream semantics. + otlpJobLogger *otlpJobLogger + // jobAPI is the Job API server for this job. It's retained so the executor // can consume out-of-band requests made by hooks, such as a working // directory set by an unwrapped hook via the /workdir endpoint. @@ -205,6 +210,7 @@ func (e *Executor) Run(ctx context.Context) (exitCode int) { if err != nil { e.shell.Warningf("Failed to initialize OTLP job log exporter: %v", err) } else { + e.otlpJobLogger = jobLogger e.shell.SetOutputInterceptor(jobLogger.Wrap) // Mirror the redacted shell logger control output (section headers, // prompts, comments, warnings) into OTLP so the exported records @@ -219,6 +225,7 @@ func (e *Executor) Run(ctx context.Context) (exitCode int) { if err := jobLogger.Close(); err != nil { e.shell.Warningf("Failed to close OTLP job log exporter: %v", err) } + e.otlpJobLogger = nil }() } } @@ -616,7 +623,7 @@ func logMissingHookInfo(l shell.Logger, hookName, wrapperPath string) { func (e *Executor) runWrappedShellScriptHook(ctx context.Context, hookName string, hookCfg HookConfig) error { defer func() { - if err := e.redactors.Flush(); err != nil { + if err := e.flushOutputRedactors(); err != nil { e.shell.Errorf("Error flushing redactors: %v", err) } }() @@ -809,6 +816,14 @@ func (e *Executor) addOutputRedactors() { } } +func (e *Executor) flushOutputRedactors() error { + err := e.redactors.Flush() + if e.otlpJobLogger != nil { + e.otlpJobLogger.FlushRedactors() + } + return err +} + func (e *Executor) hasGlobalHook(name string) bool { _, err := hook.Find(nil, e.HooksPath, name) if err == nil { @@ -1246,7 +1261,7 @@ func (e *Executor) CommandPhase(ctx context.Context) (hookErr, commandErr error) // defaultCommandPhase is executed if there is no global or plugin command hook func (e *Executor) defaultCommandPhase(ctx context.Context) (retErr error) { defer func() { - if err := e.redactors.Flush(); err != nil { + if err := e.flushOutputRedactors(); err != nil { e.shell.Errorf("Error flushing redactors: %v", err) } }() diff --git a/internal/job/otlp_job_logger.go b/internal/job/otlp_job_logger.go index 3cc1831dbf..8cec1f52d7 100644 --- a/internal/job/otlp_job_logger.go +++ b/internal/job/otlp_job_logger.go @@ -149,12 +149,7 @@ func (l *otlpJobLogger) Close() error { if l.control != nil { l.control.flush() } - l.streamsMu.Lock() - streams := append([]*otlpJobLogStream(nil), l.streams...) - l.streamsMu.Unlock() - for _, stream := range streams { - stream.flush() - } + l.FlushRedactors() if l.provider == nil { return nil } @@ -169,6 +164,19 @@ func (l *otlpJobLogger) Close() error { return shutdownErr } +// FlushRedactors ends the current shared OTLP redaction streams. The executor +// calls this at the same explicit hook/default-command boundaries where it +// flushes the customer-facing redactors. Individual subprocesses within one of +// those phases deliberately do not flush this state. +func (l *otlpJobLogger) FlushRedactors() { + l.streamsMu.Lock() + streams := append([]*otlpJobLogStream(nil), l.streams...) + l.streamsMu.Unlock() + for _, stream := range streams { + stream.flush() + } +} + // otlpJobLogWriter tees process output to the normal (already redacting) job-log // writer and to a redacting OTLP line emitter, so OTLP records carry the same // redacted content as the customer-facing job log. diff --git a/internal/job/otlp_job_logger_test.go b/internal/job/otlp_job_logger_test.go index c37d382858..5bc3ae6e6a 100644 --- a/internal/job/otlp_job_logger_test.go +++ b/internal/job/otlp_job_logger_test.go @@ -238,6 +238,50 @@ func TestOTLPJobLoggerRedactsSecretsSplitAcrossCommands(t *testing.T) { } } +// TestOTLPJobLoggerFlushRedactorsMatchesExecutorBoundary ensures an explicit +// executor redactor flush ends a partial match and emits it using the phase +// that produced it, while ordinary per-command flushes do not. +func TestOTLPJobLoggerFlushRedactorsMatchesExecutorBoundary(t *testing.T) { + t.Parallel() + + const secret = "supersekret-value" + cap := &captureLogger{} + l := newTestOTLPJobLogger(cap, secret) + var downstream bytes.Buffer + + first := l.Wrap(t.Context(), &downstream, map[string]string{"buildkite.phase": "hook"}) + if _, err := first.Write([]byte("start super")); err != nil { + t.Fatalf("first Write() error = %v", err) + } + if f, ok := first.(interface{ Flush() }); ok { + f.Flush() + } + l.FlushRedactors() + + second := l.Wrap(t.Context(), &downstream, map[string]string{"buildkite.phase": "command"}) + if _, err := second.Write([]byte("sekret-value end\n")); err != nil { + t.Fatalf("second Write() error = %v", err) + } + if f, ok := second.(interface{ Flush() }); ok { + f.Flush() + } + + cap.mu.Lock() + defer cap.mu.Unlock() + // The first command flush has already emitted the safe prefix. The + // executor boundary then releases the withheld partial match before the + // next phase starts. + want := []string{"start ", "super", "sekret-value end"} + if len(cap.bodies) != len(want) { + t.Fatalf("emitted records = %q, want %q", cap.bodies, want) + } + for i := range want { + if cap.bodies[i] != want[i] { + t.Errorf("record[%d] = %q, want %q", i, cap.bodies[i], want[i]) + } + } +} + func TestOTLPJobLoggerChunksUnterminatedOutput(t *testing.T) { t.Parallel()