9c88801a12
Back in the before time, the best practices surrounding usage of Context weren't quite worked out. We defined our own type to make usage easier. As this packaged was used elsewhere, it make it more and more challenging to integrate with the forked `Context` type. Now that it is available in the standard library, we can just use that one directly. To make usage more consistent, we now use `dcontext` when referring to the distribution context package. Signed-off-by: Stephen J Day <stephen.day@docker.com>
105 lines
2.8 KiB
Go
105 lines
2.8 KiB
Go
package context
|
|
|
|
import (
|
|
"context"
|
|
"runtime"
|
|
"time"
|
|
|
|
"github.com/docker/distribution/uuid"
|
|
)
|
|
|
|
// WithTrace allocates a traced timing span in a new context. This allows a
|
|
// caller to track the time between calling WithTrace and the returned done
|
|
// function. When the done function is called, a log message is emitted with a
|
|
// "trace.duration" field, corresponding to the elapsed time and a
|
|
// "trace.func" field, corresponding to the function that called WithTrace.
|
|
//
|
|
// The logging keys "trace.id" and "trace.parent.id" are provided to implement
|
|
// dapper-like tracing. This function should be complemented with a WithSpan
|
|
// method that could be used for tracing distributed RPC calls.
|
|
//
|
|
// The main benefit of this function is to post-process log messages or
|
|
// intercept them in a hook to provide timing data. Trace ids and parent ids
|
|
// can also be linked to provide call tracing, if so required.
|
|
//
|
|
// Here is an example of the usage:
|
|
//
|
|
// func timedOperation(ctx Context) {
|
|
// ctx, done := WithTrace(ctx)
|
|
// defer done("this will be the log message")
|
|
// // ... function body ...
|
|
// }
|
|
//
|
|
// If the function ran for roughly 1s, such a usage would emit a log message
|
|
// as follows:
|
|
//
|
|
// INFO[0001] this will be the log message trace.duration=1.004575763s trace.func=github.com/docker/distribution/context.traceOperation trace.id=<id> ...
|
|
//
|
|
// Notice that the function name is automatically resolved, along with the
|
|
// package and a trace id is emitted that can be linked with parent ids.
|
|
func WithTrace(ctx context.Context) (context.Context, func(format string, a ...interface{})) {
|
|
if ctx == nil {
|
|
ctx = Background()
|
|
}
|
|
|
|
pc, file, line, _ := runtime.Caller(1)
|
|
f := runtime.FuncForPC(pc)
|
|
ctx = &traced{
|
|
Context: ctx,
|
|
id: uuid.Generate().String(),
|
|
start: time.Now(),
|
|
parent: GetStringValue(ctx, "trace.id"),
|
|
fnname: f.Name(),
|
|
file: file,
|
|
line: line,
|
|
}
|
|
|
|
return ctx, func(format string, a ...interface{}) {
|
|
GetLogger(ctx,
|
|
"trace.duration",
|
|
"trace.id",
|
|
"trace.parent.id",
|
|
"trace.func",
|
|
"trace.file",
|
|
"trace.line").
|
|
Debugf(format, a...)
|
|
}
|
|
}
|
|
|
|
// traced represents a context that is traced for function call timing. It
|
|
// also provides fast lookup for the various attributes that are available on
|
|
// the trace.
|
|
type traced struct {
|
|
context.Context
|
|
id string
|
|
parent string
|
|
start time.Time
|
|
fnname string
|
|
file string
|
|
line int
|
|
}
|
|
|
|
func (ts *traced) Value(key interface{}) interface{} {
|
|
switch key {
|
|
case "trace.start":
|
|
return ts.start
|
|
case "trace.duration":
|
|
return time.Since(ts.start)
|
|
case "trace.id":
|
|
return ts.id
|
|
case "trace.parent.id":
|
|
if ts.parent == "" {
|
|
return nil // must return nil to signal no parent.
|
|
}
|
|
|
|
return ts.parent
|
|
case "trace.func":
|
|
return ts.fnname
|
|
case "trace.file":
|
|
return ts.file
|
|
case "trace.line":
|
|
return ts.line
|
|
}
|
|
|
|
return ts.Context.Value(key)
|
|
}
|