From 63e6de60007f1bd9ea8aec0c6e38add2228a552a 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 | 3 +- spanlogger/noop.go | 52 ++++++++++++++ spanlogger/spanlogger.go | 123 ++++++++++++++++++++++++++++++++++ spanlogger/spanlogger_test.go | 76 +++++++++++++++++++++ 4 files changed, 253 insertions(+), 1 deletion(-) create mode 100644 spanlogger/noop.go create mode 100644 spanlogger/spanlogger.go create mode 100644 spanlogger/spanlogger_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index f20521261..7043a779b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,4 +9,5 @@ * [CHANGE] Rename `kv/kvtls` to `crypto/tls`. #39 * [ENHANCEMENT] Add middleware package. #38 * [ENHANCEMENT] Add limiter package. #41 -* [ENHANCEMENT] Add grpcclient, grpcencoding and grpcutil packages. #39 \ No newline at end of file +* [ENHANCEMENT] Add grpcclient, grpcencoding and grpcutil packages. #39 +* [ENHANCEMENT] Add spanlogger package. #42 \ No newline at end of file diff --git a/spanlogger/noop.go b/spanlogger/noop.go new file mode 100644 index 000000000..8c7480ec8 --- /dev/null +++ b/spanlogger/noop.go @@ -0,0 +1,52 @@ +package spanlogger + +import ( + opentracing "github.com/opentracing/opentracing-go" + "github.com/opentracing/opentracing-go/log" +) + +type noopTracer struct{} + +type noopSpan struct{} +type noopSpanContext struct{} + +var ( + defaultNoopSpanContext = noopSpanContext{} + defaultNoopSpan = noopSpan{} + defaultNoopTracer = noopTracer{} +) + +const ( + emptyString = "" +) + +func (n noopSpanContext) ForeachBaggageItem(handler func(k, v string) bool) {} + +func (n noopSpan) Context() opentracing.SpanContext { return defaultNoopSpanContext } +func (n noopSpan) SetBaggageItem(key, val string) opentracing.Span { return defaultNoopSpan } +func (n noopSpan) BaggageItem(key string) string { return emptyString } +func (n noopSpan) SetTag(key string, value interface{}) opentracing.Span { return n } +func (n noopSpan) LogFields(fields ...log.Field) {} +func (n noopSpan) LogKV(keyVals ...interface{}) {} +func (n noopSpan) Finish() {} +func (n noopSpan) FinishWithOptions(opts opentracing.FinishOptions) {} +func (n noopSpan) SetOperationName(operationName string) opentracing.Span { return n } +func (n noopSpan) Tracer() opentracing.Tracer { return defaultNoopTracer } +func (n noopSpan) LogEvent(event string) {} +func (n noopSpan) LogEventWithPayload(event string, payload interface{}) {} +func (n noopSpan) Log(data opentracing.LogData) {} + +// StartSpan belongs to the Tracer interface. +func (n noopTracer) StartSpan(operationName string, opts ...opentracing.StartSpanOption) opentracing.Span { + return defaultNoopSpan +} + +// Inject belongs to the Tracer interface. +func (n noopTracer) Inject(sp opentracing.SpanContext, format interface{}, carrier interface{}) error { + return nil +} + +// Extract belongs to the Tracer interface. +func (n noopTracer) Extract(format interface{}, carrier interface{}) (opentracing.SpanContext, error) { + return nil, opentracing.ErrSpanContextNotFound +} diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go new file mode 100644 index 000000000..e3c311362 --- /dev/null +++ b/spanlogger/spanlogger.go @@ -0,0 +1,123 @@ +package spanlogger + +import ( + "context" + "strings" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" + opentracing "github.com/opentracing/opentracing-go" + "github.com/opentracing/opentracing-go/ext" + otlog "github.com/opentracing/opentracing-go/log" + "github.com/weaveworks/common/tracing" + "github.com/weaveworks/common/user" +) + +type loggerCtxMarker struct{} + +const ( + // TenantIDsTagName is the tenant IDs tag name. + TenantIDsTagName = "tenant_ids" +) + +var ( + loggerCtxKey = &loggerCtxMarker{} +) + +// SpanLogger unifies tracing and logging, to reduce repetition. +type SpanLogger struct { + log.Logger + opentracing.Span +} + +// 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) +} + +// 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 id := tenantID(ctx); id != "" { + span.SetTag(TenantIDsTagName, []string{id}) + } + l := &SpanLogger{ + Logger: log.With(withContext(ctx, logger), "method", method), + Span: span, + } + if len(kvps) > 0 { + level.Debug(l).Log(kvps...) + } + + ctx = context.WithValue(ctx, loggerCtxKey, logger) + return l, 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 +// within the context. If the context doesn't have a logger, the fallback +// logger is used. +func FromContext(ctx context.Context, fallback log.Logger) *SpanLogger { + logger, ok := ctx.Value(loggerCtxKey).(log.Logger) + if !ok { + logger = fallback + } + sp := opentracing.SpanFromContext(ctx) + if sp == nil { + sp = defaultNoopSpan + } + return &SpanLogger{ + Logger: withContext(ctx, logger), + Span: sp, + } +} + +// Log implements gokit's Logger interface; sends logs to underlying logger and +// also puts the on the spans. +func (s *SpanLogger) Log(kvps ...interface{}) error { + s.Logger.Log(kvps...) + fields, err := otlog.InterleavedKVToFields(kvps...) + if err != nil { + return err + } + s.Span.LogFields(fields...) + return nil +} + +// 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 + } + ext.Error.Set(s.Span, true) + s.Span.LogFields(otlog.Error(err)) + return err +} diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go new file mode 100644 index 000000000..a294e93a9 --- /dev/null +++ b/spanlogger/spanlogger_test.go @@ -0,0 +1,76 @@ +package spanlogger + +import ( + "context" + "testing" + + "github.com/go-kit/kit/log" + "github.com/opentracing/opentracing-go" + "github.com/opentracing/opentracing-go/mocktracer" + "github.com/pkg/errors" + "github.com/stretchr/testify/require" + "github.com/weaveworks/common/user" +) + +func TestSpanLogger_Log(t *testing.T) { + logger := log.NewNopLogger() + span, ctx := New(context.Background(), logger, "test", "bar") + _ = span.Log("foo") + newSpan := FromContext(ctx, logger) + require.Equal(t, span.Span, newSpan.Span) + _ = newSpan.Log("bar") + noSpan := FromContext(context.Background(), logger) + _ = noSpan.Log("foo") + require.Error(t, noSpan.Error(errors.New("err"))) + require.NoError(t, noSpan.Error(nil)) +} + +func TestSpanLogger_CustomLogger(t *testing.T) { + var logged [][]interface{} + var logger funcLogger = func(keyvals ...interface{}) error { + logged = append(logged, keyvals) + return nil + } + span, ctx := New(context.Background(), logger, "test") + _ = span.Log("msg", "original spanlogger") + + span = FromContext(ctx, log.NewNopLogger()) + _ = span.Log("msg", "restored spanlogger") + + span = FromContext(context.Background(), logger) + _ = span.Log("msg", "fallback spanlogger") + + expect := [][]interface{}{ + {"method", "test", "msg", "original spanlogger"}, + {"msg", "restored spanlogger"}, + {"msg", "fallback spanlogger"}, + } + require.Equal(t, expect, logged) +} + +func TestSpanCreatedWithTenantTag(t *testing.T) { + mockSpan := createSpan(user.InjectOrgID(context.Background(), "team-a")) + + require.Equal(t, []string{"team-a"}, mockSpan.Tag(TenantIDsTagName)) +} + +func TestSpanCreatedWithoutTenantTag(t *testing.T) { + mockSpan := createSpan(context.Background()) + + _, exist := mockSpan.Tags()[TenantIDsTagName] + require.False(t, exist) +} + +func createSpan(ctx context.Context) *mocktracer.MockSpan { + mockTracer := mocktracer.New() + opentracing.SetGlobalTracer(mockTracer) + + logger, _ := New(ctx, log.NewNopLogger(), "name") + return logger.Span.(*mocktracer.MockSpan) +} + +type funcLogger func(keyvals ...interface{}) error + +func (f funcLogger) Log(keyvals ...interface{}) error { + return f(keyvals...) +}