From 38d4544f9e0233e623c19e38d97eb88d5db3e0bf Mon Sep 17 00:00:00 2001 From: Bob Stasyszyn Date: Fri, 13 Jan 2023 14:40:41 -0500 Subject: [PATCH] feat: Add OpenTelemetry trace and span IDs Added functions to allow for logging with implicit, context-specific fields, such as OpenTelemetry trace and span ID. Signed-off-by: Bob Stasyszyn --- go.mod | 6 +++ go.sum | 14 +++++++ pkg/log/fields.go | 93 +++++++++++++++++++++++++++++------------- pkg/log/fields_test.go | 33 ++++++++++++--- pkg/log/logger.go | 70 +++++++++++++++++++++++++++++-- pkg/log/logger_test.go | 32 +++++++++++++++ 6 files changed, 210 insertions(+), 38 deletions(-) diff --git a/go.mod b/go.mod index aecc81d..0fafab3 100644 --- a/go.mod +++ b/go.mod @@ -8,13 +8,19 @@ go 1.19 require ( github.com/stretchr/testify v1.8.1 + go.opentelemetry.io/otel v1.12.0 + go.opentelemetry.io/otel/sdk v1.12.0 + go.opentelemetry.io/otel/trace v1.12.0 go.uber.org/zap v1.23.0 ) require ( github.com/davecgh/go-spew v1.1.1 // indirect + github.com/go-logr/logr v1.2.3 // indirect + github.com/go-logr/stdr v1.2.2 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect go.uber.org/atomic v1.7.0 // indirect go.uber.org/multierr v1.6.0 // indirect + golang.org/x/sys v0.0.0-20220919091848-fb04ddd9f9c8 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 74272bc..9874220 100644 --- a/go.sum +++ b/go.sum @@ -2,6 +2,12 @@ github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLj github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0= +github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= +github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= @@ -13,6 +19,12 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk= github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= +go.opentelemetry.io/otel v1.12.0 h1:IgfC7kqQrRccIKuB7Cl+SRUmsKbEwSGPr0Eu+/ht1SQ= +go.opentelemetry.io/otel v1.12.0/go.mod h1:geaoz0L0r1BEOR81k7/n9W4TCXYCJ7bPO7K374jQHG0= +go.opentelemetry.io/otel/sdk v1.12.0 h1:8npliVYV7qc0t1FKdpU08eMnOjgPFMnriPhn0HH4q3o= +go.opentelemetry.io/otel/sdk v1.12.0/go.mod h1:WYcvtgquYvgODEvxOry5owO2y9MyciW7JqMz6cpXShE= +go.opentelemetry.io/otel/trace v1.12.0 h1:p28in++7Kd0r2d8gSt931O57fdjUyWxkVbESuILAeUc= +go.opentelemetry.io/otel/trace v1.12.0/go.mod h1:pHlgBynn6s25qJ2szD+Bv+iwKJttjHSI3lUAyf0GNuQ= go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI= @@ -20,6 +32,8 @@ go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY= go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY= +golang.org/x/sys v0.0.0-20220919091848-fb04ddd9f9c8 h1:h+EGohizhe9XlX18rfpa8k8RAc5XyaeamM+0VHRd4lc= +golang.org/x/sys v0.0.0-20220919091848-fb04ddd9f9c8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/pkg/log/fields.go b/pkg/log/fields.go index 72cae3c..1b69a0d 100644 --- a/pkg/log/fields.go +++ b/pkg/log/fields.go @@ -7,44 +7,34 @@ SPDX-License-Identifier: Apache-2.0 package log import ( + "context" "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" + + "go.opentelemetry.io/otel/trace" ) // Log Fields. const ( - FieldAddress = "address" - FieldDuration = "duration" - FieldHTTPStatus = "httpStatus" - FieldID = "id" - FieldName = "name" - FieldPath = "path" - FieldResponse = "response" - FieldState = "state" - FieldToken = "token" - FieldTopic = "topic" - FieldTxID = "txID" - FieldURL = "url" + FieldAddress = "address" + FieldDuration = "duration" + FieldHTTPStatus = "httpStatus" + FieldID = "id" + FieldName = "name" + FieldPath = "path" + FieldResponse = "response" + FieldState = "state" + FieldToken = "token" + FieldTopic = "topic" + FieldTxID = "txID" + FieldURL = "url" + FieldTraceID = "traceID" + FieldSpanID = "spanID" + FieldParentSpanID = "parentSpanID" ) -// ObjectMarshaller uses reflection to marshal an object's fields. -type ObjectMarshaller struct { - key string - obj interface{} -} - -// NewObjectMarshaller returns a new ObjectMarshaller. -func NewObjectMarshaller(key string, obj interface{}) *ObjectMarshaller { - return &ObjectMarshaller{key: key, obj: obj} -} - -// MarshalLogObject marshals the object's fields. -func (m *ObjectMarshaller) MarshalLogObject(e zapcore.ObjectEncoder) error { - return e.AddReflected(m.key, m.obj) -} - // WithError sets the error field. func WithError(err error) zap.Field { return zap.Error(err) @@ -109,3 +99,50 @@ func WithState(state string) zap.Field { func WithAddress(address string) zap.Field { return zap.String(FieldAddress, address) } + +// WithTracing adds OpenTelemetry fields, i.e. traceID, spanID, and (optionally) parentSpanID fields. +// If the provided context doesn't contain OpenTelemetry data then the fields are not logged. +func WithTracing(ctx context.Context) zap.Field { + return zap.Inline(&otelMarshaller{ctx: ctx}) +} + +// otelMarshaller is an OpenTelemetry marshaller which adds Open-Telemetry +// trace and span IDs (as well as parent span ID if exists) to the log message. +type otelMarshaller struct { + ctx context.Context +} + +type childSpan interface { + Parent() trace.SpanContext +} + +const ( + nilTraceID = "00000000000000000000000000000000" + nilSpanID = "0000000000000000" +) + +func (m *otelMarshaller) MarshalLogObject(e zapcore.ObjectEncoder) error { + s := trace.SpanFromContext(m.ctx) + + traceID := s.SpanContext().TraceID().String() + if traceID == "" || traceID == nilTraceID { + return nil + } + + e.AddString(FieldTraceID, traceID) + + spanID := s.SpanContext().SpanID().String() + if spanID != "" && spanID != nilSpanID { + e.AddString(FieldSpanID, spanID) + } + + cspan, ok := s.(childSpan) + if ok { + parentSpanID := cspan.Parent().SpanID().String() + if parentSpanID != "" && parentSpanID != nilSpanID { + e.AddString(FieldParentSpanID, parentSpanID) + } + } + + return nil +} diff --git a/pkg/log/fields_test.go b/pkg/log/fields_test.go index 2b5fae4..cafead4 100644 --- a/pkg/log/fields_test.go +++ b/pkg/log/fields_test.go @@ -7,6 +7,7 @@ SPDX-License-Identifier: Apache-2.0 package log import ( + "context" "encoding/json" "errors" "net/http" @@ -14,6 +15,7 @@ import ( "time" "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/sdk/trace" ) //nolint:maintidx @@ -63,7 +65,17 @@ func TestStandardFields(t *testing.T) { txID := "some tx id" state := "some state" - logger.Info("Some message", + tracer := trace.NewTracerProvider().Tracer("unit-test") + + ctx, span := tracer.Start(context.Background(), "parent-span") + ctx2, span2 := tracer.Start(ctx, "child-span") + + cspan, ok := span2.(childSpan) + require.True(t, ok) + + parentSpanID := cspan.Parent().SpanID().String() + + logger.Infoc(ctx2, "Some message", WithDuration(duration), WithHTTPStatus(http.StatusNotFound), WithID(id), @@ -77,9 +89,15 @@ func TestStandardFields(t *testing.T) { WithAddress(address), ) + span2.End() + span.End() + t.Logf(stdOut.String()) l := unmarshalLogData(t, stdOut.Bytes()) + require.Equal(t, span2.SpanContext().TraceID().String(), l.TraceID) + require.Equal(t, span2.SpanContext().SpanID().String(), l.SpanID) + require.Equal(t, parentSpanID, l.ParentSpanID) require.Equal(t, 404, l.HTTPStatus) require.Equal(t, id, l.ID) require.Equal(t, name, l.Name) @@ -94,11 +112,14 @@ func TestStandardFields(t *testing.T) { } type logData struct { - Level string `json:"level"` - Time string `json:"time"` - Logger string `json:"logger"` - Caller string `json:"caller"` - Error string `json:"error"` + Level string `json:"level"` + Time string `json:"time"` + Logger string `json:"logger"` + Caller string `json:"caller"` + Error string `json:"error"` + TraceID string `json:"traceID"` + SpanID string `json:"spanID"` + ParentSpanID string `json:"parentSpanID"` HTTPStatus int `json:"httpStatus"` ID string `json:"id"` diff --git a/pkg/log/logger.go b/pkg/log/logger.go index 0a1e755..e069897 100644 --- a/pkg/log/logger.go +++ b/pkg/log/logger.go @@ -7,6 +7,7 @@ SPDX-License-Identifier: Apache-2.0 package log import ( + "context" "errors" "fmt" "os" @@ -137,18 +138,24 @@ func WithEncoding(encoding Encoding) Option { } } -// Log uses the Zap Logger to log messages in a structured way. +// Log uses the Zap Logger to log messages in a structured way. Functions are also included to +// log context-specific fields, such as OpenTelemetry trace and span IDs. type Log struct { *zap.Logger - module string + ctxLogger *zap.Logger + module string } -// New creates a structured Logger implementation based on given module name. +// New creates a Zap Logger to log messages in a structured way. func New(module string, opts ...Option) *Log { options := getOptions(opts) return &Log{ - Logger: newZap(module, options.encoding, options.stdOut, options.stdErr).With(options.fields...), + Logger: newZap(module, options.encoding, options.stdOut, options.stdErr). + With(options.fields...), + ctxLogger: newZap(module, options.encoding, options.stdOut, options.stdErr). + WithOptions(zap.AddCallerSkip(1)). + With(options.fields...), module: module, } } @@ -158,6 +165,61 @@ func (l *Log) IsEnabled(level Level) bool { return levels.isEnabled(l.module, level) } +// With creates a child logger and adds structured context to it. Fields added +// to the child don't affect the parent, and vice versa. +func (l *Log) With(fields ...zap.Field) *Log { + if len(fields) == 0 { + return l + } + + return &Log{ + Logger: l.Logger.With(fields...), + ctxLogger: l.ctxLogger.With(fields...), + module: l.module, + } +} + +// Debugc logs a message at Debug level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +func (l *Log) Debugc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Debug(msg, append(fields, WithTracing(ctx))...) +} + +// Infoc logs a message at Info level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +func (l *Log) Infoc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Info(msg, append(fields, WithTracing(ctx))...) +} + +// Warnc logs a message at Warning level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +func (l *Log) Warnc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Warn(msg, append(fields, WithTracing(ctx))...) +} + +// Errorc logs a message at Error level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +func (l *Log) Errorc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Error(msg, append(fields, WithTracing(ctx))...) +} + +// Panicc logs a message at Panic level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +// +// The logger then panics, even if logging at PanicLevel is disabled. +func (l *Log) Panicc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Panic(msg, append(fields, WithTracing(ctx))...) +} + +// Fatalc logs a message at Fatal level, including the provided fields and any implicit context +// fields (such as OpenTelemetry trace ID and span ID). +// +// The logger then calls os.Exit(1), even if logging at FatalLevel is +// disabled. +func (l *Log) Fatalc(ctx context.Context, msg string, fields ...zap.Field) { + l.ctxLogger.Fatal(msg, append(fields, WithTracing(ctx))...) +} + // SetLevel sets the log level for given module and level. func SetLevel(module string, level Level) { levels.Set(module, level) diff --git a/pkg/log/logger_test.go b/pkg/log/logger_test.go index 6f56393..821595c 100644 --- a/pkg/log/logger_test.go +++ b/pkg/log/logger_test.go @@ -8,9 +8,11 @@ package log import ( "bytes" + "context" "testing" "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/sdk/trace" ) type mockWriter struct { @@ -336,6 +338,36 @@ func TestLogLevels(t *testing.T) { require.False(t, mlevel.isEnabled("module-xyz-random-module", DEBUG)) } +func TestContextLogger(t *testing.T) { + tracer := trace.NewTracerProvider().Tracer("unit-test") + + const module = "context-module" + + SetLevel(module, DEBUG) + + t.Run("OpenTelemetry traceing", func(t *testing.T) { + stdOut := newMockWriter() + stdErr := newMockWriter() + + logger := New(module, WithStdOut(stdOut), WithStdErr(stdErr)) + + ctx, span := tracer.Start(context.Background(), "parent-span") + defer span.End() + + logger.Debugc(ctx, "Sample debug log") + logger.Infoc(ctx, "Sample info log") + logger.Warnc(ctx, "Sample warn log") + logger.Errorc(ctx, "Sample error log") + + require.Panics(t, func() { + logger.Panicc(ctx, "Sample panic log") + }) + + require.Contains(t, stdOut.Buffer.String(), "traceID") + require.Contains(t, stdOut.Buffer.String(), "spanID") + }) +} + func resetLoggingLevels() { SetLevel("module1", INFO) SetLevel("module2", INFO)