vendor/github.com/docker/distribution/context/trace.go

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