-
Notifications
You must be signed in to change notification settings - Fork 60
/
spanlogger.go
183 lines (162 loc) · 5.6 KB
/
spanlogger.go
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
package spanlogger
import (
"context"
"go.uber.org/atomic" // Really just need sync/atomic but there is a lint rule preventing it.
"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/grafana/dskit/tracing"
)
type loggerCtxMarker struct{}
// TenantResolver provides methods for extracting tenant IDs from a context.
type TenantResolver interface {
// TenantID tries to extract a tenant ID from a context.
TenantID(context.Context) (string, error)
// TenantIDs tries to extract tenant IDs from a context.
TenantIDs(context.Context) ([]string, error)
}
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 {
ctx context.Context // context passed in, with logger
resolver TenantResolver // passed in
baseLogger log.Logger // passed in
logger atomic.Pointer[log.Logger] // initialized on first use
opentracing.Span
sampled bool
debugEnabled bool
}
// 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, resolver TenantResolver, kvps ...interface{}) (*SpanLogger, context.Context) {
span, ctx := opentracing.StartSpanFromContext(ctx, method)
if ids, err := resolver.TenantIDs(ctx); err == nil && len(ids) > 0 {
span.SetTag(TenantIDsTagName, ids)
}
_, sampled := tracing.ExtractSampledTraceID(ctx)
l := &SpanLogger{
ctx: ctx,
resolver: resolver,
baseLogger: log.With(logger, "method", method),
Span: span,
sampled: sampled,
debugEnabled: debugEnabled(logger),
}
if len(kvps) > 0 {
l.DebugLog(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, resolver TenantResolver) *SpanLogger {
logger, ok := ctx.Value(loggerCtxKey).(log.Logger)
if !ok {
logger = fallback
}
sampled := false
sp := opentracing.SpanFromContext(ctx)
if sp == nil {
sp = opentracing.NoopTracer{}.StartSpan("noop")
} else {
_, sampled = tracing.ExtractSampledTraceID(ctx)
}
return &SpanLogger{
ctx: ctx,
baseLogger: logger,
resolver: resolver,
Span: sp,
sampled: sampled,
debugEnabled: debugEnabled(logger),
}
}
// Detect whether we should output debug logging.
// false iff the logger says it's not enabled; true if the logger doesn't say.
func debugEnabled(logger log.Logger) bool {
if x, ok := logger.(interface{ DebugEnabled() bool }); ok && !x.DebugEnabled() {
return false
}
return true
}
// 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.getLogger().Log(kvps...)
return s.spanLog(kvps...)
}
// DebugLog is more efficient than level.Debug().Log().
// Also it swallows the error return because nobody checks for errors on debug logs.
func (s *SpanLogger) DebugLog(kvps ...interface{}) {
if s.debugEnabled {
// The call to Log() through an interface makes its argument escape, so make a copy here,
// in the debug-only path, so the function is faster for the non-debug path.
localCopy := append([]any{}, kvps...)
level.Debug(s.getLogger()).Log(localCopy...)
}
_ = s.spanLog(kvps...)
}
func (s *SpanLogger) spanLog(kvps ...interface{}) error {
if !s.sampled {
return nil
}
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 || !s.sampled {
return err
}
ext.Error.Set(s.Span, true)
s.Span.LogFields(otlog.Error(err))
return err
}
func (s *SpanLogger) getLogger() log.Logger {
pLogger := s.logger.Load()
if pLogger != nil {
return *pLogger
}
// If no logger stored in the pointer, start to make one.
logger := s.baseLogger
userID, err := s.resolver.TenantID(s.ctx)
if err == nil && userID != "" {
logger = log.With(logger, "user", userID)
}
traceID, ok := tracing.ExtractSampledTraceID(s.ctx)
if ok {
logger = log.With(logger, "trace_id", traceID)
}
// If the value has been set by another goroutine, fetch that other value and discard the one we made.
if !s.logger.CompareAndSwap(nil, &logger) {
pLogger := s.logger.Load()
logger = *pLogger
}
return logger
}
// SetSpanAndLogTag sets a tag on the span used by this SpanLogger, and appends a key/value pair to the logger used for
// future log lines emitted by this SpanLogger.
//
// It is not safe to call this method from multiple goroutines simultaneously.
// It is safe to call this method at the same time as calling other SpanLogger methods, however, this may produce
// inconsistent results (eg. some log lines may be emitted with the provided key/value pair, and others may not).
func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) {
s.Span.SetTag(key, value)
logger := s.getLogger()
wrappedLogger := log.With(logger, key, value)
s.logger.Store(&wrappedLogger)
}