From 276d94d65396b98e5dcd6da8760b849805c8d62a Mon Sep 17 00:00:00 2001 From: Tim Raymond Date: Tue, 8 Feb 2022 11:47:07 -0500 Subject: [PATCH 1/5] fix: panic caused by nil Writer provided to Logger In the log.(*Logger).Init method, several different strategies are considered based on the configuration provided by the user. In one common case, a rotating log file is opened and the log output is tee-ed into it. If there is any issue with opening that log file, the `log.(*Log).SetOutput` method is never invoked on the underlying logger. Since this standard library logger was created with `nil` passed as the `io.Writer`, this results in a nil pointer deref panic. The error causing the issue is also not surfaced to the user. This initializes the standard library logger with the `io.Discard` writer. This adheres to the original intention here, while also being a safer alternative to nil (effectively writes are to /dev/null). Also, the error is written out to stderr, in the hopes that an operator will be able to diagnose and fix the issue (in the absense of a correct logger configuration). Finally, the logger initialization has been moved to a new function, `log.NewLoggerE` that properly exposes the underlying error. The original function, `NewLogger`, has been modified to use this function instead and has been marked Deprecated. --- log/logger.go | 41 ++++++++++++++++++++++++++++++----------- log/logger_test.go | 23 +++++++++++++++++++++++ 2 files changed, 53 insertions(+), 11 deletions(-) diff --git a/log/logger.go b/log/logger.go index 9381ca4a65..bd233f71dd 100644 --- a/log/logger.go +++ b/log/logger.go @@ -58,20 +58,39 @@ type Logger struct { var pid = os.Getpid() +// NewLoggerE creates a new Logger and surfaces any errors encountered during the process +func NewLoggerE(name string, level int, target int, logDir string) (*Logger, error) { + logger := &Logger{ + l: log.New(io.Discard, logPrefix, log.LstdFlags), + name: name, + level: level, + directory: logDir, + maxFileSize: maxLogFileSize, + maxFileCount: maxLogFileCount, + mutex: &sync.Mutex{}, + } + + err := logger.SetTarget(target) + if err != nil { + return nil, fmt.Errorf("setting log target: %w", err) + } + return logger, nil +} + // NewLogger creates a new Logger. +// +// Deprecated: use NewLoggerE instead func NewLogger(name string, level int, target int, logDir string) *Logger { - var logger Logger - - logger.l = log.New(nil, logPrefix, log.LstdFlags) - logger.name = name - logger.level = level - logger.directory = logDir - logger.SetTarget(target) - logger.maxFileSize = maxLogFileSize - logger.maxFileCount = maxLogFileCount - logger.mutex = &sync.Mutex{} + logger, err := NewLoggerE(name, level, target, logDir) + if err != nil { + // ideally this would be returned to the caller, but this API is depended + // on by unknown parties. Given at this point we have an unusable (but + // safe) logger, we log to stderr with the standard library in hopes that + // an operator will see the error and be able to take corrective action + log.Println("error initializing logger: err:", err) + } - return &logger + return logger } // SetName sets the log name. diff --git a/log/logger_test.go b/log/logger_test.go index 70c0636006..ddd89a1569 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -6,6 +6,7 @@ package log import ( "fmt" "os" + "path" "strings" "testing" ) @@ -14,6 +15,28 @@ const ( logName = "test" ) +func TestNewLoggerError(t *testing.T) { + // we expect an error from NewLoggerE in the event that we provide an + // unwriteable directory + + targetDir := "/definitelyDoesNotExist" + + // TODO(timraymond): this is some duplicated logic from + // (*Logger).getFileName. It should be possible to make it a publicly + // callable function to make this a little less brittle + fullLogPath := path.Join(targetDir, logName+".log") + + // confirm the assumptions of this test before we run it: + if _, err := os.Stat(fullLogPath); err == nil { + t.Skipf("The log file at %q exists, so this test cannot sensibly run. Delete it first", fullLogPath) + } + + _, err := NewLoggerE(logName, LevelInfo, TargetLogfile, targetDir) + if err == nil { + t.Error("expected an error but did not receive one") + } +} + // Tests that the log file rotates when size limit is reached. func TestLogFileRotatesWhenSizeLimitIsReached(t *testing.T) { logDirectory := "" // This sets the current location for logs From e3b22460ab7bce112a33eef0610376b40fa35d7f Mon Sep 17 00:00:00 2001 From: Tim Raymond Date: Tue, 8 Feb 2022 15:54:04 -0500 Subject: [PATCH 2/5] Remove redundant types in function signatures The linter correctly pointed out that the types are redundant here. While ordinarily I tend to leave them if the ellision appears in the middle of the signature, I respect the linter's decision :) --- log/logger.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/log/logger.go b/log/logger.go index bd233f71dd..51cb4ff1db 100644 --- a/log/logger.go +++ b/log/logger.go @@ -59,7 +59,7 @@ type Logger struct { var pid = os.Getpid() // NewLoggerE creates a new Logger and surfaces any errors encountered during the process -func NewLoggerE(name string, level int, target int, logDir string) (*Logger, error) { +func NewLoggerE(name string, level, target int, logDir string) (*Logger, error) { logger := &Logger{ l: log.New(io.Discard, logPrefix, log.LstdFlags), name: name, @@ -80,7 +80,7 @@ func NewLoggerE(name string, level int, target int, logDir string) (*Logger, err // NewLogger creates a new Logger. // // Deprecated: use NewLoggerE instead -func NewLogger(name string, level int, target int, logDir string) *Logger { +func NewLogger(name string, level, target int, logDir string) *Logger { logger, err := NewLoggerE(name, level, target, logDir) if err != nil { // ideally this would be returned to the caller, but this API is depended From 6abe0719d9d13bba6ee161009b2391e9d5f3d545 Mon Sep 17 00:00:00 2001 From: Tim Raymond Date: Tue, 8 Feb 2022 15:56:15 -0500 Subject: [PATCH 3/5] Change NewLoggerE test to use TempDir Rather than trying to pull a non-existant path out of thin air and hoping that it doesn't exist, this instead uses os.TempDir to create a guaranteed-empty directory. From within the newly-created tempdir we try to use a non-existent path. This is better both on a single platform, but also has the benefit of working well on Windows too. --- log/logger_test.go | 27 ++++++++++++++------------- 1 file changed, 14 insertions(+), 13 deletions(-) diff --git a/log/logger_test.go b/log/logger_test.go index ddd89a1569..79d780eaf2 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -19,19 +19,20 @@ func TestNewLoggerError(t *testing.T) { // we expect an error from NewLoggerE in the event that we provide an // unwriteable directory - targetDir := "/definitelyDoesNotExist" - - // TODO(timraymond): this is some duplicated logic from - // (*Logger).getFileName. It should be possible to make it a publicly - // callable function to make this a little less brittle - fullLogPath := path.Join(targetDir, logName+".log") - - // confirm the assumptions of this test before we run it: - if _, err := os.Stat(fullLogPath); err == nil { - t.Skipf("The log file at %q exists, so this test cannot sensibly run. Delete it first", fullLogPath) - } - - _, err := NewLoggerE(logName, LevelInfo, TargetLogfile, targetDir) + // this test needs a guaranteed empty directory, so we create a temporary one + // and ensure that it gets destroyed afterward. + targetDir := os.TempDir() + t.Cleanup(func() { + // This removal could produce an error, but since it's a temporary + // directory anyway, this is a best-effort cleanup + os.Remove(targetDir) + }) + + // if we just use the targetDir, NewLoggerE will create the file and it will + // work. We need a non-existent directory *within* the tempdir + fullPath := path.Join(targetDir, "definitelyDoesNotExist") + + _, err := NewLoggerE(logName, LevelInfo, TargetLogfile, fullPath) if err == nil { t.Error("expected an error but did not receive one") } From ff7b369b315ed22ade2c2289450c8755b2555f7c Mon Sep 17 00:00:00 2001 From: Tim Raymond Date: Tue, 8 Feb 2022 16:58:52 -0500 Subject: [PATCH 4/5] Fix test to use os.MkdirTemp instead of os.TempDir The intention of this test was to create a new temporary directory rather than use the system's temporary directory. This mistake was pointed out by @rbtr in a code review (thanks!). --- log/logger_test.go | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/log/logger_test.go b/log/logger_test.go index 79d780eaf2..e341b5604a 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -21,7 +21,11 @@ func TestNewLoggerError(t *testing.T) { // this test needs a guaranteed empty directory, so we create a temporary one // and ensure that it gets destroyed afterward. - targetDir := os.TempDir() + targetDir, err := os.MkdirTemp("", "acn") + if err != nil { + t.Fatal("unable to create temporary directory: err:", err) + } + t.Cleanup(func() { // This removal could produce an error, but since it's a temporary // directory anyway, this is a best-effort cleanup @@ -32,7 +36,7 @@ func TestNewLoggerError(t *testing.T) { // work. We need a non-existent directory *within* the tempdir fullPath := path.Join(targetDir, "definitelyDoesNotExist") - _, err := NewLoggerE(logName, LevelInfo, TargetLogfile, fullPath) + _, err = NewLoggerE(logName, LevelInfo, TargetLogfile, fullPath) if err == nil { t.Error("expected an error but did not receive one") } From 231d34800fec5d8aa38aa2c2e590ae717ddf42a2 Mon Sep 17 00:00:00 2001 From: Tim Raymond Date: Tue, 8 Feb 2022 17:00:25 -0500 Subject: [PATCH 5/5] Fix nil logger under error conditions When an error is present, we want to return both the error and the logger to guarantee that a usable logger is always present. This returns the logger in all circumstances and documents that fact in the godoc for this function. --- log/logger.go | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/log/logger.go b/log/logger.go index 51cb4ff1db..065cd6e064 100644 --- a/log/logger.go +++ b/log/logger.go @@ -58,7 +58,11 @@ type Logger struct { var pid = os.Getpid() -// NewLoggerE creates a new Logger and surfaces any errors encountered during the process +// NewLoggerE creates a new Logger and surfaces any errors encountered during +// the process. The returned logger is guaranteed to be safe to use when a +// non-nil error is returned, but may have undesired behavior. Callers should +// treat the logger as nil under error conditions unless necessary for +// backwards compatibility reasons. func NewLoggerE(name string, level, target int, logDir string) (*Logger, error) { logger := &Logger{ l: log.New(io.Discard, logPrefix, log.LstdFlags), @@ -72,7 +76,8 @@ func NewLoggerE(name string, level, target int, logDir string) (*Logger, error) err := logger.SetTarget(target) if err != nil { - return nil, fmt.Errorf("setting log target: %w", err) + // we *do* want to return the logger here for backwards compatibility + return logger, fmt.Errorf("setting log target: %w", err) } return logger, nil }