Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 7 commits into from
Nov 9, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions cli/deployment/config.go
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
5 changes: 4 additions & 1 deletion cli/server.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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,
Expand Down
8 changes: 8 additions & 0 deletions cli/testdata/coder_server_--help.golden
Original file line number Diff line number Diff line change
Expand Up @@ -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".
Expand Down
116 changes: 116 additions & 0 deletions coderd/tracing/slog.go
Original file line number Diff line number Diff line change
@@ -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
}
209 changes: 209 additions & 0 deletions coderd/tracing/slog_test.go
Original file line number Diff line number Diff line change
@@ -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
}
1 change: 1 addition & 0 deletions codersdk/deploymentconfig.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
1 change: 1 addition & 0 deletions site/src/api/typesGenerated.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down