Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[7.17](backport #38421) Make log messages in the file scanner less noisy #40555

Merged
merged 5 commits into from
Aug 19, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG-developer.next.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,7 @@ The list below covers the major changes between 7.0.0-rc2 and master only.
- Improve tests files with shorter statements. {pull}35667[35667]
- Improve compatibility and reduce flakyness of Python tests {pull}31588[31588]
- Pin PyYAML version to 5.3.1 to avoid CI errors temporarily {pull}36091[36091]
- Make logs for empty and small files less noisy when using fingerprint file identity in filestream. {pull}38421[38421]

==== Deprecated

Expand Down
13 changes: 11 additions & 2 deletions filebeat/input/filestream/fswatch.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ package filestream
import (
"crypto/sha256"
"encoding/hex"
"errors"
"fmt"
"hash"
"io"
Expand All @@ -44,6 +45,10 @@ const (
watcherDebugKey = "file_watcher"
)

var (
errFileTooSmall = errors.New("file size is too small for ingestion")
)

type fileWatcherConfig struct {
// Interval is the time between two scans.
Interval time.Duration `config:"check_interval"`
Expand Down Expand Up @@ -201,7 +206,7 @@ func (w *fileWatcher) watch(ctx unison.Canceler) {
for path, fd := range newFilesByName {
// no need to react on empty new files
if fd.Info.Size() == 0 {
w.log.Warnf("file %q has no content yet, skipping", fd.Filename)
w.log.Debugf("file %q has no content yet, skipping", fd.Filename)
delete(paths, path)
continue
}
Expand Down Expand Up @@ -384,6 +389,10 @@ func (s *fileScanner) GetFiles() map[string]loginp.FileDescriptor {
}

fd, err := s.toFileDescriptor(&it)
if errors.Is(err, errFileTooSmall) {
s.log.Debugf("cannot start ingesting from file %q: %s", filename, err)
continue
}
if err != nil {
s.log.Warnf("cannot create a file descriptor for an ingest target %q: %s", filename, err)
continue
Expand Down Expand Up @@ -470,7 +479,7 @@ func (s *fileScanner) toFileDescriptor(it *ingestTarget) (fd loginp.FileDescript
// we should not open the file if we know it's too small
minSize := s.cfg.Fingerprint.Offset + s.cfg.Fingerprint.Length
if fileSize < minSize {
return fd, fmt.Errorf("filesize of %q is %d bytes, expected at least %d bytes for fingerprinting", fd.Filename, fileSize, minSize)
return fd, fmt.Errorf("filesize of %q is %d bytes, expected at least %d bytes for fingerprinting: %w", fd.Filename, fileSize, minSize, errFileTooSmall)
}

file, err := os.Open(it.originalFilename)
Expand Down
36 changes: 30 additions & 6 deletions filebeat/input/filestream/fswatch_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -275,17 +275,20 @@
err = os.WriteFile(filename, nil, 0777)
require.NoError(t, err)

t.Run("issues a warning in logs", func(t *testing.T) {
var lastWarning string
t.Run("issues a debug message in logs", func(t *testing.T) {
expLogMsg := fmt.Sprintf("file %q has no content yet, skipping", filename)
require.Eventually(t, func() bool {
logs := logp.ObserverLogs().FilterLevelExact(logp.WarnLevel.ZapLevel()).TakeAll()
logs := logp.ObserverLogs().FilterLevelExact(logp.DebugLevel.ZapLevel()).TakeAll()
if len(logs) == 0 {
return false
}
lastWarning = logs[len(logs)-1].Message
return strings.Contains(lastWarning, expLogMsg)
}, 100*time.Millisecond, 10*time.Millisecond, "required a warning message %q but got %q", expLogMsg, lastWarning)
for _, l := range logs {
if strings.Contains(l.Message, expLogMsg) {
return true
}
}
return false
}, 100*time.Millisecond, 10*time.Millisecond, "required a debug message %q but never found", expLogMsg)
})

t.Run("emits a create event once something is written to the empty file", func(t *testing.T) {
Expand Down Expand Up @@ -395,7 +398,8 @@
Info: testFileInfo{name: secondBasename, size: 5}, // "line\n"
},
}
//lint:ignore SA4006 False positive, nextEvt is used below.
nextEvt := loginp.FSEvent{}

Check failure on line 402 in filebeat/input/filestream/fswatch_test.go

View workflow job for this annotation

GitHub Actions / lint (darwin)

SA4006: this value of `nextEvt` is never used (staticcheck)

// Events can be out of order, at least on Windows, so we
// need to check the fileneame, then compare the events.
Expand Down Expand Up @@ -799,6 +803,26 @@
})
}

t.Run("does not issue warnings when file is too small", func(t *testing.T) {
cfgStr := `
scanner:
fingerprint:
enabled: true
offset: 0
length: 1024
`
err := logp.DevelopmentSetup(logp.ToObserverOutput())
require.NoError(t, err)

// this file is 128 bytes long
paths := []string{filepath.Join(dir, undersizedBasename)}
s := createScannerWithConfig(t, paths, cfgStr)
files := s.GetFiles()
require.Empty(t, files)
logs := logp.ObserverLogs().FilterLevelExact(logp.WarnLevel.ZapLevel()).TakeAll()
require.Empty(t, logs, "there must be no warning logs for files too small")
})

t.Run("returns error when creating scanner with a fingerprint too small", func(t *testing.T) {
cfgStr := `
scanner:
Expand Down
Loading