diff --git a/NOTICE.txt b/NOTICE.txt index 156912a3654..fd944b13cbf 100644 --- a/NOTICE.txt +++ b/NOTICE.txt @@ -7568,6 +7568,35 @@ THE SOFTWARE. +-------------------------------------------------------------------------------- +Dependency : github.com/brianvoe/gofakeit +Version: v3.18.0+incompatible +Licence type (autodetected): MIT +-------------------------------------------------------------------------------- + +Contents of probable licence file $GOMODCACHE/github.com/brianvoe/gofakeit@v3.18.0+incompatible/LICENSE.txt: + +The MIT License (MIT) + +Copyright (c) [year] [fullname] + +Permission is hereby granted, free of charge, to any person obtaining a copy of +this software and associated documentation files (the "Software"), to deal in +the Software without restriction, including without limitation the rights to +use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of +the Software, and to permit persons to whom the Software is furnished to do so, +subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS +FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR +COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER +IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN +CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + -------------------------------------------------------------------------------- Dependency : github.com/cavaliergopher/rpm Version: v1.2.0 diff --git a/changelog/fragments/1760488402-Prevent-modified-files-close-due-to-inactivity.yaml b/changelog/fragments/1760488402-Prevent-modified-files-close-due-to-inactivity.yaml new file mode 100644 index 00000000000..f054d24974e --- /dev/null +++ b/changelog/fragments/1760488402-Prevent-modified-files-close-due-to-inactivity.yaml @@ -0,0 +1,33 @@ +# Kind can be one of: +# - breaking-change: a change to previously-documented behavior +# - deprecation: functionality that is being removed in a later release +# - bug-fix: fixes a problem in a previous version +# - enhancement: extends functionality but does not break or fix existing behavior +# - feature: new functionality +# - known-issue: problems that we are aware of in a given version +# - security: impacts on the security of a product or a user’s deployment. +# - upgrade: important information for someone upgrading from a prior version +# - other: does not fit into any of the other categories +kind: bug-fix + +# Change summary; a 80ish characters long description of the change. +summary: >- + [Filestream] ensure harvester always restarts if the file has not been fully ingested. + +# Long description; in case the summary is not enough to describe the change +# this field accommodate a description without length limits. +# NOTE: This field will be rendered only for breaking-change and known-issue kinds at the moment. +#description: + +# Affected component; usually one of "elastic-agent", "fleet-server", "filebeat", "metricbeat", "auditbeat", "all", etc. +component: filebeat + +# PR URL; optional; the PR number that added the changeset. +# If not present is automatically filled by the tooling finding the PR where this changelog fragment has been added. +# NOTE: the tooling supports backports, so it's able to fill the original PR number instead of the backport PR number. +# Please provide it if you are adding a fragment for a different PR. +pr: https://github.com/elastic/beats/pull/47107 + +# Issue URL; optional; the GitHub issue related to this changeset (either closes or is part of). +# If not present is automatically filled by the tooling with the issue linked to the PR number. +issue: https://github.com/elastic/beats/issues/46923 diff --git a/filebeat/input/filestream/config.go b/filebeat/input/filestream/config.go index 72da7509245..e23193d2a9a 100644 --- a/filebeat/input/filestream/config.go +++ b/filebeat/input/filestream/config.go @@ -37,11 +37,11 @@ import ( type config struct { Reader readerConfig `config:",inline"` - ID string `config:"id"` - Paths []string `config:"paths"` - Close closerConfig `config:"close"` - FileWatcher *conf.Namespace `config:"prospector"` - FileIdentity *conf.Namespace `config:"file_identity"` + ID string `config:"id"` + Paths []string `config:"paths"` + Close closerConfig `config:"close"` + FileWatcher fileWatcherConfig `config:"prospector.scanner"` + FileIdentity *conf.Namespace `config:"file_identity"` // -1 means that registry will never be cleaned CleanInactive time.Duration `config:"clean_inactive" validate:"min=-1"` @@ -114,6 +114,7 @@ func defaultConfig() config { CleanRemoved: true, HarvesterLimit: 0, IgnoreOlder: 0, + FileWatcher: defaultFileWatcherConfig(), // Config key: prospector.scanner } } diff --git a/filebeat/input/filestream/environment_test.go b/filebeat/input/filestream/environment_test.go index c7383044107..8f41eb80a60 100644 --- a/filebeat/input/filestream/environment_test.go +++ b/filebeat/input/filestream/environment_test.go @@ -20,13 +20,13 @@ package filestream import ( - "bytes" "context" "fmt" "os" "path/filepath" "strings" "sync" + "sync/atomic" "testing" "time" @@ -42,19 +42,19 @@ import ( "github.com/elastic/beats/v7/libbeat/monitoring/inputmon" "github.com/elastic/beats/v7/libbeat/statestore" "github.com/elastic/beats/v7/libbeat/statestore/storetest" + libbeatinteg "github.com/elastic/beats/v7/libbeat/tests/integration" conf "github.com/elastic/elastic-agent-libs/config" - "github.com/elastic/elastic-agent-libs/logp" + "github.com/elastic/elastic-agent-libs/logp/logptest" "github.com/elastic/go-concert/unison" ) type inputTestingEnvironment struct { - logger *logp.Logger - loggerBuffer *bytes.Buffer - t *testing.T - workingDir string - stateStore statestore.States - pipeline *mockPipelineConnector - monitoring beat.Monitoring + testLogger *logptest.Logger + t *testing.T + workingDir string + stateStore statestore.States + pipeline *mockPipelineConnector + monitoring beat.Monitoring pluginInitOnce sync.Once plugin v2.Plugin @@ -71,38 +71,19 @@ type registryEntry struct { } func newInputTestingEnvironment(t *testing.T) *inputTestingEnvironment { - // logp.NewInMemoryLocal will always use a console encoder, passing a - // JSONEncoderConfig will only change the keys, not the final encoding. - logger, buff := logp.NewInMemoryLocal("", logp.ConsoleEncoderConfig()) - - t.Cleanup(func() { - if t.Failed() { - f, err := os.CreateTemp("", t.Name()+"-*") - if err != nil { - t.Errorf("cannot create temp file for logs: %s", err) - } - - defer f.Close() - - data := buff.Bytes() - t.Logf("Debug Logs:%s\n", string(data)) - t.Logf("Logs written to %s", f.Name()) - if _, err := f.Write(data); err != nil { - t.Logf("could not write log file for debugging: %s", err) - } - - return - } - }) + tempDir := libbeatinteg.CreateTempDir(t, filepath.Join("..", "..", "build", "integration-tests")) + logger := logptest.NewFileLogger( + t, + tempDir, + ) return &inputTestingEnvironment{ - logger: logger, - loggerBuffer: buff, - t: t, - workingDir: t.TempDir(), - stateStore: openTestStatestore(), - pipeline: &mockPipelineConnector{}, - monitoring: beat.NewMonitoring(), + testLogger: logger, + t: t, + workingDir: tempDir, + stateStore: openTestStatestore(), + pipeline: &mockPipelineConnector{}, + monitoring: beat.NewMonitoring(), } } @@ -134,7 +115,7 @@ func (e *inputTestingEnvironment) createInput(config map[string]any) (v2.Input, func (e *inputTestingEnvironment) getManager() v2.InputManager { e.pluginInitOnce.Do(func() { - e.plugin = Plugin(e.logger, e.stateStore) + e.plugin = Plugin(e.testLogger.Logger, e.stateStore) }) return e.plugin.Manager } @@ -145,7 +126,7 @@ func (e *inputTestingEnvironment) startInput(ctx context.Context, id string, inp defer wg.Done() defer func() { _ = grp.Stop() }() - logger, _ := logp.NewDevelopmentLogger("") + logger := e.testLogger.Named("metrics-registry") reg := inputmon.NewMetricsRegistry( id, inp.Name(), e.monitoring.InputsRegistry(), logger) defer inputmon.CancelMetricsRegistry( @@ -158,7 +139,7 @@ func (e *inputTestingEnvironment) startInput(ctx context.Context, id string, inp Cancelation: ctx, StatusReporter: nil, MetricsRegistry: reg, - Logger: e.logger, + Logger: e.testLogger.Named("input.filestream"), } _ = inp.Run(inputCtx, e.pipeline) }(&e.wg, &e.grp) @@ -168,12 +149,15 @@ func (e *inputTestingEnvironment) waitUntilInputStops() { e.wg.Wait() } -func (e *inputTestingEnvironment) mustWriteToFile(filename string, data []byte) { +// mustWriteToFile writes data to file and returns the full path +func (e *inputTestingEnvironment) mustWriteToFile(filename string, data []byte) string { path := e.abspath(filename) err := os.WriteFile(path, data, 0o644) if err != nil { e.t.Fatalf("failed to write file '%s': %+v", path, err) } + + return path } func (e *inputTestingEnvironment) mustAppendToFile(filename string, data []byte) { @@ -266,34 +250,37 @@ func (e *inputTestingEnvironment) requireOffsetInRegistry(filename, inputID stri // requireMetaInRegistry checks if the expected metadata is saved to the registry. func (e *inputTestingEnvironment) waitUntilMetaInRegistry(filename, inputID string, expectedMeta fileMeta) { - for { + require.EventuallyWithT(e.t, func(t *assert.CollectT) { filepath := e.abspath(filename) fi, err := os.Stat(filepath) if err != nil { - continue + t.Errorf("cannot stat file: %s", err) + return } id := getIDFromPath(filepath, inputID, fi) entry, err := e.getRegistryState(id) if err != nil { - continue + t.Errorf("cannot get registry state: %s", err) + return } if entry.Meta == nil { - continue + t.Errorf("entry metadata cannot be nil") + return } var meta fileMeta err = typeconv.Convert(&meta, entry.Meta) if err != nil { - e.t.Fatalf("cannot convert: %+v", err) + t.Errorf("cannot convert: %+v", err) } - if requireMetadataEquals(expectedMeta, meta) { - break + if !requireMetadataEquals(expectedMeta, meta) { + t.Errorf("Metadata is not equal. Expecting:\n%#v\nGot:\n%#v", expectedMeta, meta) } - time.Sleep(10 * time.Millisecond) - } + + }, 30*time.Second, time.Second, "Metadata differs expected") } func requireMetadataEquals(one, other fileMeta) bool { @@ -386,7 +373,6 @@ func (e *inputTestingEnvironment) getRegistryState(key string) (registryEntry, e keys = append(keys, key) return false, nil }) - e.t.Logf("keys in store: %v", keys) return registryEntry{}, fmt.Errorf("error when getting expected key '%s' from store: %w", @@ -467,13 +453,15 @@ func (e *inputTestingEnvironment) waitUntilEventCountCtx(ctx context.Context, co // waitUntilAtLeastEventCount waits until at least count events arrive to the client. func (e *inputTestingEnvironment) waitUntilAtLeastEventCount(count int) { - for { - sum := len(e.pipeline.GetAllEvents()) - if count <= sum { - return - } - time.Sleep(10 * time.Millisecond) - } + require.EventuallyWithTf( + e.t, + func(t *assert.CollectT) { + sum := len(e.pipeline.GetAllEvents()) + require.GreaterOrEqualf(t, sum, count, "got %d events", sum) + }, + 30*time.Second, + 200*time.Millisecond, + "found less than %d events", count) } // waitUntilHarvesterIsDone detects Harvester stop by checking if the last client has been closed @@ -482,7 +470,7 @@ func (e *inputTestingEnvironment) waitUntilHarvesterIsDone() { require.Eventually( e.t, func() bool { - return e.pipeline.clients[len(e.pipeline.clients)-1].closed + return e.pipeline.clients[len(e.pipeline.clients)-1].closed.Load() }, time.Second*10, time.Millisecond*10, @@ -564,6 +552,18 @@ func (e *inputTestingEnvironment) requireEventTimestamp(nr int, ts string) { require.True(e.t, selectedEvent.Timestamp.Equal(tm), "got: %s, expected: %s", selectedEvent.Timestamp.String(), tm.String()) } +// logContains ensures s is a sub string on any log line. +// If s is not found, the test fails +func (e *inputTestingEnvironment) logContains(s string) { + e.t.Helper() + e.testLogger.LogContains(e.t, s) +} + +func (e *inputTestingEnvironment) WaitLogsContains(s string, timeout time.Duration, msgAndArgs ...any) { + e.t.Helper() + e.testLogger.WaitLogsContains(e.t, s, timeout, msgAndArgs...) +} + var _ statestore.States = (*testInputStore)(nil) type testInputStore struct { @@ -592,7 +592,7 @@ type mockClient struct { publishing []beat.Event published []beat.Event ackHandler beat.EventListener - closed bool + closed atomic.Bool mtx sync.Mutex canceler context.CancelFunc } @@ -635,11 +635,11 @@ func (c *mockClient) Close() error { c.mtx.Lock() defer c.mtx.Unlock() - if c.closed { + if c.closed.Load() { return fmt.Errorf("mock client already closed") } - c.closed = true + c.closed.Store(true) return nil } diff --git a/filebeat/input/filestream/filestream.go b/filebeat/input/filestream/filestream.go index ec13d625f40..e20354adf33 100644 --- a/filebeat/input/filestream/filestream.go +++ b/filebeat/input/filestream/filestream.go @@ -22,6 +22,7 @@ import ( "errors" "io" "os" + "sync" "time" "github.com/elastic/go-concert/ctxtool" @@ -37,6 +38,7 @@ import ( var ( ErrFileTruncate = errors.New("detected file being truncated") ErrClosed = errors.New("reader closed") + ErrInactive = errors.New("inactive file, reader closed") ) // logFile contains all log related data @@ -53,10 +55,15 @@ type logFile struct { closeRemoved bool closeRenamed bool + // offsetMutex is a mutex to ensure 'offset' and 'lastTimeRead' are + // atomically updated. Atomically updating them prevents issues + // detecting when the file is inactive by [shouldBeClosed]. + offsetMutex sync.Mutex offset int64 lastTimeRead time.Time - backoff backoff.Backoff - tg *unison.TaskGroup + + backoff backoff.Backoff + tg *unison.TaskGroup } // newFileReader creates a new log instance to read log sources @@ -104,8 +111,7 @@ func (f *logFile) Read(buf []byte) (int, error) { for f.readerCtx.Err() == nil { n, err := f.file.Read(buf) if n > 0 { - f.offset += int64(n) - f.lastTimeRead = time.Now() + f.updateOffset(n) } totalN += n @@ -179,9 +185,13 @@ func (f *logFile) periodicStateCheck(ctx unison.Canceler) { func (f *logFile) shouldBeClosed() bool { if f.closeInactive > 0 { + f.offsetMutex.Lock() if time.Since(f.lastTimeRead) > f.closeInactive { + f.log.Debugf("'%s' is inactive", f.file.Name()) + f.offsetMutex.Unlock() return true } + f.offsetMutex.Unlock() } if !f.closeRemoved && !f.closeRenamed { @@ -270,3 +280,11 @@ func (f *logFile) Close() error { _ = f.tg.Stop() // Wait until all resources are released for sure. return err } + +// updateOffset updates the offset and lastTimeRead atomically +func (f *logFile) updateOffset(delta int) { + f.offsetMutex.Lock() + f.offset += int64(delta) + f.lastTimeRead = time.Now() + f.offsetMutex.Unlock() +} diff --git a/filebeat/input/filestream/filestream_test.go b/filebeat/input/filestream/filestream_test.go index 4a63ef10985..1e1c8c3ced7 100644 --- a/filebeat/input/filestream/filestream_test.go +++ b/filebeat/input/filestream/filestream_test.go @@ -22,6 +22,7 @@ import ( "io" "io/ioutil" "os" + "path/filepath" "testing" "time" @@ -60,8 +61,8 @@ func TestLogFileTimedClosing(t *testing.T) { t.Run(name, func(t *testing.T) { reader, err := newFileReader( - logptest.NewTestingLogger(t, ""), - context.TODO(), + logptest.NewFileLogger(t, filepath.Join("..", "..", "build", "integration-tests")).Logger, + t.Context(), f, readerConfig{}, closerConfig{ diff --git a/filebeat/input/filestream/fswatch.go b/filebeat/input/filestream/fswatch.go index 6e23dce31be..dc74e9a1338 100644 --- a/filebeat/input/filestream/fswatch.go +++ b/filebeat/input/filestream/fswatch.go @@ -26,16 +26,15 @@ import ( "io" "os" "path/filepath" + "sync" "time" - "github.com/elastic/go-concert/timed" "github.com/elastic/go-concert/unison" "github.com/elastic/beats/v7/filebeat/input/file" loginp "github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile" commonfile "github.com/elastic/beats/v7/libbeat/common/file" "github.com/elastic/beats/v7/libbeat/common/match" - conf "github.com/elastic/elastic-agent-libs/config" "github.com/elastic/elastic-agent-libs/logp" ) @@ -63,41 +62,50 @@ type fileWatcherConfig struct { // fileWatcher gets the list of files from a FSWatcher and creates events by // comparing the files between its last two runs. type fileWatcher struct { - cfg fileWatcherConfig - prev map[string]loginp.FileDescriptor - scanner loginp.FSScanner - log *logp.Logger - events chan loginp.FSEvent + cfg fileWatcherConfig + prev map[string]loginp.FileDescriptor + scanner loginp.FSScanner + log *logp.Logger + events chan loginp.FSEvent + notifyChan chan loginp.HarvesterStatus + fileIdentifier fileIdentifier + sourceIdentifier *loginp.SourceIdentifier + + // closedHarvesters is a map of harvester ID to the current + // offset of the file + closedHarvesters map[string]int64 + // closedHarvestersMutex controls access to closedHarvesters + closedHarvestersMutex sync.Mutex } -func newFileWatcher(logger *logp.Logger, paths []string, ns *conf.Namespace) (loginp.FSWatcher, error) { - var config *conf.C - if ns == nil { - config = conf.NewConfig() - } else { - config = ns.Config() - } +// Ensure fileWatcher implements loginp.FSWatcher +var _ loginp.FSWatcher = &fileWatcher{} - return newScannerWatcher(logger, paths, config) -} +func newFileWatcher( + logger *logp.Logger, + paths []string, + config fileWatcherConfig, + fi fileIdentifier, + srci *loginp.SourceIdentifier, +) (*fileWatcher, error) { -func newScannerWatcher(logger *logp.Logger, paths []string, c *conf.C) (loginp.FSWatcher, error) { - config := defaultFileWatcherConfig() - err := c.Unpack(&config) - if err != nil { - return nil, err - } scanner, err := newFileScanner(logger, paths, config.Scanner) if err != nil { return nil, err } return &fileWatcher{ - log: logger.Named(watcherDebugKey), - cfg: config, - prev: make(map[string]loginp.FileDescriptor, 0), - scanner: scanner, - events: make(chan loginp.FSEvent), + log: logger.Named(watcherDebugKey), + cfg: config, + prev: make(map[string]loginp.FileDescriptor, 0), + scanner: scanner, + events: make(chan loginp.FSEvent), + closedHarvesters: map[string]int64{}, + // notifyChan is a buffered channel to prevent the harvester from + // blocking while waiting for the fileWatcher to read from the channel + notifyChan: make(chan loginp.HarvesterStatus, 5), // magic number + fileIdentifier: fi, + sourceIdentifier: srci, }, nil } @@ -109,17 +117,46 @@ func defaultFileWatcherConfig() fileWatcherConfig { } } +func (w *fileWatcher) NotifyChan() chan loginp.HarvesterStatus { + return w.notifyChan +} + func (w *fileWatcher) Run(ctx unison.Canceler) { defer close(w.events) // run initial scan before starting regular w.watch(ctx) - _ = timed.Periodic(ctx, w.cfg.Interval, func() error { - w.watch(ctx) + // Read from notifyChan in a separate goroutine becase + // there are cases when w.watch can take minutes or even + // hours, so we do not want to block the harvesters + go func() { + for { + select { + case evt := <-w.notifyChan: + w.processNotification(evt) + case <-ctx.Done(): + return + } + } + }() - return nil - }) + tick := time.Tick(w.cfg.Interval) + for { + select { + case <-tick: + w.watch(ctx) + case <-ctx.Done(): + return + } + } +} + +func (w *fileWatcher) processNotification(evt loginp.HarvesterStatus) { + w.log.Debugf("Harvester Closed notification received. ID: %s, Size: %d", evt.ID, evt.Size) + w.closedHarvestersMutex.Lock() + w.closedHarvesters[evt.ID] = evt.Size + w.closedHarvestersMutex.Unlock() } func (w *fileWatcher) watch(ctx unison.Canceler) { @@ -138,6 +175,10 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { newFilesByID := make(map[string]*loginp.FileDescriptor) for path, fd := range paths { + // srcID is the file identity, it is the same value used to identify + // the harvester and as registry key for the file's state + srcID := w.getFileIdentity(fd) + // if the scanner found a new path or an existing path // with a different file, it is a new file prevDesc, ok := w.prev[path] @@ -148,24 +189,55 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { continue } + // If we got notifications about harvesters being closed, update + // the state accordingly. + // + // This is used to prevent a sort of race condition: + // When the reader/harvester reaches EOF, it blocks on a backoff, + // if during this time [logFile.shouldBeClosed] is called, marks the + // file as inactive and closes the reader context, once the backoff + // time expires the reader and harvester are closed without ingesting + // any more data. + // + // If the [fileWatcher] sends a write event while the harvester was blocked + // no new harvester is started because one is already running, however the + // [fileWatcher] updates its internal state and won't send write events until + // more data is added to the file. + // + // This can cause some lines to be missed because the harvester closed + // and the write event was lost. + // + // To prevent this from happening we get notified the offset of the file + // (data ingested) when the harvester closes. If we have this data we + // update our state to the same as the harvester, therefore starting + // a new harvester if needed. + w.closedHarvestersMutex.Lock() + if size, harvesterClosed := w.closedHarvesters[srcID]; harvesterClosed { + w.log.Debugf("Updating previous state because harvester was closed. '%s': %d", srcID, size) + prevDesc.SetBytesIngested(size) + } + w.closedHarvestersMutex.Unlock() + var e loginp.FSEvent switch { // the new size is smaller, the file was truncated case prevDesc.Info.Size() > fd.Info.Size(): - e = truncateEvent(path, fd) + e = truncateEvent(path, fd, srcID) truncatedCount++ // the size is the same, timestamps are different, the file was touched case prevDesc.Info.Size() == fd.Info.Size() && prevDesc.Info.ModTime() != fd.Info.ModTime(): if w.cfg.ResendOnModTime { - e = truncateEvent(path, fd) + e = truncateEvent(path, fd, srcID) truncatedCount++ } - // the new size is larger, something was written - case prevDesc.Info.Size() < fd.Info.Size(): - e = writeEvent(path, fd) + // the new size is larger, something was written. + // If a harvester for this file was closed recently, + // we use its state instead of the one we have cached. + case prevDesc.SizeOrBytesIngested() < fd.Info.Size(): + e = writeEvent(path, fd, srcID) writtenCount++ } @@ -180,6 +252,10 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { // delete from previous state to mark that we've seen the existing file again delete(w.prev, path) + // Delete used state from closedHarvesters + w.closedHarvestersMutex.Lock() + delete(w.closedHarvesters, srcID) + w.closedHarvestersMutex.Unlock() } // remaining files in the prev map are the ones that are missing @@ -188,14 +264,18 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { var e loginp.FSEvent id := remainingDesc.FileID() + srcID := w.getFileIdentity(remainingDesc) if newDesc, renamed := newFilesByID[id]; renamed { - e = renamedEvent(remainingPath, newDesc.Filename, *newDesc) + e = renamedEvent(remainingPath, newDesc.Filename, *newDesc, srcID) delete(newFilesByName, newDesc.Filename) delete(newFilesByID, id) renamedCount++ } else { - e = deleteEvent(remainingPath, remainingDesc) + e = deleteEvent(remainingPath, remainingDesc, srcID) removedCount++ + w.closedHarvestersMutex.Lock() + delete(w.closedHarvesters, srcID) + w.closedHarvestersMutex.Unlock() } select { case <-ctx.Done(): @@ -215,7 +295,7 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { select { case <-ctx.Done(): return - case w.events <- createEvent(path, *fd): + case w.events <- createEvent(path, *fd, w.getFileIdentity(*fd)): createdCount++ } } @@ -232,23 +312,31 @@ func (w *fileWatcher) watch(ctx unison.Canceler) { w.prev = paths } -func createEvent(path string, fd loginp.FileDescriptor) loginp.FSEvent { +// getFileIdentity mimics the same algorithm used by the harvester to generate +// the file identity to any given file. +// See 'startHarvester' on internal/input-logfile/harvester.go. +func (w *fileWatcher) getFileIdentity(d loginp.FileDescriptor) string { + src := w.fileIdentifier.GetSource(loginp.FSEvent{Descriptor: d}) + return w.sourceIdentifier.ID(src) +} + +func createEvent(path string, fd loginp.FileDescriptor, srcID string) loginp.FSEvent { return loginp.FSEvent{Op: loginp.OpCreate, OldPath: "", NewPath: path, Descriptor: fd} } -func writeEvent(path string, fd loginp.FileDescriptor) loginp.FSEvent { +func writeEvent(path string, fd loginp.FileDescriptor, srcID string) loginp.FSEvent { return loginp.FSEvent{Op: loginp.OpWrite, OldPath: path, NewPath: path, Descriptor: fd} } -func truncateEvent(path string, fd loginp.FileDescriptor) loginp.FSEvent { +func truncateEvent(path string, fd loginp.FileDescriptor, srcID string) loginp.FSEvent { return loginp.FSEvent{Op: loginp.OpTruncate, OldPath: path, NewPath: path, Descriptor: fd} } -func renamedEvent(oldPath, path string, fd loginp.FileDescriptor) loginp.FSEvent { +func renamedEvent(oldPath, path string, fd loginp.FileDescriptor, srcID string) loginp.FSEvent { return loginp.FSEvent{Op: loginp.OpRename, OldPath: oldPath, NewPath: path, Descriptor: fd} } -func deleteEvent(path string, fd loginp.FileDescriptor) loginp.FSEvent { +func deleteEvent(path string, fd loginp.FileDescriptor, srcID string) loginp.FSEvent { return loginp.FSEvent{Op: loginp.OpDelete, OldPath: path, NewPath: "", Descriptor: fd} } diff --git a/filebeat/input/filestream/fswatch_test.go b/filebeat/input/filestream/fswatch_test.go index 8c9a9acb586..2b363d7c068 100644 --- a/filebeat/input/filestream/fswatch_test.go +++ b/filebeat/input/filestream/fswatch_test.go @@ -55,8 +55,8 @@ scanner: ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() - logger := logp.NewNopLogger() - fw := createWatcherWithConfig(t, logger, paths, cfgStr) + logger := logptest.NewFileLogger(t, filepath.Join("..", "..", "build", "integration-tests")) + fw := createWatcherWithConfig(t, logger.Logger, paths, cfgStr) go fw.Run(ctx) @@ -75,6 +75,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 5}), // 5 bytes written }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -98,6 +99,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 10}), // +5 bytes appended }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -120,6 +122,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: newBasename, size: 10}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -140,6 +143,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 2}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -160,6 +164,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 2}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -179,6 +184,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 2}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -199,8 +205,8 @@ scanner: ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() - logger := logp.NewNopLogger() - fw := createWatcherWithConfig(t, logger, paths, cfgStr) + logger := logptest.NewFileLogger(t, filepath.Join("../", "../", "build", "integration-tests")) + fw := createWatcherWithConfig(t, logger.Logger, paths, cfgStr) go fw.Run(ctx) @@ -219,6 +225,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 1024}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) @@ -234,8 +241,8 @@ scanner: ctx, cancel := context.WithTimeout(context.Background(), 1000*time.Millisecond) defer cancel() - logger := logp.NewNopLogger() - fw := createWatcherWithConfig(t, logger, paths, cfgStr) + logger := logptest.NewFileLogger(t, filepath.Join("../", "../", "build", "integration-tests")) + fw := createWatcherWithConfig(t, logger.Logger, paths, cfgStr) go fw.Run(ctx) @@ -253,6 +260,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 1024}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) time := time.Now().Local().Add(time.Hour) @@ -314,6 +322,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 5}), // +5 bytes appended }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) }) }) @@ -330,8 +339,8 @@ scanner: ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond) defer cancel() - logger := logp.NewNopLogger() - fw := createWatcherWithConfig(t, logger, paths, cfgStr) + logger := logptest.NewFileLogger(t, filepath.Join("../", "../", "build", "integration-tests")) + fw := createWatcherWithConfig(t, logger.Logger, paths, cfgStr) go fw.Run(ctx) @@ -350,6 +359,7 @@ scanner: Info: file.ExtendFileInfo(&testFileInfo{name: basename, size: 1024}), }, } + expEvent.SrcID = fw.getFileIdentity(expEvent.Descriptor) requireEqualEvents(t, expEvent, e) // collisions are resolved in the alphabetical order, the first filename wins @@ -388,9 +398,8 @@ scanner: ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() - logp.DevelopmentSetup(logp.ToObserverOutput()) - - fw := createWatcherWithConfig(t, logp.L(), paths, cfgStr) + inMemoryLog, buff := logp.NewInMemoryLocal("", logp.JSONEncoderConfig()) + fw := createWatcherWithConfig(t, inMemoryLog, paths, cfgStr) go fw.Run(ctx) @@ -412,6 +421,10 @@ scanner: }, }, } + // Add the SrcIDs + for i := range expectedEvents { + expectedEvents[i].SrcID = fw.getFileIdentity(expectedEvents[i].Descriptor) + } var actualEvents []loginp.FSEvent actualEvents = append(actualEvents, fw.Event()) actualEvents = append(actualEvents, fw.Event()) @@ -429,9 +442,8 @@ scanner: for i, actualEvent := range actualEvents { requireEqualEvents(t, expectedEvents[i], actualEvent) } - - logs := logp.ObserverLogs().FilterLevelExact(logp.WarnLevel.ZapLevel()).TakeAll() - require.Lenf(t, logs, 0, "must be no warning messages, got: %v", logs) + require.NotContainsf(t, buff.String(), "WARN", + "must be no warning messages") }) } @@ -873,22 +885,21 @@ scanner: }) t.Run("returns error when creating scanner with a fingerprint too small", func(t *testing.T) { - cfgStr := ` -scanner: - fingerprint: - enabled: true - offset: 0 - length: 1 -` - cfg, err := conf.NewConfigWithYAML([]byte(cfgStr), cfgStr) - require.NoError(t, err) - - ns := &conf.Namespace{} - err = ns.Unpack(cfg) - require.NoError(t, err) - - logger := logptest.NewTestingLogger(t, "log-selector") - _, err = newFileWatcher(logger, paths, ns) + cfg := fileWatcherConfig{ + Scanner: fileScannerConfig{ + Fingerprint: fingerprintConfig{ + Enabled: true, + Offset: 0, + Length: 1, + }, + }} + _, err = newFileWatcher( + logptest.NewTestingLogger(t, ""), + paths, + cfg, + mustPathIdentifier(false), + mustSourceIdentifier("foo-id"), + ) require.Error(t, err) require.Contains(t, err.Error(), "fingerprint size 1 bytes cannot be smaller than 64 bytes") }) @@ -928,6 +939,22 @@ func parseLogs(buff string) []logEntry { return logEntries } +func mustFingerprintIdentifier() fileIdentifier { + fi, _ := newFingerprintIdentifier(nil, nil) + + return fi +} + +func mustSourceIdentifier(inputID string) *loginp.SourceIdentifier { + si, err := loginp.NewSourceIdentifier("filestream", inputID) + if err != nil { + // this will never happen + panic(err) + } + + return si +} + const benchmarkFileCount = 1000 func BenchmarkGetFiles(b *testing.B) { @@ -986,15 +1013,25 @@ func BenchmarkGetFilesWithFingerprint(b *testing.B) { } } -func createWatcherWithConfig(t *testing.T, logger *logp.Logger, paths []string, cfgStr string) loginp.FSWatcher { +func createWatcherWithConfig(t *testing.T, logger *logp.Logger, paths []string, cfgStr string) *fileWatcher { + tmpCfg := struct { + Scaner fileWatcherConfig `config:"scanner"` + }{ + Scaner: defaultFileWatcherConfig(), + } cfg, err := conf.NewConfigWithYAML([]byte(cfgStr), cfgStr) require.NoError(t, err) - ns := &conf.Namespace{} - err = ns.Unpack(cfg) - require.NoError(t, err) + err = cfg.Unpack(&tmpCfg) + require.NoError(t, err, "cannot unpack file watcher config") - fw, err := newFileWatcher(logger, paths, ns) + fw, err := newFileWatcher( + logger, + paths, + tmpCfg.Scaner, + mustPathIdentifier(false), + mustSourceIdentifier("foo-id"), + ) require.NoError(t, err) return fw diff --git a/filebeat/input/filestream/input.go b/filebeat/input/filestream/input.go index c4cca14b0db..6c631f74463 100644 --- a/filebeat/input/filestream/input.go +++ b/filebeat/input/filestream/input.go @@ -85,7 +85,10 @@ func Plugin(log *logp.Logger, store statestore.States) input.Plugin { } } -func configure(cfg *conf.C, log *logp.Logger) (loginp.Prospector, loginp.Harvester, error) { +func configure( + cfg *conf.C, + log *logp.Logger, + src *loginp.SourceIdentifier) (loginp.Prospector, loginp.Harvester, error) { config := defaultConfig() if err := cfg.Unpack(&config); err != nil { return nil, nil, err @@ -93,7 +96,7 @@ func configure(cfg *conf.C, log *logp.Logger) (loginp.Prospector, loginp.Harvest config.TakeOver.LogWarnings(log) - prospector, err := newProspector(config, log) + prospector, err := newProspector(config, log, src) if err != nil { return nil, nil, fmt.Errorf("cannot create prospector: %w", err) } @@ -170,7 +173,15 @@ func (inp *filestream) Run( // The caller of Run already reports the error and filters out errors that // must not be reported, like 'context cancelled'. - return inp.readFromSource(ctx, log, r, fs.newPath, state, publisher, metrics) + err = inp.readFromSource(ctx, log, r, fs.newPath, state, publisher, metrics) + if err != nil { + // First handle actual errors + if !errors.Is(err, io.EOF) && !errors.Is(err, ErrInactive) { + return fmt.Errorf("error reading from source: %w", err) + } + } + + return nil } func initState(log *logp.Logger, c loginp.Cursor, s fileSource) state { @@ -371,6 +382,9 @@ func (inp *filestream) readFromSource( log.Debugf("Reader was closed. Closing. Path='%s'", path) } else if errors.Is(err, io.EOF) { log.Debugf("EOF has been reached. Closing. Path='%s'", path) + } else if errors.Is(err, ErrInactive) { + log.Debugf("File is inactive. Closing. Path='%s'", path) + return err } else { log.Errorf("Read line error: %v", err) metrics.ProcessingErrors.Inc() diff --git a/filebeat/input/filestream/input_integration_test.go b/filebeat/input/filestream/input_integration_test.go index 7f74828ee2d..730f920a1f9 100644 --- a/filebeat/input/filestream/input_integration_test.go +++ b/filebeat/input/filestream/input_integration_test.go @@ -24,6 +24,7 @@ import ( "context" "fmt" "os" + "path/filepath" "runtime" "strconv" "strings" @@ -35,6 +36,8 @@ import ( "golang.org/x/text/encoding" "golang.org/x/text/encoding/unicode" "golang.org/x/text/transform" + + "github.com/elastic/beats/v7/libbeat/tests/integration" ) // test_close_renamed from test_harvester.py @@ -979,9 +982,9 @@ func TestFilestreamTruncate(t *testing.T) { inp := env.mustCreateInput(map[string]interface{}{ "id": id, "paths": []string{ - env.abspath("*"), + env.abspath("test.log*"), }, - "prospector.scanner.check_interval": "1ms", + "prospector.scanner.check_interval": "250ms", "prospector.scanner.resend_on_touch": "true", "prospector.scanner.symlinks": "true", "prospector.scanner.fingerprint.enabled": false, @@ -1081,7 +1084,7 @@ func TestRotatingCloseInactiveLargerWriteRate(t *testing.T) { inp := env.mustCreateInput(map[string]interface{}{ "id": id, "paths": []string{ - env.abspath("*"), + env.abspath("test.log*"), }, "prospector.scanner.check_interval": "100ms", "close.on_state_change.check_interval": "1s", @@ -1130,7 +1133,7 @@ func TestRotatingCloseInactiveLowWriteRate(t *testing.T) { inp := env.mustCreateInput(map[string]interface{}{ "id": id, "paths": []string{ - env.abspath("*"), + env.abspath("test.log*"), }, "prospector.scanner.check_interval": "1ms", "close.on_state_change.check_interval": "1ms", @@ -1143,8 +1146,6 @@ func TestRotatingCloseInactiveLowWriteRate(t *testing.T) { ctx, cancelInput := context.WithCancel(context.Background()) env.startInput(ctx, id, inp) - time.Sleep(1 * time.Second) - env.mustWriteToFile(testlogName, []byte("Line 1\n")) env.waitUntilEventCount(1) @@ -1161,3 +1162,95 @@ func TestRotatingCloseInactiveLowWriteRate(t *testing.T) { cancelInput() env.waitUntilInputStops() } + +func TestDataAddedAfterCloseInactive(t *testing.T) { + env := newInputTestingEnvironment(t) + + logFilePath := filepath.Join(env.t.TempDir(), "log.log") + t.Cleanup(func() { + if t.Failed() { + t.Logf("log file path: %s", logFilePath) + } + }) + + // Escape windows path separator + logFilePathStr := strings.ReplaceAll(logFilePath, `\`, `\\`) + integration.WriteLogFile(t, logFilePath, 50, false) + + id := "fake-ID-" + uuid.Must(uuid.NewV4()).String() + // The duration used to configure the input need to obey + // the following restrictions: + // - Backoff needs to be longer than the prospector and close check + // interval, as well as the inactive timeout so we can have a + // a harvester failing to start because there is one blocked on + // its backoff. + // - Close check interval needs to be smaller than the prospector + // check interval + // - Inactive timeout needs to me as small as possible so the reader + // context is closed due to inactivity while the reader is waiting + // on its backoff. + inp := env.mustCreateInput(map[string]any{ + "id": id, + "paths": []string{ + logFilePath, + }, + "prospector.scanner.check_interval": "2s", + "close.on_state_change.check_interval": "1s", + "close.on_state_change.inactive": "1s", + "backoff.init": "3s", + "backoff.max": "3s", + }) + + env.startInput(t.Context(), id, inp) + // File has been fully read + env.WaitLogsContains( + fmt.Sprintf("End of file reached: %s; Backoff now.", logFilePathStr), + 1*time.Second) + + // File is inactive, the reader context will be cancelled + env.WaitLogsContains( + fmt.Sprintf("'%s' is inactive", logFilePathStr), + 5*time.Second, + "missing 'file is inactive' logs") + + // Add more data to the file while the reader is blocked + // on its backoff and its context has been cancelled. + integration.WriteLogFile(t, logFilePath, 5, true) + + // Ensure the FileWatcher detected the new data and sent a write event + env.WaitLogsContains( + fmt.Sprintf("File %s has been updated", logFilePathStr), + 3*time.Second) + + // Ensure the write event did not start a new harvester + env.WaitLogsContains("Harvester already running", 5*time.Second) // mabye increase it a bit + + // Wait for the harvester to close + env.WaitLogsContains("Stopped harvester for file", 5*time.Second) + + // HERE + // Wait for a new scan from the fileWatcher + env.WaitLogsContains("Start next scan", 5*time.Second) + + // Ensure it got notified when the harvester closed and the offset + // is correct + env.WaitLogsContains( + "Updating previous state because harvester was closed.", + 1*time.Second) + + // Ensure the fileWatcher sent an write event + env.WaitLogsContains( + fmt.Sprintf("File %s has been updated", logFilePathStr), + 1*time.Second) + + // Wait for a new harvester to start + env.WaitLogsContains("Starting harvester for file", 2*time.Second) + + // Wait for EOF to be reached + env.WaitLogsContains( + fmt.Sprintf("End of file reached: %s; Backoff now.", logFilePathStr), + 2*time.Second) + + // Ensure all events have been ingested + env.waitUntilEventCount(55) +} diff --git a/filebeat/input/filestream/internal/input-logfile/fswatch.go b/filebeat/input/filestream/internal/input-logfile/fswatch.go index 1f91515036f..7d2f26f57fd 100644 --- a/filebeat/input/filestream/internal/input-logfile/fswatch.go +++ b/filebeat/input/filestream/internal/input-logfile/fswatch.go @@ -64,6 +64,25 @@ type FileDescriptor struct { Info file.ExtendedFileInfo // Fingerprint is a computed hash of the file header Fingerprint string + // bytesIngested is the number of bytes already ingested by the harvester + // for this file + bytesIngested int64 +} + +// SetBytesIngested allows for setting a size that is different than the one in Info +func (fd *FileDescriptor) SetBytesIngested(s int64) { + fd.bytesIngested = s +} + +// SizeOrBytesIngested returns the bytes ingested for the file or its size. +// If [SetBytesIngested] has been called with a value other +// than zero, the bytes ingested is returned, otherwise Info.Size() is returned. +func (fd FileDescriptor) SizeOrBytesIngested() int64 { + if fd.bytesIngested != 0 { + return fd.bytesIngested + } + + return fd.Info.Size() } // FileID returns a unique file ID @@ -92,6 +111,9 @@ type FSEvent struct { Op Operation // Descriptor describes the file in the event. Descriptor FileDescriptor + // SrcID is the identifier used to identify the harvester and the + // entry in the registry + SrcID string } // FSScanner retrieves a list of files from the file system. @@ -111,4 +133,7 @@ type FSWatcher interface { Run(unison.Canceler) // Event returns the next event captured by FSWatcher. Event() FSEvent + // NotifyChan returns the channel used to listen for + // harvester closing notifications + NotifyChan() chan HarvesterStatus } diff --git a/filebeat/input/filestream/internal/input-logfile/harvester.go b/filebeat/input/filestream/internal/input-logfile/harvester.go index 15c7a67deee..97f52221d88 100644 --- a/filebeat/input/filestream/internal/input-logfile/harvester.go +++ b/filebeat/input/filestream/internal/input-logfile/harvester.go @@ -114,6 +114,8 @@ type HarvesterGroup interface { Stop(Source) // StopHarvesters cancels all running Harvesters. StopHarvesters() error + // SetObserver sets the observer to get notified when a harvester closes + SetObserver(c chan HarvesterStatus) } type defaultHarvesterGroup struct { @@ -123,9 +125,31 @@ type defaultHarvesterGroup struct { cleanTimeout time.Duration store *store ackCH *updateChan - identifier *sourceIdentifier + identifier *SourceIdentifier tg *task.Group metrics *Metrics + notifyChan chan HarvesterStatus +} + +// HarvesterStatus is used to notify an observer that the harvester for the ID +// has closed and the amount of data ingested from the file. +type HarvesterStatus struct { + // ID is the ID of the harvester + ID string + // Size is the amount of data ingested, in other words the size of the file + // when the harvester closed. + Size int64 +} + +func (hg *defaultHarvesterGroup) notifyObserver(srcID string, size int64) { + if hg.notifyChan != nil { + hg.notifyChan <- HarvesterStatus{srcID, size} + } +} + +// SetObserver sets the observer to get notifications when a harvester closes +func (hg *defaultHarvesterGroup) SetObserver(c chan HarvesterStatus) { + hg.notifyChan = c } // Start starts the Harvester for a Source if no Harvester is running for the @@ -202,6 +226,7 @@ func startHarvester( // only thing it does is to log the error. So to avoid unnecessary errors, // we just return nil. if errors.Is(err, ErrHarvesterAlreadyRunning) { + ctx.Logger.Debug("Harvester already running") return nil } return fmt.Errorf("error while adding new reader to the bookkeeper %w", err) @@ -230,6 +255,24 @@ func startHarvester( cursor := makeCursor(resource) publisher := &cursorPublisher{canceler: ctx.Cancelation, client: client, cursor: &cursor} + defer func() { + // The cursor struct used by Filestream, it is defined on: + // filebeat/input/filestream/input.go + st := struct { + Offset int64 `json:"offset" struct:"offset"` + }{} + if err := cursor.Unpack(&st); err != nil { + // Unpack should never fail, if it fails either the cursor + // structure had a breaking change or our registry is corrupted. + // Either way, it is better to not notify the observer. + ctx.Logger.Errorf("cannot unpack cursor at the end of the harvester: %s", err) + return + } + + hg.notifyObserver(srcID, st.Offset) + ctx.Logger.Debugf("Harvester '%s' closed with offset: %d", srcID, st.Offset) + }() + err = hg.harvester.Run(ctx, src, cursor, publisher, metrics) if err != nil && !errors.Is(err, context.Canceled) { hg.readers.remove(srcID) diff --git a/filebeat/input/filestream/internal/input-logfile/harvester_test.go b/filebeat/input/filestream/internal/input-logfile/harvester_test.go index 6f5938e308a..7126c0a5f57 100644 --- a/filebeat/input/filestream/internal/input-logfile/harvester_test.go +++ b/filebeat/input/filestream/internal/input-logfile/harvester_test.go @@ -396,7 +396,7 @@ func testDefaultHarvesterGroup(t *testing.T, mockHarvester Harvester) *defaultHa pipeline: &MockPipeline{}, harvester: mockHarvester, store: testOpenStore(t, "test", nil), - identifier: &sourceIdentifier{"filestream::.global::"}, + identifier: &SourceIdentifier{"filestream::.global::"}, tg: task.NewGroup(0, time.Second, logp.L(), ""), } } diff --git a/filebeat/input/filestream/internal/input-logfile/input.go b/filebeat/input/filestream/internal/input-logfile/input.go index 1ed98826274..7769292e10a 100644 --- a/filebeat/input/filestream/internal/input-logfile/input.go +++ b/filebeat/input/filestream/internal/input-logfile/input.go @@ -30,11 +30,13 @@ import ( ) type managedInput struct { - userID string + // id is the input ID, it is defined by setting 'id' + // in the input configuration + id string metricsID string manager *InputManager ackCH *updateChan - sourceIdentifier *sourceIdentifier + sourceIdentifier *SourceIdentifier prospector Prospector harvester Harvester cleanTimeout time.Duration @@ -58,6 +60,8 @@ func (inp *managedInput) Run( groupStore := inp.manager.getRetainedStore() defer groupStore.Release() + ctx.Logger = ctx.Logger.With("filestream_id", inp.id) + // Setup cancellation using a custom cancel context. All workers will be // stopped if one failed badly by returning an error. cancelCtx, cancel := context.WithCancel(ctxtool.FromCanceller(ctx.Cancelation)) @@ -94,7 +98,7 @@ func (inp *managedInput) Run( // Notify the manager the input has stopped, currently that is used to // keep track of duplicated IDs - inp.manager.StopInput(inp.userID) + inp.manager.StopInput(inp.id) return nil } diff --git a/filebeat/input/filestream/internal/input-logfile/manager.go b/filebeat/input/filestream/internal/input-logfile/manager.go index eb95b4a1b2b..7155c9e71b7 100644 --- a/filebeat/input/filestream/internal/input-logfile/manager.go +++ b/filebeat/input/filestream/internal/input-logfile/manager.go @@ -63,7 +63,7 @@ type InputManager struct { // Configure returns an array of Sources, and a configured Input instances // that will be used to collect events from each source. - Configure func(cfg *conf.C, log *logp.Logger) (Prospector, Harvester, error) + Configure func(cfg *conf.C, log *logp.Logger, src *SourceIdentifier) (Prospector, Harvester, error) initOnce sync.Once initErr error @@ -75,7 +75,7 @@ type InputManager struct { } // Source describe a source the input can collect data from. -// The `Name` method must return an unique name, that will be used to identify +// The [Name] method must return an unique name, that will be used to identify // the source in the persistent state store. type Source interface { Name() string @@ -222,7 +222,12 @@ func (cim *InputManager) Create(config *conf.C) (inp v2.Input, retErr error) { } }() - prospector, harvester, err := cim.Configure(config, cim.Logger) + srcIdentifier, err := NewSourceIdentifier(cim.Type, settings.ID) + if err != nil { + return nil, fmt.Errorf("error while creating source identifier for input: %w", err) + } + + prospector, harvester, err := cim.Configure(config, cim.Logger, srcIdentifier) if err != nil { return nil, err } @@ -230,15 +235,10 @@ func (cim *InputManager) Create(config *conf.C) (inp v2.Input, retErr error) { return nil, errNoInputRunner } - srcIdentifier, err := newSourceIdentifier(cim.Type, settings.ID) - if err != nil { - return nil, fmt.Errorf("error while creating source identifier for input: %w", err) - } - - var previousSrcIdentifiers []*sourceIdentifier + var previousSrcIdentifiers []*SourceIdentifier if settings.TakeOver.Enabled { for _, id := range settings.TakeOver.FromIDs { - si, err := newSourceIdentifier(cim.Type, id) + si, err := NewSourceIdentifier(cim.Type, id) if err != nil { return nil, fmt.Errorf( @@ -257,7 +257,7 @@ func (cim *InputManager) Create(config *conf.C) (inp v2.Input, retErr error) { // create a store with the deprecated global ID. This will be used to // migrate the entries in the registry to use the new input ID. - globalIdentifier, err := newSourceIdentifier(cim.Type, "") + globalIdentifier, err := NewSourceIdentifier(cim.Type, "") if err != nil { return nil, fmt.Errorf("cannot create global identifier for input: %w", err) } @@ -271,7 +271,7 @@ func (cim *InputManager) Create(config *conf.C) (inp v2.Input, retErr error) { return &managedInput{ manager: cim, ackCH: cim.ackCH, - userID: settings.ID, + id: settings.ID, prospector: prospector, harvester: harvester, sourceIdentifier: srcIdentifier, @@ -305,11 +305,11 @@ func (cim *InputManager) getRetainedStore() *store { return store } -type sourceIdentifier struct { +type SourceIdentifier struct { prefix string } -func newSourceIdentifier(pluginName, userID string) (*sourceIdentifier, error) { +func NewSourceIdentifier(pluginName, userID string) (*SourceIdentifier, error) { if userID == globalInputID { return nil, fmt.Errorf("invalid input ID: .global") } @@ -318,16 +318,16 @@ func newSourceIdentifier(pluginName, userID string) (*sourceIdentifier, error) { userID = globalInputID } - return &sourceIdentifier{ + return &SourceIdentifier{ prefix: pluginName + "::" + userID + "::", }, nil } -func (i *sourceIdentifier) ID(s Source) string { +func (i *SourceIdentifier) ID(s Source) string { return i.prefix + s.Name() } -func (i *sourceIdentifier) MatchesInput(id string) bool { +func (i *SourceIdentifier) MatchesInput(id string) bool { return strings.HasPrefix(id, i.prefix) } diff --git a/filebeat/input/filestream/internal/input-logfile/manager_test.go b/filebeat/input/filestream/internal/input-logfile/manager_test.go index 58e014dba0a..88252be3dc4 100644 --- a/filebeat/input/filestream/internal/input-logfile/manager_test.go +++ b/filebeat/input/filestream/internal/input-logfile/manager_test.go @@ -81,7 +81,7 @@ func TestSourceIdentifier_ID(t *testing.T) { test := test t.Run(name, func(t *testing.T) { - srcIdentifier, err := newSourceIdentifier(testPluginName, test.userID) + srcIdentifier, err := NewSourceIdentifier(testPluginName, test.userID) if err != nil { t.Fatalf("cannot create identifier: %v", err) } @@ -120,7 +120,7 @@ func TestSourceIdentifier_MatchesInput(t *testing.T) { for name, test := range testCases { t.Run(name, func(t *testing.T) { - srcIdentifier, err := newSourceIdentifier(testPluginName, test.userID) + srcIdentifier, err := NewSourceIdentifier(testPluginName, test.userID) if err != nil { t.Fatalf("cannot create identifier: %v", err) } @@ -150,7 +150,7 @@ func TestSourceIdentifier_NotMatchesInput(t *testing.T) { for name, test := range testCases { t.Run(name, func(t *testing.T) { - srcIdentifier, err := newSourceIdentifier(testPluginName, test.userID) + srcIdentifier, err := NewSourceIdentifier(testPluginName, test.userID) if err != nil { t.Fatalf("cannot create identifier: %v", err) } @@ -165,11 +165,11 @@ func TestSourceIdentifier_NotMatchesInput(t *testing.T) { } func TestSourceIdentifierNoAccidentalMatches(t *testing.T) { - noIDIdentifier, err := newSourceIdentifier(testPluginName, "") + noIDIdentifier, err := NewSourceIdentifier(testPluginName, "") if err != nil { t.Fatalf("cannot create identifier: %v", err) } - withIDIdentifier, err := newSourceIdentifier(testPluginName, "id") + withIDIdentifier, err := NewSourceIdentifier(testPluginName, "id") if err != nil { t.Fatalf("cannot create identifier: %v", err) } @@ -192,7 +192,7 @@ func TestInputManager_Create(t *testing.T) { cim := &InputManager{ Logger: log, StateStore: testStateStore{Store: testStore}, - Configure: func(_ *config.C, _ *logp.Logger) (Prospector, Harvester, error) { + Configure: func(_ *config.C, _ *logp.Logger, _ *SourceIdentifier) (Prospector, Harvester, error) { return nil, nil, nil }} cfg, err := config.NewConfigFrom("id: my-id") @@ -236,7 +236,7 @@ func TestInputManager_Create(t *testing.T) { cim := &InputManager{ Logger: log, StateStore: testStateStore{Store: testStore}, - Configure: func(_ *config.C, _ *logp.Logger) (Prospector, Harvester, error) { + Configure: func(_ *config.C, _ *logp.Logger, _ *SourceIdentifier) (Prospector, Harvester, error) { var wg sync.WaitGroup return &noopProspector{}, &mockHarvester{onRun: correctOnRun, wg: &wg}, nil @@ -287,7 +287,7 @@ paths: cim := &InputManager{ Logger: log, StateStore: testStateStore{Store: testStore}, - Configure: func(cfg *config.C, _ *logp.Logger) (Prospector, Harvester, error) { + Configure: func(cfg *config.C, _ *logp.Logger, _ *SourceIdentifier) (Prospector, Harvester, error) { var wg sync.WaitGroup settings := struct { @@ -385,7 +385,7 @@ paths: cim := &InputManager{ Logger: log, StateStore: testStateStore{Store: testStore}, - Configure: func(_ *config.C, _ *logp.Logger) (Prospector, Harvester, error) { + Configure: func(_ *config.C, _ *logp.Logger, _ *SourceIdentifier) (Prospector, Harvester, error) { var wg sync.WaitGroup return &noopProspector{}, &mockHarvester{onRun: correctOnRun, wg: &wg}, nil diff --git a/filebeat/input/filestream/internal/input-logfile/publish.go b/filebeat/input/filestream/internal/input-logfile/publish.go index 2d1f1f3b3aa..861f197ce3a 100644 --- a/filebeat/input/filestream/internal/input-logfile/publish.go +++ b/filebeat/input/filestream/internal/input-logfile/publish.go @@ -122,7 +122,7 @@ func (op *updateOp) Execute(store *store, n uint) { resource.stateMutex.Lock() defer resource.stateMutex.Unlock() - if resource.lockedVersion != op.resource.version || resource.isDeleted() { + if resource.lockedVersion != op.resource.version || resource.unsafeIsDeleted() { return } diff --git a/filebeat/input/filestream/internal/input-logfile/store.go b/filebeat/input/filestream/internal/input-logfile/store.go index 2e471314392..b48b28c57df 100644 --- a/filebeat/input/filestream/internal/input-logfile/store.go +++ b/filebeat/input/filestream/internal/input-logfile/store.go @@ -38,10 +38,10 @@ import ( // from an input. type sourceStore struct { // identifier is the sourceIdentifier used to generate IDs fro this store. - identifier *sourceIdentifier + identifier *SourceIdentifier // identifiersToTakeOver are sourceIdentifier from previous input instances // that this sourceStore will take states over. - identifiersToTakeOver []*sourceIdentifier + identifiersToTakeOver []*SourceIdentifier // store is the underlying store that encapsulates // the in-memory and persistent store. store *store @@ -177,8 +177,8 @@ func openStore(log *logp.Logger, statestore statestore.States, prefix string) (* // identifiersToTakeOver is optional and can be nil. func newSourceStore( s *store, - identifier *sourceIdentifier, - identifiersToTakeOver []*sourceIdentifier, + identifier *SourceIdentifier, + identifiersToTakeOver []*SourceIdentifier, ) *sourceStore { return &sourceStore{ @@ -639,7 +639,7 @@ func (s *store) UpdateTTL(resource *resource, ttl time.Duration) { s.writeState(resource) - if resource.isDeleted() { + if resource.unsafeIsDeleted() { // version must be incremented to make sure existing resource // instances do not overwrite the removal of the entry resource.version++ @@ -697,7 +697,17 @@ func (r *resource) IsNew() bool { return r.pendingCursorValue == nil && r.pendingUpdate == nil && r.cursor == nil } +// isDeleted locks stateMutex then checks whether [resource] is deleted. func (r *resource) isDeleted() bool { + r.stateMutex.Lock() + defer r.stateMutex.Unlock() + return r.unsafeIsDeleted() +} + +// unsafeIsDeleted DOES NOT LOCK THE RESOURCE!!! +// Only call unsafeIsDeleted if you're currently holding the +// lock from resource.stateMutex +func (r *resource) unsafeIsDeleted() bool { return !r.internalState.Updated.IsZero() && r.internalState.TTL == 0 } diff --git a/filebeat/input/filestream/internal/input-logfile/store_test.go b/filebeat/input/filestream/internal/input-logfile/store_test.go index 9f600fa58b9..3df890472a9 100644 --- a/filebeat/input/filestream/internal/input-logfile/store_test.go +++ b/filebeat/input/filestream/internal/input-logfile/store_test.go @@ -356,7 +356,7 @@ func TestSourceStore_UpdateIdentifiers(t *testing.T) { s := testOpenStore(t, "test", backend) defer s.Release() store := &sourceStore{ - identifier: &sourceIdentifier{"test"}, + identifier: &SourceIdentifier{"test"}, store: s, } @@ -411,8 +411,8 @@ func TestSourceStoreTakeOver(t *testing.T) { s := testOpenStore(t, "filestream", backend) defer s.Release() store := &sourceStore{ - identifier: &sourceIdentifier{"filestream::current-id::"}, - identifiersToTakeOver: []*sourceIdentifier{{"filestream::previous-id::"}}, + identifier: &SourceIdentifier{"filestream::current-id::"}, + identifiersToTakeOver: []*SourceIdentifier{{"filestream::previous-id::"}}, store: s, } @@ -471,7 +471,7 @@ func TestSourceStore_CleanIf(t *testing.T) { s := testOpenStore(t, "test", backend) defer s.Release() store := &sourceStore{ - identifier: &sourceIdentifier{"test"}, + identifier: &SourceIdentifier{"test"}, store: s, } @@ -509,7 +509,7 @@ func TestSourceStore_CleanIf(t *testing.T) { s := testOpenStore(t, "test", backend) defer s.Release() store := &sourceStore{ - identifier: &sourceIdentifier{"test"}, + identifier: &SourceIdentifier{"test"}, store: s, } diff --git a/filebeat/input/filestream/legacy_metrics_integration_test.go b/filebeat/input/filestream/legacy_metrics_integration_test.go index c1b98aceca3..8feab7f9904 100644 --- a/filebeat/input/filestream/legacy_metrics_integration_test.go +++ b/filebeat/input/filestream/legacy_metrics_integration_test.go @@ -76,7 +76,8 @@ func TestLegacyMetrics(t *testing.T) { filebeat.WriteConfigFile(cfg) filebeat.Start() - filebeat.WaitForLogs("Metrics endpoint listening on:", + filebeat.WaitLogsContains( + "Metrics endpoint listening on:", 10*time.Second, "metrics endpoint did not start") diff --git a/filebeat/input/filestream/prospector.go b/filebeat/input/filestream/prospector.go index 2af372ac00b..5754af7f4fa 100644 --- a/filebeat/input/filestream/prospector.go +++ b/filebeat/input/filestream/prospector.go @@ -90,7 +90,6 @@ func (p *fileProspector) Init( newID func(loginp.Source) string, ) error { files := p.filewatcher.GetFiles() - // If this fileProspector belongs to an input that did not have an ID // this will find its files in the registry and update them to use the // new ID. @@ -282,14 +281,20 @@ func (p *fileProspector) Init( // //nolint:dupl // Different prospectors have a similar run method func (p *fileProspector) Run(ctx input.Context, s loginp.StateMetadataUpdater, hg loginp.HarvesterGroup) { - log := ctx.Logger.With("prospector", prospectorDebugKey) - log.Debug("Starting prospector") - defer log.Debug("Prospector has stopped") + p.logger.Debug("Starting prospector") + defer p.logger.Debug("Prospector has stopped") - defer p.stopHarvesterGroup(log, hg) + // ctx.Logger has its 'log.logger' set to 'input.filestream'. + // Because the harvester is not really part of the prospector, + // we use this logger instead of the prospector logger. + defer p.stopHarvesterGroup(ctx.Logger, hg) var tg unison.MultiErrGroup + // The harvester needs to notify the FileWatcher + // when it closes + hg.SetObserver(p.filewatcher.NotifyChan()) + tg.Go(func() error { p.filewatcher.Run(ctx.Cancelation) return nil @@ -306,17 +311,19 @@ func (p *fileProspector) Run(ctx input.Context, s loginp.StateMetadataUpdater, h } src := p.identifier.GetSource(fe) - p.onFSEvent(loggerWithEvent(log, fe, src), ctx, fe, src, s, hg, ignoreInactiveSince) + p.onFSEvent(loggerWithEvent(p.logger, fe, src), ctx, fe, src, s, hg, ignoreInactiveSince) } return nil }) errs := tg.Wait() if len(errs) > 0 { - log.Errorf("running prospector failed: %v", errors.Join(errs...)) + p.logger.Errorf("running prospector failed: %v", errors.Join(errs...)) } } +// onFSEvent uses 'log' instead of the [fileProspector] logger +// because 'log' has been enriched with event information func (p *fileProspector) onFSEvent( log *logp.Logger, ctx input.Context, @@ -326,6 +333,7 @@ func (p *fileProspector) onFSEvent( group loginp.HarvesterGroup, ignoreSince time.Time, ) { + log = log.With("source_file", event.SrcID) switch event.Op { case loginp.OpCreate, loginp.OpWrite: if event.Op == loginp.OpCreate { diff --git a/filebeat/input/filestream/prospector_creator.go b/filebeat/input/filestream/prospector_creator.go index 2f55db92e37..b0fe2a09ff7 100644 --- a/filebeat/input/filestream/prospector_creator.go +++ b/filebeat/input/filestream/prospector_creator.go @@ -24,7 +24,6 @@ import ( loginp "github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile" "github.com/elastic/beats/v7/libbeat/common/cfgwarn" - conf "github.com/elastic/elastic-agent-libs/config" "github.com/elastic/elastic-agent-libs/logp" ) @@ -37,24 +36,37 @@ const ( var experimentalWarning sync.Once -func newProspector(config config, log *logp.Logger) (loginp.Prospector, error) { - logger := log.With("filestream_id", config.ID) - err := checkConfigCompatibility(config.FileWatcher, config.FileIdentity) +func newProspector( + config config, + log *logp.Logger, + srci *loginp.SourceIdentifier) (loginp.Prospector, error) { + + logger := log.Named("filestream").With("filestream_id", config.ID) + err := checkConfigCompatibility(config) if err != nil { return nil, err } - filewatcher, err := newFileWatcher(logger, config.Paths, config.FileWatcher) + identifier, err := newFileIdentifier( + config.FileIdentity, + config.Reader.Parsers.Suffix, + logger) if err != nil { - return nil, fmt.Errorf("error while creating filewatcher %w", err) + return nil, fmt.Errorf("error while creating file identifier: %w", err) } + logger.Debugf("file identity is set to %s", identifier.Name()) - identifier, err := newFileIdentifier(config.FileIdentity, config.Reader.Parsers.Suffix, log) + filewatcher, err := newFileWatcher( + logger, + config.Paths, + config.FileWatcher, + identifier, + srci, + ) if err != nil { - return nil, fmt.Errorf("error while creating file identifier: %w", err) + return nil, fmt.Errorf("error while creating filewatcher %w", err) } - logger = logger.Named("filestream") logger.Debugf("file identity is set to %s", identifier.Name()) fileprospector := fileProspector{ @@ -117,21 +129,11 @@ func newProspector(config config, log *logp.Logger) (loginp.Prospector, error) { return nil, fmt.Errorf("no such rotation method: %s", rotationMethod) } -func checkConfigCompatibility(fileWatcher, fileIdentifier *conf.Namespace) error { - var fwCfg struct { - Fingerprint struct { - Enabled bool `config:"enabled"` - } `config:"fingerprint"` - } - - if fileWatcher != nil && fileIdentifier != nil && fileIdentifier.Name() == fingerprintName { - err := fileWatcher.Config().Unpack(&fwCfg) - if err != nil { - return fmt.Errorf("failed to parse file watcher configuration: %w", err) - } - if !fwCfg.Fingerprint.Enabled { - return fmt.Errorf("fingerprint file identity can be used only when fingerprint is enabled in the scanner") - } +func checkConfigCompatibility(config config) error { + if config.FileIdentity != nil && + config.FileIdentity.Name() == fingerprintName && + !config.FileWatcher.Scanner.Fingerprint.Enabled { + return fmt.Errorf("fingerprint file identity can be used only when fingerprint is enabled in the scanner") } return nil diff --git a/filebeat/input/filestream/prospector_creator_test.go b/filebeat/input/filestream/prospector_creator_test.go index 8288b9f0fa8..e08ba4ab15b 100644 --- a/filebeat/input/filestream/prospector_creator_test.go +++ b/filebeat/input/filestream/prospector_creator_test.go @@ -24,7 +24,7 @@ import ( "github.com/stretchr/testify/require" conf "github.com/elastic/elastic-agent-libs/config" - "github.com/elastic/elastic-agent-libs/logp/logptest" + "github.com/elastic/elastic-agent-libs/logp" ) func TestCreateProspector(t *testing.T) { @@ -48,7 +48,7 @@ func TestCreateProspector(t *testing.T) { c := config{ IgnoreInactive: ignoreInactiveSettings[test.ignore_inactive_since], } - p, _ := newProspector(c, logptest.NewTestingLogger(t, "")) + p, _ := newProspector(c, logp.NewNopLogger(), mustSourceIdentifier("foo-id")) fileProspector := p.(*fileProspector) assert.Equal(t, fileProspector.ignoreInactiveSince, ignoreInactiveSettings[test.ignore_inactive_since]) }) @@ -102,7 +102,7 @@ prospector.scanner.fingerprint.enabled: false err = c.Unpack(&cfg) require.NoError(t, err) - _, err = newProspector(cfg, logptest.NewTestingLogger(t, "")) + _, err = newProspector(cfg, logp.NewNopLogger(), mustSourceIdentifier("foo-id")) if tc.err == "" { require.NoError(t, err) return diff --git a/filebeat/input/filestream/prospector_test.go b/filebeat/input/filestream/prospector_test.go index 56b6f14e2fd..fa48ac320fe 100644 --- a/filebeat/input/filestream/prospector_test.go +++ b/filebeat/input/filestream/prospector_test.go @@ -638,6 +638,10 @@ func (t *testHarvesterGroup) StopHarvesters() error { return nil } +// SetObserver is a no-op +func (t *testHarvesterGroup) SetObserver(c chan loginp.HarvesterStatus) { +} + type mockFileWatcher struct { events []loginp.FSEvent filesOnDisk map[string]loginp.FileDescriptor @@ -645,6 +649,8 @@ type mockFileWatcher struct { outputCount, eventCount int out chan loginp.FSEvent + + c chan loginp.HarvesterStatus } // newMockFileWatcher creates an FSWatch mock, so you can read @@ -681,6 +687,10 @@ func (m *mockFileWatcher) Run(_ unison.Canceler) {} func (m *mockFileWatcher) GetFiles() map[string]loginp.FileDescriptor { return m.filesOnDisk } +func (m *mockFileWatcher) NotifyChan() chan loginp.HarvesterStatus { + return m.c +} + type mockMetadataUpdater struct { table map[string]interface{} } diff --git a/filebeat/tests/integration/autodiscover_test.go b/filebeat/tests/integration/autodiscover_test.go index 76c5dd3a1c6..7342b86b6a3 100644 --- a/filebeat/tests/integration/autodiscover_test.go +++ b/filebeat/tests/integration/autodiscover_test.go @@ -63,7 +63,7 @@ func TestHintsDocker(t *testing.T) { // By ensuring the Filestream input started with the correct ID, we're // testing that the whole autodiscover + hints is working as expected. - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf( `"message":"Input 'filestream' starting","service.name":"filebeat","id":"container-logs-%s"`, containerID, @@ -94,7 +94,7 @@ func TestHintsKubernetes(t *testing.T) { // By ensuring the Filestream input started with the correct ID, we're // testing that the whole autodiscover + hints is working as expected. - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf( `"message":"Input 'filestream' starting","service.name":"filebeat","id":"container-logs-%s"`, containerID, diff --git a/filebeat/tests/integration/crawler_test.go b/filebeat/tests/integration/crawler_test.go index 9cc27bf7944..4dfcf0b9756 100644 --- a/filebeat/tests/integration/crawler_test.go +++ b/filebeat/tests/integration/crawler_test.go @@ -68,7 +68,8 @@ output.file: filebeat.Start() // 3. Create the log file - integration.GenerateLogFile(t, filepath.Join(tempDir, "log.log"), 10, false) + //integration.WriteLogFile + integration.WriteLogFile(t, filepath.Join(tempDir, "log.log"), 10, false) // wait for output file to exist var outputFile string @@ -83,7 +84,8 @@ output.file: }, 2*time.Minute, 10*time.Second) // Ensure all log lines are ingested eventually - integration.AssertLinesInFile(t, outputFile, 10) + // integration.WaitLineCountInFile + integration.WaitLineCountInFile(t, outputFile, 10) // append a line without \n and ensure it is not crawled logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666) @@ -98,7 +100,7 @@ output.file: } // Ensure number of lines has not increased - integration.AssertLinesInFile(t, outputFile, 10) + integration.WaitLineCountInFile(t, outputFile, 10) // add \n to logfile _, err = logFile.Write([]byte("\n")) @@ -107,20 +109,20 @@ output.file: } // Add one more line to make sure it keeps reading - integration.GenerateLogFile(t, filepath.Join(tempDir, "log.log"), 1, true) + integration.WriteLogFile(t, filepath.Join(tempDir, "log.log"), 1, true) // Ensure all logs are ingested - integration.AssertLinesInFile(t, outputFile, 12) + integration.WaitLineCountInFile(t, outputFile, 12) // rename the file assert.NoError(t, os.Rename(logFilePath, filepath.Join(tempDir, "newlog.log"))) // using 6 events to have a separate log line that we can // grep for. - integration.GenerateLogFile(t, filepath.Join(tempDir, "newlog.log"), 6, true) + integration.WriteLogFile(t, filepath.Join(tempDir, "newlog.log"), 6, true) // Ensure all logs are ingested - integration.AssertLinesInFile(t, outputFile, 18) + integration.WaitLineCountInFile(t, outputFile, 18) } @@ -159,9 +161,9 @@ output.file: // 3. Create the log file iterations := 20 - integration.GenerateLogFile(t, logFilePath, iterations, false, "DBG: a simple debug message") - integration.GenerateLogFile(t, logFilePath, iterations, true, "ERR: a simple error message") - integration.GenerateLogFile(t, logFilePath, iterations, true, "WARNING: a simple warning message") + integration.WriteLogFile(t, logFilePath, iterations, false, "DBG: a simple debug message") + integration.WriteLogFile(t, logFilePath, iterations, true, "ERR: a simple error message") + integration.WriteLogFile(t, logFilePath, iterations, true, "WARNING: a simple warning message") // wait for output file to exist var outputFile string @@ -176,7 +178,7 @@ output.file: }, 2*time.Minute, 10*time.Second) // Ensure include_lines only events are ingested - integration.AssertLinesInFile(t, outputFile, 2*iterations) + integration.WaitLineCountInFile(t, outputFile, 2*iterations) } // Checks log lines defined by exclude_lines are excluded @@ -214,9 +216,9 @@ output.file: // 3. Create the log file iterations := 20 - integration.GenerateLogFile(t, logFilePath, iterations, false, "DBG: a simple debug message") - integration.GenerateLogFile(t, logFilePath, iterations, true, "ERR: a simple error message") - integration.GenerateLogFile(t, logFilePath, iterations, true, "WARNING: a simple warning message") + integration.WriteLogFile(t, logFilePath, iterations, false, "DBG: a simple debug message") + integration.WriteLogFile(t, logFilePath, iterations, true, "ERR: a simple error message") + integration.WriteLogFile(t, logFilePath, iterations, true, "WARNING: a simple warning message") // wait for output file to exist var outputFile string @@ -230,5 +232,5 @@ output.file: return true }, 2*time.Minute, 10*time.Second) - integration.AssertLinesInFile(t, outputFile, 2*iterations) + integration.WaitLineCountInFile(t, outputFile, 2*iterations) } diff --git a/filebeat/tests/integration/filebeat_test.go b/filebeat/tests/integration/filebeat_test.go index 58208f2d7b4..ca71e7d7eaf 100644 --- a/filebeat/tests/integration/filebeat_test.go +++ b/filebeat/tests/integration/filebeat_test.go @@ -58,7 +58,7 @@ func TestFilebeatRunsAndLogsJSONToFile(t *testing.T) { logFilePath := path.Join(tempDir, "log.log") // 2. Create the log file - integration.GenerateLogFile(t, logFilePath, 10, false) + integration.WriteLogFile(t, logFilePath, 10, false) // 3. Write configuration file and start Filebeat filebeat.WriteConfigFile(fmt.Sprintf(filebeatBasicConfig, logFilePath, tempDir)) diff --git a/filebeat/tests/integration/filestream_test.go b/filebeat/tests/integration/filestream_test.go index 63fa26ec693..ab8f524a9ae 100644 --- a/filebeat/tests/integration/filestream_test.go +++ b/filebeat/tests/integration/filestream_test.go @@ -74,6 +74,7 @@ logging: selectors: - input - input.filestream + - input.filestream.prospector metrics: enabled: false ` @@ -94,16 +95,15 @@ func TestFilestreamCleanInactive(t *testing.T) { filebeat.Start() // 3. Create the log file - integration.GenerateLogFile(t, logFilePath, 10, false) + integration.WriteLogFile(t, logFilePath, 10, false) // 4. Wait for Filebeat to start scanning for files - // - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf("A new file %s has been found", logFilePath), 10*time.Second, "Filebeat did not start looking for files to ingest") - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf("Reader was closed. Closing. Path='%s", logFilePath), 10*time.Second, "Filebeat did not close the file") @@ -111,7 +111,7 @@ func TestFilestreamCleanInactive(t *testing.T) { // of the file, so once the TTL of its state expires and the store GC runs, // it will be removed from the registry. // Wait for the log message stating 1 entry has been removed from the registry - filebeat.WaitForLogs("1 entries removed", 20*time.Second, "entry was not removed from registry") + filebeat.WaitLogsContains("1 entries removed", 20*time.Second, "entry was not removed from registry") // 6. Then assess it has been removed in the registry registryFile := filepath.Join(filebeat.TempDir(), "data", "registry", "filebeat", "log.json") @@ -226,14 +226,14 @@ logging: filebeat.Start() // Wait for error log - filebeat.WaitForLogs( + filebeat.WaitLogsContains( "filestream inputs validation error", 10*time.Second, "Filebeat did not log a filestream input validation error") - proc, err := filebeat.Process.Wait() - require.NoError(t, err, "filebeat process.Wait returned an error") - assert.False(t, proc.Success(), "filebeat should have failed to start") + err := filebeat.Cmd.Wait() + require.Error(t, err, "filebeat Cmd.Wait must return an error because Filebeat should fail to start") + assert.False(t, filebeat.Cmd.ProcessState.Success(), "filebeat should have failed to start") }) } @@ -275,7 +275,7 @@ logging: filebeat.Start() // Wait for error log - filebeat.WaitForLogs( + filebeat.WaitLogsContains( "Input 'filestream' starting", 10*time.Second, "Filebeat did not log a validation error") @@ -363,7 +363,7 @@ logging: workDir := filebeat.TempDir() outputFile := filepath.Join(workDir, "output-file*") logFilepath := filepath.Join(workDir, "log.log") - integration.GenerateLogFile(t, logFilepath, 25, false) + integration.WriteLogFile(t, logFilepath, 25, false) cfgYAML := fmt.Sprintf(cfgTemplate, logFilepath, tc.oldIdentityCfg, workDir) filebeat.WriteConfigFile(cfgYAML) @@ -371,7 +371,7 @@ logging: // Wait for the file to be fully ingested eofMsg := fmt.Sprintf("End of file reached: %s; Backoff now.", logFilepath) - filebeat.WaitForLogs(eofMsg, time.Second*10, "EOF was not reached") + filebeat.WaitLogsContains(eofMsg, time.Second*10, "EOF was not reached") requirePublishedEvents(t, filebeat, 25, outputFile) filebeat.Stop() @@ -386,14 +386,14 @@ logging: if tc.expectMigration { // Test the case where the registry migration happens migratingMsg := fmt.Sprintf("are the same, migrating. Source: '%s'", logFilepath) - filebeat.WaitForLogs(migratingMsg, time.Second*10, "prospector did not migrate registry entry") - filebeat.WaitForLogs("migrated entry in registry from", time.Second*10, "store did not update registry key") - filebeat.WaitForLogs(eofMsg, time.Second*10, "EOF was not reached the second time") + filebeat.WaitLogsContains(migratingMsg, time.Second*10, "prospector did not migrate registry entry") + filebeat.WaitLogsContains("migrated entry in registry from", time.Second*10, "store did not update registry key") + filebeat.WaitLogsContains(eofMsg, time.Second*10, "EOF was not reached the second time") requirePublishedEvents(t, filebeat, 25, outputFile) // Ingest more data to ensure the offset was migrated - integration.GenerateLogFile(t, logFilepath, 17, true) - filebeat.WaitForLogs(eofMsg, time.Second*5, "EOF was not reached the third time") + integration.WriteLogFile(t, logFilepath, 17, true) + filebeat.WaitLogsContains(eofMsg, time.Second*5, "EOF was not reached the third time") requirePublishedEvents(t, filebeat, 42, outputFile) requireRegistryEntryRemoved(t, workDir, tc.oldIdentityName) @@ -403,18 +403,18 @@ logging: // Another option is for no keys to be migrated because the current // file identity is not fingerprint if tc.notMigrateMsg != "" { - filebeat.WaitForLogs(tc.notMigrateMsg, time.Second*10, "the registry should not have been migrated") + filebeat.WaitLogsContains(tc.notMigrateMsg, time.Second*10, "the registry should not have been migrated") } // The last thing to test when there is no migration is to assert // the file has been fully re-ingested because the file identity // changed - filebeat.WaitForLogs(eofMsg, time.Second*10, "EOF was not reached the second time") + filebeat.WaitLogsContains(eofMsg, time.Second*10, "EOF was not reached the second time") requirePublishedEvents(t, filebeat, 50, outputFile) // Ingest more data to ensure the offset is correctly tracked - integration.GenerateLogFile(t, logFilepath, 10, true) - filebeat.WaitForLogs(eofMsg, time.Second*5, "EOF was not reached the third time") + integration.WriteLogFile(t, logFilepath, 10, true) + filebeat.WaitLogsContains(eofMsg, time.Second*5, "EOF was not reached the third time") requirePublishedEvents(t, filebeat, 60, outputFile) }) } @@ -495,15 +495,15 @@ logging: migratingMsg := fmt.Sprintf("are the same, migrating. Source: '%s'", logFilepath) eofMsg := fmt.Sprintf("End of file reached: %s; Backoff now.", logFilepath) - filebeat.WaitForLogs(migratingMsg, time.Second*10, "prospector did not migrate registry entry") - filebeat.WaitForLogs("migrated entry in registry from", time.Second*10, "store did not update registry key") + filebeat.WaitLogsContains(migratingMsg, time.Second*10, "prospector did not migrate registry entry") + filebeat.WaitLogsContains("migrated entry in registry from", time.Second*10, "store did not update registry key") // Filebeat logs the EOF message when it starts and the file had already been fully ingested. - filebeat.WaitForLogs(eofMsg, time.Second*10, "EOF was not reached after restart") + filebeat.WaitLogsContains(eofMsg, time.Second*10, "EOF was not reached after restart") requirePublishedEvents(t, filebeat, 200, outputFile) // Ingest more data to ensure the offset was migrated - integration.GenerateLogFile(t, logFilepath, 20, true) - filebeat.WaitForLogs(eofMsg, time.Second*5, "EOF was not reached after adding data") + integration.WriteLogFile(t, logFilepath, 20, true) + filebeat.WaitLogsContains(eofMsg, time.Second*5, "EOF was not reached after adding data") requirePublishedEvents(t, filebeat, 220, outputFile) requireRegistryEntryRemoved(t, workDir, "native") @@ -716,10 +716,11 @@ func createFileAndWaitIngestion( } } - integration.GenerateLogFile(t, logFilepath, n, false) + integration.WriteLogFile(t, logFilepath, n, false) eofMsg := fmt.Sprintf("End of file reached: %s; Backoff now.", logFilepath) - fb.WaitForLogs(eofMsg, time.Second*10, "EOF was not reached") + + fb.WaitLogsContains(eofMsg, time.Second*10, "EOF was not reached") requirePublishedEvents(t, fb, outputTotal, outputFilepath) } diff --git a/filebeat/tests/integration/filestream_truncation_test.go b/filebeat/tests/integration/filestream_truncation_test.go index bd80f327578..569a441fe91 100644 --- a/filebeat/tests/integration/filestream_truncation_test.go +++ b/filebeat/tests/integration/filestream_truncation_test.go @@ -80,10 +80,10 @@ func TestFilestreamLiveFileTruncation(t *testing.T) { filebeat.WriteConfigFile(fmt.Sprintf(truncationCfg, logFile, tempDir, tempDir)) // 1. Create a log file and let Filebeat harvest all contents - integration.GenerateLogFile(t, logFile, 200, false) + integration.WriteLogFile(t, logFile, 200, false) filebeat.Start() - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") // 2. Truncate the file and wait Filebeat to close the file if err := os.Truncate(logFile, 0); err != nil { @@ -91,10 +91,9 @@ func TestFilestreamLiveFileTruncation(t *testing.T) { } // 3. Ensure Filebeat detected the file truncation - filebeat.WaitForLogs("File was truncated as offset (10000) > size (0)", 20*time.Second, "file was not truncated") - filebeat.WaitForLogs("File was truncated, nothing to read", 20*time.Second, "reader loop did not stop") - filebeat.WaitForLogs("Stopped harvester for file", 20*time.Second, "harvester did not stop") - filebeat.WaitForLogs("Closing reader of filestream", 20*time.Second, "reader did not close") + filebeat.WaitLogsContains("File was truncated as offset (10000) > size (0)", 20*time.Second, "file was not truncated") + filebeat.WaitLogsContains("File was truncated, nothing to read", 20*time.Second, "reader loop did not stop") + filebeat.WaitLogsContains("Stopped harvester for file", 20*time.Second, "harvester did not stop") // 4. Now we need to stop Filebeat before the next scan cycle filebeat.Stop() @@ -103,12 +102,12 @@ func TestFilestreamLiveFileTruncation(t *testing.T) { assertLastOffset(t, registryLogFile, 10_000) // Open for appending because the file has already been truncated - integration.GenerateLogFile(t, logFile, 10, true) + integration.WriteLogFile(t, logFile, 10, true) // 5. Start Filebeat again. filebeat.Start() - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") assertLastOffset(t, registryLogFile, 500) } @@ -126,12 +125,12 @@ func TestFilestreamOfflineFileTruncation(t *testing.T) { filebeat.WriteConfigFile(fmt.Sprintf(truncationCfg, logFile, tempDir, tempDir)) // 1. Create a log file with some lines - integration.GenerateLogFile(t, logFile, 10, false) + integration.WriteLogFile(t, logFile, 10, false) // 2. Ingest the file and stop Filebeat filebeat.Start() - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") filebeat.Stop() // 3. Assert the offset is correctly set in the registry @@ -141,12 +140,12 @@ func TestFilestreamOfflineFileTruncation(t *testing.T) { if err := os.Truncate(logFile, 0); err != nil { t.Fatalf("could not truncate log file: %s", err) } - integration.GenerateLogFile(t, logFile, 5, true) + integration.WriteLogFile(t, logFile, 5, true) // 5. Read the file again and stop Filebeat filebeat.Start() - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") - filebeat.WaitForLogs("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("End of file reached", 30*time.Second, "Filebeat did not finish reading the log file") filebeat.Stop() // 6. Assert the registry offset is new, smaller file size. diff --git a/filebeat/tests/integration/input_reload_test.go b/filebeat/tests/integration/input_reload_test.go index 76a963a7235..8bbb4fd7b9a 100644 --- a/filebeat/tests/integration/input_reload_test.go +++ b/filebeat/tests/integration/input_reload_test.go @@ -79,7 +79,7 @@ logging.level: debug filebeat.WriteConfigFile(fmt.Sprintf(configTemplate, inputs, tempDir)) // 3. Create the log file - integration.GenerateLogFile(t, logFilePath, 10, false) + integration.WriteLogFile(t, logFilePath, 10, false) assert.NoError(t, os.WriteFile(filepath.Join(inputs, "filestream.yml"), []byte(fmt.Sprintf(inputConfig, logFilePath)), 0666)) @@ -99,16 +99,16 @@ logging.level: debug }, 2*time.Minute, 10*time.Second) // Ensure all log lines are ingested eventually - integration.AssertLinesInFile(t, outputFile, 10) + integration.WaitLineCountInFile(t, outputFile, 10) assert.NoError(t, os.Rename(filepath.Join(inputs, "filestream.yml"), filepath.Join(inputs, "filestream.yml.disabled"))) - filebeat.WaitForLogs("Runner: 'filestream' has stopped", 2*time.Minute) + filebeat.WaitLogsContains("Runner: 'filestream' has stopped", 2*time.Minute) logFilePath2 := filepath.Join(tempDir, "log2.log") - integration.GenerateLogFile(t, logFilePath2, 10, false) + integration.WriteLogFile(t, logFilePath2, 10, false) // bring another file up assert.NoError(t, os.WriteFile(filepath.Join(inputs, "secondInput.yml"), []byte(fmt.Sprintf(inputConfig, logFilePath2)), 0666)) // Ensure all log lines are ingested eventually - integration.AssertLinesInFile(t, outputFile, 20) + integration.WaitLineCountInFile(t, outputFile, 20) } diff --git a/filebeat/tests/integration/journald_test.go b/filebeat/tests/integration/journald_test.go index b81959ab097..06a0d9bd537 100644 --- a/filebeat/tests/integration/journald_test.go +++ b/filebeat/tests/integration/journald_test.go @@ -53,7 +53,7 @@ func TestJournaldInputRunsAndRecoversFromJournalctlFailures(t *testing.T) { filebeat.WriteConfigFile(yamlCfg) filebeat.Start() - filebeat.WaitForLogs("journalctl started with PID", 10*time.Second, "journalctl did not start") + filebeat.WaitLogsContains("journalctl started with PID", 10*time.Second, "journalctl did not start") pidLine := filebeat.GetLastLogLine("journalctl started with PID") logEntry := struct{ Message string }{} @@ -71,7 +71,7 @@ func TestJournaldInputRunsAndRecoversFromJournalctlFailures(t *testing.T) { } generateJournaldLogs(t, syslogID, 5, 100) - filebeat.WaitForLogs("journalctl started with PID", 10*time.Second, "journalctl did not start") + filebeat.WaitLogsContains("journalctl started with PID", 10*time.Second, "journalctl did not start") filebeat.WaitPublishedEvents(5*time.Second, 8) } @@ -95,7 +95,7 @@ func TestJournaldInputDoesNotDuplicateData(t *testing.T) { filebeat.WriteConfigFile(yamlCfg) filebeat.Start() - filebeat.WaitForLogs("journalctl started with PID", 10*time.Second, "journalctl did not start") + filebeat.WaitLogsContains("journalctl started with PID", 10*time.Second, "journalctl did not start") pidLine := filebeat.GetLastLogLine("journalctl started with PID") logEntry := struct{ Message string }{} @@ -114,7 +114,7 @@ func TestJournaldInputDoesNotDuplicateData(t *testing.T) { filebeat.Start() // Wait for journalctl to start - filebeat.WaitForLogs("journalctl started with PID", 10*time.Second, "journalctl did not start") + filebeat.WaitLogsContains("journalctl started with PID", 10*time.Second, "journalctl did not start") // Wait for last even in the output filebeat.WaitPublishedEvents(5*time.Second, 8) @@ -148,7 +148,7 @@ func TestJournaldLargeLines(t *testing.T) { Message string `json:"message"` } - evts := integration.GetEventsFromFileOutput[evt](filebeat, 5) + evts := integration.GetEventsFromFileOutput[evt](filebeat, 5, true) for i, e := range evts { if len(e.Message) != evtLen { t.Errorf("event %d: expecting len %d, got %d", i, evtLen, len(e.Message)) diff --git a/filebeat/tests/integration/setup_pipelines_test.go b/filebeat/tests/integration/setup_pipelines_test.go index bb74ecbe24f..92c3e111a85 100644 --- a/filebeat/tests/integration/setup_pipelines_test.go +++ b/filebeat/tests/integration/setup_pipelines_test.go @@ -65,7 +65,7 @@ setup.kibana: filebeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.Host, esURL.User.Username(), esPassword, kURL.Host, kUserInfo.Username(), kPassword)) filebeat.Start("setup") - filebeat.WaitForLogs("Setup called, but no modules enabled.", 10*time.Second) + filebeat.WaitLogsContains("Setup called, but no modules enabled.", 10*time.Second) } func TestSetupModulesNoFileset(t *testing.T) { @@ -104,7 +104,7 @@ logging.level: debug filebeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.Host, esURL.User.Username(), esPassword, kURL.Host, kUserInfo.Username(), kPassword)) filebeat.Start("setup", "--pipelines") - filebeat.WaitForLogs("Number of module configs found: 0", 10*time.Second) + filebeat.WaitLogsContains("Number of module configs found: 0", 10*time.Second) } func TestSetupModulesOneEnabled(t *testing.T) { @@ -143,7 +143,7 @@ logging.level: debug filebeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.Host, esURL.User.Username(), esPassword, kURL.Host, kUserInfo.Username(), kPassword)) filebeat.Start("setup", "--pipelines", "--modules", "apache") - filebeat.WaitForLogs("Exiting: module apache is configured but has no enabled filesets", 10*time.Second) + filebeat.WaitLogsContains("Exiting: module apache is configured but has no enabled filesets", 10*time.Second) } func TestSetupModulesOneEnabledOverride(t *testing.T) { @@ -197,6 +197,6 @@ logging.level: debug } }) filebeat.Start("setup", "--pipelines", "--modules", "apache", "--force-enable-module-filesets") - filebeat.WaitForLogs("Elasticsearch pipeline loaded.", 10*time.Second) - filebeat.WaitForLogs("Elasticsearch pipeline loaded.", 10*time.Second) + filebeat.WaitLogsContains("Elasticsearch pipeline loaded.", 10*time.Second) + filebeat.WaitLogsContains("Elasticsearch pipeline loaded.", 10*time.Second) } diff --git a/filebeat/tests/integration/store_test.go b/filebeat/tests/integration/store_test.go index e187c682676..af2f09926a6 100644 --- a/filebeat/tests/integration/store_test.go +++ b/filebeat/tests/integration/store_test.go @@ -85,7 +85,7 @@ func TestStore(t *testing.T) { for i := 0; i < numLogFiles; i++ { logFile := path.Join(logsFolder, fmt.Sprintf("log-%d.log", i)) - integration.GenerateLogFile(t, logFile, 10, false) + integration.WriteLogFile(t, logFile, 10, false) } logsFolderGlob := filepath.Join(logsFolder, "*") filebeat.WriteConfigFile(fmt.Sprintf(testStoreCfg, logsFolderGlob, tempDir)) @@ -97,14 +97,14 @@ func TestStore(t *testing.T) { // Files can be ingested out of order, so we cannot specify their path. // There will be more than one log line per file, but that at least gives us // some assurance the files were read - filebeat.WaitForLogs("Closing reader of filestream", 30*time.Second, "Filebeat did not finish reading the log file") + filebeat.WaitLogsContains("Closing reader of filestream", 30*time.Second, "Filebeat did not finish reading the log file") } // 3. Remove files so their state can be cleaned if err := os.RemoveAll(logsFolder); err != nil { t.Fatalf("could not remove logs folder '%s': %s", logsFolder, err) } - filebeat.WaitForLogs(fmt.Sprintf("%d entries removed", numLogFiles), 30*time.Second, "store entries not removed") + filebeat.WaitLogsContains(fmt.Sprintf("%d entries removed", numLogFiles), 30*time.Second, "store entries not removed") filebeat.Stop() registryLogFile := filepath.Join(tempDir, "data/registry/filebeat/log.json") diff --git a/filebeat/tests/integration/translate_ldap_attribute_test.go b/filebeat/tests/integration/translate_ldap_attribute_test.go index 26b61862807..9ca1321a7c2 100644 --- a/filebeat/tests/integration/translate_ldap_attribute_test.go +++ b/filebeat/tests/integration/translate_ldap_attribute_test.go @@ -99,7 +99,7 @@ func TestTranslateGUIDWithLDAP(t *testing.T) { // 1. Generate the log file path logFilePath := path.Join(tempDir, "log.log") - integration.GenerateLogFile(t, logFilePath, 1, false) + integration.WriteLogFile(t, logFilePath, 1, false) // 2. Write configuration file and start Filebeat filebeat.WriteConfigFile( diff --git a/go.mod b/go.mod index 27c74642551..8e49ac6a522 100644 --- a/go.mod +++ b/go.mod @@ -246,6 +246,7 @@ require ( ) require ( + github.com/brianvoe/gofakeit v3.18.0+incompatible go.opentelemetry.io/collector/config/configauth v0.135.0 go.opentelemetry.io/collector/config/confighttp v0.135.0 go.opentelemetry.io/collector/config/configoptional v0.135.0 diff --git a/go.sum b/go.sum index 85e6a11f642..4ae6a67654b 100644 --- a/go.sum +++ b/go.sum @@ -256,6 +256,8 @@ github.com/blakesmith/ar v0.0.0-20150311145944-8bd4349a67f2 h1:oMCHnXa6CCCafdPDb github.com/blakesmith/ar v0.0.0-20150311145944-8bd4349a67f2/go.mod h1:PkYb9DJNAwrSvRx5DYA+gUcOIgTGVMNkfSCbZM8cWpI= github.com/bluekeyes/go-gitdiff v0.7.1 h1:graP4ElLRshr8ecu0UtqfNTCHrtSyZd3DABQm/DWesQ= github.com/bluekeyes/go-gitdiff v0.7.1/go.mod h1:QpfYYO1E0fTVHVZAZKiRjtSGY9823iCdvGXBcEzHGbM= +github.com/brianvoe/gofakeit v3.18.0+incompatible h1:wDOmHc9DLG4nRjUVVaxA+CEglKOW72Y5+4WNxUIkjM8= +github.com/brianvoe/gofakeit v3.18.0+incompatible/go.mod h1:kfwdRA90vvNhPutZWfH7WPaDzUjz+CZFqG+rPkOjGOc= github.com/cavaliergopher/rpm v1.2.0 h1:s0h+QeVK252QFTolkhGiMeQ1f+tMeIMhGl8B1HUmGUc= github.com/cavaliergopher/rpm v1.2.0/go.mod h1:R0q3vTqa7RUvPofAZYrnjJ63hh2vngjFfphuXiExVos= github.com/cenkalti/backoff/v5 v5.0.3 h1:ZN+IMa753KfX5hd8vVaMixjnqRZ3y8CuJKRKj1xcsSM= diff --git a/libbeat/tests/integration/README.md b/libbeat/tests/integration/README.md new file mode 100644 index 00000000000..39f52cea696 --- /dev/null +++ b/libbeat/tests/integration/README.md @@ -0,0 +1,90 @@ +# Beats Integration tests framework + +This integration test framework aims to replace our Python one, it +started small by implementing in Go the basic functionality and +helpers provided by the Python one and since then it has been growing +in features and helper functions. + +## Beat Process Creation and Management + +### Beat Creation ++ `NewBeat`: Creates a new Beat process from the system tests binary with specific settings. ++ `NewStandardBeat`: Creates a Beat process from a standard binary without the system test flag. ++ `NewAgentBeat`: Creates a new agentbeat process that runs the beatName as a subcommand. + +#### Process Control ++ `Start`: Starts the Beat process with optional additional arguments. ++ `Stop`: Stops the Beat process (framework adds cleanup to stop automatically at test end). ++ `RestartOnBeatOnExit`: When set to true, automatically restarts the Beat when it exits. + +#### Configuration Management ++ `WriteConfigFile`: Writes provided configuration string to a file for the Beat to use. ++ `ConfigFilePath`: Returns the path to the Beat's configuration file. ++ `RemoveAllCLIArgs`: Removes all CLI arguments, keeping only the required `--systemTest` flag. + +## Reading and Writing log files + +### Methods search in logs keeping track of the lines already read +These methods remember what they've already read and only check new content on subsequent calls: + ++ `LogContains`: Checks if logs contain a string (keeps track of offset). ++ `LogMatch`: Tests if logs match a regular expression (keeps track of offset). ++ `WaitLogsContains`: Waits for logs to contain a string (uses `LogContains` with offset tracking). + +### Methods search in logs without tracking of the lines already read +These methods always read from the beginning of logs: + ++ `GetLogLine`: Searches for a string in logs and returns the matching line. ++ `GetLastLogLine`: Searches for a string from the end of logs and returns the matching line. ++ `WaitLogsContainsFromBeginning`: Resets offset, then waits for logs to contain a string. ++ `WaitLogsContainsAnyOrder` - Waits for all specified strings to appear in logs in any order within the given timeout. + +### Generating log files for ingestion + ++ `WriteLogFile` - Writes a log file with the specified number of lines, each containing timestamp and a counter. ++ `WriteNLogFiles` - Generates multiple log files (nFiles) each containing the specified number of random lines (nLines). ++ `WriteAppendingLogFile` - Generates a log file by appending the current time to it every second. + +## File Operations + ++ `FileContains`: Searches for a string in a file and returns the first matching line. ++ `WaitFileContains`: Waits for a file to contain a specific string. ++ `WaitStdErrContains`: Waits for stderr to contain a specific string. ++ `WaitStdOutContains`: Waits for stdout to contain a specific string. ++ `WaitPublishedEvents` - Waits until the desired number of events have been published to the file output. ++ `CountFileLines`: Counts the number of lines in files matching a glob pattern. ++ `RemoveLogFiles`: Removes log files and resets the tracked offsets. + +## Reading data from the Output + ++ `GetEventsMsgFromES` - Retrieves event messages from Elasticsearch with specified query parameters. ++ `GetEventsFromFileOutput` - Reads events from output files in the specified directory with optional limit on number of events. + +## Utilities + ++ `TempDir`: Returns the temporary directory used by the Beat (preserved on test failure). ++ `LoadMeta`: Loads metadata from the Beat's meta.json file. ++ `Stdin`: Returns the standard input for interacting with the Beat process. ++ `WaitLineCountInFile`: Waits until a file has a specific number of lines. + +### Elasticsearch Integration + +#### Connection ++ `EnsureESIsRunning`: Checks that Elasticsearch is running and accessible. ++ `GetESClient`: Gets an Elasticsearch client configured with test credentials. ++ `GetESURL`: Returns the Elasticsearch URL with standard user credentials. ++ `GetESAdminURL`: Returns the Elasticsearch URL with admin credentials. + +#### Mock Elasticsearch ++ `StartMockES`: Starts a mock Elasticsearch server with configurable behavior. + +### HTTP Requests ++ `HttpDo`: Performs an HTTP request to a specified URL. ++ `FormatDatastreamURL`: Formats a URL for a datastream endpoint. ++ `FormatIndexTemplateURL`: Formats a URL for an index template endpoint. ++ `FormatPolicyURL`: Formats a URL for a policy endpoint. ++ `FormatRefreshURL`: Formats a URL for refreshing indices. ++ `FormatDataStreamSearchURL`: Formats a URL for searching a datastream. + +### Kibana Integration ++ `GetKibana`: Returns the Kibana URL and user credentials. diff --git a/libbeat/tests/integration/base_test.go b/libbeat/tests/integration/base_test.go index 38bebb59f2c..aa045af81d8 100644 --- a/libbeat/tests/integration/base_test.go +++ b/libbeat/tests/integration/base_test.go @@ -43,9 +43,9 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) mockbeat.Stop() - mockbeat.WaitForLogs("mockbeat stopped.", 30*time.Second) + mockbeat.WaitLogsContains("mockbeat stopped.", 30*time.Second) } func TestSigHUP(t *testing.T) { @@ -66,19 +66,19 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) - err := mockbeat.Process.Signal(syscall.SIGHUP) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) + err := mockbeat.Cmd.Process.Signal(syscall.SIGHUP) require.NoErrorf(t, err, "error sending SIGHUP to mockbeat") mockbeat.Stop() - mockbeat.WaitForLogs("mockbeat stopped.", 30*time.Second) + mockbeat.WaitLogsContains("mockbeat stopped.", 30*time.Second) } func TestNoConfig(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with error code") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("error loading config file", 10*time.Second) } @@ -91,9 +91,9 @@ test: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("error loading config file", 10*time.Second) } @@ -112,9 +112,9 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test", "-d", "config", "-E", "output.console=invalid") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("error unpacking config data", 10*time.Second) } @@ -205,5 +205,6 @@ output.console: mockbeat.Start() mockbeat.WaitStdErrContains("mockbeat start running.", 10*time.Second) metaFile2, err := mockbeat.LoadMeta() + require.NoError(t, err, "LoadMeta returned an error") require.Equal(t, metaFile1.UUID.String(), metaFile2.UUID.String()) } diff --git a/libbeat/tests/integration/ca_pinning_test.go b/libbeat/tests/integration/ca_pinning_test.go index 98c3db6729d..ecbb925eeda 100644 --- a/libbeat/tests/integration/ca_pinning_test.go +++ b/libbeat/tests/integration/ca_pinning_test.go @@ -53,8 +53,8 @@ output.elasticsearch: ` mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), caPath)) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) - mockbeat.WaitForLogs("doBulkRequest: 1 events have been sent", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("doBulkRequest: 1 events have been sent", 60*time.Second) } func TestCAPinningBadSHA(t *testing.T) { @@ -84,6 +84,6 @@ output.elasticsearch: ` mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), caPath)) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) - mockbeat.WaitForLogs("provided CA certificate pins doesn't match any of the certificate authorities used to validate the certificate", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("provided CA certificate pins doesn't match any of the certificate authorities used to validate the certificate", 60*time.Second) } diff --git a/libbeat/tests/integration/cmd_keystore_test.go b/libbeat/tests/integration/cmd_keystore_test.go index efb9b91a1c9..fc64d605d11 100644 --- a/libbeat/tests/integration/cmd_keystore_test.go +++ b/libbeat/tests/integration/cmd_keystore_test.go @@ -103,33 +103,33 @@ func TestKeystoreRemoveMultipleExistingKeys(t *testing.T) { fmt.Fprintf(mockbeat.stdin, "pass1") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key2", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass2") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key3", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass3") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "remove", "key2", "key3") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "list") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("key1", 10*time.Second) } @@ -144,28 +144,28 @@ func TestKeystoreList(t *testing.T) { mockbeat.Start("keystore", "add", "key1", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass1") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key2", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass2") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key3", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass3") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "list") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("key1", 10*time.Second) mockbeat.WaitStdOutContains("key2", 10*time.Second) @@ -177,9 +177,9 @@ func TestKeystoreListEmptyKeystore(t *testing.T) { keystorePath := filepath.Join(mockbeat.TempDir(), "test.keystore") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, keystorePath)) mockbeat.Start("keystore", "list") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") } func TestKeystoreAddSecretFromStdin(t *testing.T) { @@ -188,16 +188,16 @@ func TestKeystoreAddSecretFromStdin(t *testing.T) { mockbeat.WriteConfigFile(fmt.Sprintf(cfg, keystorePath)) mockbeat.Start("keystore", "create") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key1", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass1") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") } func TestKeystoreUpdateForce(t *testing.T) { @@ -205,21 +205,21 @@ func TestKeystoreUpdateForce(t *testing.T) { keystorePath := filepath.Join(mockbeat.TempDir(), "test.keystore") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, keystorePath)) mockbeat.Start("keystore", "create") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key1", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass1") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.Start("keystore", "add", "key1", "--force", "--stdin") fmt.Fprintf(mockbeat.stdin, "pass2") require.NoError(t, mockbeat.stdin.Close(), "could not close mockbeat stdin") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") } diff --git a/libbeat/tests/integration/cmd_setup_index_management_test.go b/libbeat/tests/integration/cmd_setup_index_management_test.go index f099b692445..d30cdfe3583 100644 --- a/libbeat/tests/integration/cmd_setup_index_management_test.go +++ b/libbeat/tests/integration/cmd_setup_index_management_test.go @@ -62,9 +62,9 @@ func TestSetupIdxMgmt(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(IdxMgmtCfg, esURL.String())) mockbeat.Start("setup", "--index-management", "-v", "-e") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") require.True(t, isTemplateLoaded(t, dataStream)) require.True(t, isIndexPatternSet(t, "mockbeat-9.9.9")) require.True(t, isPolicyCreated(t, policy)) @@ -84,9 +84,9 @@ func TestSetupTemplateDisabled(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(IdxMgmtCfg, esURL.String())) mockbeat.Start("setup", "--index-management", "-v", "-e") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") require.True(t, isTemplateLoaded(t, dataStream)) require.True(t, isIndexPatternSet(t, "mockbeat-9.9.9")) require.True(t, isPolicyCreated(t, policy)) diff --git a/libbeat/tests/integration/cmd_test.go b/libbeat/tests/integration/cmd_test.go index 08953740014..231e9407ed8 100644 --- a/libbeat/tests/integration/cmd_test.go +++ b/libbeat/tests/integration/cmd_test.go @@ -48,18 +48,18 @@ func TestCmdTest(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(CmdTestCfg, esURL.String())) mockbeat.Start("test", "config") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("Config OK", 10*time.Second) } func TestCmdTestNoConfig(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.Start("test", "config") - procState, err := mockbeat.Process.Wait() - require.NoError(t, err) - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") } func TestCmdTestOutput(t *testing.T) { @@ -67,9 +67,9 @@ func TestCmdTestOutput(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(CmdTestCfg, esURL.String())) mockbeat.Start("test", "output") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("parse url... OK", 10*time.Second) mockbeat.WaitStdOutContains("TLS... WARN secure connection disabled", 10*time.Second) mockbeat.WaitStdOutContains("talk to server... OK", 10*time.Second) @@ -79,9 +79,9 @@ func TestCmdTestOutputBadHost(t *testing.T) { mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(CmdTestCfg, "badhost:9200")) mockbeat.Start("test", "output") - procState, err := mockbeat.Process.Wait() - require.NoError(t, err) - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("parse url... OK", 10*time.Second) mockbeat.WaitStdOutContains("dns lookup... ERROR", 10*time.Second) } diff --git a/libbeat/tests/integration/cmd_version_test.go b/libbeat/tests/integration/cmd_version_test.go index 2c078f79c2f..2c87c90841d 100644 --- a/libbeat/tests/integration/cmd_version_test.go +++ b/libbeat/tests/integration/cmd_version_test.go @@ -43,9 +43,9 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start("version") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("mockbeat", 10*time.Second) mockbeat.WaitStdOutContains("version", 10*time.Second) mockbeat.WaitStdOutContains("9.9.9", 10*time.Second) diff --git a/libbeat/tests/integration/dashboard_test.go b/libbeat/tests/integration/dashboard_test.go index bdcd7f8ee67..5f7f6fbef33 100644 --- a/libbeat/tests/integration/dashboard_test.go +++ b/libbeat/tests/integration/dashboard_test.go @@ -56,9 +56,9 @@ queue.mem: "-E", "output.elasticsearch.username=admin", "-E", "output.elasticsearch.password=testing", "-E", "output.file.enabled=false") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("Skipping loading dashboards", 10*time.Second) } @@ -90,10 +90,10 @@ queue.mem: "-E", "output.elasticsearch.username=admin", "-E", "output.elasticsearch.password=testing", "-E", "output.file.enabled=false") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") - mockbeat.WaitForLogs("Kibana dashboards successfully loaded", 30*time.Second) + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") + mockbeat.WaitLogsContains("Kibana dashboards successfully loaded", 30*time.Second) } func TestDashboardLoadIndexOnly(t *testing.T) { @@ -125,10 +125,10 @@ queue.mem: "-E", "output.elasticsearch.username=admin", "-E", "output.elasticsearch.password=testing", "-E", "output.file.enabled=false") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") - mockbeat.WaitForLogs("Kibana dashboards successfully loaded", 30*time.Second) + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") + mockbeat.WaitLogsContains("Kibana dashboards successfully loaded", 30*time.Second) } func TestDashboardExportById(t *testing.T) { @@ -160,10 +160,10 @@ queue.mem: "-E", "output.elasticsearch.username=admin", "-E", "output.elasticsearch.password=testing", "-E", "output.file.enabled=false") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") - mockbeat.WaitForLogs("Kibana dashboards successfully loaded", 30*time.Second) + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") + mockbeat.WaitLogsContains("Kibana dashboards successfully loaded", 30*time.Second) mockbeat.Start("export", "dashboard", @@ -174,9 +174,9 @@ queue.mem: "-E", "setup.kibana.password=testing", "--id", "Metricbeat-system-overview", "--folder", filepath.Join(mockbeat.TempDir(), "system-overview")) - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") dbPath := filepath.Join(mockbeat.TempDir(), "system-overview", "_meta", "kibana", "9", "dashboard", "Metricbeat-system-overview.json") require.FileExists(t, dbPath, "dashboard file not exported") b, err := os.ReadFile(dbPath) @@ -207,7 +207,7 @@ queue.mem: "-E", "setup.kibana.password=testing", "--id", "No-such-dashboard", "--folder", filepath.Join(mockbeat.TempDir(), "system-overview")) - procState, err := mockbeat.Process.Wait() - require.NoError(t, err) - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") } diff --git a/libbeat/tests/integration/datagenerator.go b/libbeat/tests/integration/datagenerator.go new file mode 100644 index 00000000000..d22df6fba90 --- /dev/null +++ b/libbeat/tests/integration/datagenerator.go @@ -0,0 +1,157 @@ +// Licensed to Elasticsearch B.V. under one or more contributor +// license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright +// ownership. Elasticsearch B.V. licenses this file to you under +// the Apache License, Version 2.0 (the "License"); you may +// not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +//go:build integration + +package integration + +import ( + "fmt" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/brianvoe/gofakeit" +) + +// WriteLogFile writes count lines to path. +// Each line contains the current time (RFC3339) and a counter. +// Prefix is added instead of current time if it exists. +// If no prefix is passed, each line is 50 bytes long +func WriteLogFile(t *testing.T, path string, count int, append bool, prefix ...string) { + var file *os.File + var err error + if !append { + file, err = os.Create(path) + if err != nil { + t.Fatalf("could not create file '%s': %s", path, err) + } + } else { + file, err = os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666) + if err != nil { + t.Fatalf("could not open or create file: '%s': %s", path, err) + } + } + + defer func() { + if err := file.Close(); err != nil { + t.Fatalf("could not close file: %s", err) + } + }() + defer func() { + if err := file.Sync(); err != nil { + t.Fatalf("could not sync file: %s", err) + } + }() + + var now string + if len(prefix) == 0 { + // If the length is different, e.g when there is no offset from UTC. + // add some padding so the length is predictable + now = time.Now().Format(time.RFC3339) + if len(now) != len(time.RFC3339) { + paddingNeeded := len(time.RFC3339) - len(now) + for range paddingNeeded { + now += "-" + } + } + } else { + now = strings.Join(prefix, "") + } + + for i := range count { + if _, err := fmt.Fprintf(file, "%s %13d\n", now, i); err != nil { + t.Fatalf("could not write line %d to file: %s", count+1, err) + } + } +} + +// WriteNLogFiles generates nFiles with nLines in each. The lines are a +// random phrase generated by Gofakeit. Files are generated into a `logs` +// folder created in tempDir and the names follow the format "%06d.log". +// The returned value is the folder containing the log files. +func WriteNLogFiles(t *testing.T, tempDir string, nFiles, nLines int) string { + basePath := filepath.Join(tempDir, "logs") + if err := os.MkdirAll(basePath, 0777); err != nil { + t.Fatalf("cannot create folder to store logs: %s", err) + } + + for fCount := range nFiles { + path := filepath.Join(basePath, fmt.Sprintf("%06d.log", fCount)) + f, err := os.Create(path) + if err != nil { + t.Errorf("cannot create file: %s", err) + } + for range nLines { + _, _ = f.WriteString(gofakeit.HackerPhrase() + "\n") + } + if err := f.Sync(); err != nil { + t.Errorf("cannot sync %q: %s", path, err) + } + if err := f.Close(); err != nil { + t.Errorf("cannot close %q: %s", path, err) + } + } + + return basePath +} + +// WriteAppendingLogFile generates a log file by appending the current +// time to it every second. The files are flushed after every write. +func WriteAppendingLogFile(t *testing.T, fullPath string) { + t.Helper() + f, err := os.Create(fullPath) + if err != nil { + t.Fatalf("could not create file '%s: %s", fullPath, err) + } + + go func() { + t.Helper() + ticker := time.NewTicker(time.Second) + t.Cleanup(ticker.Stop) + + done := make(chan struct{}) + t.Cleanup(func() { close(done) }) + + defer func() { + if err := f.Close(); err != nil { + t.Errorf("could not close log file '%s': %s", fullPath, err) + } + }() + + for { + select { + case <-done: + return + case now := <-ticker.C: + _, err := fmt.Fprintln(f, now.Format(time.RFC3339)) + if err != nil { + // The Go compiler does not allow me to call t.Fatalf from a non-test + // goroutine, so just log it instead + t.Errorf("could not write data to log file '%s': %s", fullPath, err) + return + } + // make sure log lines are synced as quickly as possible + if err := f.Sync(); err != nil { + t.Errorf("could not sync file '%s': %s", fullPath, err) + } + } + } + }() +} diff --git a/libbeat/tests/integration/elasticsearch_test.go b/libbeat/tests/integration/elasticsearch_test.go index d27cfa51b7a..061a9a4f22e 100644 --- a/libbeat/tests/integration/elasticsearch_test.go +++ b/libbeat/tests/integration/elasticsearch_test.go @@ -77,13 +77,13 @@ func TestESOutputRecoversFromNetworkError(t *testing.T) { } // 3. Wait for connection error logs - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf(`Get \"%s\": dial tcp %s: connect: connection refused`, esAddr, esURL.Host), 2*time.Second, "did not find connection refused error") - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf("Attempting to reconnect to backoff(elasticsearch(%s)) with 2 reconnect attempt(s)", esAddr), 2*time.Second, "did not find two tries to reconnect") @@ -92,7 +92,7 @@ func TestESOutputRecoversFromNetworkError(t *testing.T) { s, _, _, mr = StartMockES(t, ":4242", 0, 0, 0, 0, 0) // 5. Wait for reconnection logs - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf("Connection to backoff(elasticsearch(%s)) established", esAddr), 5*time.Second, // There is a backoff, so ensure we wait enough "did not find re connection confirmation") @@ -128,8 +128,8 @@ logging.level: debug mockbeat.Start() // 1. wait mockbeat to start - mockbeat.WaitForLogs( - "mockbeat start running", + mockbeat.WaitLogsContains( + fmt.Sprint("mockbeat start running"), 10*time.Second, "did not find 'mockbeat start running' log") @@ -138,20 +138,20 @@ logging.level: debug require.NoError(t, err, "could not rotate CA") // 3. Wait for cert change detection logs - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf("some of the following files have been modified: [%s]", caPath), 10*time.Second, "did not detect CA rotation") // 4. Wait for CA load log - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf("Successfully loaded CA certificate: %s", caPath), 10*time.Second, "did not find 'Successfully loaded CA' log") // 5. wait mockbeat to start again - mockbeat.WaitForLogs( - "mockbeat start running", + mockbeat.WaitLogsContains( + fmt.Sprint("mockbeat start running"), 10*time.Second, "did not find 'mockbeat start running' log again") } diff --git a/libbeat/tests/integration/framework.go b/libbeat/tests/integration/framework.go index f0bb0ab0cd2..8ad5b60d872 100644 --- a/libbeat/tests/integration/framework.go +++ b/libbeat/tests/integration/framework.go @@ -15,6 +15,8 @@ // specific language governing permissions and limitations // under the License. +// This file was contributed to by generative AI + //go:build integration package integration @@ -50,6 +52,7 @@ import ( "github.com/stretchr/testify/require" sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "github.com/elastic/beats/v7/libbeat/common/proc" "github.com/elastic/go-elasticsearch/v8" "github.com/elastic/mock-es/pkg/api" ) @@ -71,8 +74,11 @@ type BeatProc struct { stdin io.WriteCloser stdout *os.File stderr *os.File - Process *os.Process cleanUpOnce sync.Once + jobObject proc.Job + stopOnce sync.Once + Cmd *exec.Cmd + expectedErrorCode int } type Meta struct { @@ -111,7 +117,12 @@ type Total struct { // `args` will be passed as CLI arguments to the Beat func NewBeat(t *testing.T, beatName, binary string, args ...string) *BeatProc { require.FileExistsf(t, binary, "beat binary must exists") - tempDir := createTempDir(t) + rootDir, err := filepath.Abs(filepath.Join("..", "..", "build", "integration-tests")) + if err != nil { + t.Fatalf("failed to determine absolute path for temp dir: %s", err) + } + + tempDir := CreateTempDir(t, rootDir) configFile := filepath.Join(tempDir, beatName+".yml") stdoutFile, err := os.Create(filepath.Join(tempDir, "stdout")) @@ -119,6 +130,9 @@ func NewBeat(t *testing.T, beatName, binary string, args ...string) *BeatProc { stderrFile, err := os.Create(filepath.Join(tempDir, "stderr")) require.NoError(t, err, "error creating stderr file") + jobObject, err := proc.CreateJobObject() + require.NoError(t, err, "creating job object") + p := BeatProc{ Binary: binary, baseArgs: append([]string{ @@ -136,13 +150,16 @@ func NewBeat(t *testing.T, beatName, binary string, args ...string) *BeatProc { t: t, stdout: stdoutFile, stderr: stderrFile, + jobObject: jobObject, } + t.Cleanup(func() { if !t.Failed() { return } reportErrors(t, tempDir, beatName) }) + return &p } @@ -156,41 +173,20 @@ func NewStandardBeat(t *testing.T, beatName, binary string, args ...string) *Bea // NewAgentBeat creates a new agentbeat process that runs the beatName as a subcommand. // See `NewBeat` for options and information for the parameters. func NewAgentBeat(t *testing.T, beatName, binary string, args ...string) *BeatProc { - require.FileExistsf(t, binary, "agentbeat binary must exists") - tempDir := createTempDir(t) - configFile := filepath.Join(tempDir, beatName+".yml") - - stdoutFile, err := os.Create(filepath.Join(tempDir, "stdout")) - require.NoError(t, err, "error creating stdout file") - stderrFile, err := os.Create(filepath.Join(tempDir, "stderr")) - require.NoError(t, err, "error creating stderr file") + b := NewBeat(t, beatName, binary, args...) - p := BeatProc{ - Binary: binary, - baseArgs: append([]string{ + // Remove the first two arguments: beatName and --systemTest + baseArgs := b.baseArgs[2:] + // Add the agentbeat argumet and re-organise the others + b.baseArgs = append( + []string{ "agentbeat", "--systemTest", beatName, - "--path.home", tempDir, - "--path.logs", tempDir, - "-E", "logging.to_files=true", - "-E", "logging.files.rotateeverybytes=104857600", // About 100MB - "-E", "logging.files.rotateonstartup=false", - }, args...), - tempDir: tempDir, - beatName: beatName, - configFile: configFile, - t: t, - stdout: stdoutFile, - stderr: stderrFile, - } - t.Cleanup(func() { - if !t.Failed() { - return - } - reportErrors(t, tempDir, beatName) - }) - return &p + }, + baseArgs...) + + return b } // Start starts the Beat process @@ -257,29 +253,38 @@ func (b *BeatProc) startBeat() { _, _ = b.stderr.Seek(0, 0) _ = b.stderr.Truncate(0) - cmd := exec.Cmd{ + b.Cmd = &exec.Cmd{ Path: b.fullPath, Args: b.Args, Stdout: b.stdout, Stderr: b.stderr, + // OS dependant attributes to allow gracefully terminating process + // on Linux and Windows + SysProcAttr: proc.GetSysProcAttr(), } var err error - b.stdin, err = cmd.StdinPipe() + b.stdin, err = b.Cmd.StdinPipe() require.NoError(b.t, err, "could not get cmd StdinPipe") - err = cmd.Start() + err = b.Cmd.Start() require.NoError(b.t, err, "error starting beat process") - b.Process = cmd.Process + if err := b.jobObject.Assign(b.Cmd.Process); err != nil { + _ = b.Cmd.Process.Kill() + b.t.Fatalf("failed job assignment: %s", err) + } b.t.Cleanup(func() { // If the test failed, print the whole cmd line to help debugging if b.t.Failed() { - args := strings.Join(cmd.Args, " ") - b.t.Log("CMD line to execute Beat:", cmd.Path, args) + args := strings.Join(b.Cmd.Args, " ") + b.t.Log("CMD line to execute Beat:", b.Cmd.Path, args) } }) + + // Every time we start a process, we can stop it again + b.stopOnce = sync.Once{} } // waitBeatToExit blocks until the Beat exits. @@ -291,11 +296,10 @@ func (b *BeatProc) waitBeatToExit() { } defer b.waitingMutex.Unlock() - processState, err := b.Process.Wait() - if err != nil { + if err := b.Cmd.Wait(); err != nil { exitCode := "unknown" - if processState != nil { - exitCode = strconv.Itoa(processState.ExitCode()) + if b.Cmd.ProcessState != nil { + exitCode = strconv.Itoa(b.Cmd.ProcessState.ExitCode()) } b.t.Fatalf("error waiting for %q to finish: %s. Exit code: %s", @@ -314,36 +318,39 @@ func (b *BeatProc) Stop() { // stopNonsynced is the actual stop code, but without locking so it can be reused // by methods that have already acquired the lock. func (b *BeatProc) stopNonsynced() { - // Windows does not support interrupt - if runtime.GOOS == "windows" { - if err := b.Process.Kill(); err != nil { - b.t.Logf("[WARN] could not send kill signal to process with PID: %d, err: %s", - b.Process.Pid, err) + b.stopOnce.Do(func() { + // If the test/caller has already stopped the process, do nothing. + if b.Cmd.ProcessState != nil { + return } - } else { - if err := b.Process.Signal(os.Interrupt); err != nil { - if errors.Is(err, os.ErrProcessDone) { + + if err := proc.StopCmd(b.Cmd.Process); err != nil { + b.t.Fatalf("cannot stop process: %s", err) + } + + if !b.waitingMutex.TryLock() { + // b.waitBeatToExit must be waiting on the process already. Nothing to do. + return + } + defer b.waitingMutex.Unlock() + err := b.Cmd.Wait() + if err != nil { + if b.expectedErrorCode != 0 { + if b.Cmd.ProcessState.ExitCode() != b.expectedErrorCode { + b.t.Fatalf("expecting exit code %d, got %d", + b.expectedErrorCode, + b.Cmd.ProcessState.ExitCode()) + } return } - b.t.Fatalf("could not send interrupt signal to process with PID: %d, err: %s", - b.Process.Pid, err) + b.t.Logf("[WARN] got an error waiting %s to stop: %v", b.beatName, err) + return } - } - - if !b.waitingMutex.TryLock() { - // b.waitBeatToExit must be waiting on the process already. Nothing to do. - return - } - defer b.waitingMutex.Unlock() - ps, err := b.Process.Wait() - if err != nil { - b.t.Logf("[WARN] got an error waiting %s to stop: %v", b.beatName, err) - return - } - if !ps.Success() { - b.t.Logf("[WARN] %s did not stopped successfully: %v", b.beatName, ps.String()) - } + if !b.Cmd.ProcessState.Success() { + b.t.Logf("[WARN] %s did not stop successfully: %v", b.beatName, b.Cmd.ProcessState.String()) + } + }) } // LogMatch tests each line of the logfile to see if contains any @@ -434,6 +441,30 @@ func (b *BeatProc) LogContains(s string) bool { return found } +func (b *BeatProc) RemoveLogFiles() { + year := time.Now().Year() + tmpls := []string{"%s-events-data-%d*.ndjson", "%s-%d*.ndjson"} + + files := []string{} + for _, tmpl := range tmpls { + glob := fmt.Sprintf(tmpl, filepath.Join(b.tempDir, b.beatName), year) + foundFiles, err := filepath.Glob(glob) + if err != nil { + b.t.Fatalf("cannot resolve glob: %s", err) + } + files = append(files, foundFiles...) + } + + for _, file := range files { + if err := os.Remove(file); err != nil { + b.t.Fatalf("cannot remove file: %s", err) + } + } + + b.eventLogFileOffset = 0 + b.logFileOffset = 0 +} + // GetLogLine search for the string s starting at the beginning // of the logs, if it is found the whole log line is returned, otherwise // an empty string is returned. GetLogLine does not keep track of @@ -559,12 +590,81 @@ func (b *BeatProc) searchStrInLogsReversed(logFile *os.File, s string) (bool, st return false, "" } -// WaitForLogs waits for the specified string s to be present in the logs within +// WaitLogsContains waits for the specified string s to be present in the logs within // the given timeout duration and fails the test if s is not found. +// It keeps track of the log file offset, reading only new lines. Each +// subsequent call to WaitLogsContains will only check logs not yet evaluated. // msgAndArgs should be a format string and arguments that will be printed // if the logs are not found, providing additional context for debugging. -func (b *BeatProc) WaitForLogs(s string, timeout time.Duration, msgAndArgs ...any) { +func (b *BeatProc) WaitLogsContains(s string, timeout time.Duration, msgAndArgs ...any) { + b.t.Helper() + require.Eventually(b.t, func() bool { + return b.LogContains(s) + }, timeout, 100*time.Millisecond, msgAndArgs...) +} + +// WaitLogsContainsAnyOrder waits for all strings in the msgs slice to appear in the logs. +// The strings can appear in any order. The function will return once all strings +// have been found or the timeout has been reached. +// If the timeout is reached before all strings are found, the test will fail with +// the provided error message and arguments (failMsg). +func (b *BeatProc) WaitLogsContainsAnyOrder(msgs []string, timeout time.Duration, failMsg string) { + b.t.Helper() + + if len(msgs) == 0 { + return + } + + // Create a map to track which messages have been found + found := make(map[string]bool, len(msgs)) + for _, msg := range msgs { + found[msg] = false + } + + msg := &strings.Builder{} + + assert.Eventually( + b.t, + func() bool { + // Check for each unfound message + allFound := true + + for msgToFind := range found { + if !found[msgToFind] { + if b.GetLogLine(msgToFind) != "" { + found[msgToFind] = true + } else { + allFound = false + } + } + } + + // Prepare message for potential failure + if !allFound { + msg.Reset() + fmt.Fprintf(msg, "%s\nwaiting for log messages: ", failMsg) + for msgToFind, wasFound := range found { + if !wasFound { + fmt.Fprintf(msg, "\n- %q (not found)", msgToFind) + } else { + fmt.Fprintf(msg, "\n- %q (✓)", msgToFind) + } + } + } + + return allFound + }, + timeout, + 100*time.Millisecond, + msg, + ) +} + +// WaitForLogsFromBeginning has the same behaviour as WaitForLogs, but it first +// resets the log offset. +func (b *BeatProc) WaitLogsContainsFromBeginning(s string, timeout time.Duration, msgAndArgs ...any) { b.t.Helper() + b.logFileOffset = 0 require.Eventually(b.t, func() bool { return b.LogContains(s) }, timeout, 100*time.Millisecond, msgAndArgs...) @@ -590,12 +690,11 @@ func (b *BeatProc) WriteConfigFile(cfg string) { } // openGlobFile opens a file defined by glob. The glob must resolve to a single -// file otherwise the test fails. It returns a *os.File and a boolean indicating -// whether a file was found. +// file otherwise the test fails. It returns a *os.File or nil if none is found. // -// If `waitForFile` is true, it will wait up to 5 seconds for the file to -// be created. The test will fail if the file is not found. If it is false -// and no file is found, nil and false are returned. +// If `waitForFile` is true, it will wait up to 45 seconds for the file to +// be created. The test will fail if the file is not found. If waitForFile is +// false and no file is found, nil and false are returned. func (b *BeatProc) openGlobFile(glob string, waitForFile bool) *os.File { t := b.t @@ -611,7 +710,7 @@ func (b *BeatProc) openGlobFile(glob string, waitForFile bool) *os.File { t.Fatalf("could not expand log file glob: %s", err) } return len(files) == 1 - }, 5*time.Second, 100*time.Millisecond, + }, 45*time.Second, 100*time.Millisecond, "waiting for log file matching glob '%s' to be created", glob) } @@ -647,29 +746,43 @@ func (b *BeatProc) openLogFile() *os.File { // If the events log file does not exist, nil is returned // It's the caller's responsibility to close the file. func (b *BeatProc) openEventLogFile() *os.File { + return b.openGlobFile(b.getEventLogFileGlob(), false) +} + +func (b *BeatProc) getEventLogFileGlob() string { // Beats can produce two different log files, to make sure we're // reading the normal one we add the year to the glob. The default // log file name looks like: filebeat-20240116.ndjson year := time.Now().Year() glob := fmt.Sprintf("%s-events-data-%d*.ndjson", filepath.Join(b.tempDir, b.beatName), year) + return glob +} - return b.openGlobFile(glob, false) +// SetExpectedErrorCode sets the expected exit error code. +// Setting this asserts the exit error code once the Beat +// process exits. +func (b *BeatProc) SetExpectedErrorCode(errorCode int) { + b.expectedErrorCode = errorCode } -// createTempDir creates a temporary directory that will be -// removed after the tests passes. +// CreateTempDir creates a temporary directory that will be +// removed after the tests passes. The temporary directory is +// created on rootDir. If rootDir is empty, then os.TempDir() is used. // // If the test fails, the temporary directory is not removed. // // If the tests are run with -v, the temporary directory will // be logged. -func createTempDir(t *testing.T) string { - rootDir, err := filepath.Abs("../../build/integration-tests") - if err != nil { - t.Fatalf("failed to determine absolute path for temp dir: %s", err) +func CreateTempDir(t *testing.T, rootDir string) string { + if rootDir == "" { + rootDir = os.TempDir() } - err = os.MkdirAll(rootDir, 0o750) + + rootDir, err := filepath.Abs(rootDir) if err != nil { + t.Fatalf("cannot get abs path of root dir: %s", err) + } + if err := os.MkdirAll(rootDir, 0o750); err != nil { t.Fatalf("error making test dir: %s: %s", rootDir, err) } tempDir, err := os.MkdirTemp(rootDir, strings.ReplaceAll(t.Name(), "/", "-")) @@ -758,6 +871,10 @@ func GetESClient(t *testing.T, scheme string) *elasticsearch.Client { } +// FileContains searches for `match` in `filename` and returns the first matching line. +// The method reads the file line by line, looking for the first occurrence of the match string. +// If no match is found, it returns an empty string. +// The test will fail (t.Fatal) if the file cannot be opened or if an error occurs while reading. func (b *BeatProc) FileContains(filename string, match string) string { file, err := os.Open(filename) require.NoErrorf(b.t, err, "error opening: %s", filename) @@ -832,7 +949,22 @@ func (b *BeatProc) ReadStdout() (string, error) { return string(by), err } +// GetESURL Returns the ES URL with username and password set, +// it uses ES_USER and ES_PASS that on our mage automation defaults +// to user 'beats' and pass 'testing'. This user/role has limited +// privileges, it cannot create arbitrary indexes. func GetESURL(t *testing.T, scheme string) url.URL { + return getESURL(t, scheme, "ES_USER", "ES_PASS") +} + +// GetESURL Returns the ES URL with admin username and password set, +// it uses ES_SUPERUSER_USER and ES_SUPERUSER_PASS that on our mage +// automation defaults to user 'admin' and pass 'testing'. +func GetESAdminURL(t *testing.T, scheme string) url.URL { + return getESURL(t, scheme, "ES_SUPERUSER_USER", "ES_SUPERUSER_PASS") +} + +func getESURL(t *testing.T, scheme string, userEnvVar, passEnvVar string) url.URL { t.Helper() esHost := os.Getenv("ES_HOST") @@ -852,12 +984,12 @@ func GetESURL(t *testing.T, scheme string) url.URL { } } - user := os.Getenv("ES_USER") + user := os.Getenv(userEnvVar) if user == "" { user = "admin" } - pass := os.Getenv("ES_PASS") + pass := os.Getenv(passEnvVar) if pass == "" { pass = "testing" } @@ -1011,59 +1143,8 @@ func reportErrors(t *testing.T, tempDir string, beatName string) { } } -// GenerateLogFile writes count lines to path -// Each line contains the current time (RFC3339) and a counter -// Prefix is added instead of current time if it exists -func GenerateLogFile(t *testing.T, path string, count int, append bool, prefix ...string) { - var file *os.File - var err error - if !append { - file, err = os.Create(path) - if err != nil { - t.Fatalf("could not create file '%s': %s", path, err) - } - } else { - file, err = os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666) - if err != nil { - t.Fatalf("could not open or create file: '%s': %s", path, err) - } - } - - defer func() { - if err := file.Close(); err != nil { - t.Fatalf("could not close file: %s", err) - } - }() - defer func() { - if err := file.Sync(); err != nil { - t.Fatalf("could not sync file: %s", err) - } - }() - - var now string - if len(prefix) == 0 { - // If the length is different, e.g when there is no offset from UTC. - // add some padding so the length is predictable - now = time.Now().Format(time.RFC3339) - if len(now) != len(time.RFC3339) { - paddingNeeded := len(time.RFC3339) - len(now) - for i := 0; i < paddingNeeded; i++ { - now += "-" - } - } - } else { - now = strings.Join(prefix, "") - } - - for i := 0; i < count; i++ { - if _, err := fmt.Fprintf(file, "%s %13d\n", now, i); err != nil { - t.Fatalf("could not write line %d to file: %s", count+1, err) - } - } -} - -// AssertLinesInFile counts number of lines in the given file and asserts if it matches expected count -func AssertLinesInFile(t *testing.T, path string, count int) { +// WaitLineCountInFile counts number of lines in the given file and asserts if it matches expected count +func WaitLineCountInFile(t *testing.T, path string, count int) { t.Helper() var lines []byte var err error @@ -1093,6 +1174,17 @@ func (b *BeatProc) CountFileLines(glob string) int { return bytes.Count(data, []byte{'\n'}) } +func (b *BeatProc) WaitEventsInLogFile(events int, timeout time.Duration) { + msg := strings.Builder{} + + require.Eventually(b.t, func() bool { + msg.Reset() + got := b.CountFileLines(b.getEventLogFileGlob()) + fmt.Fprintf(&msg, "expecting %d events, got %d", events, got) + return events == got + }, timeout, 100*time.Millisecond, &msg) +} + // ConfigFilePath returns the config file path func (b *BeatProc) ConfigFilePath() string { return b.configFile @@ -1195,7 +1287,9 @@ func (b *BeatProc) WaitPublishedEvents(timeout time.Duration, events int) { // GetEventsFromFileOutput reads all events from file output. If n > 0, // then it reads up to n events. It assumes the filename // for the output is 'output' and 'path' is set to the TempDir. -func GetEventsFromFileOutput[E any](b *BeatProc, n int) []E { +// If waitForFile is true, it will GetEventsFromFileOutput wait up to 45 +// seconds for the file to appear. +func GetEventsFromFileOutput[E any](b *BeatProc, n int, waitForFile bool) []E { b.t.Helper() if n < 1 { @@ -1205,7 +1299,7 @@ func GetEventsFromFileOutput[E any](b *BeatProc, n int) []E { var events []E path := filepath.Join(b.TempDir(), "output-*.ndjson") - f := b.openGlobFile(path, true) + f := b.openGlobFile(path, waitForFile) scanner := bufio.NewScanner(f) for scanner.Scan() { diff --git a/libbeat/tests/integration/http_test.go b/libbeat/tests/integration/http_test.go index ccc156a4e19..24b8ba050d8 100644 --- a/libbeat/tests/integration/http_test.go +++ b/libbeat/tests/integration/http_test.go @@ -56,7 +56,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test", "-E", "http.enabled=true") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("Starting stats endpoint", 60*time.Second) + mockbeat.WaitLogsContains("Starting stats endpoint", 60*time.Second) time.Sleep(time.Second) r, err := http.Get("http://localhost:5066") //nolint:noctx // fine for tests @@ -89,7 +89,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test", "-E", "http.enabled=true") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("Starting stats endpoint", 60*time.Second) + mockbeat.WaitLogsContains("Starting stats endpoint", 60*time.Second) r, err := http.Get("http://localhost:5066/stats") //nolint:noctx // fine for tests require.NoError(t, err) @@ -123,7 +123,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test", "-E", "http.enabled=true") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("Starting stats endpoint", 60*time.Second) + mockbeat.WaitLogsContains("Starting stats endpoint", 60*time.Second) r, err := http.Get("http://localhost:5066/not-exist") //nolint:noctx // fine for tests require.NoError(t, err) @@ -146,7 +146,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test", "-E", "http.enabled=true") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("Starting stats endpoint", 60*time.Second) + mockbeat.WaitLogsContains("Starting stats endpoint", 60*time.Second) r, err := http.Get("http://localhost:5066/debug/pprof/") //nolint:noctx // fine for tests require.NoError(t, err) diff --git a/libbeat/tests/integration/kafka_test.go b/libbeat/tests/integration/kafka_test.go index 2dc12ae3d89..53c484dc85f 100644 --- a/libbeat/tests/integration/kafka_test.go +++ b/libbeat/tests/integration/kafka_test.go @@ -82,7 +82,7 @@ func TestKafkaOutputCanConnectAndPublish(t *testing.T) { // Wait for mockbeat to log that it successfully published a batch to Kafka. // This ensures that mockbeat received the expected produce response configured above. - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( `finished kafka batch`, 10*time.Second, "did not find finished batch log") @@ -120,7 +120,7 @@ func TestAuthorisationErrors(t *testing.T) { // Wait for mockbeat to log each of the errors. for _, err := range authErrors { t.Log("waiting for:", err) - mockbeat.WaitForLogs( + mockbeat.WaitLogsContains( fmt.Sprintf("Kafka (topic=test_topic): authorisation error: %s", err), 10*time.Second, "did not find error log: %s", err) diff --git a/libbeat/tests/integration/meta_test.go b/libbeat/tests/integration/meta_test.go index e4fc44afb4c..537f0341753 100644 --- a/libbeat/tests/integration/meta_test.go +++ b/libbeat/tests/integration/meta_test.go @@ -42,7 +42,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) _, err := os.Stat(mockbeat.TempDir() + "/data/meta.json") require.NoError(t, err) } @@ -62,7 +62,7 @@ output.console: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) stat, err := os.Stat(mockbeat.TempDir() + "/data/meta.json") require.NoError(t, err) require.Equal(t, stat.Mode().String(), "-rw-------") diff --git a/libbeat/tests/integration/template_test.go b/libbeat/tests/integration/template_test.go index 3dc30cbf430..dc216768b23 100644 --- a/libbeat/tests/integration/template_test.go +++ b/libbeat/tests/integration/template_test.go @@ -43,9 +43,9 @@ output: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(mockbeatConfigWithIndex) mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("setup.template.name and setup.template.pattern have to be set if index name is modified", 60*time.Second) } @@ -63,7 +63,7 @@ output: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) } // Test that beat stops in case elasticsearch index is modified and pattern not @@ -79,9 +79,9 @@ setup.template: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("setup.template.name and setup.template.pattern have to be set if index name is modified", 60*time.Second) } @@ -98,9 +98,9 @@ setup.template: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - procState, err := mockbeat.Process.Wait() - require.NoError(t, err, "error waiting for mockbeat to exit") - require.Equal(t, 1, procState.ExitCode(), "incorrect exit code") + err := mockbeat.Cmd.Wait() + require.Error(t, err, "mockbeat must exit with an error") + require.Equal(t, 1, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdErrContains("setup.template.name and setup.template.pattern have to be set if index name is modified", 60*time.Second) } @@ -122,7 +122,7 @@ setup.template: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) } // Test loading of json based template @@ -154,6 +154,7 @@ logging: // prepare the config pwd, err := os.Getwd() + require.NoError(t, err, "cannot get work directory") path := filepath.Join(pwd, "../files/template.json") esUrl := GetESURL(t, "http") user := esUrl.User.Username() @@ -164,11 +165,11 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) msg := "Loading json template from file" - mockbeat.WaitForLogs(msg, 60*time.Second) + mockbeat.WaitLogsContains(msg, 60*time.Second) msg = "Template with name \\\"bla\\\" loaded." - mockbeat.WaitForLogs(msg, 60*time.Second) + mockbeat.WaitLogsContains(msg, 60*time.Second) // check effective changes in ES indexURL, err := FormatIndexTemplateURL(t, esUrl, templateName) @@ -221,8 +222,8 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) - mockbeat.WaitForLogs("Template with name \\\"mockbeat-9.9.9\\\" loaded.", 20*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("Template with name \\\"mockbeat-9.9.9\\\" loaded.", 20*time.Second) require.Eventually(t, func() bool { return mockbeat.LogMatch("doBulkRequest: [[:digit:]]+ events have been sent") }, 20*time.Second, 100*time.Millisecond, "looking for PublishEvents") @@ -240,13 +241,13 @@ logging: refreshURL := FormatRefreshURL(t, esUrl) require.NoError(t, err) - status, body, err = HttpDo(t, http.MethodPost, refreshURL) + status, _, err = HttpDo(t, http.MethodPost, refreshURL) require.NoError(t, err) require.Equal(t, http.StatusOK, status, "incorrect http status") searchURL, err := FormatDataStreamSearchURL(t, esUrl, datastream) require.NoError(t, err) - status, body, err = HttpDo(t, http.MethodGet, searchURL) + _, body, err = HttpDo(t, http.MethodGet, searchURL) require.NoError(t, err) var results SearchResult err = json.Unmarshal(body, &results) @@ -294,13 +295,17 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start() - mockbeat.WaitForLogs("mockbeat start running.", 60*time.Second) + mockbeat.WaitLogsContains("mockbeat start running.", 60*time.Second) require.Eventually(t, func() bool { return mockbeat.LogMatch("doBulkRequest: [[:digit:]]+ events have been sent") }, 20*time.Second, 100*time.Millisecond, "looking for PublishEvents") u := fmt.Sprintf("%s/_index_template/%s", esUrl.String(), datastream) - r, _ := http.Get(u) + r, err := http.Get(u) //nolint:gosec,noctx // It's a test + if err != nil { + defer r.Body.Close() + } + require.NoError(t, err, "could not query the index template") require.Equal(t, 404, r.StatusCode, "incorrect status code") } @@ -348,9 +353,9 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), user, pass)) mockbeat.Start("setup", "--index-management") - procState, err := mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") // check template loaded status, body, err := HttpDo(t, http.MethodGet, templateURL) @@ -424,21 +429,19 @@ setup: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), user, pass)) mockbeat.Start("setup", "--index-management") - procState, err := mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") // check template didn't load - status, body, err := HttpDo(t, http.MethodGet, templateURL) + status, _, err := HttpDo(t, http.MethodGet, templateURL) require.NoError(t, err) require.Equal(t, http.StatusNotFound, status, "incorrect status code") - status, body, err = HttpDo(t, http.MethodGet, policyURL) + status, body, err := HttpDo(t, http.MethodGet, policyURL) require.NoError(t, err) require.Equal(t, http.StatusOK, status, "incorrect status code") - require.Truef(t, strings.Contains(string(body), "max_primary_shard_size\":\"50gb"), "primary shard not found in %s", string(body)) - require.Truef(t, strings.Contains(string(body), "max_age\":\"30d"), "max_age not found in %s", string(body)) } @@ -486,9 +489,9 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), user, pass)) mockbeat.Start("setup", "--index-management", "-E", "setup.ilm.enabled=false", "-E", "setup.template.settings.index.number_of_shards=2") - procState, err := mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") // check template loaded status, body, err := HttpDo(t, http.MethodGet, templateURL) @@ -541,9 +544,9 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(fmt.Sprintf(cfg, esURL.String(), user, pass)) mockbeat.Start("setup", "--index-management", "-E", "setup.ilm.enabled=false") - procState, err := mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") // check template loaded status, body, err := HttpDo(t, http.MethodGet, templateURL) @@ -562,14 +565,14 @@ logging: require.Truef(t, found, "data stream should be in: %v", r.IndexTemplates) // check policy not created - status, body, err = HttpDo(t, http.MethodGet, policyURL) + status, _, err = HttpDo(t, http.MethodGet, policyURL) require.NoError(t, err) require.Equalf(t, http.StatusNotFound, status, "incorrect status code for: %s", policyURL.String()) mockbeat.Start("setup", "--index-management", "-E", "setup.template.overwrite=false", "-E", "setup.template.settings.index.number_of_shards=2") - procState, err = mockbeat.Process.Wait() + err = mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") // check policy created status, body, err = HttpDo(t, http.MethodGet, policyURL) @@ -594,9 +597,9 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start("export", "template") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("mockbeat-9.9.9", 5*time.Second) } @@ -613,9 +616,9 @@ logging: mockbeat := NewBeat(t, "mockbeat", "../../libbeat.test") mockbeat.WriteConfigFile(cfg) mockbeat.Start("export", "template", "-E", "setup.template.enabled=false") - procState, err := mockbeat.Process.Wait() + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("mockbeat-9.9.9", 5*time.Second) } @@ -636,9 +639,10 @@ logging: }) mockbeat.WriteConfigFile(cfg) mockbeat.Start("export", "template", "--dir", mockbeat.TempDir()) - procState, err := mockbeat.Process.Wait() + + err := mockbeat.Cmd.Wait() require.NoError(t, err) - require.Equal(t, 0, procState.ExitCode(), "incorrect exit code") + require.Equal(t, 0, mockbeat.Cmd.ProcessState.ExitCode(), "incorrect exit code") mockbeat.WaitStdOutContains("Writing to", 5*time.Second) mockbeat.WaitFileContains(output, "mockbeat-9.9.9", 5*time.Second) } diff --git a/x-pack/filebeat/tests/integration/input_metrics_test.go b/x-pack/filebeat/tests/integration/input_metrics_test.go index ef96d845c2e..a78add4fa20 100644 --- a/x-pack/filebeat/tests/integration/input_metrics_test.go +++ b/x-pack/filebeat/tests/integration/input_metrics_test.go @@ -143,12 +143,12 @@ logging.level: debug filebeat.Start() // 4. Wait for Filebeat to start scanning for files - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf("A new file %s has been found", logFilePath), 30*time.Second, "Filebeat did not start looking for files to ingest") - filebeat.WaitForLogs( + filebeat.WaitLogsContains( fmt.Sprintf("End of file reached: %s; Backoff now.", logFilePath), 10*time.Second, "Filebeat did not close the file") diff --git a/x-pack/filebeat/tests/integration/registrydiagnostics_test.go b/x-pack/filebeat/tests/integration/registrydiagnostics_test.go index 121999455cf..d794c4eee37 100644 --- a/x-pack/filebeat/tests/integration/registrydiagnostics_test.go +++ b/x-pack/filebeat/tests/integration/registrydiagnostics_test.go @@ -30,7 +30,7 @@ import ( func TestFilestreamRegistryIsInDiagnostics(t *testing.T) { filebeat := NewFilebeat(t) logfile := filepath.Join(filebeat.TempDir(), "log.log") - integration.GenerateLogFile(t, logfile, 2, false) + integration.WriteLogFile(t, logfile, 2, false) input := proto.UnitExpected{ Id: "input-" + t.Name(), Type: proto.UnitType_INPUT, diff --git a/x-pack/metricbeat/tests/integration/setup_integration_test.go b/x-pack/metricbeat/tests/integration/setup_integration_test.go index f461f46ba62..89b389617f5 100644 --- a/x-pack/metricbeat/tests/integration/setup_integration_test.go +++ b/x-pack/metricbeat/tests/integration/setup_integration_test.go @@ -65,10 +65,11 @@ metricbeat.config.modules: "-E", "setup.kibana.port="+kURL.Port(), "-E", "output.elasticsearch.protocol=http", "-E", "output.elasticsearch.hosts=['"+esURL.String()+"']") - procState, err := metricbeat.Process.Wait() - require.NoError(t, err, "metricbeat setup failed") - require.Equalf(t, 0, procState.ExitCode(), - "metricbeat setup failed: incorrect exit code: %d", procState.ExitCode()) + + require.NoError(t, metricbeat.Cmd.Wait(), "metricbeat setup failed") + exitCode := metricbeat.Cmd.ProcessState.ExitCode() + require.Equalf(t, 0, exitCode, + "metricbeat setup failed: incorrect exit code: %d", exitCode) // generate an event with dynamically mapped fields fields := map[string]string{}