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

(cherry picked from commit 4df595f)
  • Loading branch information
rdner authored and mergify[bot] committed Aug 19, 2024
1 parent db75c5e commit b4a03b2
Show file tree
Hide file tree
Showing 3 changed files with 48 additions and 8 deletions.
9 changes: 9 additions & 0 deletions CHANGELOG-developer.next.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,15 @@ 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]
- Skip dependabot updates for github.com/elastic/mito. {pull}36158[36158]
- Add device handling to Okta API package for entity analytics. {pull}35980[35980]
- Make Filebeat HTTPJSON input process responses sequentially. {pull}36493[36493]
- Add initial infrastructure for a caching enrichment processor. {pull}36619[36619]
- Add file-backed cache for cache enrichment processor. {pull}36686[36686] {pull}36696[36696]
- 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 @@ -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
34 changes: 28 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 @@ 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 @@ -799,6 +802,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())

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

View workflow job for this annotation

GitHub Actions / lint (windows)

Error return value of `logp.DevelopmentSetup` is not checked (errcheck)

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

View workflow job for this annotation

GitHub Actions / lint (linux)

Error return value of `logp.DevelopmentSetup` is not checked (errcheck)

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

View workflow job for this annotation

GitHub Actions / lint (darwin)

Error return value of `logp.DevelopmentSetup` is not checked (errcheck)

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

Please sign in to comment.