From e174b74cadda74b06b2f0afe954f3439d4bd047c Mon Sep 17 00:00:00 2001 From: Shawn Poulson <92753637+Baliedge@users.noreply.github.com> Date: Tue, 16 Aug 2022 10:23:29 -0400 Subject: [PATCH] Log level improvements (#126) Simplify log level usage by converting log level parameters to constant enum type. This type mirrors `logrus.Level` exactly so it can be easily converted (e.g. `level := tracing.Level(logrus.GetLevel())`). **Breaking Change**: This is a breaking change to the `tracing.WithLevel()` option. Fix documentation around meaning of level numbers. Tag spans with `log.level=` and `log.levelNum=`. Using `StartScopeError()` will also tag span in error status. --- tracing/README.md | 11 +++----- tracing/dummy_span_test.go | 35 ++++++++++++------------ tracing/level.go | 54 ++++++++++++++++++++++++++++++-------- tracing/option.go | 6 ++--- tracing/scope.go | 53 ++++++++++++++++++++----------------- tracing/tracing.go | 4 +-- 6 files changed, 97 insertions(+), 66 deletions(-) diff --git a/tracing/README.md b/tracing/README.md index 448de2a..1df9617 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -125,17 +125,14 @@ severity. Spans that do not meed the minimum severity are simply dropped and not exported. Log level is passed with option `tracing.WithLevel()` as a numeric -[RFC5424](https://www.rfc-editor.org/rfc/rfc5424) log level (0-7). +log level (0-6): Panic, Fatal, Error, Warning, Info, Debug, Trace. -As a convenience, you may use log level constants from Logrus, like so: +As a convenience, use constants, such as `tracing.DebugLevel`: ```go -import ( - "github.com/mailgun/holster/v4/tracing" - "github.com/sirupsen/logrus" -) +import "github.com/mailgun/holster/v4/tracing" -level := int64(logrus.DebugLevel) +level := tracing.DebugLevel err := tracing.InitTracing(ctx, "my library name", tracing.WithLevel(level)) ``` diff --git a/tracing/dummy_span_test.go b/tracing/dummy_span_test.go index 4d7dd8e..3ab5121 100644 --- a/tracing/dummy_span_test.go +++ b/tracing/dummy_span_test.go @@ -5,7 +5,6 @@ import ( "testing" "github.com/mailgun/holster/v4/tracing" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -23,7 +22,7 @@ func TestDummySpan(t *testing.T) { mockProcessor := new(MockSpanProcessor) mockProcessor.On("Shutdown", mock.Anything).Once().Return(nil) - level := int64(logrus.InfoLevel) + level := tracing.InfoLevel setupMockTracerProvider(t, level, mockProcessor) // Call code. @@ -49,11 +48,11 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) }) mockProcessor.On("Shutdown", mock.Anything).Once().Return(nil) - level := int64(logrus.InfoLevel) + level := tracing.InfoLevel setupMockTracerProvider(t, level, mockProcessor) // Call code. @@ -86,7 +85,7 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) firstSpan = s }) mockProcessor.On("OnEnd", matchLeafSpan). @@ -94,12 +93,12 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) leafSpan = s }) mockProcessor.On("Shutdown", mock.Anything).Once().Return(nil) - level := int64(logrus.InfoLevel) + level := tracing.InfoLevel setupMockTracerProvider(t, level, mockProcessor) // Call code. @@ -131,11 +130,11 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) }) mockProcessor.On("Shutdown", mock.Anything).Once().Return(nil) - level := int64(logrus.InfoLevel) + level := tracing.InfoLevel setupMockTracerProvider(t, level, mockProcessor) // Call code. @@ -172,7 +171,7 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) firstSpan = s }) mockProcessor.On("OnEnd", matchLeafSpan). @@ -180,12 +179,12 @@ func TestDummySpan(t *testing.T) { Run(func(args mock.Arguments) { s := args.Get(0).(sdktrace.ReadOnlySpan) assertReadOnlySpanNoError(t, s) - assertHasLogLevel(t, int64(logrus.InfoLevel), s) + assertHasLogLevel(t, tracing.InfoLevel, s) leafSpan = s }) mockProcessor.On("Shutdown", mock.Anything).Once().Return(nil) - level := int64(logrus.InfoLevel) + level := tracing.InfoLevel setupMockTracerProvider(t, level, mockProcessor) // Call code. @@ -210,7 +209,7 @@ func TestDummySpan(t *testing.T) { }) } -func assertHasLogLevel(t *testing.T, expectedLogLevel int64, s sdktrace.ReadOnlySpan) { +func assertHasLogLevel(t *testing.T, expectedLogLevel tracing.Level, s sdktrace.ReadOnlySpan) { level, ok := levelFromReadOnlySpan(s) if !ok { t.Error("Error: Expected span log level to be defined") @@ -228,17 +227,17 @@ func assertReadOnlySpanNoError(t *testing.T, s sdktrace.ReadOnlySpan) { } } -func levelFromReadOnlySpan(s sdktrace.ReadOnlySpan) (int64, bool) { +func levelFromReadOnlySpan(s sdktrace.ReadOnlySpan) (tracing.Level, bool) { for _, attr := range s.Attributes() { - if string(attr.Key) == tracing.LogLevelKey { - return attr.Value.AsInt64(), true + if string(attr.Key) == tracing.LogLevelNumKey { + return tracing.Level(attr.Value.AsInt64()), true } } - return 0, false + return tracing.Level(0), false } -func setupMockTracerProvider(t *testing.T, level int64, mockProcessor *MockSpanProcessor) { +func setupMockTracerProvider(t *testing.T, level tracing.Level, mockProcessor *MockSpanProcessor) { t.Setenv("OTEL_EXPORTERS", "none") ctx := context.Background() opts := []tracing.TracingOption{ diff --git a/tracing/level.go b/tracing/level.go index 051f3dc..be3ecb4 100644 --- a/tracing/level.go +++ b/tracing/level.go @@ -3,36 +3,58 @@ package tracing import ( "context" - "github.com/sirupsen/logrus" "go.opentelemetry.io/otel/attribute" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace" ) +type Level uint64 + // LevelTracerProvider wraps a TracerProvider to apply log level processing. -// Tag spans with `log.level=n`, where `n` is numeric log level 0-7 (RFC5424). +// Tag spans with `log.level` and `log.levelNum=n`, where `n` is numeric log +// level 0-6 (Panic, Fatal, Error, Warn, Info, Debug, Trace). // If span log level is lower severity than threshold, create a `DummySpan` // instead. -// `DummySpan` behaves like an alias of its next non-dummy ancestor, but get -// filtered out because does not get exported. Nested spans containing a mix -// of real and `DummySpan` will be linked as if the `DummySpan` never happened. +// `DummySpan` behaves like an alias of its next non-dummy ancestor, but gets +// filtered out and omitted from export. Nested spans containing a mix of real +// and `DummySpan` will be linked as if the `DummySpan` never happened. type LevelTracerProvider struct { *sdktrace.TracerProvider - level int64 + level Level } // LevelTracer is created by `LevelTracerProvider`. type LevelTracer struct { trace.Tracer - level int64 + level Level } // LogLevelKey is the span attribute key for storing numeric log level. const LogLevelKey = "log.level" +const LogLevelNumKey = "log.levelNum" + +const ( + PanicLevel Level = iota + FatalLevel + ErrorLevel + WarnLevel + InfoLevel + DebugLevel + TraceLevel +) var logLevelCtxKey struct{} +var logLevelNames = []string{ + "PANIC", + "FATAL", + "ERROR", + "WARNING", + "INFO", + "DEBUG", + "TRACE", +} -func NewLevelTracerProvider(level int64, opts ...sdktrace.TracerProviderOption) *LevelTracerProvider { +func NewLevelTracerProvider(level Level, opts ...sdktrace.TracerProviderOption) *LevelTracerProvider { tp := sdktrace.NewTracerProvider(opts...) return &LevelTracerProvider{ @@ -51,7 +73,7 @@ func (tp *LevelTracerProvider) Tracer(libraryName string, opts ...trace.TracerOp func (t *LevelTracer) Start(ctx context.Context, spanName string, opts ...trace.SpanStartOption) (context.Context, trace.Span) { // Check log level. - ctxLevel, hasLevel := ctx.Value(logLevelCtxKey).(int64) + ctxLevel, hasLevel := ctx.Value(logLevelCtxKey).(Level) if hasLevel { // Prevent log level parameter from propagating to child spans. ctx = context.WithValue(ctx, logLevelCtxKey, nil) @@ -60,12 +82,22 @@ func (t *LevelTracer) Start(ctx context.Context, spanName string, opts ...trace. return newDummySpan(ctx) } } else { - ctxLevel = int64(logrus.InfoLevel) + ctxLevel = InfoLevel } // Pass-through. spanCtx, span := t.Tracer.Start(ctx, spanName, opts...) - span.SetAttributes(attribute.Int64(LogLevelKey, ctxLevel)) + span.SetAttributes( + attribute.Int64(LogLevelNumKey, int64(ctxLevel)), + attribute.String(LogLevelKey, logLevelName(ctxLevel)), + ) return spanCtx, span } + +func logLevelName(level Level) string { + if level >= 0 && level <= 6 { + return logLevelNames[level] + } + return "" +} diff --git a/tracing/option.go b/tracing/option.go index 0c7ec9e..bb626b4 100644 --- a/tracing/option.go +++ b/tracing/option.go @@ -42,13 +42,11 @@ func (o *ResourceOption) apply(state *initState) { } type LevelTracingOption struct { - level int64 + level Level } // WithLevel passes a log level to InitTracing. -// `level` is RFC5424 numeric log level (0-7). -// For convenience, use logrus constants, such as: `int64(logrus.InfoLevel)` -func WithLevel(level int64) *LevelTracingOption { +func WithLevel(level Level) *LevelTracingOption { return &LevelTracingOption{ level: level, } diff --git a/tracing/scope.go b/tracing/scope.go index d9490d8..414f839 100644 --- a/tracing/scope.go +++ b/tracing/scope.go @@ -17,7 +17,6 @@ import ( "strconv" "github.com/mailgun/holster/v4/errors" - "github.com/sirupsen/logrus" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" @@ -32,7 +31,7 @@ const ( // Start a scope with span named after fully qualified caller function. func StartScope(ctx context.Context, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.InfoLevel) + level := InfoLevel spanName, fileTag := getCallerSpanName(2) return startSpan(ctx, spanName, fileTag, level, opts...) } @@ -40,7 +39,7 @@ func StartScope(ctx context.Context, opts ...trace.SpanStartOption) context.Cont // Start a scope with span named after fully qualified caller function with // debug log level. func StartScopeDebug(ctx context.Context, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.DebugLevel) + level := DebugLevel spanName, fileTag := getCallerSpanName(2) return startSpan(ctx, spanName, fileTag, level, opts...) } @@ -48,7 +47,7 @@ func StartScopeDebug(ctx context.Context, opts ...trace.SpanStartOption) context // Start a scope with span named after fully qualified caller function with // info log level. func StartScopeInfo(ctx context.Context, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.InfoLevel) + level := InfoLevel spanName, fileTag := getCallerSpanName(2) return startSpan(ctx, spanName, fileTag, level, opts...) } @@ -56,7 +55,7 @@ func StartScopeInfo(ctx context.Context, opts ...trace.SpanStartOption) context. // Start a scope with span named after fully qualified caller function with // warning log level. func StartScopeWarn(ctx context.Context, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.WarnLevel) + level := WarnLevel spanName, fileTag := getCallerSpanName(2) return startSpan(ctx, spanName, fileTag, level, opts...) } @@ -64,44 +63,48 @@ func StartScopeWarn(ctx context.Context, opts ...trace.SpanStartOption) context. // Start a scope with span named after fully qualified caller function with // error log level. func StartScopeError(ctx context.Context, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.ErrorLevel) + level := ErrorLevel spanName, fileTag := getCallerSpanName(2) - return startSpan(ctx, spanName, fileTag, level, opts...) + ctx = startSpan(ctx, spanName, fileTag, level, opts...) + trace.SpanFromContext(ctx).SetAttributes(attribute.Bool("error", true)) + return ctx } // Start a scope with user-provided span name. func StartNamedScope(ctx context.Context, spanName string, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.InfoLevel) + level := InfoLevel fileTag := getFileTag(2) return startSpan(ctx, spanName, fileTag, level, opts...) } // Start a scope with user-provided span name with debug log level. func StartNamedScopeDebug(ctx context.Context, spanName string, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.DebugLevel) + level := DebugLevel fileTag := getFileTag(2) return startSpan(ctx, spanName, fileTag, level, opts...) } // Start a scope with user-provided span name with info log level. func StartNamedScopeInfo(ctx context.Context, spanName string, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.InfoLevel) + level := InfoLevel fileTag := getFileTag(2) return startSpan(ctx, spanName, fileTag, level, opts...) } // Start a scope with user-provided span name with warning log level. func StartNamedScopeWarn(ctx context.Context, spanName string, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.WarnLevel) + level := WarnLevel fileTag := getFileTag(2) return startSpan(ctx, spanName, fileTag, level, opts...) } // Start a scope with user-provided span name with error log level. func StartNamedScopeError(ctx context.Context, spanName string, opts ...trace.SpanStartOption) context.Context { - level := int64(logrus.ErrorLevel) + level := ErrorLevel fileTag := getFileTag(2) - return startSpan(ctx, spanName, fileTag, level, opts...) + ctx = startSpan(ctx, spanName, fileTag, level, opts...) + trace.SpanFromContext(ctx).SetAttributes(attribute.Bool("error", true)) + return ctx } // End scope created by `StartScope()`/`StartNamedScope()`. @@ -129,7 +132,7 @@ func EndScope(ctx context.Context, err error) { // function. // Equivalent to wrapping a code block with `StartScope()`/`EndScope()`. func Scope(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.InfoLevel) + level := InfoLevel spanName, fileTag := getCallerSpanName(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -141,7 +144,7 @@ func Scope(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOptio // function. Scope tagged with log level debug. // Equivalent to wrapping a code block with `StartScope()`/`EndScope()`. func ScopeDebug(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.DebugLevel) + level := DebugLevel spanName, fileTag := getCallerSpanName(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -153,7 +156,7 @@ func ScopeDebug(ctx context.Context, action ScopeAction, opts ...trace.SpanStart // function. Scope tagged with log level info. // Equivalent to wrapping a code block with `StartScope()`/`EndScope()`. func ScopeInfo(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.InfoLevel) + level := InfoLevel spanName, fileTag := getCallerSpanName(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -165,7 +168,7 @@ func ScopeInfo(ctx context.Context, action ScopeAction, opts ...trace.SpanStartO // function. Scope tagged with log level warning. // Equivalent to wrapping a code block with `StartScope()`/`EndScope()`. func ScopeWarn(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.WarnLevel) + level := WarnLevel spanName, fileTag := getCallerSpanName(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -177,9 +180,10 @@ func ScopeWarn(ctx context.Context, action ScopeAction, opts ...trace.SpanStartO // function. Scope tagged with log level error. // Equivalent to wrapping a code block with `StartScope()`/`EndScope()`. func ScopeError(ctx context.Context, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.ErrorLevel) + level := ErrorLevel spanName, fileTag := getCallerSpanName(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) + trace.SpanFromContext(ctx).SetAttributes(attribute.Bool("error", true)) err := action(ctx) EndScope(ctx, err) return err @@ -188,7 +192,7 @@ func ScopeError(ctx context.Context, action ScopeAction, opts ...trace.SpanStart // NamedScope calls action function within a tracing span. // Equivalent to wrapping a code block with `StartNamedScope()`/`EndScope()`. func NamedScope(ctx context.Context, spanName string, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.InfoLevel) + level := InfoLevel fileTag := getFileTag(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -200,7 +204,7 @@ func NamedScope(ctx context.Context, spanName string, action ScopeAction, opts . // with log level debug. // Equivalent to wrapping a code block with `StartNamedScope()`/`EndScope()`. func NamedScopeDebug(ctx context.Context, spanName string, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.DebugLevel) + level := DebugLevel fileTag := getFileTag(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -212,7 +216,7 @@ func NamedScopeDebug(ctx context.Context, spanName string, action ScopeAction, o // with log level info. // Equivalent to wrapping a code block with `StartNamedScope()`/`EndScope()`. func NamedScopeInfo(ctx context.Context, spanName string, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.InfoLevel) + level := InfoLevel fileTag := getFileTag(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -224,7 +228,7 @@ func NamedScopeInfo(ctx context.Context, spanName string, action ScopeAction, op // with log level warning. // Equivalent to wrapping a code block with `StartNamedScope()`/`EndScope()`. func NamedScopeWarn(ctx context.Context, spanName string, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.WarnLevel) + level := WarnLevel fileTag := getFileTag(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) err := action(ctx) @@ -236,15 +240,16 @@ func NamedScopeWarn(ctx context.Context, spanName string, action ScopeAction, op // with log level error. // Equivalent to wrapping a code block with `StartNamedScope()`/`EndScope()`. func NamedScopeError(ctx context.Context, spanName string, action ScopeAction, opts ...trace.SpanStartOption) error { - level := int64(logrus.ErrorLevel) + level := ErrorLevel fileTag := getFileTag(2) ctx = startSpan(ctx, spanName, fileTag, level, opts...) + trace.SpanFromContext(ctx).SetAttributes(attribute.Bool("error", true)) err := action(ctx) EndScope(ctx, err) return err } -func startSpan(ctx context.Context, spanName, fileTag string, level int64, opts ...trace.SpanStartOption) context.Context { +func startSpan(ctx context.Context, spanName, fileTag string, level Level, opts ...trace.SpanStartOption) context.Context { opts = append(opts, trace.WithAttributes( attribute.String("file", fileTag), )) diff --git a/tracing/tracing.go b/tracing/tracing.go index b6f27e8..3a2bbcd 100644 --- a/tracing/tracing.go +++ b/tracing/tracing.go @@ -27,7 +27,7 @@ type tracerKey struct{} type initState struct { opts []sdktrace.TracerProviderOption - level int64 + level Level } var logLevels = []logrus.Level{ @@ -51,7 +51,7 @@ func InitTracing(ctx context.Context, libraryName string, opts ...TracingOption) // Setup exporter. var err error state := &initState{ - level: int64(logrus.GetLevel()), + level: Level(logrus.GetLevel()), } exportersEnv := os.Getenv("OTEL_EXPORTERS")