1// Package log is the logging library used by IPFS 2// (https://github.com/ipfs/go-ipfs). It uses a modified version of 3// https://godoc.org/github.com/whyrusleeping/go-logging . 4package log 5 6import ( 7 "context" 8 "encoding/json" 9 "fmt" 10 "time" 11 12 opentrace "github.com/opentracing/opentracing-go" 13 otExt "github.com/opentracing/opentracing-go/ext" 14 otl "github.com/opentracing/opentracing-go/log" 15) 16 17// StandardLogger provides API compatibility with standard printf loggers 18// eg. go-logging 19type StandardLogger interface { 20 Debug(args ...interface{}) 21 Debugf(format string, args ...interface{}) 22 Error(args ...interface{}) 23 Errorf(format string, args ...interface{}) 24 Fatal(args ...interface{}) 25 Fatalf(format string, args ...interface{}) 26 Info(args ...interface{}) 27 Infof(format string, args ...interface{}) 28 Panic(args ...interface{}) 29 Panicf(format string, args ...interface{}) 30 Warning(args ...interface{}) 31 Warningf(format string, args ...interface{}) 32} 33 34// EventLogger extends the StandardLogger interface to allow for log items 35// containing structured metadata 36type EventLogger interface { 37 StandardLogger 38 39 // Event merges structured data from the provided inputs into a single 40 // machine-readable log event. 41 // 42 // If the context contains metadata, a copy of this is used as the base 43 // metadata accumulator. 44 // 45 // If one or more loggable objects are provided, these are deep-merged into base blob. 46 // 47 // Next, the event name is added to the blob under the key "event". If 48 // the key "event" already exists, it will be over-written. 49 // 50 // Finally the timestamp and package name are added to the accumulator and 51 // the metadata is logged. 52 Event(ctx context.Context, event string, m ...Loggable) 53 54 EventBegin(ctx context.Context, event string, m ...Loggable) *EventInProgress 55 56 EventBeginInContext(ctx context.Context, event string, m ...Loggable) context.Context 57} 58 59// Logger retrieves an event logger by name 60func Logger(system string) EventLogger { 61 62 // TODO if we would like to adjust log levels at run-time. Store this event 63 // logger in a map (just like the util.Logger impl) 64 if len(system) == 0 { 65 setuplog := getLogger("setup-logger") 66 setuplog.Warning("Missing name parameter") 67 system = "undefined" 68 } 69 70 logger := getLogger(system) 71 72 return &eventLogger{system: system, StandardLogger: logger} 73} 74 75// eventLogger implements the EventLogger and wraps a go-logging Logger 76type eventLogger struct { 77 StandardLogger 78 79 system string 80 // TODO add log-level 81} 82 83func (el *eventLogger) EventBegin(ctx context.Context, event string, metadata ...Loggable) *EventInProgress { 84 start := time.Now() 85 el.Event(ctx, fmt.Sprintf("%sBegin", event), metadata...) 86 87 span, ctx := opentrace.StartSpanFromContext(ctx, event) 88 89 eip := &EventInProgress{} 90 eip.doneFunc = func(additional []Loggable) { 91 metadata = append(metadata, additional...) // anything added during the operation 92 metadata = append(metadata, LoggableMap(map[string]interface{}{ // finally, duration of event 93 "duration": time.Now().Sub(start), 94 })) 95 96 el.Event(ctx, event, metadata...) 97 if traceingDisabled() { 98 return 99 } 100 otExt.Component.Set(span, el.system) 101 for _, m := range metadata { 102 for l, v := range m.Loggable() { 103 if l == "error" { 104 otExt.Error.Set(span, true) 105 } 106 f := getOpentracingField(l, v) 107 span.LogFields(f) 108 } 109 } 110 span.Finish() 111 } 112 return eip 113} 114 115type activeEventKeyType struct{} 116 117var activeEventKey = activeEventKeyType{} 118 119// Stores an event in a context to be finished at a later point 120func (el *eventLogger) EventBeginInContext(ctx context.Context, event string, metadata ...Loggable) context.Context { 121 eip := el.EventBegin(ctx, event, metadata...) 122 return context.WithValue(ctx, activeEventKey, eip) 123} 124 125// Will complete an event if there is one in ctx 126func MaybeFinishEvent(ctx context.Context) { 127 val := ctx.Value(activeEventKey) 128 if eip, ok := val.(*EventInProgress); ok { 129 eip.Done() 130 } 131} 132 133func (el *eventLogger) Event(ctx context.Context, event string, metadata ...Loggable) { 134 135 // short circuit if theres nothing to write to 136 if !WriterGroup.Active() { 137 return 138 } 139 140 // Collect loggables for later logging 141 var loggables []Loggable 142 143 // get any existing metadata from the context 144 existing, err := MetadataFromContext(ctx) 145 if err != nil { 146 existing = Metadata{} 147 } 148 loggables = append(loggables, existing) 149 150 for _, datum := range metadata { 151 loggables = append(loggables, datum) 152 } 153 154 e := entry{ 155 loggables: loggables, 156 system: el.system, 157 event: event, 158 } 159 160 accum := Metadata{} 161 for _, loggable := range e.loggables { 162 accum = DeepMerge(accum, loggable.Loggable()) 163 } 164 165 // apply final attributes to reserved keys 166 // TODO accum["level"] = level 167 accum["event"] = e.event 168 accum["system"] = e.system 169 accum["time"] = FormatRFC3339(time.Now()) 170 171 out, err := json.Marshal(accum) 172 if err != nil { 173 el.Errorf("ERROR FORMATTING EVENT ENTRY: %s", err) 174 return 175 } 176 177 WriterGroup.Write(append(out, '\n')) 178} 179 180// EventInProgress represent and event which is happening 181type EventInProgress struct { 182 loggables []Loggable 183 doneFunc func([]Loggable) 184} 185 186// Append adds loggables to be included in the call to Done 187func (eip *EventInProgress) Append(l Loggable) { 188 eip.loggables = append(eip.loggables, l) 189} 190 191// SetError includes the provided error 192func (eip *EventInProgress) SetError(err error) { 193 eip.loggables = append(eip.loggables, LoggableMap{ 194 "error": err.Error(), 195 }) 196} 197 198// Done creates a new Event entry that includes the duration and appended 199// loggables. 200func (eip *EventInProgress) Done() { 201 eip.doneFunc(eip.loggables) // create final event with extra data 202} 203 204// DoneWithErr creates a new Event entry that includes the duration and appended 205// loggables. DoneWithErr accepts an error, if err is non-nil, it is set on 206// the EventInProgress. Otherwise the logic is the same as the `Done()` method 207func (eip *EventInProgress) DoneWithErr(err error) { 208 if err != nil { 209 eip.SetError(err) 210 } 211 eip.doneFunc(eip.loggables) 212} 213 214// Close is an alias for done 215func (eip *EventInProgress) Close() error { 216 eip.Done() 217 return nil 218} 219 220// FormatRFC3339 returns the given time in UTC with RFC3999Nano format. 221func FormatRFC3339(t time.Time) string { 222 return t.UTC().Format(time.RFC3339Nano) 223} 224 225func getOpentracingField(l string, v interface{}) otl.Field { 226 var f otl.Field 227 switch v.(type) { 228 case bool: 229 f = otl.Bool(l, v.(bool)) 230 case string: 231 f = otl.String(l, v.(string)) 232 case float32: 233 f = otl.Float32(l, v.(float32)) 234 case float64: 235 f = otl.Float64(l, v.(float64)) 236 case int: 237 f = otl.Int(l, v.(int)) 238 case int32: 239 f = otl.Int32(l, v.(int32)) 240 case int64: 241 f = otl.Int64(l, v.(int64)) 242 case uint32: 243 f = otl.Uint32(l, v.(uint32)) 244 case uint64: 245 f = otl.Uint64(l, v.(uint64)) 246 default: 247 f = otl.Object(l, v) 248 } 249 return f 250} 251 252func traceingDisabled() bool { 253 maybeTracer := opentrace.GlobalTracer() 254 switch maybeTracer.(type) { 255 case opentrace.NoopTracer: 256 return true 257 default: 258 return false 259 } 260} 261