From c1cc4095584341d228e8d01093632371fb23324f Mon Sep 17 00:00:00 2001 From: Daniel Date: Fri, 6 Sep 2019 22:45:49 +0200 Subject: [PATCH] Cleanup log package, remove dependency on taskmanager package --- log/flags.go | 2 +- log/formatting.go | 14 +- log/formatting_linux.go | 2 +- log/formatting_windows.go | 2 +- log/input.go | 78 ++++++----- log/logging.go | 39 +++--- log/output.go | 31 +++-- log/trace.go | 279 ++++++++++++++++++++------------------ log/trace_test.go | 18 +-- 9 files changed, 255 insertions(+), 210 deletions(-) diff --git a/log/flags.go b/log/flags.go index cc86e6b..0fcfb75 100644 --- a/log/flags.go +++ b/log/flags.go @@ -9,5 +9,5 @@ var ( func init() { flag.StringVar(&logLevelFlag, "log", "info", "set log level to [trace|debug|info|warning|error|critical]") - flag.StringVar(&pkgLogLevelsFlag, "plog", "", "set log level of packages: database=trace,firewall=debug") + flag.StringVar(&pkgLogLevelsFlag, "plog", "", "set log level of packages: database=trace,notifications=debug") } diff --git a/log/formatting.go b/log/formatting.go index 731c5d9..f25dcb0 100644 --- a/log/formatting.go +++ b/log/formatting.go @@ -9,7 +9,7 @@ var counter uint16 const maxCount uint16 = 999 -func (s severity) String() string { +func (s Severity) String() string { switch s { case TraceLevel: return "TRAC" @@ -51,15 +51,15 @@ func formatLine(line *logLine, duplicates uint64, useColor bool) string { 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 { + if line.tracer != nil { // append full trace time - if len(line.trace.actions) > 0 { - fLine += fmt.Sprintf(" Σ=%s", line.timestamp.Sub(line.trace.actions[0].timestamp)) + if len(line.tracer.logs) > 0 { + fLine += fmt.Sprintf(" Σ=%s", line.timestamp.Sub(line.tracer.logs[0].timestamp)) } // append all trace actions var d time.Duration - for i, action := range line.trace.actions { + for i, action := range line.tracer.logs { // set color if useColor { colorStart = action.level.color() @@ -71,10 +71,10 @@ func formatLine(line *logLine, duplicates uint64, useColor bool) string { fPartStart = 0 } // format - if i == len(line.trace.actions)-1 { // last + if i == len(line.tracer.logs)-1 { // last d = line.timestamp.Sub(action.timestamp) } else { - d = line.trace.actions[i+1].timestamp.Sub(action.timestamp) + d = line.tracer.logs[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) } diff --git a/log/formatting_linux.go b/log/formatting_linux.go index 4b8096e..f24cf32 100644 --- a/log/formatting_linux.go +++ b/log/formatting_linux.go @@ -16,7 +16,7 @@ const ( // colorWhite = "\033[37m" ) -func (s severity) color() string { +func (s Severity) color() string { switch s { case DebugLevel: return colorCyan diff --git a/log/formatting_windows.go b/log/formatting_windows.go index c78cef1..2ec7a15 100644 --- a/log/formatting_windows.go +++ b/log/formatting_windows.go @@ -28,7 +28,7 @@ func init() { colorsSupported = osdetail.EnableColorSupport() } -func (s severity) color() string { +func (s Severity) color() string { if colorsSupported { switch s { case DebugLevel: diff --git a/log/input.go b/log/input.go index 8b271a6..b6a99bb 100644 --- a/log/input.go +++ b/log/input.go @@ -8,24 +8,14 @@ import ( "time" ) -func fastcheck(level severity) bool { - if pkgLevelsActive.IsSet() { - return true - } - if uint32(level) < atomic.LoadUint32(logLevel) { - return false - } - return true -} - -func log(level severity, msg string, trace *ContextTracer) { +func log(level Severity, msg string, tracer *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, trace) + log(level, msg, tracer) }() return } @@ -72,7 +62,7 @@ func log(level severity, msg string, trace *ContextTracer) { // create log object log := &logLine{ msg: msg, - trace: trace, + tracer: tracer, level: level, timestamp: now, file: file, @@ -94,82 +84,96 @@ func log(level severity, msg string, trace *ContextTracer) { } -func Tracef(things ...interface{}) { - if fastcheck(TraceLevel) { - log(TraceLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +func fastcheck(level Severity) bool { + if pkgLevelsActive.IsSet() { + return true } + if uint32(level) >= atomic.LoadUint32(logLevel) { + return true + } + return false } +// Trace is used to log tiny steps. Log traces to context if you can! func Trace(msg string) { if fastcheck(TraceLevel) { log(TraceLevel, msg, nil) } } -func Debugf(things ...interface{}) { - if fastcheck(DebugLevel) { - log(DebugLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +// Tracef is used to log tiny steps. Log traces to context if you can! +func Tracef(format string, things ...interface{}) { + if fastcheck(TraceLevel) { + log(TraceLevel, fmt.Sprintf(format, things...), nil) } } +// Debug is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem. func Debug(msg string) { if fastcheck(DebugLevel) { log(DebugLevel, msg, nil) } } -func Infof(things ...interface{}) { - if fastcheck(InfoLevel) { - log(InfoLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +// Debugf is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem. +func Debugf(format string, things ...interface{}) { + if fastcheck(DebugLevel) { + log(DebugLevel, fmt.Sprintf(format, things...), nil) } } +// Info is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen. func Info(msg string) { if fastcheck(InfoLevel) { log(InfoLevel, msg, nil) } } -func Warningf(things ...interface{}) { - if fastcheck(WarningLevel) { - log(WarningLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +// Infof is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen. +func Infof(format string, things ...interface{}) { + if fastcheck(InfoLevel) { + log(InfoLevel, fmt.Sprintf(format, things...), nil) } } +// Warning is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet. func Warning(msg string) { if fastcheck(WarningLevel) { log(WarningLevel, msg, nil) } } -func Errorf(things ...interface{}) { - if fastcheck(ErrorLevel) { - log(ErrorLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +// Warningf is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet. +func Warningf(format string, things ...interface{}) { + if fastcheck(WarningLevel) { + log(WarningLevel, fmt.Sprintf(format, things...), nil) } } +// Error is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. Maybe User/Admin should be informed. func Error(msg string) { if fastcheck(ErrorLevel) { log(ErrorLevel, msg, nil) } } -func Criticalf(things ...interface{}) { - if fastcheck(CriticalLevel) { - log(CriticalLevel, fmt.Sprintf(things[0].(string), things[1:]...), nil) +// Errorf is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. +func Errorf(format string, things ...interface{}) { + if fastcheck(ErrorLevel) { + log(ErrorLevel, fmt.Sprintf(format, things...), nil) } } +// Critical is used to log events that completely break the system. Operation connot continue. User/Admin must be informed. func Critical(msg string) { if fastcheck(CriticalLevel) { log(CriticalLevel, msg, nil) } } -func Testf(things ...interface{}) { - fmt.Printf(things[0].(string), things[1:]...) -} - -func Test(msg string) { - fmt.Println(msg) +// Criticalf is used to log events that completely break the system. Operation connot continue. User/Admin must be informed. +func Criticalf(format string, things ...interface{}) { + if fastcheck(CriticalLevel) { + log(CriticalLevel, fmt.Sprintf(format, things...), nil) + } } diff --git a/log/logging.go b/log/logging.go index 419ed04..0dedb59 100644 --- a/log/logging.go +++ b/log/logging.go @@ -30,12 +30,13 @@ import ( - logging is configured by main module and is supplied access to configuration and taskmanager */ -type severity uint32 +// Severity describes a log level. +type Severity uint32 type logLine struct { msg string - trace *ContextTracer - level severity + tracer *ContextTracer + level Severity timestamp time.Time file string line int @@ -45,7 +46,7 @@ func (ll *logLine) Equal(ol *logLine) bool { switch { case ll.msg != ol.msg: return false - case ll.trace != nil || ol.trace != nil: + case ll.tracer != nil || ol.tracer != nil: return false case ll.file != ol.file: return false @@ -57,13 +58,14 @@ func (ll *logLine) Equal(ol *logLine) bool { return true } +// Log Levels const ( - TraceLevel severity = 1 - DebugLevel severity = 2 - InfoLevel severity = 3 - WarningLevel severity = 4 - ErrorLevel severity = 5 - CriticalLevel severity = 6 + TraceLevel Severity = 1 + DebugLevel Severity = 2 + InfoLevel Severity = 3 + WarningLevel Severity = 4 + ErrorLevel Severity = 5 + CriticalLevel Severity = 6 ) var ( @@ -74,7 +76,7 @@ var ( logLevel = &logLevelInt pkgLevelsActive = abool.NewBool(false) - pkgLevels = make(map[string]severity) + pkgLevels = make(map[string]Severity) pkgLevelsLock sync.Mutex logsWaiting = make(chan bool, 1) @@ -90,22 +92,26 @@ var ( testErrors = abool.NewBool(false) ) -func SetPkgLevels(levels map[string]severity) { +// SetPkgLevels sets individual log levels for packages. +func SetPkgLevels(levels map[string]Severity) { pkgLevelsLock.Lock() pkgLevels = levels pkgLevelsLock.Unlock() pkgLevelsActive.Set() } +// UnSetPkgLevels removes all individual log levels for packages. func UnSetPkgLevels() { pkgLevelsActive.UnSet() } -func SetLogLevel(level severity) { +// SetLogLevel sets a new log level. +func SetLogLevel(level Severity) { atomic.StoreUint32(logLevel, uint32(level)) } -func ParseLevel(level string) severity { +// ParseLevel returns the level severity of a log level name. +func ParseLevel(level string) Severity { switch strings.ToLower(level) { case "trace": return 1 @@ -123,6 +129,7 @@ func ParseLevel(level string) severity { return 0 } +// Start starts the logging system. Must be called in order to see logs. func Start() (err error) { if !initializing.SetToIf(false, true) { @@ -143,7 +150,7 @@ func Start() (err error) { // get and set file loglevels pkgLogLevels := pkgLogLevelsFlag if len(pkgLogLevels) > 0 { - newPkgLevels := make(map[string]severity) + newPkgLevels := make(map[string]Severity) for _, pair := range strings.Split(pkgLogLevels, ",") { splitted := strings.Split(pair, "=") if len(splitted) != 2 { @@ -170,7 +177,7 @@ func Start() (err error) { return err } -// Shutdown writes remaining log lines and then stops the logger. +// Shutdown writes remaining log lines and then stops the log system. func Shutdown() { close(shutdownSignal) shutdownWaitGroup.Wait() diff --git a/log/output.go b/log/output.go index a545230..622e91b 100644 --- a/log/output.go +++ b/log/output.go @@ -3,10 +3,29 @@ package log import ( "fmt" "time" - - "github.com/safing/portbase/taskmanager" ) +var ( + schedulingEnabled = false + writeTrigger = make(chan struct{}) +) + +// EnableScheduling enables external scheduling of the logger. This will require to manually trigger writes via TriggerWrite whenevery logs should be written. Please note that full buffers will also trigger writing. Must be called before Start() to have an effect. +func EnableScheduling() { + if !initializing.IsSet() { + schedulingEnabled = true + } +} + +// TriggerWriter triggers log output writing. +func TriggerWriter() { + if started.IsSet() && schedulingEnabled { + select { + case writeTrigger <- struct{}{}: + } + } +} + func writeLine(line *logLine, duplicates uint64) { fmt.Println(formatLine(line, duplicates, true)) // TODO: implement file logging and setting console/file logging @@ -23,7 +42,6 @@ func writer() { var line *logLine var lastLine *logLine var duplicates uint64 - startedTask := false defer shutdownWaitGroup.Done() for { @@ -41,8 +59,7 @@ func writer() { // wait for timeslot to log, or when buffer is full select { - case <-taskmanager.StartVeryLowPriorityMicroTask(): - startedTask = true + case <-writeTrigger: case <-forceEmptyingOfBuffer: case <-shutdownSignal: for { @@ -89,10 +106,6 @@ func writer() { writeLine(line, duplicates) duplicates = 0 default: - if startedTask { - taskmanager.EndMicroTask() - startedTask = false - } break writeLoop } } diff --git a/log/trace.go b/log/trace.go index e6a9635..1369ada 100644 --- a/log/trace.go +++ b/log/trace.go @@ -5,41 +5,35 @@ import ( "fmt" "runtime" "sync" - "sync/atomic" "time" ) -// Key for context value +// ContextTracerKey is the key used for the context key/value storage. type ContextTracerKey struct{} +// ContextTracer is attached to a context in order bind logs to a context. type ContextTracer struct { sync.Mutex - actions []*Action -} - -type Action struct { - timestamp time.Time - level severity - msg string - file string - line int + logs []*logLine } var ( - key = ContextTracerKey{} - nilTracer *ContextTracer + key = ContextTracerKey{} ) -func AddTracer(ctx context.Context) context.Context { - if ctx != nil && fastcheckLevel(TraceLevel) { +// AddTracer adds a ContextTracer to the returned Context. Will return a nil ContextTracer if one already exists. Will return a nil context if nil. +func AddTracer(ctx context.Context) (context.Context, *ContextTracer) { + if ctx != nil && fastcheck(TraceLevel) { _, ok := ctx.Value(key).(*ContextTracer) if !ok { - return context.WithValue(ctx, key, &ContextTracer{}) + tracer := &ContextTracer{} + return context.WithValue(ctx, key, tracer), tracer } } - return ctx + return ctx, nil } +// Tracer returns the ContextTracer previously added to the given Context. func Tracer(ctx context.Context) *ContextTracer { if ctx != nil { tracer, ok := ctx.Value(key).(*ContextTracer) @@ -47,10 +41,59 @@ func Tracer(ctx context.Context) *ContextTracer { return tracer } } - return nilTracer + return nil } -func (ct *ContextTracer) logTrace(level severity, msg string) { +// Submit collected logs on the context for further processing/outputting. Does nothing if called on a nil ContextTracer. +func (tracer *ContextTracer) Submit() { + if tracer != nil { + return + } + + if !started.IsSet() { + // a bit resouce intense, but keeps logs before logging started. + // FIXME: create option to disable logging + go func() { + <-startedSignal + tracer.Submit() + }() + return + } + + if len(tracer.logs) == 0 { + return + } + + // extract last line as main line + mainLine := tracer.logs[len(tracer.logs)-1] + tracer.logs = tracer.logs[:len(tracer.logs)-1] + + // create log object + log := &logLine{ + msg: mainLine.msg, + tracer: tracer, + level: mainLine.level, + timestamp: mainLine.timestamp, + file: mainLine.file, + line: mainLine.line, + } + + // send log to processing + select { + case logBuffer <- log: + default: + forceEmptyingOfBuffer <- true + logBuffer <- log + } + + // wake up writer if necessary + if logsWaitingFlag.SetToIf(false, true) { + logsWaiting <- true + } + +} + +func (tracer *ContextTracer) log(level Severity, msg string) { // get file and line _, file, line, ok := runtime.Caller(2) if !ok { @@ -64,9 +107,9 @@ func (ct *ContextTracer) logTrace(level severity, msg string) { } } - ct.Lock() - defer ct.Unlock() - ct.actions = append(ct.actions, &Action{ + tracer.Lock() + defer tracer.Unlock() + tracer.logs = append(tracer.logs, &logLine{ timestamp: time.Now(), level: level, msg: msg, @@ -75,146 +118,122 @@ func (ct *ContextTracer) logTrace(level severity, msg string) { }) } -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 +// Trace is used to log tiny steps. Log traces to context if you can! +func (tracer *ContextTracer) Trace(msg string) { + switch { + case tracer != nil: + tracer.log(TraceLevel, msg) + case fastcheck(TraceLevel): + log(TraceLevel, msg, nil) } - return false } -func (ct *ContextTracer) Trace(msg string) (ok bool) { - if ct != nil { - if fastcheckLevel(TraceLevel) { - ct.logTrace(TraceLevel, msg) - } - return true +// Tracef is used to log tiny steps. Log traces to context if you can! +func (tracer *ContextTracer) Tracef(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(TraceLevel, fmt.Sprintf(format, things...)) + case fastcheck(TraceLevel): + log(TraceLevel, fmt.Sprintf(format, things...), nil) } - 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 +// Debug is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem. +func (tracer *ContextTracer) Debug(msg string) { + switch { + case tracer != nil: + tracer.log(DebugLevel, msg) + case fastcheck(DebugLevel): + log(DebugLevel, msg, nil) } - return false } -func (ct *ContextTracer) Warning(msg string) (ok bool) { - if ct != nil { - if fastcheckLevel(TraceLevel) { - ct.logTrace(WarningLevel, msg) - } - return true +// Debugf is used to log minor errors or unexpected events. These occurences are usually not worth mentioning in itself, but they might hint at a bigger problem. +func (tracer *ContextTracer) Debugf(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(DebugLevel, fmt.Sprintf(format, things...)) + case fastcheck(DebugLevel): + log(DebugLevel, fmt.Sprintf(format, things...), nil) } - 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 +// Info is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen. +func (tracer *ContextTracer) Info(msg string) { + switch { + case tracer != nil: + tracer.log(InfoLevel, msg) + case fastcheck(InfoLevel): + log(InfoLevel, msg, nil) } - return false } -func (ct *ContextTracer) Error(msg string) (ok bool) { - if ct != nil { - if fastcheckLevel(TraceLevel) { - ct.logTrace(ErrorLevel, msg) - } - return true +// Infof is used to log mildly significant events. Should be used to inform about somewhat bigger or user affecting events that happen. +func (tracer *ContextTracer) Infof(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(InfoLevel, fmt.Sprintf(format, things...)) + case fastcheck(InfoLevel): + log(InfoLevel, fmt.Sprintf(format, things...), nil) } - 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 +// Warning is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet. +func (tracer *ContextTracer) Warning(msg string) { + switch { + case tracer != nil: + tracer.log(WarningLevel, msg) + case fastcheck(WarningLevel): + log(WarningLevel, msg, nil) } - 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 +// Warningf is used to log (potentially) bad events, but nothing broke (even a little) and there is no need to panic yet. +func (tracer *ContextTracer) Warningf(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(WarningLevel, fmt.Sprintf(format, things...)) + case fastcheck(WarningLevel): + log(WarningLevel, fmt.Sprintf(format, things...), nil) } - 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 +// Error is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. Maybe User/Admin should be informed. +func (tracer *ContextTracer) Error(msg string) { + switch { + case tracer != nil: + tracer.log(ErrorLevel, msg) + case fastcheck(ErrorLevel): + log(ErrorLevel, msg, nil) } - 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 +// Errorf is used to log errors that break or impair functionality. The task/process may have to be aborted and tried again later. The system is still operational. +func (tracer *ContextTracer) Errorf(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(ErrorLevel, fmt.Sprintf(format, things...)) + case fastcheck(ErrorLevel): + log(ErrorLevel, fmt.Sprintf(format, things...), nil) } - 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 +// Critical is used to log events that completely break the system. Operation connot continue. User/Admin must be informed. +func (tracer *ContextTracer) Critical(msg string) { + switch { + case tracer != nil: + tracer.log(CriticalLevel, msg) + case fastcheck(CriticalLevel): + log(CriticalLevel, msg, nil) } - 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 +// Criticalf is used to log events that completely break the system. Operation connot continue. User/Admin must be informed. +func (tracer *ContextTracer) Criticalf(format string, things ...interface{}) { + switch { + case tracer != nil: + tracer.log(CriticalLevel, fmt.Sprintf(format, things...)) + case fastcheck(CriticalLevel): + log(CriticalLevel, fmt.Sprintf(format, things...), nil) } - 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 { - return uint32(level) >= atomic.LoadUint32(logLevel) } diff --git a/log/trace_test.go b/log/trace_test.go index 929cb70..1e7df02 100644 --- a/log/trace_test.go +++ b/log/trace_test.go @@ -12,20 +12,22 @@ func TestContextTracer(t *testing.T) { t.Skip() } - ctx := AddTracer(context.Background()) + ctx, tracer := AddTracer(context.Background()) + _ = Tracer(ctx) - Tracer(ctx).Trace("api: request received, checking security") + tracer.Trace("api: request received, checking security") time.Sleep(1 * time.Millisecond) - Tracer(ctx).Trace("login: logging in user") + tracer.Trace("login: logging in user") time.Sleep(1 * time.Millisecond) - Tracer(ctx).Trace("database: fetching requested resources") + tracer.Trace("database: fetching requested resources") time.Sleep(10 * time.Millisecond) - Tracer(ctx).Warning("database: partial failure") + tracer.Warning("database: partial failure") time.Sleep(10 * time.Microsecond) - Tracer(ctx).Trace("renderer: rendering output") + tracer.Trace("renderer: rendering output") time.Sleep(1 * time.Millisecond) - Tracer(ctx).Trace("api: returning request") + tracer.Trace("api: returning request") - DebugTrace(ctx, "api: completed request") + tracer.Trace("api: completed request") + tracer.Submit() time.Sleep(100 * time.Millisecond) }