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 <[email protected]>

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
 )

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,13 +19,21 @@ 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=
 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=

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
+}

pkg/log/fields_test.go

@@ -7,13 +7,15 @@ SPDX-License-Identifier: Apache-2.0
 package log
 
 import (
+	"context"
 	"encoding/json"
 	"errors"
 	"net/http"
 	"testing"
 	"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"`

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)

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)