Improve and fix logging

log/input.go

@@ -75,15 +75,21 @@ func log(level Severity, msg string, tracer *ContextTracer) {
 	select {
 	case logBuffer <- log:
 	default:
-		forceEmptyingOfBuffer <- struct{}{}
+	forceEmptyingLoop:
-		logBuffer <- log
+		// force empty buffer until we can send to it
+		for {
+			select {
+			case forceEmptyingOfBuffer <- struct{}{}:
+			case logBuffer <- log:
+				break forceEmptyingLoop
+			}
+		}
 	}
 
 	// wake up writer if necessary
 	if logsWaitingFlag.SetToIf(false, true) {
 		logsWaiting <- struct{}{}
 	}
-
 }
 
 func fastcheck(level Severity) bool {

log/logging.go

@@ -70,7 +70,7 @@ const (
 
 var (
 	logBuffer             chan *logLine
-	forceEmptyingOfBuffer chan struct{}
+	forceEmptyingOfBuffer = make(chan struct{})
 
 	logLevelInt = uint32(3)
 	logLevel    = &logLevelInt
@@ -79,7 +79,7 @@ var (
 	pkgLevels       = make(map[string]Severity)
 	pkgLevelsLock   sync.Mutex
 
-	logsWaiting     = make(chan struct{}, 1)
+	logsWaiting     = make(chan struct{}, 4)
 	logsWaitingFlag = abool.NewBool(false)
 
 	shutdownSignal    = make(chan struct{})
@@ -135,7 +135,6 @@ func Start() (err error) {
 	}
 
 	logBuffer = make(chan *logLine, 1024)
-	forceEmptyingOfBuffer = make(chan struct{}, 16)
 
 	initialLogLevel := ParseLevel(logLevelFlag)
 	if initialLogLevel > 0 {

log/output.go

@@ -45,31 +45,32 @@ func startWriter() {
 }
 
 func writer() {
-	var line *logLine
+	var currentLine *logLine
-	var lastLine *logLine
+	var nextLine *logLine
 	var duplicates uint64
 	defer shutdownWaitGroup.Done()
 
 	for {
 		// reset
-		line = nil
+		currentLine = nil
-		lastLine = nil //nolint:ineffassign // only ineffectual in first loop
+		nextLine = nil
 		duplicates = 0
 
 		// wait until logs need to be processed
 		select {
-		case <-logsWaiting:
+		case <-logsWaiting: // normal process
 			logsWaitingFlag.UnSet()
-		case <-shutdownSignal:
+		case <-forceEmptyingOfBuffer: // log buffer is full!
+		case <-shutdownSignal: // shutting down
 			finalizeWriting()
 			return
 		}
 
-		// wait for timeslot to log, or when buffer is full
+		// wait for timeslot to log
 		select {
-		case <-writeTrigger:
+		case <-writeTrigger: // normal process
-		case <-forceEmptyingOfBuffer:
+		case <-forceEmptyingOfBuffer: // log buffer is full!
-		case <-shutdownSignal:
+		case <-shutdownSignal: // shutting down
 			finalizeWriting()
 			return
 		}
@@ -78,38 +79,39 @@ func writer() {
 	writeLoop:
 		for {
 			select {
-			case line = <-logBuffer:
+			case nextLine = <-logBuffer:
-
+				// first line we process, just assign to currentLine
-				// look-ahead for deduplication (best effort)
+				if currentLine == nil {
-			dedupLoop:
+					currentLine = nextLine
-				for {
+					continue writeLoop
-					// check if there is another line waiting
-					select {
-					case nextLine := <-logBuffer:
-						lastLine = line
-						line = nextLine
-					default:
-						break dedupLoop
 				}
 
-					// deduplication
+				// we now have currentLine and nextLine
-					if !line.Equal(lastLine) {
-						// no duplicate
-						break dedupLoop
-					}
 
-					// duplicate
+				// if currentLine and nextLine are equal, do not print, just increase counter and continue
+				if nextLine.Equal(currentLine) {
 					duplicates++
+					continue writeLoop
 				}
 
-				// write actual line
+				// if currentLine and line are _not_ equal, output currentLine
-				writeLine(line, duplicates)
+				writeLine(currentLine, duplicates)
+				// reset duplicate counter
 				duplicates = 0
+				// set new currentLine
+				currentLine = nextLine
 			default:
 				break writeLoop
 			}
 		}
 
+		// write final line
+		writeLine(currentLine, duplicates)
+		// reset state
+		currentLine = nil //nolint:ineffassign
+		nextLine = nil
+		duplicates = 0 //nolint:ineffassign
+
 		// back down a little
 		select {
 		case <-time.After(10 * time.Millisecond):

log/trace.go

@@ -83,7 +83,7 @@ func Tracer(ctx context.Context) *ContextTracer {
 
 // 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 {
+	if tracer == nil {
 		return
 	}
 
@@ -119,15 +119,21 @@ func (tracer *ContextTracer) Submit() {
 	select {
 	case logBuffer <- log:
 	default:
-		forceEmptyingOfBuffer <- struct{}{}
+	forceEmptyingLoop:
-		logBuffer <- log
+		// force empty buffer until we can send to it
+		for {
+			select {
+			case forceEmptyingOfBuffer <- struct{}{}:
+			case logBuffer <- log:
+				break forceEmptyingLoop
+			}
+		}
 	}
 
 	// wake up writer if necessary
 	if logsWaitingFlag.SetToIf(false, true) {
 		logsWaiting <- struct{}{}
 	}
-
 }
 
 func (tracer *ContextTracer) log(level Severity, msg string) {