Merge pull request #42 from grafana/feat/spanlogger

Feature: Add spanlogger package

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

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

spanlogger/spanlogger.go

@@ -0,0 +1,123 @@
+package spanlogger
+
+import (
+	"context"
+	"strings"
+
+	"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/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
+}
+
+// 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
+}
+
+// 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)
+}

spanlogger/spanlogger_test.go

@@ -0,0 +1,76 @@
+package spanlogger
+
+import (
+	"context"
+	"testing"
+
+	"github.com/go-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...)
+}