From fa597b572e845c87adc6832c30cd5c01c76d609e Mon Sep 17 00:00:00 2001 From: Arve Knudsen Date: Thu, 7 Oct 2021 11:25:15 +0200 Subject: [PATCH] Add spanlogger package Signed-off-by: Arve Knudsen --- CHANGELOG.md | 1 + spanlogger/spanlogger.go | 89 +++++++++++++++++++++-------------- spanlogger/spanlogger_test.go | 21 +++++---- 3 files changed, 66 insertions(+), 45 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1250ce6f3..e8149102a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,3 +12,4 @@ * [ENHANCEMENT] Add limiter package. #41 * [ENHANCEMENT] Add grpcclient, grpcencoding and grpcutil packages. #39 * [ENHANCEMENT] Replace go-kit/kit/log with go-kit/log. #52 +* [ENHANCEMENT] Add spanlogger package. #42 \ No newline at end of file diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index a856ceed7..b2a6d2c0e 100644 --- a/spanlogger/spanlogger.go +++ b/spanlogger/spanlogger.go @@ -2,21 +2,22 @@ package spanlogger import ( "context" + "strings" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" + "github.com/go-kit/log" + "github.com/go-kit/log/level" opentracing "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" otlog "github.com/opentracing/opentracing-go/log" - - "github.com/cortexproject/cortex/pkg/tenant" - util_log "github.com/cortexproject/cortex/pkg/util/log" + "github.com/weaveworks/common/tracing" + "github.com/weaveworks/common/user" ) type loggerCtxMarker struct{} const ( - TenantIDTagName = "tenant_ids" + // TenantIDsTagName is the tenant IDs tag name. + TenantIDsTagName = "tenant_ids" ) var ( @@ -29,44 +30,30 @@ type SpanLogger struct { opentracing.Span } -// New makes a new SpanLogger, where logs will be sent to the global logger. -func New(ctx context.Context, method string, kvps ...interface{}) (*SpanLogger, context.Context) { - return NewWithLogger(ctx, util_log.Logger, method, kvps...) -} - -// NewWithLogger makes a new SpanLogger with a custom log.Logger to send logs -// to. The provided context will have the logger attached to it and can be -// retrieved with FromContext or FromContextWithFallback. -func NewWithLogger(ctx context.Context, l log.Logger, method string, kvps ...interface{}) (*SpanLogger, context.Context) { +// New makes a new SpanLogger with a log.Logger to send logs to. The provided context will have the logger attached +// to it and can be retrieved with FromContext. +func New(ctx context.Context, logger log.Logger, method string, kvps ...interface{}) (*SpanLogger, context.Context) { span, ctx := opentracing.StartSpanFromContext(ctx, method) - if ids, _ := tenant.TenantIDs(ctx); len(ids) > 0 { - span.SetTag(TenantIDTagName, ids) + if id := tenantID(ctx); id != "" { + span.SetTag(TenantIDsTagName, []string{id}) } - logger := &SpanLogger{ - Logger: log.With(util_log.WithContext(ctx, l), "method", method), + l := &SpanLogger{ + Logger: log.With(withContext(ctx, logger), "method", method), Span: span, } if len(kvps) > 0 { - level.Debug(logger).Log(kvps...) + level.Debug(l).Log(kvps...) } - ctx = context.WithValue(ctx, loggerCtxKey, l) - return logger, ctx -} - -// FromContext returns a span logger using the current parent span. If there -// is no parent span, the SpanLogger will only log to the logger -// in the context. If the context doesn't have a logger, the global logger -// is used. -func FromContext(ctx context.Context) *SpanLogger { - return FromContextWithFallback(ctx, util_log.Logger) + ctx = context.WithValue(ctx, loggerCtxKey, logger) + return l, ctx } -// FromContextWithFallback returns a span logger using the current parent span. -// IF there is no parent span, the SpanLogger will only log to the logger +// FromContext returns a span logger using the current parent span. +// If there is no parent span, the SpanLogger will only log to the logger // within the context. If the context doesn't have a logger, the fallback // logger is used. -func FromContextWithFallback(ctx context.Context, fallback log.Logger) *SpanLogger { +func FromContext(ctx context.Context, fallback log.Logger) *SpanLogger { logger, ok := ctx.Value(loggerCtxKey).(log.Logger) if !ok { logger = fallback @@ -76,7 +63,7 @@ func FromContextWithFallback(ctx context.Context, fallback log.Logger) *SpanLogg sp = defaultNoopSpan } return &SpanLogger{ - Logger: util_log.WithContext(ctx, logger), + Logger: withContext(ctx, logger), Span: sp, } } @@ -93,7 +80,7 @@ func (s *SpanLogger) Log(kvps ...interface{}) error { return nil } -// Error sets error flag and logs the error on the span, if non-nil. Returns the err passed in. +// Error sets error flag and logs the error on the span, if non-nil. Returns the err passed in. func (s *SpanLogger) Error(err error) error { if err == nil { return nil @@ -102,3 +89,35 @@ func (s *SpanLogger) Error(err error) error { s.Span.LogFields(otlog.Error(err)) return err } + +// tenantID tries to extract the tenant ID from ctx. +func tenantID(ctx context.Context) string { + //lint:ignore faillint wrapper around upstream method + id, err := user.ExtractOrgID(ctx) + if err != nil { + return "" + } + + // handle the relative reference to current and parent path. + if id == "." || id == ".." || strings.ContainsAny(id, `\/`) { + return "" + } + + return id +} + +func withContext(ctx context.Context, l log.Logger) log.Logger { + // Weaveworks uses "orgs" and "orgID" to represent Cortex users, + // even though the code-base generally uses `userID` to refer to the same thing. + userID := tenantID(ctx) + if userID != "" { + l = log.With(l, "org_id", userID) + } + + traceID, ok := tracing.ExtractSampledTraceID(ctx) + if !ok { + return l + } + + return log.With(l, "traceID", traceID) +} diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 4d701fcbb..1c05d00ad 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -4,7 +4,7 @@ import ( "context" "testing" - "github.com/go-kit/kit/log" + "github.com/go-kit/log" "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/mocktracer" "github.com/pkg/errors" @@ -13,12 +13,13 @@ import ( ) func TestSpanLogger_Log(t *testing.T) { - span, ctx := New(context.Background(), "test", "bar") + logger := log.NewNopLogger() + span, ctx := New(context.Background(), logger, "test", "bar") _ = span.Log("foo") - newSpan := FromContext(ctx) + newSpan := FromContext(ctx, logger) require.Equal(t, span.Span, newSpan.Span) _ = newSpan.Log("bar") - noSpan := FromContext(context.Background()) + noSpan := FromContext(context.Background(), logger) _ = noSpan.Log("foo") require.Error(t, noSpan.Error(errors.New("err"))) require.NoError(t, noSpan.Error(nil)) @@ -30,13 +31,13 @@ func TestSpanLogger_CustomLogger(t *testing.T) { logged = append(logged, keyvals) return nil } - span, ctx := NewWithLogger(context.Background(), logger, "test") + span, ctx := New(context.Background(), logger, "test") _ = span.Log("msg", "original spanlogger") - span = FromContextWithFallback(ctx, log.NewNopLogger()) + span = FromContext(ctx, log.NewNopLogger()) _ = span.Log("msg", "restored spanlogger") - span = FromContextWithFallback(context.Background(), logger) + span = FromContext(context.Background(), logger) _ = span.Log("msg", "fallback spanlogger") expect := [][]interface{}{ @@ -50,13 +51,13 @@ func TestSpanLogger_CustomLogger(t *testing.T) { func TestSpanCreatedWithTenantTag(t *testing.T) { mockSpan := createSpan(user.InjectOrgID(context.Background(), "team-a")) - require.Equal(t, []string{"team-a"}, mockSpan.Tag(TenantIDTagName)) + require.Equal(t, []string{"team-a"}, mockSpan.Tag(TenantIDsTagName)) } func TestSpanCreatedWithoutTenantTag(t *testing.T) { mockSpan := createSpan(context.Background()) - _, exist := mockSpan.Tags()[TenantIDTagName] + _, exist := mockSpan.Tags()[TenantIDsTagName] require.False(t, exist) } @@ -64,7 +65,7 @@ func createSpan(ctx context.Context) *mocktracer.MockSpan { mockTracer := mocktracer.New() opentracing.SetGlobalTracer(mockTracer) - logger, _ := New(ctx, "name") + logger, _ := New(ctx, log.NewNopLogger(), "name") return logger.Span.(*mocktracer.MockSpan) }