From 2a09dd3a3952104219f8d911a93c99225bf25de7 Mon Sep 17 00:00:00 2001
From: Ramiro <64089641+ramiro-gamarra@users.noreply.github.com>
Date: Thu, 10 Aug 2023 13:16:58 -0700
Subject: [PATCH] fix: deadlock when os.Stat errors within rotate method
 (#1716)

* fix: deadlock when os.Stat errors within rotate method

* pr feedback: adding test
---
 log/logger.go      | 64 ++++++++++++++++++++++++++++------------------
 log/logger_test.go | 28 ++++++++++++++++++++
 2 files changed, 67 insertions(+), 25 deletions(-)

diff --git a/log/logger.go b/log/logger.go
index a1299c7af..17d577bac 100644
--- a/log/logger.go
+++ b/log/logger.go
@@ -149,42 +149,54 @@ func (logger *Logger) getLogFileName() string {
 	return logFileName
 }
 
-// todo: handle errors and use atomic file rotation
-// Rotate checks the active log file size and rotates log files if necessary.
-func (logger *Logger) rotate() {
-	// Return if target is not a log file.
+// todo: handle errors and use atomic file rotation.
+// rotate checks the active log file size and rotates log files if necessary.
+func (logger *Logger) rotate() error {
+	// return if target is not a log file.
 	if (logger.target != TargetLogfile && logger.target != TargetStdOutAndLogFile) || logger.out == nil {
-		return
+		return nil
 	}
 
 	fileName := logger.getLogFileName()
 	fileInfo, err := os.Stat(fileName)
 	if err != nil {
-		logger.Logf("[log] Failed to query log file info %+v.", err)
-		return
+		return fmt.Errorf("rotate: could not get file info: %w", err)
 	}
 
-	// Rotate if size limit is reached.
-	if fileInfo.Size() >= int64(logger.maxFileSize) {
-		logger.out.Close()
-		var fn1, fn2 string
+	// only rotate if size limit is reached.
+	if fileInfo.Size() < int64(logger.maxFileSize) {
+		return nil
+	}
 
-		// Rotate log files, keeping the last maxFileCount files.
-		for n := logger.maxFileCount - 1; n >= 0; n-- {
-			fn2 = fn1
-			if n == 0 {
-				fn1 = fileName
-			} else {
-				fn1 = fmt.Sprintf("%v.%v", fileName, n)
-			}
-			if fn2 != "" {
-				os.Rename(fn1, fn2)
-			}
+	// todo: what should happen if current file cannot be closed?
+	_ = logger.out.Close()
+
+	var fn1 string
+	// rotate log files, keeping the last maxFileCount files.
+	for n := logger.maxFileCount - 1; n >= 0; n-- {
+		fn2 := fn1
+
+		if n == 0 {
+			fn1 = fileName
+		} else {
+			fn1 = fmt.Sprintf("%v.%v", fileName, n)
 		}
 
-		// Create a new log file.
-		logger.SetTarget(logger.target)
+		if fn2 != "" {
+			// this algorithm attempts renaming non-existent files.
+			// todo: handle different types of error: if a non-existing file
+			// is being renamed, then continue. if an existing file cannot
+			// be renamed, log.
+			_ = os.Rename(fn1, fn2)
+		}
 	}
+
+	// Create a new log file.
+	if err := logger.SetTarget(logger.target); err != nil {
+		return fmt.Errorf("rotate: could not set target: %w", err)
+	}
+
+	return nil
 }
 
 // Request logs a structured request.
@@ -221,7 +233,9 @@ func (logger *Logger) ResponseEx(tag string, request interface{}, response inter
 // logf logs a formatted string.
 func (logger *Logger) logf(format string, args ...interface{}) {
 	if logger.callCount%rotationCheckFrq == 0 {
-		logger.rotate()
+		if err := logger.rotate(); err != nil {
+			logger.l.Printf("logf: could not rotate file: %v", err)
+		}
 	}
 	format = fmt.Sprintf("[%v] %s", pid, format)
 	logger.callCount++
diff --git a/log/logger_test.go b/log/logger_test.go
index e341b5604..76829eb0c 100644
--- a/log/logger_test.go
+++ b/log/logger_test.go
@@ -9,6 +9,9 @@ import (
 	"path"
 	"strings"
 	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 const (
@@ -42,6 +45,31 @@ func TestNewLoggerError(t *testing.T) {
 	}
 }
 
+func TestRotateFailure(t *testing.T) {
+	// this test simulates a scenario where log rotation should fail because the file to rotate does not exist.
+	// previously, such a scenario would recursively call Logf, which would deadlock because of the mutexes taken.
+	// the logging api does not bubble up any errors, and does not allow any configuration of the frequency of
+	// rotation checks, but we shouldn't couple this test (too much) to the internal algorithm.
+	//
+	// the assertions below should demonstrate that:
+	// - logging does not block even if the target file is missing.
+	// - an explicit rotation call should return with an error and not block indefinitely.
+	// - successive calls after a rotation failure should not block either.
+	l := NewLogger(logName, LevelInfo, TargetStdOutAndLogFile, "/tmp/")
+	require.NotNil(t, l)
+
+	err := os.Remove(l.getLogFileName())
+	require.NoError(t, err)
+
+	l.Logf("this log line may or may not invoke rotation")
+
+	err = l.rotate()
+	var pErr *os.PathError
+	assert.ErrorAs(t, err, &pErr)
+
+	l.Logf("this log line may or may not invoke rotation")
+}
+
 // Tests that the log file rotates when size limit is reached.
 func TestLogFileRotatesWhenSizeLimitIsReached(t *testing.T) {
 	logDirectory := "" // This sets the current location for logs