Clean up log package, improve conditional logging, make scheduling optional

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 {

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, "/")
+		pathSegments := strings.Split(file, "/")
-		if len(fileOnly) < 2 {
+		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)

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)
+	startedSignal = make(chan struct{})
-
-	testErrors = abool.NewBool(false)
 )
 
 // SetPkgLevels sets individual log levels for packages.
@@ -136,8 +134,8 @@ func Start() (err error) {
 		return nil
 	}
 
-	logBuffer = make(chan *logLine, 8192)
+	logBuffer = make(chan *logLine, 1024)
-	forceEmptyingOfBuffer = make(chan bool, 4)
+	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()

log/logging_test.go

@@ -1,17 +1,20 @@
 package log
 
 import (
+	"fmt"
 	"testing"
 	"time"
 )
 
-// test waiting
+func init() {
-func TestLogging(t *testing.T) {
-
 	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() {

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 {
+			finalizeWriting()
-				select {
+			return
-				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
-				}
-			}
 		}
 
 		// write all the logs!
@@ -94,12 +95,11 @@ func writer() {
 					// deduplication
 					if !line.Equal(lastLine) {
 						// no duplicate
-						writeLine(lastLine, duplicates)
+						break dedupLoop
-						duplicates = 0
-					} else {
-						// duplicate
-						duplicates++
 					}
+
+					// 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
+		}
+	}
+}

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: