Skip to content

Commit

Permalink
Make log messages in the file scanner less noisy (#38421)
Browse files Browse the repository at this point in the history
* Demote warning about empty files to the Debug level
* Demote warnings about files too small to the Debug level
* Improve wording, so it does not sound like an error
  • Loading branch information
rdner authored Mar 20, 2024
1 parent d64ce48 commit 4df595f
Show file tree
Hide file tree
Showing 3 changed files with 40 additions and 8 deletions.
1 change: 1 addition & 0 deletions CHANGELOG-developer.next.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -181,6 +181,7 @@ The list below covers the major changes between 7.0.0-rc2 and main only.
- Elide retryable HTTP client construction in Filebeat HTTPJSON and CEL inputs if not needed. {pull}36916[36916]
- Allow assignment of packetbeat protocols to interfaces. {issue}36574[36564] {pull}36852[36852]
- Add Active Directory entity collector for Filebeat entity analytics. {pull}37854[37854]
- 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 @@ -45,6 +46,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 @@ -202,7 +207,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 @@ -385,6 +390,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 @@ -473,7 +482,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
34 changes: 28 additions & 6 deletions filebeat/input/filestream/fswatch_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -276,17 +276,20 @@ scanner:
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 @@ -797,6 +800,25 @@ scanner:
})
}

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

// 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

0 comments on commit 4df595f

Please sign in to comment.