log: suppress identical messages within every 5-second window

Author: HouzuoGuo

cli/supervise.go

@@ -181,3 +181,17 @@ func HandleDaemonSignals() {
 	signal.Ignore(syscall.SIGPIPE)
 	signal.Ignore(syscall.SIGHUP)
 }
+
+// ClearDedupBuffersInBackground periodically clears the global LRU buffers used
+// for de-duplicating log messages.
+func ClearDedupBuffersInBackground() {
+	tickerChan := time.Tick(5 * time.Second)
+	go func() {
+		for {
+			select {
+			case <-tickerChan:
+				lalog.ClearDedupBuffers()
+			}
+		}
+	}()
+}

datastruct/lru.go

@@ -23,7 +23,7 @@ func NewLeastRecentlyUsedBuffer(maxCapacity int) *LeastRecentlyUsedBuffer {
 	return &LeastRecentlyUsedBuffer{
 		maxCapacity:  maxCapacity,
 		usageCounter: 0,
-		lastUsed:     make(map[string]uint64),
+		lastUsed:     make(map[string]uint64, maxCapacity),
 		mutex:        new(sync.RWMutex),
 	}
 }
@@ -81,6 +81,13 @@ func (lru *LeastRecentlyUsedBuffer) Len() int {
 	return len(lru.lastUsed)
 }
 
+// Clear the buffer.
+func (lru *LeastRecentlyUsedBuffer) Clear() {
+	lru.mutex.Lock()
+	defer lru.mutex.Unlock()
+	lru.lastUsed = make(map[string]uint64, lru.maxCapacity)
+}
+
 func (lru *LeastRecentlyUsedBuffer) String() string {
 	return fmt.Sprintf("%+v", lru.lastUsed)
 }

datastruct/lru_test.go

@@ -70,6 +70,11 @@ func TestLeastRecentlyUsedBuffer(t *testing.T) {
 			t.Fatal("element went missing", addAndEvict.add)
 		}
 	}
