Skip to content

Commit

Permalink
verify that logging is present on rotation test cases
Browse files Browse the repository at this point in the history
Signed-off-by: ChrsMark <[email protected]>
  • Loading branch information
ChrsMark committed May 31, 2024
1 parent c1699fc commit 78f738a
Show file tree
Hide file tree
Showing 3 changed files with 67 additions and 11 deletions.
4 changes: 2 additions & 2 deletions pkg/stanza/fileconsumer/design.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
15 changes: 6 additions & 9 deletions pkg/stanza/fileconsumer/file.go
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down
59 changes: 59 additions & 0 deletions pkg/stanza/fileconsumer/rotation_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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()
Expand All @@ -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
Expand All @@ -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()
Expand All @@ -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
Expand All @@ -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")
Expand All @@ -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,
Expand All @@ -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")
Expand All @@ -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
Expand Down

0 comments on commit 78f738a

Please sign in to comment.