From f29bd549767295584647f2d314b13124c78f5af0 Mon Sep 17 00:00:00 2001 From: Daniel Date: Fri, 20 Sep 2019 22:03:21 +0200 Subject: [PATCH] Clean up log package, improve conditional logging, make scheduling optional --- log/formatting.go | 9 ++++++--- log/input.go | 30 ++++++++++++++------------- log/logging.go | 17 ++++++++-------- log/logging_test.go | 11 ++++++---- log/output.go | 46 +++++++++++++++++++++++++++--------------- log/trace.go | 49 +++++++++++++++++++++++++++++++++++++++------ 6 files changed, 111 insertions(+), 51 deletions(-) diff --git a/log/formatting.go b/log/formatting.go index f25dcb0..d720548 100644 --- a/log/formatting.go +++ b/log/formatting.go @@ -7,7 +7,10 @@ import ( var counter uint16 -const maxCount uint16 = 999 +const ( + maxCount uint16 = 999 + timeFormat string = "060102 15:04:05.000" +) func (s Severity) String() string { switch s { @@ -41,14 +44,14 @@ 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.timestamp.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(timeFormat), 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.timestamp.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(timeFormat), line.file[fPartStart:], line.line, rightArrow, line.level.String(), counter, formatDuplicates(duplicates), colorEnd, line.msg) } if line.tracer != nil { diff --git a/log/input.go b/log/input.go index b6a99bb..e8bff6c 100644 --- a/log/input.go +++ b/log/input.go @@ -11,7 +11,7 @@ import ( func log(level Severity, msg string, tracer *ContextTracer) { if !started.IsSet() { - // a bit resouce intense, but keeps logs before logging started. + // a bit resource intense, but keeps logs before logging started. // FIXME: create option to disable logging go func() { <-startedSignal @@ -20,11 +20,6 @@ func log(level Severity, msg string, tracer *ContextTracer) { return } - // check if level is enabled - if !pkgLevelsActive.IsSet() && uint32(level) < atomic.LoadUint32(logLevel) { - return - } - // get time now := time.Now() @@ -43,20 +38,27 @@ func log(level Severity, msg string, tracer *ContextTracer) { // check if level is enabled for file or generally if pkgLevelsActive.IsSet() { - fileOnly := strings.Split(file, "/") - if len(fileOnly) < 2 { + pathSegments := strings.Split(file, "/") + if len(pathSegments) < 2 { + // file too short for package levels return } - sev, ok := pkgLevels[fileOnly[len(fileOnly)-2]] + pkgLevelsLock.Lock() + severity, ok := pkgLevels[pathSegments[len(pathSegments)-2]] + pkgLevelsLock.Unlock() if ok { - if level < sev { + if level < severity { return } } else { + // no package level set, check against global level if uint32(level) < atomic.LoadUint32(logLevel) { return } } + } else if uint32(level) < atomic.LoadUint32(logLevel) { + // no package levels set, check against global level + return } // create log object @@ -73,13 +75,13 @@ func log(level Severity, msg string, tracer *ContextTracer) { select { case logBuffer <- log: default: - forceEmptyingOfBuffer <- true + forceEmptyingOfBuffer <- struct{}{} logBuffer <- log } // wake up writer if necessary if logsWaitingFlag.SetToIf(false, true) { - logsWaiting <- true + logsWaiting <- struct{}{} } } @@ -108,14 +110,14 @@ func Tracef(format string, things ...interface{}) { } } -// 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. +// Debug is used to log minor errors or unexpected events. These occurrences 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) } } -// 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. +// Debugf is used to log minor errors or unexpected events. These occurrences 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) diff --git a/log/logging.go b/log/logging.go index 0dedb59..0ca6fac 100644 --- a/log/logging.go +++ b/log/logging.go @@ -70,7 +70,7 @@ const ( var ( logBuffer chan *logLine - forceEmptyingOfBuffer chan bool + forceEmptyingOfBuffer chan struct{} logLevelInt = uint32(3) logLevel = &logLevelInt @@ -79,17 +79,15 @@ var ( pkgLevels = make(map[string]Severity) pkgLevelsLock sync.Mutex - logsWaiting = make(chan bool, 1) + logsWaiting = make(chan struct{}, 1) logsWaitingFlag = abool.NewBool(false) - shutdownSignal = make(chan struct{}, 0) + shutdownSignal = make(chan struct{}) shutdownWaitGroup sync.WaitGroup initializing = abool.NewBool(false) started = abool.NewBool(false) - startedSignal = make(chan struct{}, 0) - - testErrors = abool.NewBool(false) + startedSignal = make(chan struct{}) ) // SetPkgLevels sets individual log levels for packages. @@ -136,8 +134,8 @@ func Start() (err error) { return nil } - logBuffer = make(chan *logLine, 8192) - forceEmptyingOfBuffer = make(chan bool, 4) + logBuffer = make(chan *logLine, 1024) + forceEmptyingOfBuffer = make(chan struct{}, 16) initialLogLevel := ParseLevel(logLevelFlag) if initialLogLevel > 0 { @@ -169,6 +167,9 @@ func Start() (err error) { SetPkgLevels(newPkgLevels) } + if !schedulingEnabled { + close(writeTrigger) + } startWriter() started.Set() diff --git a/log/logging_test.go b/log/logging_test.go index 699459d..557ab02 100644 --- a/log/logging_test.go +++ b/log/logging_test.go @@ -1,17 +1,20 @@ package log import ( + "fmt" "testing" "time" ) -// test waiting -func TestLogging(t *testing.T) { - +func init() { err := Start() if err != nil { - t.Errorf("start failed: %s", err) + panic(fmt.Sprintf("start failed: %s", err)) } +} + +// test waiting +func TestLogging(t *testing.T) { // skip if testing.Short() { diff --git a/log/output.go b/log/output.go index 622e91b..5b44fb5 100644 --- a/log/output.go +++ b/log/output.go @@ -22,10 +22,16 @@ func TriggerWriter() { if started.IsSet() && schedulingEnabled { select { case writeTrigger <- struct{}{}: + default: } } } +// TriggerWriterChannel returns the channel to trigger log writing. Returned channel will close if EnableScheduling() is not called correctly. +func TriggerWriterChannel() chan struct{} { + return writeTrigger +} + func writeLine(line *logLine, duplicates uint64) { fmt.Println(formatLine(line, duplicates, true)) // TODO: implement file logging and setting console/file logging @@ -34,7 +40,7 @@ func writeLine(line *logLine, duplicates uint64) { func startWriter() { shutdownWaitGroup.Add(1) - fmt.Println(fmt.Sprintf("%s%s %s BOF%s", InfoLevel.color(), time.Now().Format("060102 15:04:05.000"), rightArrow, endColor())) + fmt.Println(fmt.Sprintf("%s%s %s BOF%s", InfoLevel.color(), time.Now().Format(timeFormat), rightArrow, endColor())) go writer() } @@ -47,7 +53,7 @@ func writer() { for { // reset line = nil - lastLine = nil + lastLine = nil //nolint:ineffassign // only ineffectual in first loop duplicates = 0 // wait until logs need to be processed @@ -55,6 +61,8 @@ func writer() { case <-logsWaiting: logsWaitingFlag.UnSet() case <-shutdownSignal: + finalizeWriting() + return } // wait for timeslot to log, or when buffer is full @@ -62,15 +70,8 @@ func writer() { case <-writeTrigger: case <-forceEmptyingOfBuffer: case <-shutdownSignal: - for { - select { - case line = <-logBuffer: - writeLine(line, duplicates) - case <-time.After(10 * time.Millisecond): - fmt.Println(fmt.Sprintf("%s%s %s EOF%s", InfoLevel.color(), time.Now().Format("060102 15:04:05.000"), leftArrow, endColor())) - return - } - } + finalizeWriting() + return } // write all the logs! @@ -94,12 +95,11 @@ func writer() { // deduplication if !line.Equal(lastLine) { // no duplicate - writeLine(lastLine, duplicates) - duplicates = 0 - } else { - // duplicate - duplicates++ + break dedupLoop } + + // duplicate + duplicates++ } // write actual line @@ -114,7 +114,21 @@ func writer() { select { case <-time.After(10 * time.Millisecond): case <-shutdownSignal: + finalizeWriting() + return } } } + +func finalizeWriting() { + for { + select { + case line := <-logBuffer: + writeLine(line, 0) + case <-time.After(10 * time.Millisecond): + fmt.Println(fmt.Sprintf("%s%s %s EOF%s", InfoLevel.color(), time.Now().Format(timeFormat), leftArrow, endColor())) + return + } + } +} diff --git a/log/trace.go b/log/trace.go index 1369ada..6f77c37 100644 --- a/log/trace.go +++ b/log/trace.go @@ -4,7 +4,9 @@ import ( "context" "fmt" "runtime" + "strings" "sync" + "sync/atomic" "time" ) @@ -21,11 +23,46 @@ var ( key = ContextTracerKey{} ) -// AddTracer adds a ContextTracer to the returned Context. Will return a nil ContextTracer if one already exists. Will return a nil context if nil. +// AddTracer adds a ContextTracer to the returned Context. Will return a nil ContextTracer if logging level is not set to trace. Will return a nil ContextTracer if one already exists. Will return a nil ContextTracer in case of an error. Will return a nil context if nil. func AddTracer(ctx context.Context) (context.Context, *ContextTracer) { if ctx != nil && fastcheck(TraceLevel) { + // check pkg levels + if pkgLevelsActive.IsSet() { + // get file + _, file, _, ok := runtime.Caller(1) + if !ok { + // cannot get file, ignore + return ctx, nil + } + + pathSegments := strings.Split(file, "/") + if len(pathSegments) < 2 { + // file too short for package levels + return ctx, nil + } + pkgLevelsLock.Lock() + severity, ok := pkgLevels[pathSegments[len(pathSegments)-2]] + pkgLevelsLock.Unlock() + if ok { + // check against package level + if TraceLevel < severity { + return ctx, nil + } + } else { + // no package level set, check against global level + if uint32(TraceLevel) < atomic.LoadUint32(logLevel) { + return ctx, nil + } + } + } else if uint32(TraceLevel) < atomic.LoadUint32(logLevel) { + // no package levels set, check against global level + return ctx, nil + } + + // check for existing tracer _, ok := ctx.Value(key).(*ContextTracer) if !ok { + // add and return new tracer tracer := &ContextTracer{} return context.WithValue(ctx, key, tracer), tracer } @@ -51,7 +88,7 @@ func (tracer *ContextTracer) Submit() { } if !started.IsSet() { - // a bit resouce intense, but keeps logs before logging started. + // a bit resource intense, but keeps logs before logging started. // FIXME: create option to disable logging go func() { <-startedSignal @@ -82,13 +119,13 @@ func (tracer *ContextTracer) Submit() { select { case logBuffer <- log: default: - forceEmptyingOfBuffer <- true + forceEmptyingOfBuffer <- struct{}{} logBuffer <- log } // wake up writer if necessary if logsWaitingFlag.SetToIf(false, true) { - logsWaiting <- true + logsWaiting <- struct{}{} } } @@ -138,7 +175,7 @@ func (tracer *ContextTracer) Tracef(format string, things ...interface{}) { } } -// 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. +// Debug is used to log minor errors or unexpected events. These occurrences 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: @@ -148,7 +185,7 @@ func (tracer *ContextTracer) Debug(msg string) { } } -// 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. +// Debugf is used to log minor errors or unexpected events. These occurrences 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: