2018-07-04 10:51:47 +00:00
|
|
|
// Package log is the logging library used by IPFS
|
|
|
|
// (https://github.com/ipfs/go-ipfs). It uses a modified version of
|
|
|
|
// https://godoc.org/github.com/whyrusleeping/go-logging .
|
|
|
|
package log
|
|
|
|
|
|
|
|
import (
|
|
|
|
"bytes"
|
|
|
|
"context"
|
|
|
|
"encoding/json"
|
|
|
|
"path"
|
|
|
|
"runtime"
|
|
|
|
"time"
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
log2 "github.com/ipfs/go-log/v2"
|
2018-07-04 10:51:47 +00:00
|
|
|
writer "github.com/ipfs/go-log/writer"
|
|
|
|
|
|
|
|
opentrace "github.com/opentracing/opentracing-go"
|
|
|
|
otExt "github.com/opentracing/opentracing-go/ext"
|
2021-06-16 20:19:45 +00:00
|
|
|
"go.uber.org/zap"
|
2018-07-04 10:51:47 +00:00
|
|
|
)
|
|
|
|
|
|
|
|
var log = Logger("eventlog")
|
|
|
|
|
|
|
|
// StandardLogger provides API compatibility with standard printf loggers
|
|
|
|
// eg. go-logging
|
|
|
|
type StandardLogger interface {
|
2021-06-16 20:19:45 +00:00
|
|
|
log2.StandardLogger
|
|
|
|
// Deprecated use Warn
|
2018-07-04 10:51:47 +00:00
|
|
|
Warning(args ...interface{})
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated use Warnf
|
2018-07-04 10:51:47 +00:00
|
|
|
Warningf(format string, args ...interface{})
|
|
|
|
}
|
|
|
|
|
|
|
|
// EventLogger extends the StandardLogger interface to allow for log items
|
|
|
|
// containing structured metadata
|
|
|
|
type EventLogger interface {
|
|
|
|
StandardLogger
|
|
|
|
|
|
|
|
// Event merges structured data from the provided inputs into a single
|
|
|
|
// machine-readable log event.
|
|
|
|
//
|
|
|
|
// If the context contains metadata, a copy of this is used as the base
|
|
|
|
// metadata accumulator.
|
|
|
|
//
|
|
|
|
// If one or more loggable objects are provided, these are deep-merged into base blob.
|
|
|
|
//
|
|
|
|
// Next, the event name is added to the blob under the key "event". If
|
|
|
|
// the key "event" already exists, it will be over-written.
|
|
|
|
//
|
|
|
|
// Finally the timestamp and package name are added to the accumulator and
|
|
|
|
// the metadata is logged.
|
|
|
|
// DEPRECATED
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
Event(ctx context.Context, event string, m ...Loggable)
|
|
|
|
|
|
|
|
// DEPRECATED
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
EventBegin(ctx context.Context, event string, m ...Loggable) *EventInProgress
|
|
|
|
|
|
|
|
// Start starts an opentracing span with `name`, using
|
|
|
|
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
|
|
|
|
// found, Start creates a root (parentless) Span.
|
|
|
|
//
|
|
|
|
// The return value is a context.Context object built around the
|
|
|
|
// returned Span.
|
|
|
|
//
|
|
|
|
// Example usage:
|
|
|
|
//
|
|
|
|
// SomeFunction(ctx context.Context, ...) {
|
|
|
|
// ctx := log.Start(ctx, "SomeFunction")
|
|
|
|
// defer log.Finish(ctx)
|
|
|
|
// ...
|
|
|
|
// }
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
Start(ctx context.Context, name string) context.Context
|
|
|
|
|
|
|
|
// StartFromParentState starts an opentracing span with `name`, using
|
|
|
|
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
|
|
|
|
// found, StartSpanFromParentState creates a root (parentless) Span.
|
|
|
|
//
|
|
|
|
// StartFromParentState will attempt to deserialize a SpanContext from `parent`,
|
|
|
|
// using any Span found within to continue the trace
|
|
|
|
//
|
|
|
|
// The return value is a context.Context object built around the
|
|
|
|
// returned Span.
|
|
|
|
//
|
|
|
|
// An error is returned when `parent` cannot be deserialized to a SpanContext
|
|
|
|
//
|
|
|
|
// Example usage:
|
|
|
|
//
|
|
|
|
// SomeFunction(ctx context.Context, bParent []byte) {
|
|
|
|
// ctx := log.StartFromParentState(ctx, "SomeFunction", bParent)
|
|
|
|
// defer log.Finish(ctx)
|
|
|
|
// ...
|
|
|
|
// }
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
StartFromParentState(ctx context.Context, name string, parent []byte) (context.Context, error)
|
|
|
|
|
|
|
|
// Finish completes the span associated with `ctx`.
|
|
|
|
//
|
|
|
|
// Finish() must be the last call made to any span instance, and to do
|
|
|
|
// otherwise leads to undefined behavior.
|
|
|
|
// Finish will do its best to notify (log) when used in correctly
|
|
|
|
// .e.g called twice, or called on a spanless `ctx`
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
Finish(ctx context.Context)
|
|
|
|
|
|
|
|
// FinishWithErr completes the span associated with `ctx` and also calls
|
|
|
|
// SetErr if `err` is non-nil
|
|
|
|
//
|
|
|
|
// FinishWithErr() must be the last call made to any span instance, and to do
|
|
|
|
// otherwise leads to undefined behavior.
|
|
|
|
// FinishWithErr will do its best to notify (log) when used in correctly
|
|
|
|
// .e.g called twice, or called on a spanless `ctx`
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
FinishWithErr(ctx context.Context, err error)
|
|
|
|
|
|
|
|
// SetErr tags the span associated with `ctx` to reflect an error occured, and
|
|
|
|
// logs the value `err` under key `error`.
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
SetErr(ctx context.Context, err error)
|
|
|
|
|
|
|
|
// LogKV records key:value logging data about an event stored in `ctx`
|
|
|
|
// Eexample:
|
|
|
|
// log.LogKV(
|
|
|
|
// "error", "resolve failure",
|
|
|
|
// "type", "cache timeout",
|
|
|
|
// "waited.millis", 1500)
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
LogKV(ctx context.Context, alternatingKeyValues ...interface{})
|
|
|
|
|
|
|
|
// SetTag tags key `k` and value `v` on the span associated with `ctx`
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
SetTag(ctx context.Context, key string, value interface{})
|
|
|
|
|
|
|
|
// SetTags tags keys from the `tags` maps on the span associated with `ctx`
|
|
|
|
// Example:
|
|
|
|
// log.SetTags(ctx, map[string]{
|
|
|
|
// "type": bizStruct,
|
|
|
|
// "request": req,
|
|
|
|
// })
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
SetTags(ctx context.Context, tags map[string]interface{})
|
|
|
|
|
|
|
|
// SerializeContext takes the SpanContext instance stored in `ctx` and Seralizes
|
|
|
|
// it to bytes. An error is returned if the `ctx` cannot be serialized to
|
|
|
|
// a bytes array
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
SerializeContext(ctx context.Context) ([]byte, error)
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
var _ EventLogger = Logger("test-logger")
|
2018-07-04 10:51:47 +00:00
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Logger retrieves an event logger by name
|
|
|
|
func Logger(system string) *ZapEventLogger {
|
2018-07-04 10:51:47 +00:00
|
|
|
if len(system) == 0 {
|
2021-06-16 20:19:45 +00:00
|
|
|
setuplog := Logger("setup-logger")
|
|
|
|
setuplog.Error("Missing name parameter")
|
2018-07-04 10:51:47 +00:00
|
|
|
system = "undefined"
|
|
|
|
}
|
2021-06-16 20:19:45 +00:00
|
|
|
logger := log2.Logger(system)
|
|
|
|
return &ZapEventLogger{system: system, SugaredLogger: logger.SugaredLogger}
|
2018-07-04 10:51:47 +00:00
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// ZapEventLogger implements the EventLogger and wraps a go-logging Logger
|
|
|
|
type ZapEventLogger struct {
|
|
|
|
zap.SugaredLogger
|
2018-07-04 10:51:47 +00:00
|
|
|
|
|
|
|
system string
|
|
|
|
// TODO add log-level
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: use Warn
|
|
|
|
func (el *ZapEventLogger) Warning(args ...interface{}) {
|
|
|
|
el.Warn(args...)
|
|
|
|
}
|
|
|
|
|
|
|
|
// Deprecated: use Warnf
|
|
|
|
func (el *ZapEventLogger) Warningf(format string, args ...interface{}) {
|
|
|
|
el.Warnf(format, args...)
|
|
|
|
}
|
|
|
|
|
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) Start(ctx context.Context, operationName string) context.Context {
|
2018-07-04 10:51:47 +00:00
|
|
|
span, ctx := opentrace.StartSpanFromContext(ctx, operationName)
|
|
|
|
span.SetTag("system", el.system)
|
|
|
|
return ctx
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) StartFromParentState(ctx context.Context, operationName string, parent []byte) (context.Context, error) {
|
2018-07-04 10:51:47 +00:00
|
|
|
sc, err := deserializeContext(parent)
|
|
|
|
if err != nil {
|
|
|
|
return nil, err
|
|
|
|
}
|
|
|
|
|
|
|
|
//TODO RPCServerOption is probably not the best tag, as this is likely from a peer
|
|
|
|
span, ctx := opentrace.StartSpanFromContext(ctx, operationName, otExt.RPCServerOption(sc))
|
|
|
|
span.SetTag("system", el.system)
|
|
|
|
return ctx, nil
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) SerializeContext(ctx context.Context) ([]byte, error) {
|
2018-07-04 10:51:47 +00:00
|
|
|
gTracer := opentrace.GlobalTracer()
|
|
|
|
b := make([]byte, 0)
|
|
|
|
carrier := bytes.NewBuffer(b)
|
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if err := gTracer.Inject(span.Context(), opentrace.Binary, carrier); err != nil {
|
|
|
|
return nil, err
|
|
|
|
}
|
|
|
|
return carrier.Bytes(), nil
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) LogKV(ctx context.Context, alternatingKeyValues ...interface{}) {
|
2018-07-04 10:51:47 +00:00
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if span == nil {
|
|
|
|
_, file, line, _ := runtime.Caller(1)
|
|
|
|
log.Errorf("LogKV with no Span in context called on %s:%d", path.Base(file), line)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
span.LogKV(alternatingKeyValues...)
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) SetTag(ctx context.Context, k string, v interface{}) {
|
2018-07-04 10:51:47 +00:00
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if span == nil {
|
|
|
|
_, file, line, _ := runtime.Caller(1)
|
|
|
|
log.Errorf("SetTag with no Span in context called on %s:%d", path.Base(file), line)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
span.SetTag(k, v)
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) SetTags(ctx context.Context, tags map[string]interface{}) {
|
2018-07-04 10:51:47 +00:00
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if span == nil {
|
|
|
|
_, file, line, _ := runtime.Caller(1)
|
|
|
|
log.Errorf("SetTags with no Span in context called on %s:%d", path.Base(file), line)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
for k, v := range tags {
|
|
|
|
span.SetTag(k, v)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
func (el *ZapEventLogger) setErr(ctx context.Context, err error, skip int) {
|
2018-07-04 10:51:47 +00:00
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if span == nil {
|
2019-06-09 07:24:20 +00:00
|
|
|
_, file, line, _ := runtime.Caller(skip)
|
2018-07-04 10:51:47 +00:00
|
|
|
log.Errorf("SetErr with no Span in context called on %s:%d", path.Base(file), line)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
if err == nil {
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
|
|
|
otExt.Error.Set(span, true)
|
|
|
|
span.LogKV("error", err.Error())
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) SetErr(ctx context.Context, err error) {
|
2019-06-09 07:24:20 +00:00
|
|
|
el.setErr(ctx, err, 1)
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) Finish(ctx context.Context) {
|
2018-07-04 10:51:47 +00:00
|
|
|
span := opentrace.SpanFromContext(ctx)
|
|
|
|
if span == nil {
|
|
|
|
_, file, line, _ := runtime.Caller(1)
|
|
|
|
log.Errorf("Finish with no Span in context called on %s:%d", path.Base(file), line)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
span.Finish()
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) FinishWithErr(ctx context.Context, err error) {
|
2019-06-09 07:24:20 +00:00
|
|
|
el.setErr(ctx, err, 2)
|
2018-07-04 10:51:47 +00:00
|
|
|
el.Finish(ctx)
|
|
|
|
}
|
|
|
|
|
|
|
|
func deserializeContext(bCtx []byte) (opentrace.SpanContext, error) {
|
|
|
|
gTracer := opentrace.GlobalTracer()
|
|
|
|
carrier := bytes.NewReader(bCtx)
|
|
|
|
spanContext, err := gTracer.Extract(opentrace.Binary, carrier)
|
|
|
|
if err != nil {
|
|
|
|
log.Warning("Failed to deserialize context %s", err)
|
|
|
|
return nil, err
|
|
|
|
}
|
|
|
|
return spanContext, nil
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) EventBegin(ctx context.Context, event string, metadata ...Loggable) *EventInProgress {
|
2018-07-04 10:51:47 +00:00
|
|
|
ctx = el.Start(ctx, event)
|
|
|
|
|
|
|
|
for _, m := range metadata {
|
|
|
|
for l, v := range m.Loggable() {
|
|
|
|
el.LogKV(ctx, l, v)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
eip := &EventInProgress{}
|
|
|
|
eip.doneFunc = func(additional []Loggable) {
|
|
|
|
// anything added during the operation
|
|
|
|
// e.g. deprecated methods event.Append(...) or event.SetError(...)
|
|
|
|
for _, m := range eip.loggables {
|
|
|
|
for l, v := range m.Loggable() {
|
|
|
|
el.LogKV(ctx, l, v)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
el.Finish(ctx)
|
|
|
|
}
|
|
|
|
return eip
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
|
|
|
func (el *ZapEventLogger) Event(ctx context.Context, event string, metadata ...Loggable) {
|
2018-07-04 10:51:47 +00:00
|
|
|
|
|
|
|
// short circuit if theres nothing to write to
|
|
|
|
if !writer.WriterGroup.Active() {
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
|
|
|
// Collect loggables for later logging
|
|
|
|
var loggables []Loggable
|
|
|
|
|
|
|
|
// get any existing metadata from the context
|
|
|
|
existing, err := MetadataFromContext(ctx)
|
|
|
|
if err != nil {
|
|
|
|
existing = Metadata{}
|
|
|
|
}
|
|
|
|
loggables = append(loggables, existing)
|
2021-06-16 20:19:45 +00:00
|
|
|
loggables = append(loggables, metadata...)
|
2018-07-04 10:51:47 +00:00
|
|
|
|
|
|
|
e := entry{
|
|
|
|
loggables: loggables,
|
|
|
|
system: el.system,
|
|
|
|
event: event,
|
|
|
|
}
|
|
|
|
|
|
|
|
accum := Metadata{}
|
|
|
|
for _, loggable := range e.loggables {
|
|
|
|
accum = DeepMerge(accum, loggable.Loggable())
|
|
|
|
}
|
|
|
|
|
|
|
|
// apply final attributes to reserved keys
|
|
|
|
// TODO accum["level"] = level
|
|
|
|
accum["event"] = e.event
|
|
|
|
accum["system"] = e.system
|
|
|
|
accum["time"] = FormatRFC3339(time.Now())
|
|
|
|
|
2019-06-09 07:24:20 +00:00
|
|
|
var buf bytes.Buffer
|
|
|
|
encoder := json.NewEncoder(&buf)
|
|
|
|
encoder.SetEscapeHTML(false)
|
|
|
|
err = encoder.Encode(accum)
|
2018-07-04 10:51:47 +00:00
|
|
|
if err != nil {
|
|
|
|
el.Errorf("ERROR FORMATTING EVENT ENTRY: %s", err)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
2021-06-16 20:19:45 +00:00
|
|
|
_, _ = writer.WriterGroup.Write(buf.Bytes())
|
2018-07-04 10:51:47 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
// DEPRECATED
|
|
|
|
// EventInProgress represent and event which is happening
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
type EventInProgress struct {
|
|
|
|
loggables []Loggable
|
|
|
|
doneFunc func([]Loggable)
|
|
|
|
}
|
|
|
|
|
|
|
|
// DEPRECATED use `LogKV` or `SetTag`
|
|
|
|
// Append adds loggables to be included in the call to Done
|
|
|
|
func (eip *EventInProgress) Append(l Loggable) {
|
|
|
|
eip.loggables = append(eip.loggables, l)
|
|
|
|
}
|
|
|
|
|
|
|
|
// DEPRECATED use `SetError(ctx, error)`
|
|
|
|
// SetError includes the provided error
|
|
|
|
func (eip *EventInProgress) SetError(err error) {
|
|
|
|
eip.loggables = append(eip.loggables, LoggableMap{
|
|
|
|
"error": err.Error(),
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
// Done creates a new Event entry that includes the duration and appended
|
|
|
|
// loggables.
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
func (eip *EventInProgress) Done() {
|
|
|
|
eip.doneFunc(eip.loggables) // create final event with extra data
|
|
|
|
}
|
|
|
|
|
|
|
|
// DEPRECATED use `FinishWithErr`
|
|
|
|
// DoneWithErr creates a new Event entry that includes the duration and appended
|
|
|
|
// loggables. DoneWithErr accepts an error, if err is non-nil, it is set on
|
|
|
|
// the EventInProgress. Otherwise the logic is the same as the `Done()` method
|
|
|
|
func (eip *EventInProgress) DoneWithErr(err error) {
|
|
|
|
if err != nil {
|
|
|
|
eip.SetError(err)
|
|
|
|
}
|
|
|
|
eip.doneFunc(eip.loggables)
|
|
|
|
}
|
|
|
|
|
|
|
|
// Close is an alias for done
|
2021-06-16 20:19:45 +00:00
|
|
|
// Deprecated: Stop using go-log for event logging
|
2018-07-04 10:51:47 +00:00
|
|
|
func (eip *EventInProgress) Close() error {
|
|
|
|
eip.Done()
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
|
|
|
// FormatRFC3339 returns the given time in UTC with RFC3999Nano format.
|
|
|
|
func FormatRFC3339(t time.Time) string {
|
|
|
|
return t.UTC().Format(time.RFC3339Nano)
|
|
|
|
}
|