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