From 78f738aeb66dd6046eb7f0f603b421f7e48fe0f0 Mon Sep 17 00:00:00 2001 From: ChrsMark Date: Fri, 31 May 2024 16:30:51 +0300 Subject: [PATCH] verify that logging is present on rotation test cases Signed-off-by: ChrsMark --- pkg/stanza/fileconsumer/design.md | 4 +- pkg/stanza/fileconsumer/file.go | 15 +++--- pkg/stanza/fileconsumer/rotation_test.go | 59 ++++++++++++++++++++++++ 3 files changed, 67 insertions(+), 11 deletions(-) diff --git a/pkg/stanza/fileconsumer/design.md b/pkg/stanza/fileconsumer/design.md index 9fbed1f0d867..23100d22cd21 100644 --- a/pkg/stanza/fileconsumer/design.md +++ b/pkg/stanza/fileconsumer/design.md @@ -211,10 +211,10 @@ The net effect of the shut down routine is that all files are checkpointed in a #### Supported cases A) When a file is moved within the pattern with unread logs on the end, then the original is created again, -we get the unread logs on the moved as well as any new logs written to the newly created file. + we get the unread logs on the moved as well as any new logs written to the newly created file. B) When a file is copied within the pattern with unread logs on the end, then the original is truncated, -we get the unread logs on the copy as well as any new logs written to the truncated file. + we get the unread logs on the copy as well as any new logs written to the truncated file. C) When a file it rotated out of pattern via move/create, we detect that our old handle is still valid and we attempt to read from it. diff --git a/pkg/stanza/fileconsumer/file.go b/pkg/stanza/fileconsumer/file.go index b5cbaa4d14df..517526ebe503 100644 --- a/pkg/stanza/fileconsumer/file.go +++ b/pkg/stanza/fileconsumer/file.go @@ -231,19 +231,16 @@ func (m *Manager) newReader(ctx context.Context, file *os.File, fp *fingerprint. // Check previous poll cycle for match if oldReader := m.tracker.GetOpenFile(fp); oldReader != nil { if oldReader.GetFileName() != file.Name() { - m.set.Logger.Debug( - "File has been rotated", - zap.String("original_path", oldReader.GetFileName()), - zap.String("rotated_path", file.Name())) - if !oldReader.Validate() { m.set.Logger.Debug( - "File has been truncated", - zap.String("path", oldReader.GetFileName())) + "File has been rotated(truncated)", + zap.String("original_path", oldReader.GetFileName()), + zap.String("rotated_path", file.Name())) } else { m.set.Logger.Debug( - "File has been moved", - zap.String("path", oldReader.GetFileName())) + "File has been rotated(moved)", + zap.String("original_path", oldReader.GetFileName()), + zap.String("rotated_path", file.Name())) } } return m.readerFactory.NewReaderFromMetadata(file, oldReader.Close()) diff --git a/pkg/stanza/fileconsumer/rotation_test.go b/pkg/stanza/fileconsumer/rotation_test.go index 008bb01bb71f..2c8912cc6eb7 100644 --- a/pkg/stanza/fileconsumer/rotation_test.go +++ b/pkg/stanza/fileconsumer/rotation_test.go @@ -14,7 +14,10 @@ import ( "testing" "time" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" "github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/internal/filetest" "github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/testutil" @@ -215,6 +218,9 @@ func TestTrackRotatedFilesLogOrder(t *testing.T) { cfg := NewConfig().includeDir(tempDir) cfg.StartAt = "beginning" operator, sink := testManager(t, cfg) + core, observedLogs := observer.New(zap.DebugLevel) + logger := zap.New(core) + operator.set.Logger = logger originalFile := filetest.OpenTemp(t, tempDir) orginalName := originalFile.Name() @@ -240,6 +246,16 @@ func TestTrackRotatedFilesLogOrder(t *testing.T) { filetest.WriteString(t, newFile, "testlog3\n") sink.ExpectTokens(t, []byte("testlog2"), []byte("testlog3")) + + // verify that proper logging has taken place + allLogs := observedLogs.All() + foundLog := false + for _, actualLog := range allLogs { + if actualLog.Message == "File has been rotated(moved)" { + foundLog = true + } + } + assert.True(t, foundLog) } // When a file it rotated out of pattern via move/create, we should @@ -256,6 +272,9 @@ func TestRotatedOutOfPatternMoveCreate(t *testing.T) { cfg.StartAt = "beginning" operator, sink := testManager(t, cfg) operator.persister = testutil.NewUnscopedMockPersister() + core, observedLogs := observer.New(zap.DebugLevel) + logger := zap.New(core) + operator.set.Logger = logger originalFile := filetest.OpenTempWithPattern(t, tempDir, "*.log1") originalFileName := originalFile.Name() @@ -280,6 +299,20 @@ func TestRotatedOutOfPatternMoveCreate(t *testing.T) { // expect remaining log from old file as well as all from new file sink.ExpectTokens(t, []byte("testlog2"), []byte("testlog4"), []byte("testlog5")) + + // verify that proper logging has taken place + allLogs := observedLogs.All() + expectedLogs := map[string]string{ + "File has been rotated(moved)": "", + "Reading lost file": "", + } + foundLogs := 0 + for _, actualLog := range allLogs { + if _, ok := expectedLogs[actualLog.Message]; ok { + foundLogs++ + } + } + assert.Equal(t, 2, foundLogs) } // When a file it rotated out of pattern via copy/truncate, we should @@ -293,6 +326,9 @@ func TestRotatedOutOfPatternCopyTruncate(t *testing.T) { cfg.StartAt = "beginning" operator, sink := testManager(t, cfg) operator.persister = testutil.NewUnscopedMockPersister() + core, observedLogs := observer.New(zap.DebugLevel) + logger := zap.New(core) + operator.set.Logger = logger originalFile := filetest.OpenTempWithPattern(t, tempDir, "*.log1") filetest.WriteString(t, originalFile, "testlog1\n") @@ -318,6 +354,16 @@ func TestRotatedOutOfPatternCopyTruncate(t *testing.T) { operator.poll(context.Background()) sink.ExpectTokens(t, []byte("testlog4"), []byte("testlog5")) + + // verify that proper logging has taken place + allLogs := observedLogs.All() + foundLog := false + for _, actualLog := range allLogs { + if actualLog.Message == "File has been rotated(truncated)" { + foundLog = true + } + } + assert.True(t, foundLog) } // TruncateThenWrite tests that, after a file has been truncated, @@ -333,6 +379,9 @@ func TestTruncateThenWrite(t *testing.T) { cfg.StartAt = "beginning" operator, sink := testManager(t, cfg) operator.persister = testutil.NewUnscopedMockPersister() + core, observedLogs := observer.New(zap.DebugLevel) + logger := zap.New(core) + operator.set.Logger = logger temp1 := filetest.OpenTemp(t, tempDir) filetest.WriteString(t, temp1, "testlog1\ntestlog2\n") @@ -348,6 +397,16 @@ func TestTruncateThenWrite(t *testing.T) { operator.poll(context.Background()) sink.ExpectToken(t, []byte("testlog3")) sink.ExpectNoCalls(t) + + // verify that proper logging has taken place + allLogs := observedLogs.All() + foundLog := false + for _, actualLog := range allLogs { + if actualLog.Message == "File has been rotated(truncated)" { + foundLog = true + } + } + assert.True(t, foundLog) } // CopyTruncateWriteBoth tests that when a file is copied