+
+	lru.Clear()
+	if lru.Len() != 0 {
+		t.Fatal("did not clear: ", lru.Len())
+	}
 }
 
 func TestLeastRecentlyUsedBuffer_Remove(t *testing.T) {

lalog/logger.go

@@ -28,25 +28,37 @@ const (
 type LogWarningCallbackFunc func(componentName, componentID, funcName string, actorName interface{}, err error, msg string)
 
 var (
-	// LatestWarnings are a small number of the most recent log messages (warnings and info messages ) kept in memory for retrieval and inspection.
+	// LatestWarnings are a small number of the most recent log messages
+	// (warnings and info messages) kept in memory for retrieval and inspection.
 	LatestLogs = datastruct.NewRingBuffer(NumLatestLogEntries)
 
 	// LatestWarnings are a small number of the most recent warning log messages kept in memory for retrieval and inspection.
 	LatestWarnings = datastruct.NewRingBuffer(NumLatestLogEntries)
 
-	// LatestWarningActors are a small number of actors that have recently generated warning messages.
-	// The LRU buffer helps to gain a more comprehensive picture of the actors that have resulted in warning log messages by
-	// working as a conditional filter, so that only the first instance of warning from an actor (identified by component name + function name +
-	// actor name) will be added to the in-memory warning log buffer. The subsequent warning messages of that actor will be excluded from the
-	// warning buffer. The actor will get another chance to show up in the warning buffer when it eventually becomes stale and is subsequently
-	// evicted by this LRU buffer.
-	LatestWarningActors = datastruct.NewLeastRecentlyUsedBuffer(NumLatestLogEntries / 4)
+	// LatestWarningActors a small number of log entry actors that have
+	// generated the latest log messages. The buffer provides a daemon-agnostic
+	// mechanism that de-duplicates repeated log messages, to avoid flooding
+	// stderr too hard, and makes the latest log entries retrieved on-demand
+	// much easier to read.
+	LatestWarningActors = datastruct.NewLeastRecentlyUsedBuffer(NumLatestLogEntries)
+
+	// LatestLogMessageContent are small number of recent log messages.
+	// The buffer provides a daemon-agnostic mechanism that de-duplicates
+	// repeated log messages, to avoid flooding stderr too hard, and makes the
+	// latest log entries retrieved on-demand much easier to read.
+	LatestLogMessageContent = datastruct.NewLeastRecentlyUsedBuffer(NumLatestLogEntries)
 
 	// LogWarningCallback is invoked in a separate goroutine after any logger has processed a warning message.
 	// The function must avoid generating a warning log message of itself, to avoid an infinite recursion.
 	GlobalLogWarningCallback LogWarningCallbackFunc = nil
 )
 
+// Clear the global LRU buffers used for de-duplicating log messages.
+func ClearDedupBuffers() {
+	LatestWarningActors.Clear()
+	LatestLogMessageContent.Clear()
+}
+
 /*
 LoggerIDField is a field of Logger's ComponentID, all fields that make up a ComponentID offer log entry a clue as to
 which component instance generated the log message.
@@ -124,45 +136,49 @@ func callerName(skip int) string {
 	return filepath.Base(file) + ":" + funName
 }
 
-// Print a log message and keep the message in warnings buffer.
-func (logger *Logger) Warning(actorName interface{}, err error, template string, values ...interface{}) {
-	functionName := callerName(2)
-	msg := logger.Format(functionName, actorName, err, template, values...)
-	msgWithTime := time.Now().Format("2006-01-02 15:04:05 ") + msg
-	log.Print(msg)
-	// All warning messages to to the latest logs buffer
-	LatestLogs.Push(msgWithTime)
+func (logger *Logger) warning(funcName string, actorName interface{}, err error, template string, values ...interface{}) {
 	// As determined by the LRU buffer, only the first instance of warning from this actor (identified by component name + function name +
 	// actor name) will be added to the in-memory warning log buffer, this helps to gain a more comprehensive picture of actors behind latest
 	// warning messages by suppressing the most noisy actors.
-	if alreadyPresent, _ := LatestWarningActors.Add(functionName + fmt.Sprint(actorName)); !alreadyPresent {
-		LatestWarnings.Push(msgWithTime)
-		if GlobalLogWarningCallback != nil {
-			go GlobalLogWarningCallback(logger.ComponentName, logger.getComponentIDs(), functionName, actorName, err, fmt.Sprintf(template, values...))
-		}
+	if alreadyPresent, _ := LatestWarningActors.Add(funcName + fmt.Sprint(actorName)); alreadyPresent {
+		return
 	}
-}
+	msg := logger.Format(funcName, actorName, err, template, values...)
+	log.Print(msg)
 
-// Print a log message and keep the message in latest log buffer. If there is an error, also keep the message in warnings buffer.
-func (logger *Logger) Info(actorName interface{}, err error, template string, values ...interface{}) {
-	functionName := callerName(2)
-	msg := logger.Format(functionName, actorName, err, template, values...)
 	msgWithTime := time.Now().Format("2006-01-02 15:04:05 ") + msg
 	LatestLogs.Push(msgWithTime)
-	log.Print(msg)
-	// If the log message comes with an error, treat it as a warning.
+	LatestWarnings.Push(msgWithTime)
+
+	if GlobalLogWarningCallback != nil {
+		go GlobalLogWarningCallback(logger.ComponentName, logger.getComponentIDs(), funcName, actorName, err, fmt.Sprintf(template, values...))
+	}
+}
+
+// Print a log message and keep the message in warnings buffer.
+func (logger *Logger) Warning(actorName interface{}, err error, template string, values ...interface{}) {
+	funcName := callerName(2)
+	logger.warning(funcName, actorName, err, template, values...)
+}
+
+func (logger *Logger) info(funcName string, actorName interface{}, err error, template string, values ...interface{}) {
 	if err != nil {
-		// As determined by the LRU buffer, only the first instance of warning from this actor (identified by component name + function name +
-		// actor name) will be added to the in-memory warning log buffer, this helps to gain a more comprehensive picture of actors behind latest
-		// warning messages by suppressing the most noisy actors.
-		if alreadyPresent, _ := LatestWarningActors.Add(functionName + fmt.Sprint(actorName)); !alreadyPresent {
-			LatestWarnings.Push(msgWithTime)
-			if GlobalLogWarningCallback != nil {
-				go GlobalLogWarningCallback(logger.ComponentName, logger.getComponentIDs(), functionName, actorName, err, fmt.Sprintf(template, values...))
-			}
-		}
+		// If the log message comes with an error, treat it as a warning.
+		logger.warning(funcName, actorName, err, template, values...)
+	}
+	msg := logger.Format(funcName, actorName, err, template, values...)
+	if alreadyPresent, _ := LatestLogMessageContent.Add(msg); alreadyPresent {
 		return
 	}
+	msgWithTime := time.Now().Format("2006-01-02 15:04:05 ") + msg
+	log.Print(msg)
+	LatestLogs.Push(msgWithTime)
+}
+
+// Print a log message and keep the message in latest log buffer. If there is an error, also keep the message in warnings buffer.
+func (logger *Logger) Info(actorName interface{}, err error, template string, values ...interface{}) {
+	funcName := callerName(2)
+	logger.info(funcName, actorName, err, template, values...)
 }
 
 func (logger *Logger) Abort(actorName interface{}, err error, template string, values ...interface{}) {

lalog/logger_test.go

@@ -106,7 +106,7 @@ func TestLogger_Warningf(t *testing.T) {
 	logger := Logger{}
 	// The first warning originated from Adam went into in-memory warning buffer
 	logger.Warning("adam", nil, "")
-	// The second warning also originated from Adam, therefore it still gets printed though it is excluded from the buffer.
+	// The second warning is de-duplicated.
 	logger.Warning("adam", nil, "")
 
 	var countLog, countWarn int
@@ -122,7 +122,7 @@ func TestLogger_Warningf(t *testing.T) {
 		}
 		return true
 	})
-	if countLog != 2 || countWarn != 1 {
+	if countLog != 1 || countWarn != 1 {
 		t.Fatal(countLog, countWarn)
 	}
 
@@ -144,7 +144,8 @@ func TestLogger_Warningf(t *testing.T) {
 		}
 		return true
 	})
-	if countLog != 4 || countWarn != 2 {
+	// "adam" and "eve" are recorded in the all-message and warning buffers.
+	if countLog != 2 || countWarn != 2 {
 		t.Fatal(countLog, countWarn)
 	}
 }

main.go

@@ -112,6 +112,7 @@ func main() {
 	// Enable common diagnosis and security features.
 	logger.Info(nil, nil, "program is starting, here is a summary of the runtime environment:\n%s", platform.GetProgramStatusSummary(false))
 	platform.LockMemory()
+	cli.ClearDedupBuffersInBackground()
 	cli.ReseedPseudoRandAndInBackground(logger)
 	cli.StartProfilingServer(logger, pprofHTTPPort)
 	if debug {