feat: create tracing.SlogSink for storing logs as span events (#4962)

cli/deployment/config.go

@@ -295,6 +295,11 @@ func newConfig() *codersdk.DeploymentConfig {
 				Flag:   "trace-honeycomb-api-key",
 				Secret: true,
 			},
+			CaptureLogs: &codersdk.DeploymentConfigField[bool]{
+				Name:  "Capture Logs in Traces",
+				Usage: "Enables capturing of logs as events in traces. This is useful for debugging, but may result in a very large amount of events being sent to the tracing backend which may incur significant costs. If the verbose flag was supplied, debug-level logs will be included.",
+				Flag:  "trace-logs",
+			},
 		},
 		SecureAuthCookie: &codersdk.DeploymentConfigField[bool]{
 			Name:  "Secure Auth Cookie",

cli/server.go

@@ -88,6 +88,9 @@ func Server(vip *viper.Viper, newAPI func(context.Context, *coderd.Options) (*co
 			if ok, _ := cmd.Flags().GetBool(varVerbose); ok {
 				logger = logger.Leveled(slog.LevelDebug)
 			}
+			if cfg.Trace.CaptureLogs.Value {
+				logger = logger.AppendSinks(tracing.SlogSink{})
+			}
 
 			// Main command context for managing cancellation
 			// of running services.
@@ -126,7 +129,7 @@ func Server(vip *viper.Viper, newAPI func(context.Context, *coderd.Options) (*co
 				shouldCoderTrace = cfg.Telemetry.Trace.Value
 			}
 
-			if cfg.Trace.Enable.Value || shouldCoderTrace {
+			if cfg.Trace.Enable.Value || shouldCoderTrace || cfg.Trace.HoneycombAPIKey.Value != "" {
 				sdkTracerProvider, closeTracing, err := tracing.TracerProvider(ctx, "coderd", tracing.TracerOpts{
 					Default:   cfg.Trace.Enable.Value,
 					Coder:     shouldCoderTrace,

cli/testdata/coder_server_--help.golden

@@ -188,6 +188,14 @@ Flags:
       --trace-honeycomb-api-key string               Enables trace exporting to Honeycomb.io
                                                      using the provided API Key.
                                                      Consumes $CODER_TRACE_HONEYCOMB_API_KEY
+      --trace-logs                                   Enables capturing of logs as events in
+                                                     traces. This is useful for debugging, but
+                                                     may result in a very large amount of
+                                                     events being sent to the tracing backend
+                                                     which may incur significant costs. If the
+                                                     verbose flag was supplied, debug-level
+                                                     logs will be included.
+                                                     Consumes $CODER_TRACE_CAPTURE_LOGS
       --wildcard-access-url string                   Specifies the wildcard hostname to use
                                                      for workspace applications in the form
                                                      "*.example.com".

coderd/tracing/slog.go

@@ -0,0 +1,116 @@
+package tracing
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"time"
+
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+
+	"cdr.dev/slog"
+)
+
+type SlogSink struct{}
+
+var _ slog.Sink = SlogSink{}
+
+// LogEntry implements slog.Sink. All entries are added as events to the span
+// in the context. If no span is present, the entry is dropped.
+func (SlogSink) LogEntry(ctx context.Context, e slog.SinkEntry) {
+	span := trace.SpanFromContext(ctx)
+	if !span.IsRecording() {
+		// If the span is a noopSpan or isn't recording, we don't want to
+		// compute the attributes (which is expensive) below.
+		return
+	}
+
+	attributes := []attribute.KeyValue{
+		attribute.String("slog.time", e.Time.Format(time.RFC3339Nano)),
+		attribute.String("slog.logger", strings.Join(e.LoggerNames, ".")),
+		attribute.String("slog.level", e.Level.String()),
+		attribute.String("slog.message", e.Message),
+		attribute.String("slog.func", e.Func),
+		attribute.String("slog.file", e.File),
+		attribute.Int64("slog.line", int64(e.Line)),
+	}
+	attributes = append(attributes, slogFieldsToAttributes(e.Fields)...)
+
+	name := fmt.Sprintf("log: %s: %s", e.Level, e.Message)
+	span.AddEvent(name, trace.WithAttributes(attributes...))
+}
+
+// Sync implements slog.Sink. No-op as syncing is handled externally by otel.
+func (SlogSink) Sync() {}
+
+func slogFieldsToAttributes(m slog.Map) []attribute.KeyValue {
+	attrs := make([]attribute.KeyValue, 0, len(m))
+	for _, f := range m {
+		var value attribute.Value
+		switch v := f.Value.(type) {
+		case bool:
+			value = attribute.BoolValue(v)
+		case []bool:
+			value = attribute.BoolSliceValue(v)
+		case float32:
+			value = attribute.Float64Value(float64(v))
+		// no float32 slice method
+		case float64:
+			value = attribute.Float64Value(v)
+		case []float64:
+			value = attribute.Float64SliceValue(v)
+		case int:
+			value = attribute.Int64Value(int64(v))
+		case []int:
+			value = attribute.IntSliceValue(v)
+		case int8:
+			value = attribute.Int64Value(int64(v))
+		// no int8 slice method
+		case int16:
+			value = attribute.Int64Value(int64(v))
+		// no int16 slice method
+		case int32:
+			value = attribute.Int64Value(int64(v))
+		// no int32 slice method
+		case int64:
+			value = attribute.Int64Value(v)
+		case []int64:
+			value = attribute.Int64SliceValue(v)
+		case uint:
+			value = attribute.Int64Value(int64(v))
+		// no uint slice method
+		case uint8:
+			value = attribute.Int64Value(int64(v))
+		// no uint8 slice method
+		case uint16:
+			value = attribute.Int64Value(int64(v))
+		// no uint16 slice method
+		case uint32:
+			value = attribute.Int64Value(int64(v))
+		// no uint32 slice method
+		case uint64:
+			value = attribute.Int64Value(int64(v))
+		// no uint64 slice method
+		case string:
+			value = attribute.StringValue(v)
+		case []string:
+			value = attribute.StringSliceValue(v)
+		case time.Duration:
+			value = attribute.StringValue(v.String())
+		case time.Time:
+			value = attribute.StringValue(v.Format(time.RFC3339Nano))
+		case fmt.Stringer:
+			value = attribute.StringValue(v.String())
+		}
+
+		if value.Type() != attribute.INVALID {
+			attrs = append(attrs, attribute.KeyValue{
+				Key:   attribute.Key(f.Name),
+				Value: value,
+			})
+		}
+	}
+
+	return attrs
+}

coderd/tracing/slog_test.go

@@ -0,0 +1,209 @@
+package tracing_test
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"testing"
+	"time"
+
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+
+	"github.com/stretchr/testify/require"
+
+	"cdr.dev/slog"
+	"github.com/coder/coder/coderd/tracing"
+)
+
+type stringer string
+
+var _ fmt.Stringer = stringer("")
+
+func (s stringer) String() string {
+	return string(s)
+}
+
+type traceEvent struct {
+	name       string
+	attributes []attribute.KeyValue
+}
+
+type slogFakeSpan struct {
+	trace.Span // always nil
+
+	isRecording bool
+	events      []traceEvent
+}
+
+// We overwrite some methods below.
+var _ trace.Span = &slogFakeSpan{}
+
+// IsRecording implements trace.Span.
+func (s *slogFakeSpan) IsRecording() bool {
+	return s.isRecording
+}
+
+// AddEvent implements trace.Span.
+func (s *slogFakeSpan) AddEvent(name string, options ...trace.EventOption) {
+	cfg := trace.NewEventConfig(options...)
+
+	s.events = append(s.events, traceEvent{
+		name:       name,
+		attributes: cfg.Attributes(),
+	})
+}
+
+func Test_SlogSink(t *testing.T) {
+	t.Parallel()
+
+	fieldsMap := map[string]interface{}{
+		"test_bool":      true,
+		"test_[]bool":    []bool{true, false},
+		"test_float32":   float32(1.1),
+		"test_float64":   float64(1.1),
+		"test_[]float64": []float64{1.1, 2.2},
+		"test_int":       int(1),
+		"test_[]int":     []int{1, 2},
+		"test_int8":      int8(1),
+		"test_int16":     int16(1),
+		"test_int32":     int32(1),
+		"test_int64":     int64(1),
+		"test_[]int64":   []int64{1, 2},
+		"test_uint":      uint(1),
+		"test_uint8":     uint8(1),
+		"test_uint16":    uint16(1),
+		"test_uint32":    uint32(1),
+		"test_uint64":    uint64(1),
+		"test_string":    "test",
+		"test_[]string":  []string{"test1", "test2"},
+		"test_duration":  time.Second,
+		"test_time":      time.Now(),
+		"test_stringer":  stringer("test"),
+		"test_struct": struct {
+			Field string `json:"field"`
+		}{
+			Field: "test",
+		},
+	}
+
+	entry := slog.SinkEntry{
+		Time:        time.Now(),
+		Level:       slog.LevelInfo,
+		Message:     "hello",
+		LoggerNames: []string{"foo", "bar"},
+		Func:        "hello",
+		File:        "hello.go",
+		Line:        42,
+		Fields:      mapToSlogFields(fieldsMap),
+	}
+
+	t.Run("NotRecording", func(t *testing.T) {
+		t.Parallel()
+
+		sink := tracing.SlogSink{}
+		span := &slogFakeSpan{
+			isRecording: false,
+		}
+		ctx := trace.ContextWithSpan(context.Background(), span)
+
+		sink.LogEntry(ctx, entry)
+		require.Len(t, span.events, 0)
+	})
+
+	t.Run("OK", func(t *testing.T) {
+		t.Parallel()
+
+		sink := tracing.SlogSink{}
+		sink.Sync()
+
+		span := &slogFakeSpan{
+			isRecording: true,
+		}
+		ctx := trace.ContextWithSpan(context.Background(), span)
+
+		sink.LogEntry(ctx, entry)
+		require.Len(t, span.events, 1)
+
+		sink.LogEntry(ctx, entry)
+		require.Len(t, span.events, 2)
+
+		e := span.events[0]
+		require.Equal(t, "log: INFO: hello", e.name)
+
+		expectedAttributes := mapToBasicMap(fieldsMap)
+		delete(expectedAttributes, "test_struct")
+		expectedAttributes["slog.time"] = entry.Time.Format(time.RFC3339Nano)
+		expectedAttributes["slog.logger"] = strings.Join(entry.LoggerNames, ".")
+		expectedAttributes["slog.level"] = entry.Level.String()
+		expectedAttributes["slog.message"] = entry.Message
+		expectedAttributes["slog.func"] = entry.Func
+		expectedAttributes["slog.file"] = entry.File
+		expectedAttributes["slog.line"] = int64(entry.Line)
+
+		require.Equal(t, expectedAttributes, attributesToMap(e.attributes))
+	})
+}
+
+func mapToSlogFields(m map[string]interface{}) slog.Map {
+	fields := make(slog.Map, 0, len(m))
+	for k, v := range m {
+		fields = append(fields, slog.F(k, v))
+	}
+
+	return fields
+}
+
+func mapToBasicMap(m map[string]interface{}) map[string]interface{} {
+	basic := make(map[string]interface{}, len(m))
+	for k, v := range m {
+		var val interface{} = v
+		switch v := v.(type) {
+		case float32:
+			val = float64(v)
+		case int:
+			val = int64(v)
+		case []int:
+			i64Slice := make([]int64, len(v))
+			for i, v := range v {
+				i64Slice[i] = int64(v)
+			}
+			val = i64Slice
+		case int8:
+			val = int64(v)
+		case int16:
+			val = int64(v)
+		case int32:
+			val = int64(v)
+		case uint:
+			val = int64(v)
+		case uint8:
+			val = int64(v)
+		case uint16:
+			val = int64(v)
+		case uint32:
+			val = int64(v)
+		case uint64:
+			val = int64(v)
+		case time.Duration:
+			val = v.String()
+		case time.Time:
+			val = v.Format(time.RFC3339Nano)
+		case fmt.Stringer:
+			val = v.String()
+		}
+
+		basic[k] = val
+	}
+
+	return basic
+}
+
+func attributesToMap(attrs []attribute.KeyValue) map[string]interface{} {
+	m := make(map[string]interface{}, len(attrs))
+	for _, attr := range attrs {
+		m[string(attr.Key)] = attr.Value.AsInterface()
+	}
+
+	return m
+}

codersdk/deploymentconfig.go

@@ -111,6 +111,7 @@ type TLSConfig struct {
 type TraceConfig struct {
 	Enable          *DeploymentConfigField[bool]   `json:"enable" typescript:",notnull"`
 	HoneycombAPIKey *DeploymentConfigField[string] `json:"honeycomb_api_key" typescript:",notnull"`
+	CaptureLogs     *DeploymentConfigField[bool]   `json:"capture_logs" typescript:",notnull"`
 }
 
 type GitAuthConfig struct {

site/src/api/typesGenerated.ts

@@ -676,6 +676,7 @@ export interface TemplateVersionsByTemplateRequest extends Pagination {
 export interface TraceConfig {
   readonly enable: DeploymentConfigField<boolean>
   readonly honeycomb_api_key: DeploymentConfigField<string>
+  readonly capture_logs: DeploymentConfigField<boolean>
 }
 
 // From codersdk/templates.go