diff --git a/log/formatting.go b/log/formatting.go index d1dfd90..3815579 100644 --- a/log/formatting.go +++ b/log/formatting.go @@ -2,7 +2,10 @@ package log -import "fmt" +import ( + "fmt" + "time" +) var counter uint16 @@ -40,14 +43,43 @@ func formatLine(line *logLine, duplicates uint64, useColor bool) string { var fLine string if line.line == 0 { - fLine = fmt.Sprintf("%s%s ? %s %s %03d%s%s %s", colorStart, line.time.Format("060102 15:04:05.000"), rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg) + fLine = fmt.Sprintf("%s%s ? %s %s %03d%s%s %s", colorStart, line.timestamp.Format("060102 15:04:05.000"), rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg) } else { fLen := len(line.file) fPartStart := fLen - 10 if fPartStart < 0 { fPartStart = 0 } - fLine = fmt.Sprintf("%s%s %s:%03d %s %s %03d%s%s %s", colorStart, line.time.Format("060102 15:04:05.000"), line.file[fPartStart:], line.line, rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg) + fLine = fmt.Sprintf("%s%s %s:%03d %s %s %03d%s%s %s", colorStart, line.timestamp.Format("060102 15:04:05.000"), line.file[fPartStart:], line.line, rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg) + } + + if line.trace != nil { + // append full trace time + if len(line.trace.actions) > 0 { + fLine += fmt.Sprintf(" Σ=%s", line.timestamp.Sub(line.trace.actions[0].timestamp)) + } + + // append all trace actions + var d time.Duration + for i, action := range line.trace.actions { + // set color + if useColor { + colorStart = action.level.color() + } + // set filename length + fLen := len(action.file) + fPartStart := fLen - 10 + if fPartStart < 0 { + fPartStart = 0 + } + // format + if i == len(line.trace.actions)-1 { // last + d = line.timestamp.Sub(action.timestamp) + } else { + d = line.trace.actions[i+1].timestamp.Sub(action.timestamp) + } + fLine += fmt.Sprintf("\n%s%19s %s:%03d %s %s%s %s", colorStart, d, action.file[fPartStart:], action.line, rightArrow, action.level.String(), colorEnd, action.msg) + } } if counter >= maxCount { diff --git a/log/input.go b/log/input.go index ff0ff5f..beea9a7 100644 --- a/log/input.go +++ b/log/input.go @@ -20,14 +20,14 @@ func fastcheck(level severity) bool { return true } -func log(level severity, msg string) { +func log(level severity, msg string, trace *ContextTracer) { if !started.IsSet() { // a bit resouce intense, but keeps logs before logging started. // FIXME: create option to disable logging go func() { <-startedSignal - log(level, msg) + log(level, msg, trace) }() return } @@ -70,11 +70,12 @@ func log(level severity, msg string) { // create log object log := &logLine{ - msg, - level, - now, - file, - line, + msg: msg, + trace: trace, + level: level, + timestamp: now, + file: file, + line: line, } // send log to processing @@ -94,73 +95,73 @@ func log(level severity, msg string) { func Tracef(things ...interface{}) { if fastcheck(TraceLevel) { - log(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Trace(msg string) { if fastcheck(TraceLevel) { - log(TraceLevel, msg) + log(TraceLevel, msg, nil) } } func Debugf(things ...interface{}) { if fastcheck(DebugLevel) { - log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Debug(msg string) { if fastcheck(DebugLevel) { - log(DebugLevel, msg) + log(DebugLevel, msg, nil) } } func Infof(things ...interface{}) { if fastcheck(InfoLevel) { - log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Info(msg string) { if fastcheck(InfoLevel) { - log(InfoLevel, msg) + log(InfoLevel, msg, nil) } } func Warningf(things ...interface{}) { if fastcheck(WarningLevel) { - log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Warning(msg string) { if fastcheck(WarningLevel) { - log(WarningLevel, msg) + log(WarningLevel, msg, nil) } } func Errorf(things ...interface{}) { if fastcheck(ErrorLevel) { - log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Error(msg string) { if fastcheck(ErrorLevel) { - log(ErrorLevel, msg) + log(ErrorLevel, msg, nil) } } func Criticalf(things ...interface{}) { if fastcheck(CriticalLevel) { - log(CriticalLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + log(CriticalLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) } } func Critical(msg string) { if fastcheck(CriticalLevel) { - log(CriticalLevel, msg) + log(CriticalLevel, msg, nil) } } diff --git a/log/logging.go b/log/logging.go index 30b413c..366ef1b 100644 --- a/log/logging.go +++ b/log/logging.go @@ -35,17 +35,20 @@ import ( type severity uint32 type logLine struct { - msg string - level severity - time time.Time - file string - line int + msg string + trace *ContextTracer + level severity + timestamp time.Time + file string + line int } func (ll *logLine) Equal(ol *logLine) bool { switch { case ll.msg != ol.msg: return false + case ll.trace != nil || ol.trace != nil: + return false case ll.file != ol.file: return false case ll.line != ol.line: diff --git a/log/logging_test.go b/log/logging_test.go index a7bfcdb..fdbcc9f 100644 --- a/log/logging_test.go +++ b/log/logging_test.go @@ -17,7 +17,7 @@ func TestLogging(t *testing.T) { // skip if testing.Short() { - t.Skip("skipping test in short mode.") + t.Skip() } // set levels (static random) @@ -50,7 +50,7 @@ func TestLogging(t *testing.T) { SetLogLevel(TraceLevel) // log invalid level - log(0xFF, "msg") + log(0xFF, "msg", nil) // wait logs to be written time.Sleep(1 * time.Millisecond) diff --git a/log/trace.go b/log/trace.go new file mode 100644 index 0000000..deeaa62 --- /dev/null +++ b/log/trace.go @@ -0,0 +1,223 @@ +package log + +import ( + "context" + "fmt" + "runtime" + "sync" + "sync/atomic" + "time" +) + +// Key for context value +type ContextTracerKey struct{} + +type ContextTracer struct { + sync.Mutex + actions []*Action +} + +type Action struct { + timestamp time.Time + level severity + msg string + file string + line int +} + +var ( + key = ContextTracerKey{} + nilTracer *ContextTracer +) + +func AddTracer(ctx context.Context) context.Context { + if ctx != nil && fastcheckLevel(TraceLevel) { + _, ok := ctx.Value(key).(*ContextTracer) + if !ok { + return context.WithValue(ctx, key, &ContextTracer{}) + } + } + return ctx +} + +func Tracer(ctx context.Context) *ContextTracer { + if ctx != nil { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok { + return tracer + } + } + return nilTracer +} + +func (ct *ContextTracer) logTrace(level severity, msg string) { + // get file and line + _, file, line, ok := runtime.Caller(2) + if !ok { + file = "" + line = 0 + } else { + if len(file) > 3 { + file = file[:len(file)-3] + } else { + file = "" + } + } + + ct.Lock() + defer ct.Unlock() + ct.actions = append(ct.actions, &Action{ + timestamp: time.Now(), + level: level, + msg: msg, + file: file, + line: line, + }) +} + +func (ct *ContextTracer) Tracef(things ...interface{}) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + } + return true + } + return false +} + +func (ct *ContextTracer) Trace(msg string) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(TraceLevel, msg) + } + return true + } + return false +} + +func (ct *ContextTracer) Warningf(things ...interface{}) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + } + return true + } + return false +} + +func (ct *ContextTracer) Warning(msg string) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(WarningLevel, msg) + } + return true + } + return false +} + +func (ct *ContextTracer) Errorf(things ...interface{}) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...)) + } + return true + } + return false +} + +func (ct *ContextTracer) Error(msg string) (ok bool) { + if ct != nil { + if fastcheckLevel(TraceLevel) { + ct.logTrace(ErrorLevel, msg) + } + return true + } + return false +} + +func DebugTrace(ctx context.Context, msg string) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(DebugLevel, msg, tracer) + return true + } + log(DebugLevel, msg, nil) + return false +} + +func DebugTracef(ctx context.Context, things ...interface{}) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer) + return true + } + log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) + return false +} + +func InfoTrace(ctx context.Context, msg string) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(InfoLevel, msg, tracer) + return true + } + log(InfoLevel, msg, nil) + return false +} + +func InfoTracef(ctx context.Context, things ...interface{}) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer) + return true + } + log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) + return false +} + +func WarningTrace(ctx context.Context, msg string) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(WarningLevel, msg, tracer) + return true + } + log(WarningLevel, msg, nil) + return false +} + +func WarningTracef(ctx context.Context, things ...interface{}) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer) + return true + } + log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) + return false +} + +func ErrorTrace(ctx context.Context, msg string) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(ErrorLevel, msg, tracer) + return true + } + log(ErrorLevel, msg, nil) + return false +} + +func ErrorTracef(ctx context.Context, things ...interface{}) (ok bool) { + tracer, ok := ctx.Value(key).(*ContextTracer) + if ok && fastcheckLevel(TraceLevel) { + log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), tracer) + return true + } + log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) + return false +} + +func fastcheckLevel(level severity) bool { + if uint32(level) < atomic.LoadUint32(logLevel) { + return false + } + return true +} diff --git a/log/trace_test.go b/log/trace_test.go new file mode 100644 index 0000000..929cb70 --- /dev/null +++ b/log/trace_test.go @@ -0,0 +1,31 @@ +package log + +import ( + "context" + "testing" + "time" +) + +func TestContextTracer(t *testing.T) { + // skip + if testing.Short() { + t.Skip() + } + + ctx := AddTracer(context.Background()) + + Tracer(ctx).Trace("api: request received, checking security") + time.Sleep(1 * time.Millisecond) + Tracer(ctx).Trace("login: logging in user") + time.Sleep(1 * time.Millisecond) + Tracer(ctx).Trace("database: fetching requested resources") + time.Sleep(10 * time.Millisecond) + Tracer(ctx).Warning("database: partial failure") + time.Sleep(10 * time.Microsecond) + Tracer(ctx).Trace("renderer: rendering output") + time.Sleep(1 * time.Millisecond) + Tracer(ctx).Trace("api: returning request") + + DebugTrace(ctx, "api: completed request") + time.Sleep(100 * time.Millisecond) +}