Add spanlogger package

Signed-off-by: Arve Knudsen <arve.knudsen@gmail.com>

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

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,21 +51,21 @@ 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)
 }
 
 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)
 }