1 package context 2 3 import ( 4 "context" 5 "runtime" 6 "time" 7 8 "github.com/docker/distribution/uuid" 9 ) 10 11 // WithTrace allocates a traced timing span in a new context. This allows a 12 // caller to track the time between calling WithTrace and the returned done 13 // function. When the done function is called, a log message is emitted with a 14 // "trace.duration" field, corresponding to the elapsed time and a 15 // "trace.func" field, corresponding to the function that called WithTrace. 16 // 17 // The logging keys "trace.id" and "trace.parent.id" are provided to implement 18 // dapper-like tracing. This function should be complemented with a WithSpan 19 // method that could be used for tracing distributed RPC calls. 20 // 21 // The main benefit of this function is to post-process log messages or 22 // intercept them in a hook to provide timing data. Trace ids and parent ids 23 // can also be linked to provide call tracing, if so required. 24 // 25 // Here is an example of the usage: 26 // 27 // func timedOperation(ctx Context) { 28 // ctx, done := WithTrace(ctx) 29 // defer done("this will be the log message") 30 // // ... function body ... 31 // } 32 // 33 // If the function ran for roughly 1s, such a usage would emit a log message 34 // as follows: 35 // 36 // INFO[0001] this will be the log message trace.duration=1.004575763s trace.func=github.com/docker/distribution/context.traceOperation trace.id=<id> ... 37 // 38 // Notice that the function name is automatically resolved, along with the 39 // package and a trace id is emitted that can be linked with parent ids. 40 func WithTrace(ctx context.Context) (context.Context, func(format string, a ...interface{})) { 41 if ctx == nil { 42 ctx = Background() 43 } 44 45 pc, file, line, _ := runtime.Caller(1) 46 f := runtime.FuncForPC(pc) 47 ctx = &traced{ 48 Context: ctx, 49 id: uuid.Generate().String(), 50 start: time.Now(), 51 parent: GetStringValue(ctx, "trace.id"), 52 fnname: f.Name(), 53 file: file, 54 line: line, 55 } 56 57 return ctx, func(format string, a ...interface{}) { 58 GetLogger(ctx, 59 "trace.duration", 60 "trace.id", 61 "trace.parent.id", 62 "trace.func", 63 "trace.file", 64 "trace.line"). 65 Debugf(format, a...) 66 } 67 } 68 69 // traced represents a context that is traced for function call timing. It 70 // also provides fast lookup for the various attributes that are available on 71 // the trace. 72 type traced struct { 73 context.Context 74 id string 75 parent string 76 start time.Time 77 fnname string 78 file string 79 line int 80 } 81 82 func (ts *traced) Value(key interface{}) interface{} { 83 switch key { 84 case "trace.start": 85 return ts.start 86 case "trace.duration": 87 return time.Since(ts.start) 88 case "trace.id": 89 return ts.id 90 case "trace.parent.id": 91 if ts.parent == "" { 92 return nil // must return nil to signal no parent. 93 } 94 95 return ts.parent 96 case "trace.func": 97 return ts.fnname 98 case "trace.file": 99 return ts.file 100 case "trace.line": 101 return ts.line 102 } 103 104 return ts.Context.Value(key) 105 } 106