log/log.go

   1 // Package log implements a standard convention for structured logging.
   2 // Log entries are formatted as K=V pairs.
   3 // By default, output is written to stdout; this can be changed with SetOutput.
   4 package log
   5
   6 import (
   7         "context"
   8         "fmt"
   9         "io"
  10         "os"
  11         "runtime"
  12         "strconv"
  13         "strings"
  14         "sync"
  15         "time"
  16
  17         "github.com/blockchain/errors"
  18 )
  19
  20 const rfc3339NanoFixed = "2006-01-02T15:04:05.000000000Z07:00"
  21
  22 // context key type
  23 type key int
  24
  25 var (
  26         logWriterMu sync.Mutex // protects the following
  27         logWriter   io.Writer  = os.Stdout
  28         procPrefix  []byte     // process-global prefix; see SetPrefix vs AddPrefixkv
  29
  30         // pairDelims contains a list of characters that may be used as delimeters
  31         // between key-value pairs in a log entry. Keys and values will be quoted or
  32         // otherwise formatted to ensure that key-value extraction is unambiguous.
  33         //
  34         // The list of pair delimiters follows Splunk conventions, described here:
  35         // http://answers.splunk.com/answers/143368/default-delimiters-for-key-value-extraction.html
  36         pairDelims      = " ,;|&\t\n\r"
  37         illegalKeyChars = pairDelims + `="`
  38
  39         // context key for log line prefixes
  40         prefixKey key = 0
  41 )
  42
  43 // Conventional key names for log entries
  44 const (
  45         KeyCaller = "at" // location of caller
  46         KeyTime   = "t"  // time of call
  47
  48         KeyMessage = "message" // produced by Message
  49         KeyError   = "error"   // produced by Error
  50         KeyStack   = "stack"   // used by Printkv to print stack on subsequent lines
  51
  52         keyLogError = "log-error" // for errors produced by the log package itself
  53 )
  54
  55 // SetOutput sets the log output to w.
  56 // If SetOutput hasn't been called,
  57 // the default behavior is to write to stdout.
  58 func SetOutput(w io.Writer) {
  59         logWriterMu.Lock()
  60         logWriter = w
  61         logWriterMu.Unlock()
  62 }
  63
  64 func appendPrefix(b []byte, keyval ...interface{}) []byte {
  65         // Invariant: len(keyval) is always even.
  66         if len(keyval)%2 != 0 {
  67                 panic(fmt.Sprintf("odd-length prefix args: %v", keyval))
  68         }
  69         for i := 0; i < len(keyval); i += 2 {
  70                 k := formatKey(keyval[i])
  71                 v := formatValue(keyval[i+1])
  72                 b = append(b, k...)
  73                 b = append(b, '=')
  74                 b = append(b, v...)
  75                 b = append(b, ' ')
  76         }
  77         return b
  78 }
  79
  80 // SetPrefix sets the global output prefix.
  81 func SetPrefix(keyval ...interface{}) {
  82         b := appendPrefix(nil, keyval...)
  83         logWriterMu.Lock()
  84         procPrefix = b
  85         logWriterMu.Unlock()
  86 }
  87
  88 // AddPrefixkv appends keyval to any prefix stored in ctx,
  89 // and returns a new context with the longer prefix.
  90 func AddPrefixkv(ctx context.Context, keyval ...interface{}) context.Context {
  91         p := appendPrefix(prefix(ctx), keyval...)
  92         // Note: subsequent calls will append to p, so set cap(p) here.
  93         // See TestAddPrefixkvAppendTwice.
  94         p = p[0:len(p):len(p)]
  95         return context.WithValue(ctx, prefixKey, p)
  96 }
  97
  98 func prefix(ctx context.Context) []byte {
  99         b, _ := ctx.Value(prefixKey).([]byte)
 100         return b
 101 }
 102
 103 // Printkv prints a structured log entry to stdout. Log fields are
 104 // specified as a variadic sequence of alternating keys and values.
 105 //
 106 // Duplicate keys will be preserved.
 107 //
 108 // Two fields are automatically added to the log entry: t=[time]
 109 // and at=[file:line] indicating the location of the caller.
 110 // Use SkipFunc to prevent helper functions from showing up in the
 111 // at=[file:line] field.
 112 //
 113 // Printkv will also print the stack trace, if any, on separate lines
 114 // following the message. The stack is obtained from the following,
 115 // in order of preference:
 116 //   - a KeyStack value with type []byte or []errors.StackFrame
 117 //   - a KeyError value with type error, using the result of errors.Stack
 118 func Printkv(ctx context.Context, keyvals ...interface{}) {
 119         // Invariant: len(keyvals) is always even.
 120         if len(keyvals)%2 != 0 {
 121                 keyvals = append(keyvals, "", keyLogError, "odd number of log params")
 122         }
 123
 124         t := time.Now().UTC()
 125
 126         // Prepend the log entry with auto-generated fields.
 127         out := fmt.Sprintf(
 128                 "%s=%s %s=%s",
 129                 KeyCaller, caller(),
 130                 KeyTime, formatValue(t.Format(rfc3339NanoFixed)),
 131         )
 132
 133         var stack interface{}
 134         for i := 0; i < len(keyvals); i += 2 {
 135                 k := keyvals[i]
 136                 v := keyvals[i+1]
 137                 if k == KeyStack && isStackVal(v) {
 138                         stack = v
 139                         continue
 140                 }
 141                 if k == KeyError {
 142                         if e, ok := v.(error); ok && stack == nil {
 143                                 stack = errors.Stack(errors.Wrap(e)) // wrap to ensure callstack
 144                         }
 145                 }
 146                 out += " " + formatKey(k) + "=" + formatValue(v)
 147         }
 148
 149         logWriterMu.Lock()
 150         logWriter.Write(procPrefix)
 151         logWriter.Write(prefix(ctx))
 152         logWriter.Write([]byte(out)) // ignore errors
 153         logWriter.Write([]byte{'\n'})
 154         writeRawStack(logWriter, stack)
 155         logWriterMu.Unlock()
 156 }
 157
 158 // Fatalkv is equivalent to Printkv() followed by a call to os.Exit(1).
 159 func Fatalkv(ctx context.Context, keyvals ...interface{}) {
 160         Printkv(ctx, keyvals...)
 161         os.Exit(1)
 162 }
 163
 164 func writeRawStack(w io.Writer, v interface{}) {
 165         switch v := v.(type) {
 166         case []byte:
 167                 if len(v) > 0 {
 168                         w.Write(v)
 169                         w.Write([]byte{'\n'})
 170                 }
 171         case []errors.StackFrame:
 172                 for _, s := range v {
 173                         io.WriteString(w, s.String())
 174                         w.Write([]byte{'\n'})
 175                 }
 176         }
 177 }
 178
 179 func isStackVal(v interface{}) bool {
 180         switch v.(type) {
 181         case []byte:
 182                 return true
 183         case []errors.StackFrame:
 184                 return true
 185         }
 186         return false
 187 }
 188
 189 // Printf prints a log entry containing a message assigned to the
 190 // "message" key. Arguments are handled as in fmt.Printf.
 191 func Printf(ctx context.Context, format string, a ...interface{}) {
 192         Printkv(ctx, KeyMessage, fmt.Sprintf(format, a...))
 193 }
 194
 195 // Error prints a log entry containing an error message assigned to the
 196 // "error" key.
 197 // Optionally, an error message prefix can be included. Prefix arguments are
 198 // handled as in fmt.Print.
 199 func Error(ctx context.Context, err error, a ...interface{}) {
 200         if len(a) > 0 && len(errors.Stack(err)) > 0 {
 201                 err = errors.Wrap(err, a...) // keep err's stack
 202         } else if len(a) > 0 {
 203                 err = fmt.Errorf("%s: %s", fmt.Sprint(a...), err) // don't add a stack here
 204         }
 205         Printkv(ctx, KeyError, err)
 206 }
 207
 208 // formatKey ensures that the stringified key is valid for use in a
 209 // Splunk-style K=V format. It stubs out delimeter and quoter characters in
 210 // the key string with hyphens.
 211 func formatKey(k interface{}) string {
 212         s := fmt.Sprint(k)
 213         if s == "" {
 214                 return "?"
 215         }
 216
 217         for _, c := range illegalKeyChars {
 218                 s = strings.Replace(s, string(c), "-", -1)
 219         }
 220
 221         return s
 222 }
 223
 224 // formatValue ensures that the stringified value is valid for use in a
 225 // Splunk-style K=V format. It quotes the string value if delimeter or quoter
 226 // characters are present in the value string.
 227 func formatValue(v interface{}) string {
 228         s := fmt.Sprint(v)
 229         if strings.ContainsAny(s, pairDelims) {
 230                 return strconv.Quote(s)
 231         }
 232         return s
 233 }
 234
 235 // RecoverAndLogError must be used inside a defer.
 236 func RecoverAndLogError(ctx context.Context) {
 237         if err := recover(); err != nil {
 238                 const size = 64 << 10
 239                 buf := make([]byte, size)
 240                 buf = buf[:runtime.Stack(buf, false)]
 241                 Printkv(ctx,
 242                         KeyMessage, "panic",
 243                         KeyError, err,
 244                         KeyStack, buf,
 245                 )
 246         }
 247 }