From b0204f95ffae2be4c5b145c3d62dcc1f1a2ba84e Mon Sep 17 00:00:00 2001
From: Daniel <dhaavi@users.noreply.github.com>
Date: Wed, 9 Oct 2019 16:22:51 +0200
Subject: [PATCH] Improve and fix logging

---
 log/input.go   | 12 ++++++---
 log/logging.go |  5 ++--
 log/output.go  | 70 ++++++++++++++++++++++++++------------------------
 log/trace.go   | 14 +++++++---
 4 files changed, 57 insertions(+), 44 deletions(-)

diff --git a/log/input.go b/log/input.go
index e8bff6c..e8b6579 100644
--- a/log/input.go
+++ b/log/input.go
@@ -75,15 +75,21 @@ func log(level Severity, msg string, tracer *ContextTracer) {
 	select {
 	case logBuffer <- log:
 	default:
-		forceEmptyingOfBuffer <- struct{}{}
-		logBuffer <- log
+	forceEmptyingLoop:
+		// 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 {
diff --git a/log/logging.go b/log/logging.go
index 0ca6fac..f94d12e 100644
--- a/log/logging.go
+++ b/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 {
diff --git a/log/output.go b/log/output.go
index 5b44fb5..cde86c5 100644
--- a/log/output.go
+++ b/log/output.go
@@ -45,31 +45,32 @@ func startWriter() {
 }
 
 func writer() {
-	var line *logLine
-	var lastLine *logLine
+	var currentLine *logLine
+	var nextLine *logLine
 	var duplicates uint64
 	defer shutdownWaitGroup.Done()
 
 	for {
 		// reset
-		line = nil
-		lastLine = nil //nolint:ineffassign // only ineffectual in first loop
+		currentLine = nil
+		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 <-forceEmptyingOfBuffer:
-		case <-shutdownSignal:
+		case <-writeTrigger: // normal process
+		case <-forceEmptyingOfBuffer: // log buffer is full!
+		case <-shutdownSignal: // shutting down
 			finalizeWriting()
 			return
 		}
@@ -78,38 +79,39 @@ func writer() {
 	writeLoop:
 		for {
 			select {
-			case line = <-logBuffer:
-
-				// look-ahead for deduplication (best effort)
-			dedupLoop:
-				for {
-					// check if there is another line waiting
-					select {
-					case nextLine := <-logBuffer:
-						lastLine = line
-						line = nextLine
-					default:
-						break dedupLoop
-					}
-
-					// deduplication
-					if !line.Equal(lastLine) {
-						// no duplicate
-						break dedupLoop
-					}
-
-					// duplicate
-					duplicates++
+			case nextLine = <-logBuffer:
+				// first line we process, just assign to currentLine
+				if currentLine == nil {
+					currentLine = nextLine
+					continue writeLoop
 				}
 
-				// write actual line
-				writeLine(line, duplicates)
+				// we now have currentLine and nextLine
+
+				// if currentLine and nextLine are equal, do not print, just increase counter and continue
+				if nextLine.Equal(currentLine) {
+					duplicates++
+					continue writeLoop
+				}
+
+				// if currentLine and line are _not_ equal, output currentLine
+				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):
diff --git a/log/trace.go b/log/trace.go
index 6f77c37..a345f5d 100644
--- a/log/trace.go
+++ b/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{}{}
-		logBuffer <- log
+	forceEmptyingLoop:
+		// 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) {