From 26fc051441e2514d73f39261121e4338644b4372 Mon Sep 17 00:00:00 2001 From: Sven Rebhan <36194019+srebhan@users.noreply.github.com> Date: Mon, 24 Feb 2025 17:05:29 +0100 Subject: [PATCH] fix(logging): Handle closing correctly and fix tests (#16539) --- logger/event_logger.go | 11 +++- logger/event_logger_test.go | 2 + logger/logger.go | 11 +++- logger/logger_test.go | 2 + logger/structured_logger.go | 5 ++ logger/structured_logger_test.go | 96 +++++++++++++++++++++----------- logger/text_logger.go | 6 ++ logger/text_logger_test.go | 80 +++++++++++++++++--------- 8 files changed, 152 insertions(+), 61 deletions(-) diff --git a/logger/event_logger.go b/logger/event_logger.go index c5847c93b..4df25f958 100644 --- a/logger/event_logger.go +++ b/logger/event_logger.go @@ -24,7 +24,14 @@ type eventLogger struct { } func (l *eventLogger) Close() error { - return l.eventlog.Close() + if l.eventlog == nil { + return nil + } + if err := l.eventlog.Close(); err != nil { + return err + } + l.eventlog = nil + return nil } func (l *eventLogger) Print(level telegraf.LogLevel, _ time.Time, prefix string, _ map[string]interface{}, args ...interface{}) { @@ -33,7 +40,7 @@ func (l *eventLogger) Print(level telegraf.LogLevel, _ time.Time, prefix string, return } - msg := level.Indicator() + " " + prefix + fmt.Sprint(args...) + msg := prefix + fmt.Sprint(args...) var err error switch level { diff --git a/logger/event_logger_test.go b/logger/event_logger_test.go index c34b7b4ee..cc026b36d 100644 --- a/logger/event_logger_test.go +++ b/logger/event_logger_test.go @@ -58,6 +58,7 @@ func TestEventLogIntegration(t *testing.T) { Logfile: "", } require.NoError(t, SetupLogging(config)) + defer func() { require.NoError(t, CloseLogging()) }() now := time.Now() log.Println("I! Info message") @@ -80,6 +81,7 @@ func TestRestrictedEventLogIntegration(t *testing.T) { Quiet: true, } require.NoError(t, SetupLogging(config)) + defer func() { require.NoError(t, CloseLogging()) }() // separate previous log messages by small delay time.Sleep(time.Second) diff --git a/logger/logger.go b/logger/logger.go index ab5a2ff2f..7ca807a2a 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -5,6 +5,7 @@ import ( "fmt" "io" "log" + "os" "strings" "sync" "time" @@ -289,7 +290,15 @@ func RedirectLogging(w io.Writer) { } func CloseLogging() error { - return instance.close() + if instance == nil { + return nil + } + + if err := instance.close(); err != nil && !errors.Is(err, os.ErrClosed) { + return err + } + + return nil } func init() { diff --git a/logger/logger_test.go b/logger/logger_test.go index cca66fe1e..580cee8d3 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -14,6 +14,8 @@ func TestTextLogTargetDefault(t *testing.T) { Quiet: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() + logger, ok := instance.impl.(*textLogger) require.Truef(t, ok, "logging instance is not a default-logger but %T", instance.impl) require.Equal(t, logger.logger.Writer(), os.Stderr) diff --git a/logger/structured_logger.go b/logger/structured_logger.go index 5a4ed86a4..11cce9eaa 100644 --- a/logger/structured_logger.go +++ b/logger/structured_logger.go @@ -21,6 +21,11 @@ type structuredLogger struct { } func (l *structuredLogger) Close() error { + // Close the writer if possible and avoid closing stderr + if l.output == os.Stderr { + return nil + } + if closer, ok := l.output.(io.Closer); ok { return closer.Close() } diff --git a/logger/structured_logger_test.go b/logger/structured_logger_test.go index 1721bc48f..f83972c14 100644 --- a/logger/structured_logger_test.go +++ b/logger/structured_logger_test.go @@ -21,27 +21,33 @@ func TestStructuredStderr(t *testing.T) { Quiet: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() + logger, ok := instance.impl.(*structuredLogger) require.Truef(t, ok, "logging instance is not a structured-logger but %T", instance.impl) require.Equal(t, logger.output, os.Stderr) } func TestStructuredFile(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("I! TEST") log.Printf("D! TEST") // <- should be ignored - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -59,21 +65,25 @@ func TestStructuredFile(t *testing.T) { } func TestStructuredFileDebug(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("D! TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -91,22 +101,26 @@ func TestStructuredFileDebug(t *testing.T) { } func TestStructuredFileError(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Quiet: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("E! TEST") log.Printf("I! TEST") // <- should be ignored - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) @@ -125,21 +139,25 @@ func TestStructuredFileError(t *testing.T) { } func TestStructuredAddDefaultLogLevel(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -159,22 +177,26 @@ func TestStructuredAddDefaultLogLevel(t *testing.T) { func TestStructuredDerivedLogger(t *testing.T) { instance = defaultHandler() - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() l := New("testing", "test", "") l.Info("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -196,17 +218,21 @@ func TestStructuredDerivedLogger(t *testing.T) { func TestStructuredDerivedLoggerWithAttributes(t *testing.T) { instance = defaultHandler() - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() l := New("testing", "test", "myalias") l.AddAttribute("alias", "foo") // Should be ignored @@ -214,7 +240,7 @@ func TestStructuredDerivedLoggerWithAttributes(t *testing.T) { l.Info("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -236,21 +262,25 @@ func TestStructuredDerivedLoggerWithAttributes(t *testing.T) { } func TestStructuredWriteToTruncatedFile(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ @@ -266,11 +296,11 @@ func TestStructuredWriteToTruncatedFile(t *testing.T) { delete(actual, "time") require.Equal(t, expected, actual) - require.NoError(t, os.Truncate(tmpfile.Name(), 0)) + require.NoError(t, os.Truncate(filename, 0)) log.Printf("SHOULD BE FIRST") - buf, err = os.ReadFile(tmpfile.Name()) + buf, err = os.ReadFile(filename) require.NoError(t, err) expected = map[string]interface{}{ @@ -292,15 +322,13 @@ func TestStructuredWriteToFileInRotation(t *testing.T) { Logfile: filepath.Join(tempDir, "test.log"), LogFormat: "structured", RotationMaxArchives: -1, - RotationMaxSize: 30, + RotationMaxSize: 70, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() - // Close the writer here, otherwise the temp folder cannot be deleted because the current log file is in use. - defer CloseLogging() //nolint:errcheck // We cannot do anything if this fails - - log.Printf("I! TEST 1") // Writes 31 bytes, will rotate - log.Printf("I! TEST") // Writes 29 byes, no rotation expected + log.Printf("I! TEST 1") // Writes 70 bytes in structured format, will rotate + log.Printf("I! TEST") // Writes 68 bytes in structured format, no rotation expected files, err := os.ReadDir(tempDir) require.NoError(t, err) @@ -310,23 +338,27 @@ func TestStructuredWriteToFileInRotation(t *testing.T) { func TestStructuredLogMessageKey(t *testing.T) { instance = defaultHandler() - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "structured", RotationMaxArchives: -1, Debug: true, StructuredLogMessageKey: "message", } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() l := New("testing", "test", "") l.Info("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) expected := map[string]interface{}{ diff --git a/logger/text_logger.go b/logger/text_logger.go index 6cfba4ac5..72bf62043 100644 --- a/logger/text_logger.go +++ b/logger/text_logger.go @@ -11,6 +11,12 @@ import ( "github.com/influxdata/telegraf/internal/rotate" ) +// Keep those constants for backward compatibility even though they are not +// used anywhere. See https://github.com/influxdata/telegraf/pull/15514 for +// more details. +// +// Deprecated: Those constants are unused and deprecated. The removal is +// scheduled for v1.45.0, if you use them please adapt your code! const ( LogTargetFile = "file" LogTargetStderr = "stderr" diff --git a/logger/text_logger_test.go b/logger/text_logger_test.go index 3a3535649..e7aba75c3 100644 --- a/logger/text_logger_test.go +++ b/logger/text_logger_test.go @@ -19,121 +19,143 @@ func TestTextStderr(t *testing.T) { Quiet: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() + logger, ok := instance.impl.(*textLogger) require.Truef(t, ok, "logging instance is not a text-logger but %T", instance.impl) require.Equal(t, logger.logger.Writer(), os.Stderr) } func TestTextFile(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("I! TEST") log.Printf("D! TEST") // <- should be ignored - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z I! TEST\n", string(buf[19:])) } func TestTextFileDebug(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("D! TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z D! TEST\n", string(buf[19:])) } func TestTextFileError(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Quiet: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("E! TEST") log.Printf("I! TEST") // <- should be ignored - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z E! TEST\n", string(buf[19:])) } func TestTextAddDefaultLogLevel(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z I! TEST\n", string(buf[19:])) } func TestTextWriteToTruncatedFile(t *testing.T) { - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z I! TEST\n", string(buf[19:])) - require.NoError(t, os.Truncate(tmpfile.Name(), 0)) + require.NoError(t, os.Truncate(filename, 0)) log.Printf("SHOULD BE FIRST") - buf, err = os.ReadFile(tmpfile.Name()) + buf, err = os.ReadFile(filename) require.NoError(t, err) require.Equal(t, "Z I! SHOULD BE FIRST\n", string(buf[19:])) } @@ -147,9 +169,7 @@ func TestTextWriteToFileInRotation(t *testing.T) { RotationMaxSize: 30, } require.NoError(t, SetupLogging(cfg)) - - // Close the writer here, otherwise the temp folder cannot be deleted because the current log file is in use. - defer CloseLogging() //nolint:errcheck // We cannot do anything if this fails + defer func() { require.NoError(t, CloseLogging()) }() log.Printf("I! TEST 1") // Writes 31 bytes, will rotate log.Printf("I! TEST") // Writes 29 byes, no rotation expected @@ -162,22 +182,26 @@ func TestTextWriteToFileInRotation(t *testing.T) { func TestTextWriteDerivedLogger(t *testing.T) { instance = defaultHandler() - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() l := New("testing", "test", "") l.Info("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z I! [testing.test] TEST\n", string(buf[19:])) @@ -186,17 +210,21 @@ func TestTextWriteDerivedLogger(t *testing.T) { func TestTextWriteDerivedLoggerWithAttributes(t *testing.T) { instance = defaultHandler() - tmpfile, err := os.CreateTemp("", "") + tmpfile, err := os.CreateTemp(t.TempDir(), "") require.NoError(t, err) defer os.Remove(tmpfile.Name()) + filename := tmpfile.Name() + require.NoError(t, tmpfile.Close()) + cfg := &Config{ - Logfile: tmpfile.Name(), + Logfile: filename, LogFormat: "text", RotationMaxArchives: -1, Debug: true, } require.NoError(t, SetupLogging(cfg)) + defer func() { require.NoError(t, CloseLogging()) }() l := New("testing", "test", "myalias") @@ -206,7 +234,7 @@ func TestTextWriteDerivedLoggerWithAttributes(t *testing.T) { l.Info("TEST") - buf, err := os.ReadFile(tmpfile.Name()) + buf, err := os.ReadFile(filename) require.NoError(t, err) require.Greater(t, len(buf), 19) require.Equal(t, "Z I! [testing.test::myalias] TEST\n", string(buf[19:]))