Add context based log tracer

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 {

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,
+		msg:       msg,
-		level,
+		trace:     trace,
-		now,
+		level:     level,
-		file,
+		timestamp: now,
-		line,
+		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)
 	}
 }
 

log/logging.go

@@ -35,17 +35,20 @@ import (
 type severity uint32
 
 type logLine struct {
-	msg   string
+	msg       string
-	level severity
+	trace     *ContextTracer
-	time  time.Time
+	level     severity
-	file  string
+	timestamp time.Time
-	line  int
+	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:

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)

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
+}

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)
+}