From aa0b787170cadb7c95f0f1c62e980af0d266c3a6 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sat, 27 Apr 2024 23:35:22 +1000 Subject: [PATCH 01/25] refactor: Extract a stdin-pattern predicate. --- internal/tailer/tail.go | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index e3264774b..bc8208cc1 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -50,6 +50,8 @@ type Tailer struct { initDone chan struct{} } +const stdinPattern = "-" + // Option configures a new Tailer. type Option interface { apply(*Tailer) error @@ -162,8 +164,8 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, return nil, err } } - // Guarantee all existing logs get tailed before we leave. Also necessary - // in case oneshot mode is active, the logs get read! + // Guarantee all existing remaining patterns get tailed before we leave. + // Also necessary in case oneshot mode is active, the logs get read! if err := t.PollLogPatterns(); err != nil { return nil, err } @@ -183,6 +185,7 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, <-t.ctx.Done() } t.wg.Wait() + glog.V(1).InfoContextf(ctx, "tailer finished") close(t.lines) }() return t, nil @@ -224,7 +227,7 @@ func (t *Tailer) AddPattern(pattern string) error { case "", "file": // Leave path alone; may contain globs } - if path != "-" { + if path != stdinPattern { path, err = filepath.Abs(path) if err != nil { glog.V(2).Infof("Couldn't canonicalize path %q: %s", u.Path, err) @@ -281,7 +284,7 @@ func (t *Tailer) TailPath(pathname string) error { return nil } logCount.Add(-1) // Removing the current entry before re-adding. - glog.V(2).Infof("Existing logstream is finished, creating a new one.") + glog.V(2).Infof("%q: Existing logstream is finished, creating a new one.", pathname) } l, err := logstream.New(t.ctx, &t.wg, t.logstreamPollWaker, pathname, t.lines, t.oneShot) if err != nil { @@ -369,10 +372,14 @@ func (t *Tailer) PollLogPatterns() error { t.globPatternsMu.RLock() defer t.globPatternsMu.RUnlock() for pattern := range t.globPatterns { - if pattern == "-" { + // Check for a stdin, and set up a one-pass-only tail, by removing it from the set. + if isStdinPattern(pattern) { + glog.V(2).Infof("%q is stdin", pattern) if err := t.TailPath(pattern); err != nil { glog.Info(err) } + delete(t.globPatterns, pattern) + continue } matches, err := filepath.Glob(pattern) if err != nil { @@ -423,3 +430,13 @@ func (t *Tailer) Poll() error { } return nil } + +func isStdinPattern(pattern string) bool { + if pattern == stdinPattern { + return true + } + if pattern == "/dev/stdin" { + return true + } + return false +} From 9188e91378ad3a284accdaa3a17c4219221e31f3 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 19:05:11 +1000 Subject: [PATCH 02/25] fix: Don't add stdin to the glob patterns. Save some work by only tailing it once at startup; if we glob it, then we have to check every time and we then end up having to also do the work in the logstream of handling the "already closed". --- internal/tailer/tail.go | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index bc8208cc1..2298f6789 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -227,7 +227,11 @@ func (t *Tailer) AddPattern(pattern string) error { case "", "file": // Leave path alone; may contain globs } - if path != stdinPattern { + if isStdinPattern(pattern) { + // stdin is not really a socket, but it is handled by this codepath and should not be in the globs. + glog.V(2).Infof("AddPattern(%v): is stdin", pattern) + return t.TailPath(pattern) + } else { path, err = filepath.Abs(path) if err != nil { glog.V(2).Infof("Couldn't canonicalize path %q: %s", u.Path, err) @@ -372,15 +376,6 @@ func (t *Tailer) PollLogPatterns() error { t.globPatternsMu.RLock() defer t.globPatternsMu.RUnlock() for pattern := range t.globPatterns { - // Check for a stdin, and set up a one-pass-only tail, by removing it from the set. - if isStdinPattern(pattern) { - glog.V(2).Infof("%q is stdin", pattern) - if err := t.TailPath(pattern); err != nil { - glog.Info(err) - } - delete(t.globPatterns, pattern) - continue - } matches, err := filepath.Glob(pattern) if err != nil { return err From 45d2de83f18f059db3d50f281268bf3dbfd75d1d Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 19:17:16 +1000 Subject: [PATCH 03/25] refactor: Extract `doPatternGlob` from `PollLogPatterns`. The work of globbing a single pattern is separate from iterating over all patterns, setting us up to start a goroutine per pattern instead of an iterator. Issue: #331 --- internal/tailer/tail.go | 41 +++++++++++++++++++++++++---------------- 1 file changed, 25 insertions(+), 16 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 2298f6789..7f083dcbd 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -376,24 +376,33 @@ func (t *Tailer) PollLogPatterns() error { t.globPatternsMu.RLock() defer t.globPatternsMu.RUnlock() for pattern := range t.globPatterns { - matches, err := filepath.Glob(pattern) - if err != nil { + if err := t.doPatternGlob(pattern); err != nil { return err } - glog.V(1).Infof("glob matches: %v", matches) - for _, pathname := range matches { - if t.Ignore(pathname) { - continue - } - absPath, err := filepath.Abs(pathname) - if err != nil { - glog.V(2).Infof("Couldn't get absolute path for %q: %s", pathname, err) - continue - } - glog.V(2).Infof("watched path is %q", absPath) - if err := t.TailPath(absPath); err != nil { - glog.Info(err) - } + } + return nil +} + +// doPatternGlob matches a glob-style pattern against the filesystem and issues +// a TailPath for any files that match. +func (t *Tailer) doPatternGlob(pattern string) error { + matches, err := filepath.Glob(pattern) + if err != nil { + return err + } + glog.V(1).Infof("glob matches: %v", matches) + for _, pathname := range matches { + if t.Ignore(pathname) { + continue + } + absPath, err := filepath.Abs(pathname) + if err != nil { + glog.V(2).Infof("Couldn't get absolute path for %q: %s", pathname, err) + continue + } + glog.V(2).Infof("watched path is %q", absPath) + if err := t.TailPath(absPath); err != nil { + glog.Info(err) } } return nil From 926ef7bf2f6205daebf7b4bfad3bbf7604f684f6 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 19:22:33 +1000 Subject: [PATCH 04/25] refactor: Store the log pattern poll waker in the Tailer struct. We would like to use this in per-pattern goroutines. Issue: #331 --- internal/tailer/tail.go | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 7f083dcbd..54bc8a424 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -33,9 +33,10 @@ type Tailer struct { wg sync.WaitGroup // Wait for our subroutines to finish lines chan<- *logline.LogLine - globPatternsMu sync.RWMutex // protects `globPatterns' - globPatterns map[string]struct{} // glob patterns to match newly created logs in dir paths against - ignoreRegexPattern *regexp.Regexp + logPatternPollWaker waker.Waker // Used to poll for new logs + globPatternsMu sync.RWMutex // protects `globPatterns' + globPatterns map[string]struct{} // glob patterns to match newly created logs in dir paths against + ignoreRegexPattern *regexp.Regexp socketPaths []string @@ -111,7 +112,8 @@ type logPatternPollWaker struct { } func (opt logPatternPollWaker) apply(t *Tailer) error { - t.StartLogPatternPollLoop(opt.Waker) + t.logPatternPollWaker = opt.Waker + t.StartLogPatternPollLoop() return nil } @@ -345,8 +347,8 @@ func (t *Tailer) StartStaleLogstreamExpirationLoop(waker waker.Waker) { } // StartLogPatternPollLoop runs a permanent goroutine to poll for new log files. -func (t *Tailer) StartLogPatternPollLoop(waker waker.Waker) { - if waker == nil { +func (t *Tailer) StartLogPatternPollLoop() { + if t.logPatternPollWaker == nil { glog.Info("Log pattern polling disabled") return } @@ -363,7 +365,7 @@ func (t *Tailer) StartLogPatternPollLoop(waker waker.Waker) { select { case <-t.ctx.Done(): return - case <-waker.Wake(): + case <-t.logPatternPollWaker.Wake(): if err := t.Poll(); err != nil { glog.Info(err) } From 76abfd9d2e586e629206194b5621a8aa23ca7d6b Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 20:03:55 +1000 Subject: [PATCH 05/25] chore: Appease linter, name struct fields. --- internal/mtail/examples_integration_unix_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/mtail/examples_integration_unix_test.go b/internal/mtail/examples_integration_unix_test.go index 4e5d7468f..bc93e91e0 100644 --- a/internal/mtail/examples_integration_unix_test.go +++ b/internal/mtail/examples_integration_unix_test.go @@ -149,7 +149,7 @@ func TestFileSocketStreamComparison(t *testing.T) { defer wg.Done() source, err := os.OpenFile(tc.logfile, os.O_RDONLY, 0) testutil.FatalIfErr(t, err) - s, err := net.DialUnix(scheme, nil, &net.UnixAddr{sockName, scheme}) + s, err := net.DialUnix(scheme, nil, &net.UnixAddr{Name: sockName, Net: scheme}) testutil.FatalIfErr(t, err) n, err := io.Copy(s, source) testutil.FatalIfErr(t, err) From 01db87788544122d67d2d32d40ea329b81da5213 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 21:33:13 +1000 Subject: [PATCH 06/25] chore: Make some log messages more useful for debugging. --- internal/tailer/tail.go | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 54bc8a424..81ab672d1 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -220,11 +220,12 @@ func (t *Tailer) AddPattern(pattern string) error { path := pattern switch u.Scheme { default: - glog.V(2).Infof("%v: %q in path pattern %q, treating as path", ErrUnsupportedURLScheme, u.Scheme, pattern) + glog.V(2).Infof("AddPattern(%v): %v in path pattern %q, treating as path", pattern, ErrUnsupportedURLScheme, u.Scheme) + // Leave path alone per log message case "unix", "unixgram", "tcp", "udp": // Keep the scheme. - glog.V(2).Infof("AddPattern: socket %q", pattern) - t.socketPaths = append(t.socketPaths, pattern) + glog.V(2).Infof("AddPattern(%v): is a socket", path) + t.socketPaths = append(t.socketPaths, path) return nil case "", "file": // Leave path alone; may contain globs @@ -236,11 +237,11 @@ func (t *Tailer) AddPattern(pattern string) error { } else { path, err = filepath.Abs(path) if err != nil { - glog.V(2).Infof("Couldn't canonicalize path %q: %s", u.Path, err) + glog.V(2).Infof("AddPattern(%v): couldn't canonicalize path: %v", path, err) return err } } - glog.V(2).Infof("AddPattern: file %q", path) + glog.V(2).Infof("AddPattern(%v): is a file-like pattern", path) t.globPatternsMu.Lock() t.globPatterns[path] = struct{}{} t.globPatternsMu.Unlock() From 7c233c4abe3202b22145de41326a6c59702ad9ea Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Wed, 8 May 2024 22:18:09 +1000 Subject: [PATCH 07/25] refactor: Immediately tail sockets when discovered. Instead of collecting sockets and tailing them after, just tail them straight away. This makes the "early exit" check for "no things" broken, so replace that with a check in the final shutdown handler that there were no active globs. This will be replaced in the next few changes once migrated to goroutines and we can use only the `WaitGroup` for counting globs, too, but in the meantime this is more correct than the previous code. Issue: #331 --- internal/tailer/tail.go | 39 ++++++++++++++------------------------- 1 file changed, 14 insertions(+), 25 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 81ab672d1..0c0054115 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -33,13 +33,13 @@ type Tailer struct { wg sync.WaitGroup // Wait for our subroutines to finish lines chan<- *logline.LogLine + logPatterns []string + logPatternPollWaker waker.Waker // Used to poll for new logs globPatternsMu sync.RWMutex // protects `globPatterns' globPatterns map[string]struct{} // glob patterns to match newly created logs in dir paths against ignoreRegexPattern *regexp.Regexp - socketPaths []string - oneShot logstream.OneShotMode pollMu sync.Mutex // protects Poll() @@ -73,11 +73,7 @@ var OneShot = &niladicOption{func(t *Tailer) error { t.oneShot = logstream.OneSh type LogPatterns []string func (opt LogPatterns) apply(t *Tailer) error { - for _, p := range opt { - if err := t.AddPattern(p); err != nil { - return err - } - } + t.logPatterns = opt return nil } @@ -155,14 +151,9 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, if err := t.SetOption(options...); err != nil { return nil, err } - if len(t.globPatterns) == 0 && len(t.socketPaths) == 0 { - glog.Info("No patterns or sockets to tail, tailer done.") - close(t.lines) - return t, nil - } - // Set up listeners on every socket. - for _, pattern := range t.socketPaths { - if err := t.TailPath(pattern); err != nil { + // After processing options, we can add patterns. We need to ensure any Wakers were provided. + for _, p := range t.logPatterns { + if err := t.AddPattern(p); err != nil { return nil, err } } @@ -176,14 +167,12 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, go func() { defer wg.Done() <-t.initDone - // We need to wait for context.Done() before we wait for the subbies - // because we don't know how many are running at any point -- as soon - // as t.wg.Wait begins the number of waited-on goroutines is fixed, and - // we may end up leaking a LogStream goroutine and it'll try to send on - // a closed channel as a result. But in tests and oneshot, we want to - // make sure the whole log gets read so we can't wait on context.Done - // here. - if !t.oneShot { + // If there are any patterns, we need to wait for an explicit context cancellation. + // We don't during oneshot mode though. + t.globPatternsMu.RLock() + l := len(t.globPatterns) + t.globPatternsMu.RUnlock() + if l > 0 && !t.oneShot { <-t.ctx.Done() } t.wg.Wait() @@ -212,6 +201,7 @@ var ErrUnsupportedURLScheme = errors.New("unsupported URL scheme") // AddPattern adds a pattern to the list of patterns to filter filenames against. func (t *Tailer) AddPattern(pattern string) error { + glog.V(2).Infof("AddPattern(%v)", pattern) u, err := url.Parse(pattern) if err != nil { return err @@ -225,8 +215,7 @@ func (t *Tailer) AddPattern(pattern string) error { case "unix", "unixgram", "tcp", "udp": // Keep the scheme. glog.V(2).Infof("AddPattern(%v): is a socket", path) - t.socketPaths = append(t.socketPaths, path) - return nil + return t.TailPath(path) case "", "file": // Leave path alone; may contain globs } From ae2de4226ea42c975ea2798a0d9b747bfad1e3fc Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Thu, 9 May 2024 00:48:38 +1000 Subject: [PATCH 08/25] test: Rename log rotation integration tests for clarity --- internal/mtail/log_rotation_integration_test.go | 2 +- internal/mtail/log_rotation_integration_unix_test.go | 11 ++++++----- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/internal/mtail/log_rotation_integration_test.go b/internal/mtail/log_rotation_integration_test.go index 790f2c28e..57285c3f7 100644 --- a/internal/mtail/log_rotation_integration_test.go +++ b/internal/mtail/log_rotation_integration_test.go @@ -15,7 +15,7 @@ import ( "github.com/google/mtail/internal/testutil" ) -func TestLogSoftLinkChange(t *testing.T) { +func TestLogRotationBySoftLinkChange(t *testing.T) { testutil.SkipIfShort(t) for _, tc := range []bool{false, true} { diff --git a/internal/mtail/log_rotation_integration_unix_test.go b/internal/mtail/log_rotation_integration_unix_test.go index dffe8f201..891cfd7bb 100644 --- a/internal/mtail/log_rotation_integration_unix_test.go +++ b/internal/mtail/log_rotation_integration_unix_test.go @@ -17,11 +17,12 @@ import ( "github.com/google/mtail/internal/testutil" ) -// TestLogRotation is a unix-specific test because on Windows, files cannot be removed -// or renamed while there is an open read handle on them. Instead, log rotation would -// have to be implemented by copying and then truncating the original file. That test -// case is already covered by TestLogTruncation. -func TestLogRotation(t *testing.T) { +// TestLogRotationByRename is a unix-specific test because on Windows, files +// cannot be removed or renamed while there is an open read handle on +// them. Instead, log rotation would have to be implemented by copying and then +// truncating the original file. That test case is already covered by +// TestLogTruncation. +func TestLogRotationByRename(t *testing.T) { testutil.SkipIfShort(t) for _, tc := range []bool{false, true} { From 2ec659683eec6a51055ba7d23dd654456b950df7 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Thu, 9 May 2024 03:41:13 +1000 Subject: [PATCH 09/25] refactor: Rename fields in preparation for other wakers in test. Restructure the testserver constructor. --- internal/mtail/testing.go | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 3fae6ad10..64e70d203 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -24,8 +24,8 @@ const defaultDoOrTimeoutDeadline = 10 * time.Second type TestServer struct { *Server - waker waker.Waker // for idle logstreams; others are polled explicitly in PollWatched - awaken func(int) + streamWaker waker.Waker // for idle logstreams; others are polled explicitly in PollWatched + awakenStreams func(int) // the stream awakens tb testing.TB @@ -52,13 +52,18 @@ func TestMakeServer(tb testing.TB, wakers int, options ...Option) *TestServer { expvar.Get("prog_loads_total").(*expvar.Map).Init() ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, wakers) + ts := &TestServer{ + tb: tb, + cancel: cancel, + } + ts.streamWaker, ts.awakenStreams = waker.NewTest(ctx, wakers) options = append(options, - LogstreamPollWaker(waker), + LogstreamPollWaker(ts.streamWaker), ) - m, err := New(ctx, metrics.NewStore(), options...) + var err error + ts.Server, err = New(ctx, metrics.NewStore(), options...) testutil.FatalIfErr(tb, err) - return &TestServer{Server: m, waker: waker, awaken: awaken, tb: tb, cancel: cancel} + return ts } // TestStartServer creates a new TestServer and starts it running. It @@ -109,7 +114,7 @@ func (ts *TestServer) PollWatched(n int) { glog.Info(err) } glog.Info("TestServer waking idle routines") - ts.awaken(n) + ts.awakenStreams(n) glog.Info("Testserver finishing poll") } From 4536f9da809023ef1c35a434268b7c8936325936 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Thu, 9 May 2024 04:41:23 +1000 Subject: [PATCH 10/25] test: Improve debug log messages for the TestWaker. --- internal/mtail/examples_integration_test.go | 4 +-- internal/mtail/testing.go | 2 +- .../tailer/logstream/dgramstream_unix_test.go | 4 +-- internal/tailer/logstream/filestream_test.go | 12 +++---- .../tailer/logstream/filestream_unix_test.go | 6 ++-- .../tailer/logstream/pipestream_unix_test.go | 4 +-- .../logstream/socketstream_unix_test.go | 4 +-- internal/tailer/tail_test.go | 2 +- internal/waker/testwaker.go | 32 ++++++++++++------- internal/waker/testwaker_test.go | 6 ++-- 10 files changed, 42 insertions(+), 34 deletions(-) diff --git a/internal/mtail/examples_integration_test.go b/internal/mtail/examples_integration_test.go index 4d0cc51cb..57c8bd23b 100644 --- a/internal/mtail/examples_integration_test.go +++ b/internal/mtail/examples_integration_test.go @@ -92,7 +92,7 @@ func TestExamplePrograms(t *testing.T) { t.Run(fmt.Sprintf("%s on %s", tc.programfile, tc.logfile), testutil.TimeoutTest(exampleTimeout, func(t *testing.T) { //nolint:thelper ctx, cancel := context.WithCancel(context.Background()) - waker, _ := waker.NewTest(ctx, 0) // oneshot means we should never need to wake the stream + waker, _ := waker.NewTest(ctx, 0, "waker") // oneshot means we should never need to wake the stream store := metrics.NewStore() programFile := filepath.Join("../..", tc.programfile) mtail, err := mtail.New(ctx, store, mtail.ProgramPath(programFile), mtail.LogPathPatterns(tc.logfile), mtail.OneShot, mtail.OmitMetricSource, mtail.DumpAstTypes, mtail.DumpBytecode, mtail.LogPatternPollWaker(waker), mtail.LogstreamPollWaker(waker)) @@ -155,7 +155,7 @@ func BenchmarkProgram(b *testing.B) { logFile := filepath.Join(logDir, "test.log") log := testutil.TestOpenFile(b, logFile) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "streams") store := metrics.NewStore() programFile := filepath.Join("../..", bm.programfile) mtail, err := mtail.New(ctx, store, mtail.ProgramPath(programFile), mtail.LogPathPatterns(log.Name()), mtail.LogstreamPollWaker(waker)) diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 64e70d203..6f5c4212a 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -56,7 +56,7 @@ func TestMakeServer(tb testing.TB, wakers int, options ...Option) *TestServer { tb: tb, cancel: cancel, } - ts.streamWaker, ts.awakenStreams = waker.NewTest(ctx, wakers) + ts.streamWaker, ts.awakenStreams = waker.NewTest(ctx, wakers, "streams") options = append(options, LogstreamPollWaker(ts.streamWaker), ) diff --git a/internal/tailer/logstream/dgramstream_unix_test.go b/internal/tailer/logstream/dgramstream_unix_test.go index f665eacec..f9a7dae60 100644 --- a/internal/tailer/logstream/dgramstream_unix_test.go +++ b/internal/tailer/logstream/dgramstream_unix_test.go @@ -40,7 +40,7 @@ func TestDgramStreamReadCompletedBecauseSocketClosed(t *testing.T) { } lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") sockName := scheme + "://" + addr ss, err := logstream.New(ctx, &wg, waker, sockName, lines, logstream.OneShotDisabled) @@ -97,7 +97,7 @@ func TestDgramStreamReadCompletedBecauseCancel(t *testing.T) { } lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") sockName := scheme + "://" + addr ss, err := logstream.New(ctx, &wg, waker, sockName, lines, logstream.OneShotDisabled) diff --git a/internal/tailer/logstream/filestream_test.go b/internal/tailer/logstream/filestream_test.go index 9e0eb1c06..6bc3011f9 100644 --- a/internal/tailer/logstream/filestream_test.go +++ b/internal/tailer/logstream/filestream_test.go @@ -26,7 +26,7 @@ func TestFileStreamRead(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) awaken(1) @@ -61,7 +61,7 @@ func TestFileStreamReadNonSingleByteEnd(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) awaken(1) @@ -102,7 +102,7 @@ func TestStreamDoesntBreakOnCorruptRune(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) awaken(1) @@ -148,7 +148,7 @@ func TestFileStreamTruncation(t *testing.T) { lines := make(chan *logline.LogLine, 3) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) // fs.Stop() is also called explicitly further down but a failed test // and early return would lead to the handle staying open @@ -195,7 +195,7 @@ func TestFileStreamFinishedBecauseCancel(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) @@ -230,7 +230,7 @@ func TestFileStreamPartialRead(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) diff --git a/internal/tailer/logstream/filestream_unix_test.go b/internal/tailer/logstream/filestream_unix_test.go index bf5a44196..a8bbb27b4 100644 --- a/internal/tailer/logstream/filestream_unix_test.go +++ b/internal/tailer/logstream/filestream_unix_test.go @@ -35,7 +35,7 @@ func TestFileStreamRotation(t *testing.T) { lines := make(chan *logline.LogLine, 2) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) // fs.Stop() is also called explicitly further down but a failed test @@ -87,7 +87,7 @@ func TestFileStreamURL(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, "file://"+name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) awaken(1) @@ -129,7 +129,7 @@ func TestFileStreamOpenFailure(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, _ := waker.NewTest(ctx, 0) + waker, _ := waker.NewTest(ctx, 0, "stream") _, err = logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) if err == nil || !os.IsPermission(err) { diff --git a/internal/tailer/logstream/pipestream_unix_test.go b/internal/tailer/logstream/pipestream_unix_test.go index 02efc38d5..21980c74b 100644 --- a/internal/tailer/logstream/pipestream_unix_test.go +++ b/internal/tailer/logstream/pipestream_unix_test.go @@ -77,7 +77,7 @@ func TestPipeStreamReadCompletedBecauseCancel(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") f, err := os.OpenFile(name, os.O_RDWR, os.ModeNamedPipe) testutil.FatalIfErr(t, err) @@ -160,7 +160,7 @@ func TestPipeStreamReadStdin(t *testing.T) { lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") ps, err := logstream.New(ctx, &wg, waker, "-", lines, logstream.OneShotDisabled) testutil.FatalIfErr(t, err) diff --git a/internal/tailer/logstream/socketstream_unix_test.go b/internal/tailer/logstream/socketstream_unix_test.go index 6f401c6f9..c43defb25 100644 --- a/internal/tailer/logstream/socketstream_unix_test.go +++ b/internal/tailer/logstream/socketstream_unix_test.go @@ -38,7 +38,7 @@ func TestSocketStreamReadCompletedBecauseSocketClosed(t *testing.T) { } lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") sockName := scheme + "://" + addr ss, err := logstream.New(ctx, &wg, waker, sockName, lines, logstream.OneShotDisabled) @@ -93,7 +93,7 @@ func TestSocketStreamReadCompletedBecauseCancel(t *testing.T) { } lines := make(chan *logline.LogLine, 1) ctx, cancel := context.WithCancel(context.Background()) - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "stream") sockName := scheme + "://" + addr ss, err := logstream.New(ctx, &wg, waker, sockName, lines, logstream.OneShotDisabled) diff --git a/internal/tailer/tail_test.go b/internal/tailer/tail_test.go index b70b4e227..64b631868 100644 --- a/internal/tailer/tail_test.go +++ b/internal/tailer/tail_test.go @@ -39,7 +39,7 @@ func makeTestTail(t *testing.T, options ...Option) *testTail { ctx, cancel := context.WithCancel(context.Background()) lines := make(chan *logline.LogLine, 5) // 5 loglines ought to be enough for any test var wg sync.WaitGroup - waker, awaken := waker.NewTest(ctx, 1) + waker, awaken := waker.NewTest(ctx, 1, "streams") options = append(options, LogPatterns([]string{tmpDir}), LogstreamPollWaker(waker)) ta, err := New(ctx, &wg, lines, options...) testutil.FatalIfErr(t, err) diff --git a/internal/waker/testwaker.go b/internal/waker/testwaker.go index ceaf313c3..4d90041f9 100644 --- a/internal/waker/testwaker.go +++ b/internal/waker/testwaker.go @@ -18,6 +18,8 @@ type testWaker struct { n int + name string + wakeeReady chan struct{} wakeeDone chan struct{} wait chan struct{} @@ -29,11 +31,14 @@ type testWaker struct { // WakeFunc describes a function used by tests to trigger a wakeup of blocked idle goroutines under test. It takes as first parameter the number of goroutines to await before returning to the caller. type WakeFunc func(int) -// NewTest creates a new Waker to be used in tests, returning it and a function to trigger a wakeup. The constructor parameter says how many wakees are expected in the first pass. -func NewTest(ctx context.Context, n int) (Waker, WakeFunc) { +// NewTest creates a new Waker to be used in tests, returning it and a function to trigger a wakeup. +// `n` says how many wakees are expected to be waiting before the first `wakeFunc` call. +// `name` gives it a name for debug log messages +func NewTest(ctx context.Context, n int, name string) (Waker, WakeFunc) { t := &testWaker{ ctx: ctx, n: n, + name: name, wakeeReady: make(chan struct{}), wakeeDone: make(chan struct{}), wait: make(chan struct{}), @@ -42,30 +47,33 @@ func NewTest(ctx context.Context, n int) (Waker, WakeFunc) { initDone := make(chan struct{}) go func() { defer close(initDone) + glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees", t.name, t.n) for i := 0; i < t.n; i++ { <-t.wakeeDone } }() - wakeFunc := func(after int) { + // awaken issues a wakeup signal to the "wakees", those clients who've used the `Wake` call. + awaken := func(after int) { <-initDone - glog.InfoDepth(1, "TestWaker yielding to Wakee") + glog.InfoDepthf(1, "TestWaker(%s) yielding to Wakee", t.name) for i := 0; i < t.n; i++ { t.wait <- struct{}{} } - glog.Infof("waiting for %d wakees to get the wake chan", t.n) + // First wait for `t.n` wakees to have called `Wake`, synchronising them. + glog.Infof("TestWaker(%s) waiting for %d wakees to get the wake chan", t.name, t.n) for i := 0; i < t.n; i++ { <-t.wakeeReady } t.broadcastWakeAndReset() - // Now wakeFunc blocks here - glog.Infof("waiting for %d wakees to return to Wake", after) + // Now `awaken` blocks here, as we wait for them in turn to return to another call to Wake, in their polling loops. We wait for only a count of `after` routines this time, as some may exit. + glog.Infof("TestWaker(%s) waiting for %d wakees to return to Wake", t.name, after) for i := 0; i < after; i++ { <-t.wakeeDone } t.n = after - glog.InfoDepth(1, "Wakee yielding to TestWaker") + glog.InfoDepthf(1, "TestWaker(%s): Wakee yielding to TestWaker", t.name) } - return t, wakeFunc + return t, awaken } // Wake satisfies the Waker interface. @@ -73,7 +81,7 @@ func (t *testWaker) Wake() (w <-chan struct{}) { t.mu.Lock() w = t.wake t.mu.Unlock() - glog.InfoDepth(1, "waiting for wakeup on chan ", w) + glog.InfoDepthf(1, "TestWaker(%s) waiting for wakeup on chan %p", t.name, w) // Background this so we can return the wake channel. // The wakeFunc won't close the channel until this completes. go func() { @@ -102,10 +110,10 @@ func (t *testWaker) Wake() (w <-chan struct{}) { func (t *testWaker) broadcastWakeAndReset() { t.mu.Lock() defer t.mu.Unlock() - glog.Infof("broadcasting wake to chan %p", t.wake) + glog.Infof("TestWaker(%s) broadcasting wake to chan %p", t.name, t.wake) close(t.wake) t.wake = make(chan struct{}) - glog.Info("wake channel reset") + glog.Infof("TestWaker(%s) wake channel reset", t.name) } // alwaysWaker never blocks the wakee. diff --git a/internal/waker/testwaker_test.go b/internal/waker/testwaker_test.go index 5afd4154c..5c949240c 100644 --- a/internal/waker/testwaker_test.go +++ b/internal/waker/testwaker_test.go @@ -14,7 +14,7 @@ import ( func TestTestWakerWakes(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - w, awaken := waker.NewTest(ctx, 1) + w, awaken := waker.NewTest(ctx, 1, "test") c := w.Wake() select { case x := <-c: @@ -33,7 +33,7 @@ func TestTestWakerWakes(t *testing.T) { func TestTestWakerTwoWakees(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - w, awaken := waker.NewTest(ctx, 2) + w, awaken := waker.NewTest(ctx, 2, "test") var wg1, wg2, wg3 sync.WaitGroup wg1.Add(1) wg2.Add(1) @@ -76,7 +76,7 @@ func TestTestWakerTwoWakees(t *testing.T) { func TestTestWakerTwoWakeups(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - w, awaken := waker.NewTest(ctx, 1) + w, awaken := waker.NewTest(ctx, 1, "test") s := make(chan struct{}) begin := make(chan struct{}) var wg sync.WaitGroup From 3fdefe4e7d1261e656994dffad29230a8ef32599 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Mon, 13 May 2024 19:39:21 +1000 Subject: [PATCH 11/25] test: Remove `LoadAllPrograms` from `TestServer.PollWatched`. We get greater control of what's being polled for by doing so. This also removes noise so in a few changes time I can clean up the log pattern poller. --- internal/mtail/prog_load_integration_test.go | 12 +++++------- internal/mtail/testing.go | 13 +++++++++---- 2 files changed, 14 insertions(+), 11 deletions(-) diff --git a/internal/mtail/prog_load_integration_test.go b/internal/mtail/prog_load_integration_test.go index 2c60ee93f..c22c1520c 100644 --- a/internal/mtail/prog_load_integration_test.go +++ b/internal/mtail/prog_load_integration_test.go @@ -31,8 +31,7 @@ func TestNewProg(t *testing.T) { f := testutil.TestOpenFile(t, progDir+"/nocode.mtail") defer f.Close() - // No logs get watched here. - m.PollWatched(0) + m.LoadAllPrograms() progLoadsTotalCheck() } @@ -60,7 +59,7 @@ func TestProgramReloadNoDuplicateMetrics(t *testing.T) { p := testutil.TestOpenFile(t, progpath) testutil.WriteString(t, p, "counter foo\n/^foo$/ {\n foo++\n }\n") testutil.FatalIfErr(t, p.Close()) - m.PollWatched(0) + m.LoadAllPrograms() progLoadsTotalCheck() @@ -75,7 +74,7 @@ func TestProgramReloadNoDuplicateMetrics(t *testing.T) { p = testutil.TestOpenFile(t, progpath) // opens in append mode testutil.WriteString(t, p, "#\n") // append just enough to change but still valid testutil.FatalIfErr(t, p.Close()) - m.PollWatched(1) + m.LoadAllPrograms() progLoadsTotalCheck() @@ -106,15 +105,14 @@ func TestProgramUnloadIfDeleted(t *testing.T) { p := testutil.TestOpenFile(t, progpath) testutil.WriteString(t, p, "counter foo\n/^foo$/ {\n foo++\n }\n") testutil.FatalIfErr(t, p.Close()) - m.PollWatched(0) + m.LoadAllPrograms() progLoadsTotalCheck() progUnloadsTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("prog_unloads_total", "program.mtail", 1) testutil.FatalIfErr(t, os.Remove(progpath)) - - m.PollWatched(1) + m.LoadAllPrograms() progUnloadsTotalCheck() } diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 6f5c4212a..99aafafe2 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -105,10 +105,6 @@ func (ts *TestServer) PollWatched(n int) { if err := ts.t.Poll(); err != nil { glog.Info(err) } - glog.Infof("TestServer reloading programs") - if err := ts.r.LoadAllPrograms(); err != nil { - glog.Info(err) - } glog.Infof("TestServer tailer gcing") if err := ts.t.ExpireStaleLogstreams(); err != nil { glog.Info(err) @@ -118,6 +114,15 @@ func (ts *TestServer) PollWatched(n int) { glog.Info("Testserver finishing poll") } +func (ts *TestServer) LoadAllPrograms() { + ts.tb.Helper() + glog.Infof("TestServer reloading programs") + if err := ts.r.LoadAllPrograms(); err != nil { + glog.Info(err) + ts.tb.Log(err) + } +} + // GetExpvar is a helper function on TestServer that acts like TestGetExpvar. func (ts *TestServer) GetExpvar(name string) expvar.Var { ts.tb.Helper() From 83bd57dbd08812b4851fecc4562bb0e3b59ec55e Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Mon, 13 May 2024 21:01:15 +1000 Subject: [PATCH 12/25] refactor: Extract a separate routine for polling for completed logstreams. This gives us greater control in test. --- internal/mtail/testing.go | 2 +- internal/tailer/tail.go | 37 ++++++++++++++++++++++++++++--------- 2 files changed, 29 insertions(+), 10 deletions(-) diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 99aafafe2..6c4674688 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -102,7 +102,7 @@ func (ts *TestServer) Start() func() { func (ts *TestServer) PollWatched(n int) { glog.Info("Testserver starting poll") glog.Infof("TestServer polling filesystem patterns") - if err := ts.t.Poll(); err != nil { + if err := ts.t.PollLogPatterns(); err != nil { glog.Info(err) } glog.Infof("TestServer tailer gcing") diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 0c0054115..19bab373b 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -162,6 +162,8 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, if err := t.PollLogPatterns(); err != nil { return nil, err } + // Start the routine for checking if logstreams have completed. + t.startPollLogStreamsForCompletion(ctx, wg) // Setup for shutdown, once all routines are finished. wg.Add(1) go func() { @@ -356,7 +358,7 @@ func (t *Tailer) StartLogPatternPollLoop() { case <-t.ctx.Done(): return case <-t.logPatternPollWaker.Wake(): - if err := t.Poll(); err != nil { + if err := t.PollLogPatterns(); err != nil { glog.Info(err) } } @@ -416,15 +418,32 @@ func (t *Tailer) PollLogStreamsForCompletion() error { return nil } -func (t *Tailer) Poll() error { - t.pollMu.Lock() - defer t.pollMu.Unlock() - for _, f := range []func() error{t.PollLogPatterns, t.PollLogStreamsForCompletion} { - if err := f(); err != nil { - return err - } +// StartPollLogStreamsForCompletion runs a permanent goroutine to poll for +// completed LogStreams. +func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync.WaitGroup) { + if t.logstreamPollWaker == nil { + glog.Info("Log completion polling disabled by no waker") + return } - return nil + wg.Add(1) + go func() { + defer wg.Done() + <-t.initDone + if t.oneShot { + glog.Info("No logstream completion polling loop in oneshot mode.") + return + } + for { + select { + case <-ctx.Done(): + return + case <-t.logstreamPollWaker.Wake(): + if err := t.PollLogStreamsForCompletion(); err != nil { + glog.Info(err) + } + } + } + }() } func isStdinPattern(pattern string) bool { From ff649a5f528656dcb0af91df04f5983794062efc Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Mon, 13 May 2024 21:11:31 +1000 Subject: [PATCH 13/25] test: Remove `ExpireStaleLogStreams` from test poll action. This has no effect on test behaviour. --- internal/mtail/testing.go | 4 ---- 1 file changed, 4 deletions(-) diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 6c4674688..83a80603e 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -105,10 +105,6 @@ func (ts *TestServer) PollWatched(n int) { if err := ts.t.PollLogPatterns(); err != nil { glog.Info(err) } - glog.Infof("TestServer tailer gcing") - if err := ts.t.ExpireStaleLogstreams(); err != nil { - glog.Info(err) - } glog.Info("TestServer waking idle routines") ts.awakenStreams(n) glog.Info("Testserver finishing poll") From dd11ff8948bd67caae273daf591f5455e2f546bb Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Mon, 13 May 2024 21:54:53 +1000 Subject: [PATCH 14/25] test: Extract `AwakenLogStreams` from `PollWatched` and rename the latter. We now can explicitly control these two events, making the tests faster. Update the test tail comment explaining what the waker count parameters do; I keep forgetting, this hint helps! --- internal/mtail/basic_tail_integration_test.go | 11 +-- internal/mtail/examples_integration_test.go | 2 +- .../log_deletion_integration_unix_test.go | 10 ++- internal/mtail/log_glob_integration_test.go | 34 +++++---- .../mtail/log_rotation_integration_test.go | 29 +++++--- .../log_rotation_integration_unix_test.go | 22 +++--- .../mtail/log_truncation_integration_test.go | 15 ++-- ...tiple_levels_directory_integration_test.go | 7 +- .../mtail/multiple_lines_integration_test.go | 9 ++- .../mtail/partial_line_integration_test.go | 13 +++- ...permission_denied_integration_unix_test.go | 9 ++- internal/mtail/prog_load_integration_test.go | 8 +- .../mtail/read_pipe_integration_unix_test.go | 11 +-- .../relative_path_pattern_integration_test.go | 7 +- internal/mtail/testing.go | 42 ++++++----- .../unix_socket_export_integration_test.go | 2 +- .../tailer/logstream/dgramstream_unix_test.go | 4 +- internal/tailer/logstream/filestream_test.go | 30 ++++---- .../tailer/logstream/filestream_unix_test.go | 12 +-- .../tailer/logstream/pipestream_unix_test.go | 4 +- .../logstream/socketstream_unix_test.go | 4 +- internal/tailer/tail_test.go | 73 ++++++++++--------- internal/tailer/tail_unix_test.go | 18 ++--- internal/waker/testwaker.go | 53 ++++++++------ internal/waker/testwaker_test.go | 8 +- 25 files changed, 243 insertions(+), 194 deletions(-) diff --git a/internal/mtail/basic_tail_integration_test.go b/internal/mtail/basic_tail_integration_test.go index b735e3c6b..21dc9094b 100644 --- a/internal/mtail/basic_tail_integration_test.go +++ b/internal/mtail/basic_tail_integration_test.go @@ -21,7 +21,7 @@ func TestBasicTail(t *testing.T) { } logDir := testutil.TestTempDir(t) - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) defer stopM() logFile := filepath.Join(logDir, "log") @@ -31,12 +31,13 @@ func TestBasicTail(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(1) // Force sync to EOF + m.AwakenPatternPollers(1, 1) // Find `logFile` + m.AwakenLogStreams(1, 1) // Force a sync to EOF for i := 1; i <= 3; i++ { testutil.WriteString(t, f, fmt.Sprintf("%d\n", i)) } - m.PollWatched(1) // Expect to read 3 lines here. + m.AwakenLogStreams(1, 1) // Expect to read 3 lines here. var wg sync.WaitGroup wg.Add(2) @@ -57,7 +58,7 @@ func TestNewLogDoesNotMatchIsIgnored(t *testing.T) { // Start mtail logFilepath := filepath.Join(workdir, "log") - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(logFilepath)) + m, stopM := mtail.TestStartServer(t, 1, 0, mtail.LogPathPatterns(logFilepath)) defer stopM() logCountCheck := m.ExpectExpvarDeltaWithDeadline("log_count", 0) @@ -68,7 +69,7 @@ func TestNewLogDoesNotMatchIsIgnored(t *testing.T) { logFile, err := os.Create(newLogFilepath) testutil.FatalIfErr(t, err) defer logFile.Close() - m.PollWatched(0) // No streams so don't wait for any. + // No streams so don't wait for any. logCountCheck() } diff --git a/internal/mtail/examples_integration_test.go b/internal/mtail/examples_integration_test.go index 57c8bd23b..3dca5fd94 100644 --- a/internal/mtail/examples_integration_test.go +++ b/internal/mtail/examples_integration_test.go @@ -176,7 +176,7 @@ func BenchmarkProgram(b *testing.B) { count, err := io.Copy(log, l) testutil.FatalIfErr(b, err) total += count - awaken(1) + awaken(1, 1) } cancel() wg.Wait() diff --git a/internal/mtail/log_deletion_integration_unix_test.go b/internal/mtail/log_deletion_integration_unix_test.go index 9930f064f..dea2574b8 100644 --- a/internal/mtail/log_deletion_integration_unix_test.go +++ b/internal/mtail/log_deletion_integration_unix_test.go @@ -25,18 +25,20 @@ func TestLogDeletion(t *testing.T) { logFile := testutil.TestOpenFile(t, logFilepath) defer logFile.Close() - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(logFilepath)) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logFilepath)) defer stopM() logCloseCheck := m.ExpectMapExpvarDeltaWithDeadline("log_closes_total", logFilepath, 1) logCountCheck := m.ExpectExpvarDeltaWithDeadline("log_count", -1) - m.PollWatched(1) // Force sync to EOF + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) // Force read to EOF + glog.Info("remove") testutil.FatalIfErr(t, os.Remove(logFilepath)) - m.PollWatched(0) // one pass to stop + m.AwakenLogStreams(1, 1) // run stream to observe it's missing logCloseCheck() - m.PollWatched(0) // one pass to remove completed stream + m.AwakenLogStreams(1, 1) logCountCheck() } diff --git a/internal/mtail/log_glob_integration_test.go b/internal/mtail/log_glob_integration_test.go index ba8cd60bc..42f104522 100644 --- a/internal/mtail/log_glob_integration_test.go +++ b/internal/mtail/log_glob_integration_test.go @@ -45,7 +45,7 @@ func TestGlobBeforeStart(t *testing.T) { testutil.WriteString(t, log, "\n") log.Close() } - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*"))) + m, stopM := mtail.TestStartServer(t, 0, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*"))) stopM() if r := m.GetExpvar("log_count"); r.(*expvar.Int).Value() != count { @@ -75,10 +75,10 @@ func TestGlobAfterStart(t *testing.T) { false, }, } - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*"))) + m, stopM := mtail.TestStartServer(t, 1, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*"))) defer stopM() - m.PollWatched(0) // Force sync to EOF + m.AwakenPatternPollers(1, 1) var count int64 for _, tt := range globTests { @@ -90,9 +90,9 @@ func TestGlobAfterStart(t *testing.T) { for _, tt := range globTests { log := testutil.TestOpenFile(t, tt.name) defer log.Close() - m.PollWatched(0) // Force sync to EOF + m.AwakenPatternPollers(1, 1) + //m.AwakenLogStreams(0, 1) // wait for zero, wake 1 as we're in a loop } - // m.PollWatched(2) logCountCheck() } @@ -142,7 +142,7 @@ func TestGlobIgnoreFolder(t *testing.T) { testutil.WriteString(t, log, "\n") } - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*")), mtail.IgnoreRegexPattern("\\.gz")) + m, stopM := mtail.TestStartServer(t, 0, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*")), mtail.IgnoreRegexPattern("\\.gz")) stopM() @@ -184,7 +184,7 @@ func TestFilenameRegexIgnore(t *testing.T) { testutil.WriteString(t, log, "\n") } - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*")), mtail.IgnoreRegexPattern("\\.gz")) + m, stopM := mtail.TestStartServer(t, 0, 0, mtail.LogPathPatterns(filepath.Join(workdir, "log*")), mtail.IgnoreRegexPattern("\\.gz")) stopM() @@ -207,7 +207,7 @@ func TestGlobRelativeAfterStart(t *testing.T) { // Move to logdir to make relative paths testutil.Chdir(t, logDir) - m, stopM := mtail.TestStartServer(t, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns("log.*")) + m, stopM := mtail.TestStartServer(t, 1, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns("log.*")) defer stopM() { @@ -217,9 +217,11 @@ func TestGlobRelativeAfterStart(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(1) // Force sync to EOF + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(0, 1) // Force read to EOF + testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) logCountCheck() } @@ -232,9 +234,11 @@ func TestGlobRelativeAfterStart(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(2) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 2) // Force read to EOF + testutil.WriteString(t, f, "line 1\n") - m.PollWatched(2) + m.AwakenLogStreams(2, 2) logCountCheck() } @@ -245,9 +249,11 @@ func TestGlobRelativeAfterStart(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(2) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(2, 2) // Force read to EOF + testutil.WriteString(t, f, "line 2\n") - m.PollWatched(2) + m.AwakenLogStreams(2, 2) logCountCheck() } diff --git a/internal/mtail/log_rotation_integration_test.go b/internal/mtail/log_rotation_integration_test.go index 57285c3f7..f762ed64c 100644 --- a/internal/mtail/log_rotation_integration_test.go +++ b/internal/mtail/log_rotation_integration_test.go @@ -29,7 +29,7 @@ func TestLogRotationBySoftLinkChange(t *testing.T) { logFilepath := filepath.Join(workdir, "log") - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(logFilepath)) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logFilepath)) defer stopM() logCountCheck := m.ExpectExpvarDeltaWithDeadline("log_count", 1) @@ -40,33 +40,42 @@ func TestLogRotationBySoftLinkChange(t *testing.T) { testutil.FatalIfErr(t, os.Symlink(logFilepath+".true1", logFilepath)) glog.Info("symlinked") - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) inputLines := []string{"hi1", "hi2", "hi3"} for _, x := range inputLines { testutil.WriteString(t, trueLog1, x+"\n") } - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) trueLog2 := testutil.TestOpenFile(t, logFilepath+".true2") defer trueLog2.Close() - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) logClosedCheck := m.ExpectMapExpvarDeltaWithDeadline("log_closes_total", logFilepath, 1) logCompletedCheck := m.ExpectExpvarDeltaWithDeadline("log_count", -1) testutil.FatalIfErr(t, os.Remove(logFilepath)) if tc { - m.PollWatched(0) // simulate race condition with this poll. - logClosedCheck() // sync when filestream closes fd - m.PollWatched(0) // invoke the GC - logCompletedCheck() // sync to when the logstream is removed from tailer + // Simulate a race where we poll for a pattern and remove the + // existing stream. + m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. + m.AwakenLogStreams(1, 1) + logClosedCheck() // barrier until filestream closes fd + m.AwakenLogStreams(1, 1) + + logCompletedCheck() // barrier until the logstream is removed from tailer } testutil.FatalIfErr(t, os.Symlink(logFilepath+".true2", logFilepath)) - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) for _, x := range inputLines { testutil.WriteString(t, trueLog2, x+"\n") } - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) var wg sync.WaitGroup wg.Add(2) diff --git a/internal/mtail/log_rotation_integration_unix_test.go b/internal/mtail/log_rotation_integration_unix_test.go index 891cfd7bb..c5c493d65 100644 --- a/internal/mtail/log_rotation_integration_unix_test.go +++ b/internal/mtail/log_rotation_integration_unix_test.go @@ -46,17 +46,17 @@ func TestLogRotationByRename(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m, stopM := mtail.TestStartServer(t, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) defer stopM() logOpensTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("log_opens_total", logFile, 1) logLinesTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("log_lines_total", logFile, 3) testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) testutil.WriteString(t, f, "line 2\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) logClosedCheck := m.ExpectMapExpvarDeltaWithDeadline("log_closes_total", logFile, 1) logCompletedCheck := m.ExpectExpvarDeltaWithDeadline("log_count", -1) @@ -64,16 +64,20 @@ func TestLogRotationByRename(t *testing.T) { err = os.Rename(logFile, logFile+".1") testutil.FatalIfErr(t, err) if tc { - m.PollWatched(0) // simulate race condition with this poll. - logClosedCheck() // sync when filestream closes fd - m.PollWatched(0) // invoke the GC - logCompletedCheck() // sync to when the logstream is removed from tailer + // Simulate a race where we poll for a pattern and remove the + // existing stream. + m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. + m.AwakenLogStreams(1, 1) + logClosedCheck() // barrier until filestream closes fd + m.AwakenLogStreams(1, 1) // invoke the GC + logCompletedCheck() // barrier until logstream is removed from tailer } glog.Info("create") f = testutil.TestOpenFile(t, logFile) - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) var wg sync.WaitGroup wg.Add(2) diff --git a/internal/mtail/log_truncation_integration_test.go b/internal/mtail/log_truncation_integration_test.go index 186e278a2..3665e99ec 100644 --- a/internal/mtail/log_truncation_integration_test.go +++ b/internal/mtail/log_truncation_integration_test.go @@ -22,7 +22,7 @@ func TestLogTruncation(t *testing.T) { testutil.FatalIfErr(t, os.Mkdir(logDir, 0o700)) testutil.FatalIfErr(t, os.Mkdir(progDir, 0o700)) - m, stopM := mtail.TestStartServer(t, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) defer stopM() logCountCheck := m.ExpectExpvarDeltaWithDeadline("log_count", 1) @@ -31,15 +31,16 @@ func TestLogTruncation(t *testing.T) { logFile := filepath.Join(logDir, "log") f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) // Read to EOF testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) // After the last barrier, the filestream may not race ahead of the test // here, so we need to ensure that a whole filestream loop occurs and that // the file offset advances for this test to succeed, hence the second // barrier here. - m.PollWatched(1) + m.AwakenLogStreams(1, 1) err := f.Close() testutil.FatalIfErr(t, err) @@ -48,10 +49,12 @@ func TestLogTruncation(t *testing.T) { f, err = os.OpenFile(logFile, os.O_TRUNC|os.O_WRONLY, 0o600) testutil.FatalIfErr(t, err) defer f.Close() - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) testutil.WriteString(t, f, "2\n") - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) linesCountCheck() logCountCheck() diff --git a/internal/mtail/multiple_levels_directory_integration_test.go b/internal/mtail/multiple_levels_directory_integration_test.go index 64953a699..416010404 100644 --- a/internal/mtail/multiple_levels_directory_integration_test.go +++ b/internal/mtail/multiple_levels_directory_integration_test.go @@ -20,7 +20,7 @@ func TestPollLogPathPatterns(t *testing.T) { testutil.FatalIfErr(t, os.Mkdir(logDir, 0o700)) testutil.Chdir(t, logDir) - m, stopM := mtail.TestStartServer(t, 0, mtail.LogPathPatterns(logDir+"/files/*/log/*log")) + m, stopM := mtail.TestStartServer(t, 1, 0, mtail.LogPathPatterns(logDir+"/files/*/log/*log")) defer stopM() logCountCheck := m.ExpectExpvarDeltaWithDeadline("log_count", 1) @@ -31,11 +31,12 @@ func TestPollLogPathPatterns(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(0, 1) logCountCheck() testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) lineCountCheck() } diff --git a/internal/mtail/multiple_lines_integration_test.go b/internal/mtail/multiple_lines_integration_test.go index fcb85efec..f3e3528e3 100644 --- a/internal/mtail/multiple_lines_integration_test.go +++ b/internal/mtail/multiple_lines_integration_test.go @@ -29,17 +29,18 @@ func TestMultipleLinesInOneWrite(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m, stopM := mtail.TestStartServer(t, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) defer stopM() - m.PollWatched(1) // Force sync to EOF + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) // Force read to EOF { lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", 1) n, err := f.WriteString("line 1\n") testutil.FatalIfErr(t, err) glog.Infof("Wrote %d bytes", n) - m.PollWatched(1) + m.AwakenLogStreams(1, 1) lineCountCheck() } @@ -48,7 +49,7 @@ func TestMultipleLinesInOneWrite(t *testing.T) { n, err := f.WriteString("line 2\nline 3\n") testutil.FatalIfErr(t, err) glog.Infof("Wrote %d bytes", n) - m.PollWatched(1) + m.AwakenLogStreams(1, 1) lineCountCheck() } } diff --git a/internal/mtail/partial_line_integration_test.go b/internal/mtail/partial_line_integration_test.go index 7e9e8d563..b35a4f921 100644 --- a/internal/mtail/partial_line_integration_test.go +++ b/internal/mtail/partial_line_integration_test.go @@ -29,19 +29,24 @@ func TestPartialLineRead(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m, stopM := mtail.TestStartServer(t, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) defer stopM() + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) // Force read to EOF lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", 2) testutil.WriteString(t, f, "line 1\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) testutil.WriteString(t, f, "line ") - m.PollWatched(1) + // TODO: These PollLogPatterns should be unnecessary, but here are load-bearing. + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) testutil.WriteString(t, f, "2\n") - m.PollWatched(1) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) lineCountCheck() } diff --git a/internal/mtail/permission_denied_integration_unix_test.go b/internal/mtail/permission_denied_integration_unix_test.go index 12e0bee92..a7e2fcfca 100644 --- a/internal/mtail/permission_denied_integration_unix_test.go +++ b/internal/mtail/permission_denied_integration_unix_test.go @@ -14,8 +14,9 @@ import ( "github.com/google/mtail/internal/testutil" ) -// TestPermissionDeniedOnLog is a unix-specific test because on Windows, it is not possible to create a file -// that you yourself cannot read (minimum permissions are 0222). +// TestPermissionDeniedOnLog is a unix-specific test because on Windows, it is +// not possible to create a file that you yourself cannot read; there the +// minimum permissions are 0222. func TestPermissionDeniedOnLog(t *testing.T) { testutil.SkipIfShort(t) // Can't force a permission denied error if run as root. @@ -35,7 +36,7 @@ func TestPermissionDeniedOnLog(t *testing.T) { // Hide the error from stdout during test. testutil.SetFlag(t, "stderrthreshold", "FATAL") - m, stopM := mtail.TestStartServer(t, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) + m, stopM := mtail.TestStartServer(t, 1, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/log")) defer stopM() errorsTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("log_errors_total", logFile, 1) @@ -46,7 +47,7 @@ func TestPermissionDeniedOnLog(t *testing.T) { // Nothing to await on, we expect to get a Permission Denied in the // synchronous logstream.New path. - m.PollWatched(0) + m.AwakenPatternPollers(1, 1) errorsTotalCheck() } diff --git a/internal/mtail/prog_load_integration_test.go b/internal/mtail/prog_load_integration_test.go index c22c1520c..d5ebb55fd 100644 --- a/internal/mtail/prog_load_integration_test.go +++ b/internal/mtail/prog_load_integration_test.go @@ -24,7 +24,7 @@ func TestNewProg(t *testing.T) { err = os.Mkdir(progDir, 0o700) testutil.FatalIfErr(t, err) - m, stopM := mtail.TestStartServer(t, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) + m, stopM := mtail.TestStartServer(t, 0, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) defer stopM() progLoadsTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("prog_loads_total", "nocode.mtail", 1) @@ -50,7 +50,7 @@ func TestProgramReloadNoDuplicateMetrics(t *testing.T) { logFile := testutil.TestOpenFile(t, logFilepath) defer logFile.Close() - m, stopM := mtail.TestStartServer(t, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) defer stopM() progLoadsTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("prog_loads_total", "program.mtail", 1) @@ -66,7 +66,7 @@ func TestProgramReloadNoDuplicateMetrics(t *testing.T) { fooIncreaseCheck := m.ExpectProgMetricDeltaWithDeadline("foo", "program.mtail", 1) testutil.WriteString(t, logFile, "foo\n") - m.PollWatched(1) + m.AwakenLogStreams(1, 1) fooIncreaseCheck() progLoadsTotalCheck = m.ExpectMapExpvarDeltaWithDeadline("prog_loads_total", "program.mtail", 1) @@ -96,7 +96,7 @@ func TestProgramUnloadIfDeleted(t *testing.T) { logFile := testutil.TestOpenFile(t, logFilepath) defer logFile.Close() - m, stopM := mtail.TestStartServer(t, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) + m, stopM := mtail.TestStartServer(t, 0, 0, mtail.ProgramPath(progDir), mtail.LogPathPatterns(logDir+"/*")) defer stopM() progLoadsTotalCheck := m.ExpectMapExpvarDeltaWithDeadline("prog_loads_total", "program.mtail", 1) diff --git a/internal/mtail/read_pipe_integration_unix_test.go b/internal/mtail/read_pipe_integration_unix_test.go index a174f649a..cbed73a42 100644 --- a/internal/mtail/read_pipe_integration_unix_test.go +++ b/internal/mtail/read_pipe_integration_unix_test.go @@ -39,13 +39,13 @@ func TestReadFromPipe(t *testing.T) { testutil.FatalIfErr(t, f.Close()) }() - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath(progDir)) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath(progDir)) defer stopM() lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", 3) testutil.WriteString(t, f, "1\n2\n3\n") - m.PollWatched(0) + m.AwakenPatternPollers(1, 1) lineCountCheck() } @@ -66,13 +66,13 @@ func TestReadFromSocket(t *testing.T) { logFile := filepath.Join(logDir, "sock") - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(scheme+"://"+logDir+"/sock"), mtail.ProgramPath(progDir)) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(scheme+"://"+logDir+"/sock"), mtail.ProgramPath(progDir)) defer stopM() lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", 3) time.Sleep(10 * time.Millisecond) - s, err := net.DialUnix(scheme, nil, &net.UnixAddr{logFile, scheme}) + s, err := net.DialUnix(scheme, nil, &net.UnixAddr{Name: logFile, Net: scheme}) testutil.FatalIfErr(t, err) defer func() { testutil.FatalIfErr(t, s.Close()) @@ -81,7 +81,8 @@ func TestReadFromSocket(t *testing.T) { _, err = s.Write([]byte("1\n2\n3\n")) testutil.FatalIfErr(t, err) - m.PollWatched(0) + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) lineCountCheck() }) diff --git a/internal/mtail/relative_path_pattern_integration_test.go b/internal/mtail/relative_path_pattern_integration_test.go index c09109c7c..0b972af51 100644 --- a/internal/mtail/relative_path_pattern_integration_test.go +++ b/internal/mtail/relative_path_pattern_integration_test.go @@ -32,10 +32,11 @@ func TestRelativeLog(t *testing.T) { testutil.FatalIfErr(t, err) defer logFile.Close() pathnames := []string{"log"} - m, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(pathnames...)) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(pathnames...)) defer stopM() - m.PollWatched(1) // Force sync to EOF + m.AwakenPatternPollers(1, 1) + m.AwakenLogStreams(1, 1) // Force read to EOF inputLines := []string{"hi", "hi2", "hi3"} lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", int64(len(inputLines))) @@ -44,7 +45,7 @@ func TestRelativeLog(t *testing.T) { // write to log file testutil.WriteString(t, logFile, x+"\n") } - m.PollWatched(1) + m.AwakenLogStreams(1, 1) lineCountCheck() } diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index 83a80603e..edd70f2c5 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -24,8 +24,15 @@ const defaultDoOrTimeoutDeadline = 10 * time.Second type TestServer struct { *Server - streamWaker waker.Waker // for idle logstreams; others are polled explicitly in PollWatched - awakenStreams func(int) // the stream awakens + streamWaker waker.Waker // for idle logstreams; others are polled explicitly in PollWatched + // AwakenLogStreams wakes n log streams. This acts as a barrier method, + // synchronising the logstreams and the test. + AwakenLogStreams waker.WakeFunc + + patternWaker waker.Waker // polling for new glob pattern matches + // AwakenPatternPollers wakes n pattern pollers. This acts as a barrier + // method, synchronising the pattern poll with the test. + AwakenPatternPollers waker.WakeFunc // the glob awakens tb testing.TB @@ -37,7 +44,7 @@ type TestServer struct { // TestMakeServer makes a new TestServer for use in tests, but does not start // the server. If an error occurs during creation, a testing.Fatal is issued. -func TestMakeServer(tb testing.TB, wakers int, options ...Option) *TestServer { +func TestMakeServer(tb testing.TB, patternWakers int, streamWakers int, options ...Option) *TestServer { tb.Helper() // Reset counters when running multiple tests. Tests that use expvar @@ -56,9 +63,11 @@ func TestMakeServer(tb testing.TB, wakers int, options ...Option) *TestServer { tb: tb, cancel: cancel, } - ts.streamWaker, ts.awakenStreams = waker.NewTest(ctx, wakers, "streams") + ts.streamWaker, ts.AwakenLogStreams = waker.NewTest(ctx, streamWakers, "streams") + ts.patternWaker, ts.AwakenPatternPollers = waker.NewTest(ctx, patternWakers, "patterns") options = append(options, LogstreamPollWaker(ts.streamWaker), + LogPatternPollWaker(ts.patternWaker), ) var err error ts.Server, err = New(ctx, metrics.NewStore(), options...) @@ -66,11 +75,16 @@ func TestMakeServer(tb testing.TB, wakers int, options ...Option) *TestServer { return ts } -// TestStartServer creates a new TestServer and starts it running. It -// returns the server, and a stop function. -func TestStartServer(tb testing.TB, wakers int, options ...Option) (*TestServer, func()) { +// TestStartServer creates a new TestServer and starts it running. It returns +// the server, and a stop function. `patternWakers` indicates the number of +// expected pattern wakers to wait for at this moment; usually 1 because the +// test server is started with a `LogPathPattern`. `streamWakers` indiecates +// the number of expected stream wakers to wait for at this moment. The value +// of this parameter shuld be the number of log files created in test +// (e.g. with `testutil.TestOpenFile`) before invoking this function. +func TestStartServer(tb testing.TB, patternWakers int, streamWakers int, options ...Option) (*TestServer, func()) { tb.Helper() - ts := TestMakeServer(tb, wakers, options...) + ts := TestMakeServer(tb, patternWakers, streamWakers, options...) return ts, ts.Start() } @@ -98,18 +112,6 @@ func (ts *TestServer) Start() func() { } } -// Poll all watched objects for updates. The parameter n indicates how many logstreams to wait on before waking them. -func (ts *TestServer) PollWatched(n int) { - glog.Info("Testserver starting poll") - glog.Infof("TestServer polling filesystem patterns") - if err := ts.t.PollLogPatterns(); err != nil { - glog.Info(err) - } - glog.Info("TestServer waking idle routines") - ts.awakenStreams(n) - glog.Info("Testserver finishing poll") -} - func (ts *TestServer) LoadAllPrograms() { ts.tb.Helper() glog.Infof("TestServer reloading programs") diff --git a/internal/mtail/unix_socket_export_integration_test.go b/internal/mtail/unix_socket_export_integration_test.go index cfadf159d..1a71ba8f4 100644 --- a/internal/mtail/unix_socket_export_integration_test.go +++ b/internal/mtail/unix_socket_export_integration_test.go @@ -18,7 +18,7 @@ func TestBasicUNIXSockets(t *testing.T) { tmpDir := testutil.TestTempDir(t) sockListenAddr := filepath.Join(tmpDir, "mtail_test.sock") - _, stopM := mtail.TestStartServer(t, 1, mtail.LogPathPatterns(tmpDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail"), mtail.BindUnixSocket(sockListenAddr)) + _, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(tmpDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail"), mtail.BindUnixSocket(sockListenAddr)) defer stopM() glog.Infof("check that server is listening") diff --git a/internal/tailer/logstream/dgramstream_unix_test.go b/internal/tailer/logstream/dgramstream_unix_test.go index f9a7dae60..29cf41b1e 100644 --- a/internal/tailer/logstream/dgramstream_unix_test.go +++ b/internal/tailer/logstream/dgramstream_unix_test.go @@ -52,7 +52,7 @@ func TestDgramStreamReadCompletedBecauseSocketClosed(t *testing.T) { _, err = s.Write([]byte("1\n")) testutil.FatalIfErr(t, err) - awaken(0) // sync past read + awaken(0, 0) // sync past read ss.Stop() @@ -109,7 +109,7 @@ func TestDgramStreamReadCompletedBecauseCancel(t *testing.T) { _, err = s.Write([]byte("1\n")) testutil.FatalIfErr(t, err) - awaken(0) // Synchronise past read. + awaken(0, 0) // Synchronise past read. cancel() // This cancellation should cause the stream to shut down. diff --git a/internal/tailer/logstream/filestream_test.go b/internal/tailer/logstream/filestream_test.go index 6bc3011f9..f672a236c 100644 --- a/internal/tailer/logstream/filestream_test.go +++ b/internal/tailer/logstream/filestream_test.go @@ -29,10 +29,10 @@ func TestFileStreamRead(t *testing.T) { waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) testutil.WriteString(t, f, "yo\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() @@ -64,7 +64,7 @@ func TestFileStreamReadNonSingleByteEnd(t *testing.T) { waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) s := "a" for i := 0; i < 4094; i++ { @@ -73,7 +73,7 @@ func TestFileStreamReadNonSingleByteEnd(t *testing.T) { s += "中" testutil.WriteString(t, f, s+"\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() @@ -105,7 +105,7 @@ func TestStreamDoesntBreakOnCorruptRune(t *testing.T) { waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) s := string([]byte{0xF1}) // 0xF1 = 11110001 , a byte signaling the start of a unicode character that @@ -119,7 +119,7 @@ func TestStreamDoesntBreakOnCorruptRune(t *testing.T) { } testutil.WriteString(t, f, s+"\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() @@ -155,17 +155,17 @@ func TestFileStreamTruncation(t *testing.T) { defer fs.Stop() testutil.FatalIfErr(t, err) - awaken(1) // Synchronise past first read after seekToEnd + awaken(1, 1) // Synchronise past first read after seekToEnd testutil.WriteString(t, f, "1\n2\n") - awaken(1) + awaken(1, 1) testutil.FatalIfErr(t, f.Close()) - awaken(1) + awaken(1, 1) f = testutil.OpenLogFile(t, name) defer f.Close() testutil.WriteString(t, f, "3\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() @@ -199,10 +199,10 @@ func TestFileStreamFinishedBecauseCancel(t *testing.T) { fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) // Synchronise past first read after seekToEnd + awaken(1, 1) // Synchronise past first read after seekToEnd testutil.WriteString(t, f, "yo\n") - awaken(1) + awaken(1, 1) cancel() wg.Wait() @@ -234,17 +234,17 @@ func TestFileStreamPartialRead(t *testing.T) { fs, err := logstream.New(ctx, &wg, waker, name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) testutil.WriteString(t, f, "yo") - awaken(1) + awaken(1, 1) // received := testutil.LinesReceived(lines) // expected := []*logline.LogLine{} // testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) testutil.WriteString(t, f, "\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() diff --git a/internal/tailer/logstream/filestream_unix_test.go b/internal/tailer/logstream/filestream_unix_test.go index a8bbb27b4..9b6cc9ae3 100644 --- a/internal/tailer/logstream/filestream_unix_test.go +++ b/internal/tailer/logstream/filestream_unix_test.go @@ -43,11 +43,11 @@ func TestFileStreamRotation(t *testing.T) { defer fs.Stop() testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) glog.Info("write 1") testutil.WriteString(t, f, "1\n") - awaken(1) + awaken(1, 1) glog.Info("rename") testutil.FatalIfErr(t, os.Rename(name, name+".1")) @@ -56,10 +56,10 @@ func TestFileStreamRotation(t *testing.T) { f = testutil.TestOpenFile(t, name) defer f.Close() - awaken(1) + awaken(1, 1) glog.Info("write 2") testutil.WriteString(t, f, "2\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() @@ -90,10 +90,10 @@ func TestFileStreamURL(t *testing.T) { waker, awaken := waker.NewTest(ctx, 1, "stream") fs, err := logstream.New(ctx, &wg, waker, "file://"+name, lines, logstream.OneShotEnabled) testutil.FatalIfErr(t, err) - awaken(1) + awaken(1, 1) testutil.WriteString(t, f, "yo\n") - awaken(1) + awaken(1, 1) fs.Stop() wg.Wait() diff --git a/internal/tailer/logstream/pipestream_unix_test.go b/internal/tailer/logstream/pipestream_unix_test.go index 21980c74b..6918c3a8c 100644 --- a/internal/tailer/logstream/pipestream_unix_test.go +++ b/internal/tailer/logstream/pipestream_unix_test.go @@ -88,7 +88,7 @@ func TestPipeStreamReadCompletedBecauseCancel(t *testing.T) { testutil.WriteString(t, f, "1\n") // Avoid a race with cancellation if we can synchronise with waker.Wake() - awaken(0) + awaken(0, 0) cancel() // Cancellation here should cause the stream to shut down. @@ -165,7 +165,7 @@ func TestPipeStreamReadStdin(t *testing.T) { ps, err := logstream.New(ctx, &wg, waker, "-", lines, logstream.OneShotDisabled) testutil.FatalIfErr(t, err) - awaken(0) + awaken(0, 0) testutil.FatalIfErr(t, f.Close()) diff --git a/internal/tailer/logstream/socketstream_unix_test.go b/internal/tailer/logstream/socketstream_unix_test.go index c43defb25..e2b6c9a20 100644 --- a/internal/tailer/logstream/socketstream_unix_test.go +++ b/internal/tailer/logstream/socketstream_unix_test.go @@ -50,7 +50,7 @@ func TestSocketStreamReadCompletedBecauseSocketClosed(t *testing.T) { _, err = s.Write([]byte("1\n")) testutil.FatalIfErr(t, err) - awaken(0) // Sync past read + awaken(0, 0) // Sync past read // Close the socket to signal to the socketStream to shut down. testutil.FatalIfErr(t, s.Close()) @@ -105,7 +105,7 @@ func TestSocketStreamReadCompletedBecauseCancel(t *testing.T) { _, err = s.Write([]byte("1\n")) testutil.FatalIfErr(t, err) - awaken(0) // Sync past read to ensure we read + awaken(0, 0) // Sync past read to ensure we read cancel() // This cancellation should cause the stream to shut down immediately. diff --git a/internal/tailer/tail_test.go b/internal/tailer/tail_test.go index 64b631868..96ba76f78 100644 --- a/internal/tailer/tail_test.go +++ b/internal/tailer/tail_test.go @@ -22,8 +22,11 @@ type testTail struct { // Output lnes channel lines chan *logline.LogLine - // Method to wake the waker - awaken func(int) + // Method to wake the stream poller + awakenStreams waker.WakeFunc + + // Method to wake the pattern poller + awakenPattern waker.WakeFunc // Temporary dir for test tmpDir string @@ -39,31 +42,17 @@ func makeTestTail(t *testing.T, options ...Option) *testTail { ctx, cancel := context.WithCancel(context.Background()) lines := make(chan *logline.LogLine, 5) // 5 loglines ought to be enough for any test var wg sync.WaitGroup - waker, awaken := waker.NewTest(ctx, 1, "streams") - options = append(options, LogPatterns([]string{tmpDir}), LogstreamPollWaker(waker)) + streamWaker, awakenStreams := waker.NewTest(ctx, 1, "streams") + patternWaker, awakenPattern := waker.NewTest(ctx, 1, "pattern") + options = append(options, LogPatterns([]string{tmpDir}), LogPatternPollWaker(patternWaker), LogstreamPollWaker(streamWaker)) ta, err := New(ctx, &wg, lines, options...) testutil.FatalIfErr(t, err) stop := func() { cancel(); wg.Wait() } t.Cleanup(stop) - return &testTail{Tailer: ta, lines: lines, awaken: awaken, tmpDir: tmpDir, stop: stop} -} - -func TestTail(t *testing.T) { - ta := makeTestTail(t) - - logfile := filepath.Join(ta.tmpDir, "log") - f := testutil.TestOpenFile(t, logfile) - defer f.Close() - - err := ta.TailPath(logfile) - testutil.FatalIfErr(t, err) - - if _, ok := ta.logstreams[logfile]; !ok { - t.Errorf("path not found in files map: %+#v", ta.logstreams) - } + return &testTail{Tailer: ta, lines: lines, awakenStreams: awakenStreams, awakenPattern: awakenPattern, tmpDir: tmpDir, stop: stop} } -func TestTailErrors(t *testing.T) { +func TestNewErrors(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() lines := make(chan *logline.LogLine) @@ -78,6 +67,21 @@ func TestTailErrors(t *testing.T) { } } +func TestTailPath(t *testing.T) { + ta := makeTestTail(t) + + logfile := filepath.Join(ta.tmpDir, "log") + f := testutil.TestOpenFile(t, logfile) + defer f.Close() + + err := ta.TailPath(logfile) + testutil.FatalIfErr(t, err) + + if _, ok := ta.logstreams[logfile]; !ok { + t.Errorf("path not found in files map: %+#v", ta.logstreams) + } +} + func TestHandleLogUpdate(t *testing.T) { ta := makeTestTail(t) @@ -86,10 +90,10 @@ func TestHandleLogUpdate(t *testing.T) { defer f.Close() testutil.FatalIfErr(t, ta.TailPath(logfile)) - ta.awaken(1) + ta.awakenStreams(1, 1) testutil.WriteString(t, f, "a\nb\nc\nd\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() @@ -115,10 +119,10 @@ func TestHandleLogTruncate(t *testing.T) { testutil.FatalIfErr(t, ta.TailPath(logfile)) // Expect to wake 1 wakee, the logstream reading `logfile`. - ta.awaken(1) + ta.awakenStreams(1, 1) testutil.WriteString(t, f, "a\nb\nc\n") - ta.awaken(1) + ta.awakenStreams(1, 1) if err := f.Truncate(0); err != nil { t.Fatal(err) @@ -127,10 +131,10 @@ func TestHandleLogTruncate(t *testing.T) { // "File.Truncate" does not change the file offset, force a seek to start. _, err := f.Seek(0, 0) testutil.FatalIfErr(t, err) - ta.awaken(1) + ta.awakenStreams(1, 1) testutil.WriteString(t, f, "d\ne\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() @@ -153,16 +157,16 @@ func TestHandleLogUpdatePartialLine(t *testing.T) { defer f.Close() testutil.FatalIfErr(t, ta.TailPath(logfile)) - ta.awaken(1) // ensure we've hit an EOF before writing starts + ta.awakenStreams(1, 1) // ensure we've hit an EOF before writing starts testutil.WriteString(t, f, "a") - ta.awaken(1) + ta.awakenStreams(1, 1) testutil.WriteString(t, f, "b") - ta.awaken(1) + ta.awakenStreams(1, 1) testutil.WriteString(t, f, "\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() @@ -187,12 +191,13 @@ func TestTailerUnreadableFile(t *testing.T) { f := testutil.TestOpenFile(t, logfile) defer f.Close() - testutil.FatalIfErr(t, ta.PollLogPatterns()) + ta.awakenPattern(1, 1) + testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) glog.Info("write string") testutil.WriteString(t, f, "\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() @@ -257,7 +262,7 @@ func TestTailExpireStaleHandles(t *testing.T) { testutil.WriteString(t, f1, "1\n") testutil.WriteString(t, f2, "2\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() diff --git a/internal/tailer/tail_unix_test.go b/internal/tailer/tail_unix_test.go index 07e90c8bd..421e89d36 100644 --- a/internal/tailer/tail_unix_test.go +++ b/internal/tailer/tail_unix_test.go @@ -17,8 +17,9 @@ import ( "golang.org/x/sys/unix" ) -// TestTailerOpenRetries is a unix-specific test because on Windows, it is not possible to create a file -// that you yourself cannot read (minimum permissions are 0222). +// TestTailerOpenRetries is a unix-specific test because on Windows, it is not +// possible to create a file that you yourself cannot read; the minimum permissions +// there are 0222. func TestTailerOpenRetries(t *testing.T) { // Can't force a permission denied error if run as root. testutil.SkipIfRoot(t) @@ -35,31 +36,31 @@ func TestTailerOpenRetries(t *testing.T) { if err := ta.TailPath(logfile); err == nil || !os.IsPermission(err) { t.Fatalf("Expected a permission denied error here: %s", err) } - testutil.FatalIfErr(t, ta.PollLogPatterns()) testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + ta.awakenPattern(1, 1) glog.Info("remove") if err := os.Remove(logfile); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.PollLogPatterns()) testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + ta.awakenPattern(1, 1) glog.Info("openfile") f, err := os.OpenFile(logfile, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0) //nolint:staticcheck // test code defer f.Close() testutil.FatalIfErr(t, err) - testutil.FatalIfErr(t, ta.PollLogPatterns()) testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + ta.awakenPattern(1, 1) glog.Info("chmod") if err := os.Chmod(logfile, 0o666); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.PollLogPatterns()) testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) - ta.awaken(1) // force sync to EOF + ta.awakenPattern(1, 1) + ta.awakenStreams(1, 1) // force sync to EOF glog.Info("write string") testutil.WriteString(t, f, "\n") - ta.awaken(1) + ta.awakenStreams(1, 1) ta.stop() @@ -83,7 +84,6 @@ func TestAddStdin(t *testing.T) { if err := ta.AddPattern("-"); err != nil { t.Errorf("AddPattern(-) -> %v", err) } - testutil.FatalIfErr(t, ta.PollLogPatterns()) ta.stop() diff --git a/internal/waker/testwaker.go b/internal/waker/testwaker.go index 4d90041f9..5f69353ee 100644 --- a/internal/waker/testwaker.go +++ b/internal/waker/testwaker.go @@ -10,7 +10,11 @@ import ( "github.com/golang/glog" ) -// A testWaker is used to manually signal to idle routines it's time to look for new work. +// A testWaker is used to manually signal to idle routines it's time to look +// for new work. It works by synchronising several client goroutines +// ("wakees"), waiting for a certain number to have called `Wake()`, and then +// sending them a wakeup signal together. It then waits in a loop for more +// goroutines to call `Wake` again before returning to the test. type testWaker struct { Waker @@ -22,56 +26,59 @@ type testWaker struct { wakeeReady chan struct{} wakeeDone chan struct{} - wait chan struct{} + waiting chan struct{} mu sync.Mutex // protects following fields wake chan struct{} } -// WakeFunc describes a function used by tests to trigger a wakeup of blocked idle goroutines under test. It takes as first parameter the number of goroutines to await before returning to the caller. -type WakeFunc func(int) +// WakeFunc describes a function used by tests to trigger a wakeup of blocked +// idle goroutines under test. It takes as first parameter the number of +// goroutines to wake up, and the second parameter is the number of goroutines +// to wait to call Wake before returning. +type WakeFunc func(int, int) // NewTest creates a new Waker to be used in tests, returning it and a function to trigger a wakeup. -// `n` says how many wakees are expected to be waiting before the first `wakeFunc` call. +// `wait` says how many wakees are expected to be waiting before the first `wakeFunc` call. // `name` gives it a name for debug log messages -func NewTest(ctx context.Context, n int, name string) (Waker, WakeFunc) { +func NewTest(ctx context.Context, wait int, name string) (Waker, WakeFunc) { t := &testWaker{ ctx: ctx, - n: n, name: name, wakeeReady: make(chan struct{}), wakeeDone: make(chan struct{}), - wait: make(chan struct{}), + waiting: make(chan struct{}), wake: make(chan struct{}), } initDone := make(chan struct{}) go func() { defer close(initDone) - glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees", t.name, t.n) - for i := 0; i < t.n; i++ { + glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees to call Wake()", t.name, wait) + for i := 0; i < wait; i++ { <-t.wakeeDone } }() - // awaken issues a wakeup signal to the "wakees", those clients who've used the `Wake` call. - awaken := func(after int) { + // awaken issues a wakeup signal to the "wakees", those clients who've used + // the `Wake` call. wake is the number of wakees we expect to wake up, + // wait is the number of wakees to wait for before returning. + awaken := func(wake, wait int) { <-initDone glog.InfoDepthf(1, "TestWaker(%s) yielding to Wakee", t.name) - for i := 0; i < t.n; i++ { - t.wait <- struct{}{} + for i := 0; i < wake; i++ { + t.waiting <- struct{}{} } // First wait for `t.n` wakees to have called `Wake`, synchronising them. - glog.Infof("TestWaker(%s) waiting for %d wakees to get the wake chan", t.name, t.n) - for i := 0; i < t.n; i++ { + glog.Infof("TestWaker(%s) waiting for %d wakees to receive from the wake chan", t.name, wake) + for i := 0; i < wake; i++ { <-t.wakeeReady } t.broadcastWakeAndReset() // Now `awaken` blocks here, as we wait for them in turn to return to another call to Wake, in their polling loops. We wait for only a count of `after` routines this time, as some may exit. - glog.Infof("TestWaker(%s) waiting for %d wakees to return to Wake", t.name, after) - for i := 0; i < after; i++ { + glog.Infof("TestWaker(%s) waiting for %d wakees to call Wake()", t.name, wait) + for i := 0; i < wait; i++ { <-t.wakeeDone } - t.n = after - glog.InfoDepthf(1, "TestWaker(%s): Wakee yielding to TestWaker", t.name) + glog.Infof("TestWaker(%s): Wakees returned, yielding to TestWaker", t.name) } return t, awaken } @@ -81,7 +88,7 @@ func (t *testWaker) Wake() (w <-chan struct{}) { t.mu.Lock() w = t.wake t.mu.Unlock() - glog.InfoDepthf(1, "TestWaker(%s) waiting for wakeup on chan %p", t.name, w) + glog.InfoDepthf(1, "Wakee on TestWaker(%s) waiting for wakeup on chan %p", t.name, w) // Background this so we can return the wake channel. // The wakeFunc won't close the channel until this completes. go func() { @@ -95,7 +102,7 @@ func (t *testWaker) Wake() (w <-chan struct{}) { select { case <-t.ctx.Done(): return - case <-t.wait: + case <-t.waiting: } // Signal we've got the wake chan, telling wakeFunc it can now issue a broadcast. select { @@ -113,7 +120,7 @@ func (t *testWaker) broadcastWakeAndReset() { glog.Infof("TestWaker(%s) broadcasting wake to chan %p", t.name, t.wake) close(t.wake) t.wake = make(chan struct{}) - glog.Infof("TestWaker(%s) wake channel reset", t.name) + glog.Infof("TestWaker(%s) wake channel reset to chan %p", t.name, t.wake) } // alwaysWaker never blocks the wakee. diff --git a/internal/waker/testwaker_test.go b/internal/waker/testwaker_test.go index 5c949240c..2eaf6b153 100644 --- a/internal/waker/testwaker_test.go +++ b/internal/waker/testwaker_test.go @@ -21,7 +21,7 @@ func TestTestWakerWakes(t *testing.T) { t.Errorf("<-w.Wake() == %v, expected nothing (should block)", x) default: } - awaken(0) + awaken(1, 0) select { case <-c: // Luke Luck likes lakes. Luke's duck likes lakes. @@ -68,7 +68,7 @@ func TestTestWakerTwoWakees(t *testing.T) { } }() wg1.Done() - awaken(0) // wake 2, and await none + awaken(2, 0) // wake 2, and await none wg2.Done() wg3.Wait() } @@ -99,10 +99,10 @@ func TestTestWakerTwoWakeups(t *testing.T) { defer wg.Done() <-begin <-s - awaken(1) + awaken(1, 1) // awaken 1, wait for 1 <-s // we don't expect anyone to call Wake() after this - awaken(0) + awaken(1, 0) }() close(begin) wg.Wait() From 29b9e0202f3e64b4fbb0aac0a55454688514b7a9 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sat, 25 May 2024 10:52:56 +0100 Subject: [PATCH 15/25] ci: Update the automerge workflow based on the community discussion. --- .github/workflows/automerge.yml | 23 ++++++++++++----------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/.github/workflows/automerge.yml b/.github/workflows/automerge.yml index 7a809d00e..aa12eae84 100644 --- a/.github/workflows/automerge.yml +++ b/.github/workflows/automerge.yml @@ -17,20 +17,21 @@ jobs: enable-automerge: if: github.event.pull_request.user.login == 'dependabot[bot]' && contains(github.event.pull_request.labels.*.name, 'dependencies') runs-on: ubuntu-latest + # https://github.com/orgs/community/discussions/24686 permissions: - # enable-automerge is a graphql query, not REST, so isn't documented, - # except in a mention in - # https://github.blog/changelog/2021-02-04-pull-request-auto-merge-is-now-generally-available/ - # which says "can only be enabled by users with permissino to merge"; the - # REST documentation says you need contents: write to perform a merge. - # https://github.community/t/what-permission-does-a-github-action-need-to-call-graphql-enablepullrequestautomerge/197708 - # says this is it contents: write + pull-requests: write steps: - # Enable auto-merge *before* issuing an approval. - - uses: alexwilson/enable-github-automerge-action@main - with: - github-token: "${{ secrets.GITHUB_TOKEN }}" + - run: | + gh api graphql -f pullRequestId="${{ github.event.pull_request.node_id }}" -f query=' + mutation EnablePullRequestAutoMerge($pullRequestId: ID!) { + enablePullRequestAutoMerge(input: {pullRequestId: $pullRequestId}) { + clientMutationId + } + } + ' + env: + GH_TOKEN: ${{ github.token }} wait-on-checks: needs: enable-automerge From ff635f936fad1227b20869591d90728953ec8366 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sat, 25 May 2024 15:20:17 +0100 Subject: [PATCH 16/25] Extract pattern polling into a goroutine per pattern. This lets us await a goroutine per pattern, and if there are none, no waiting need be done, making shutdown cleaner. The completion poller is still a bit of a mess though. --- internal/mtail/basic_tail_integration_test.go | 6 +- .../log_deletion_integration_unix_test.go | 4 +- .../mtail/log_rotation_integration_test.go | 7 +- .../log_rotation_integration_unix_test.go | 10 +-- .../mtail/read_pipe_integration_unix_test.go | 5 -- internal/tailer/tail.go | 73 ++++++++----------- internal/tailer/tail_test.go | 35 ++++----- internal/waker/testwaker.go | 8 +- 8 files changed, 62 insertions(+), 86 deletions(-) diff --git a/internal/mtail/basic_tail_integration_test.go b/internal/mtail/basic_tail_integration_test.go index 21dc9094b..25b6d9fd0 100644 --- a/internal/mtail/basic_tail_integration_test.go +++ b/internal/mtail/basic_tail_integration_test.go @@ -17,11 +17,11 @@ import ( func TestBasicTail(t *testing.T) { testutil.SkipIfShort(t) if testing.Verbose() { - testutil.SetFlag(t, "vmodule", "tail=2,log_watcher=2") + testutil.SetFlag(t, "vmodule", "tail=2,filestream=2") } logDir := testutil.TestTempDir(t) - m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) + m, stopM := mtail.TestStartServer(t, 2, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) defer stopM() logFile := filepath.Join(logDir, "log") @@ -31,7 +31,7 @@ func TestBasicTail(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.AwakenPatternPollers(1, 1) // Find `logFile` + m.AwakenPatternPollers(2, 2) // Find `logFile` m.AwakenLogStreams(1, 1) // Force a sync to EOF for i := 1; i <= 3; i++ { diff --git a/internal/mtail/log_deletion_integration_unix_test.go b/internal/mtail/log_deletion_integration_unix_test.go index dea2574b8..d02d032dc 100644 --- a/internal/mtail/log_deletion_integration_unix_test.go +++ b/internal/mtail/log_deletion_integration_unix_test.go @@ -37,8 +37,8 @@ func TestLogDeletion(t *testing.T) { glog.Info("remove") testutil.FatalIfErr(t, os.Remove(logFilepath)) - m.AwakenLogStreams(1, 1) // run stream to observe it's missing + m.AwakenLogStreams(1, 0) // run stream to observe it's missing logCloseCheck() - m.AwakenLogStreams(1, 1) + m.AwakenPatternPollers(1, 1) logCountCheck() } diff --git a/internal/mtail/log_rotation_integration_test.go b/internal/mtail/log_rotation_integration_test.go index f762ed64c..7bf0c452c 100644 --- a/internal/mtail/log_rotation_integration_test.go +++ b/internal/mtail/log_rotation_integration_test.go @@ -61,15 +61,14 @@ func TestLogRotationBySoftLinkChange(t *testing.T) { // Simulate a race where we poll for a pattern and remove the // existing stream. m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. - m.AwakenLogStreams(1, 1) + m.AwakenLogStreams(1, 0) logClosedCheck() // barrier until filestream closes fd - m.AwakenLogStreams(1, 1) - + m.AwakenPatternPollers(1, 1) logCompletedCheck() // barrier until the logstream is removed from tailer } testutil.FatalIfErr(t, os.Symlink(logFilepath+".true2", logFilepath)) m.AwakenPatternPollers(1, 1) - m.AwakenLogStreams(1, 1) + m.AwakenLogStreams(0, 1) for _, x := range inputLines { testutil.WriteString(t, trueLog2, x+"\n") diff --git a/internal/mtail/log_rotation_integration_unix_test.go b/internal/mtail/log_rotation_integration_unix_test.go index c5c493d65..a3a240f3e 100644 --- a/internal/mtail/log_rotation_integration_unix_test.go +++ b/internal/mtail/log_rotation_integration_unix_test.go @@ -67,15 +67,15 @@ func TestLogRotationByRename(t *testing.T) { // Simulate a race where we poll for a pattern and remove the // existing stream. m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. - m.AwakenLogStreams(1, 1) - logClosedCheck() // barrier until filestream closes fd - m.AwakenLogStreams(1, 1) // invoke the GC - logCompletedCheck() // barrier until logstream is removed from tailer + m.AwakenLogStreams(1, 0) + logClosedCheck() // barrier until filestream closes fd + m.AwakenPatternPollers(1, 1) + logCompletedCheck() // barrier until the logstream is removed from tailer } glog.Info("create") f = testutil.TestOpenFile(t, logFile) m.AwakenPatternPollers(1, 1) - m.AwakenLogStreams(1, 1) + m.AwakenLogStreams(0, 1) testutil.WriteString(t, f, "line 1\n") m.AwakenLogStreams(1, 1) diff --git a/internal/mtail/read_pipe_integration_unix_test.go b/internal/mtail/read_pipe_integration_unix_test.go index cbed73a42..5034dce08 100644 --- a/internal/mtail/read_pipe_integration_unix_test.go +++ b/internal/mtail/read_pipe_integration_unix_test.go @@ -11,7 +11,6 @@ import ( "path/filepath" "syscall" "testing" - "time" "github.com/google/mtail/internal/mtail" "github.com/google/mtail/internal/testutil" @@ -70,7 +69,6 @@ func TestReadFromSocket(t *testing.T) { defer stopM() lineCountCheck := m.ExpectExpvarDeltaWithDeadline("lines_total", 3) - time.Sleep(10 * time.Millisecond) s, err := net.DialUnix(scheme, nil, &net.UnixAddr{Name: logFile, Net: scheme}) testutil.FatalIfErr(t, err) @@ -81,9 +79,6 @@ func TestReadFromSocket(t *testing.T) { _, err = s.Write([]byte("1\n2\n3\n")) testutil.FatalIfErr(t, err) - m.AwakenPatternPollers(1, 1) - m.AwakenLogStreams(1, 1) - lineCountCheck() }) } diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 19bab373b..326a33cb7 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -42,8 +42,6 @@ type Tailer struct { oneShot logstream.OneShotMode - pollMu sync.Mutex // protects Poll() - logstreamPollWaker waker.Waker // Used for waking idle logstreams logstreamsMu sync.RWMutex // protects `logstreams`. logstreams map[string]logstream.LogStream // Map absolte pathname to logstream reading that pathname. @@ -109,7 +107,6 @@ type logPatternPollWaker struct { func (opt logPatternPollWaker) apply(t *Tailer) error { t.logPatternPollWaker = opt.Waker - t.StartLogPatternPollLoop() return nil } @@ -157,25 +154,24 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, return nil, err } } - // Guarantee all existing remaining patterns get tailed before we leave. - // Also necessary in case oneshot mode is active, the logs get read! - if err := t.PollLogPatterns(); err != nil { - return nil, err - } // Start the routine for checking if logstreams have completed. t.startPollLogStreamsForCompletion(ctx, wg) // Setup for shutdown, once all routines are finished. + subsDone := make(chan struct{}) + wg.Add(1) + go func() { + defer wg.Done() + <-t.initDone + t.wg.Wait() + close(subsDone) + }() wg.Add(1) go func() { defer wg.Done() <-t.initDone - // If there are any patterns, we need to wait for an explicit context cancellation. - // We don't during oneshot mode though. - t.globPatternsMu.RLock() - l := len(t.globPatterns) - t.globPatternsMu.RUnlock() - if l > 0 && !t.oneShot { - <-t.ctx.Done() + select { + case <-subsDone: + case <-t.ctx.Done(): } t.wg.Wait() glog.V(1).InfoContextf(ctx, "tailer finished") @@ -203,7 +199,6 @@ var ErrUnsupportedURLScheme = errors.New("unsupported URL scheme") // AddPattern adds a pattern to the list of patterns to filter filenames against. func (t *Tailer) AddPattern(pattern string) error { - glog.V(2).Infof("AddPattern(%v)", pattern) u, err := url.Parse(pattern) if err != nil { return err @@ -236,22 +231,23 @@ func (t *Tailer) AddPattern(pattern string) error { t.globPatternsMu.Lock() t.globPatterns[path] = struct{}{} t.globPatternsMu.Unlock() + t.pollLogPattern(path) return nil } func (t *Tailer) Ignore(pathname string) bool { absPath, err := filepath.Abs(pathname) if err != nil { - glog.V(2).Infof("Couldn't get absolute path for %q: %s", pathname, err) + glog.V(2).Infof("Ignore(%v): couldn't get absolute path: %v", pathname, err) return true } fi, err := os.Stat(absPath) if err != nil { - glog.V(2).Infof("Couldn't stat path %q: %s", pathname, err) + glog.V(2).Infof("Ignore(%v): couldn't stat: %v", pathname, err) return true } if fi.Mode().IsDir() { - glog.V(2).Infof("ignore path %q because it is a folder", pathname) + glog.V(2).Infof("Ignore(%v): is a folder", pathname) return true } return t.ignoreRegexPattern != nil && t.ignoreRegexPattern.MatchString(fi.Name()) @@ -338,10 +334,13 @@ func (t *Tailer) StartStaleLogstreamExpirationLoop(waker waker.Waker) { }() } -// StartLogPatternPollLoop runs a permanent goroutine to poll for new log files. -func (t *Tailer) StartLogPatternPollLoop() { +// pollLogPattern runs a permanent goroutine to poll for new log files that match `pattern`. +func (t *Tailer) pollLogPattern(pattern string) { + if err := t.doPatternGlob(pattern); err != nil { + glog.Infof("pollPattern(%v): glob failed: %v", pattern, err) + } if t.logPatternPollWaker == nil { - glog.Info("Log pattern polling disabled") + glog.Infof("pollPattern(%v): log pattern polling disabled by no waker", pattern) return } t.wg.Add(1) @@ -349,34 +348,23 @@ func (t *Tailer) StartLogPatternPollLoop() { defer t.wg.Done() <-t.initDone if t.oneShot { - glog.Info("No polling loop in oneshot mode.") + glog.Infof("pollPattern(%v): no polling loop in oneshot mode", pattern) return } - // glog.Infof("Starting log pattern poll loop every %s", duration.String()) + glog.V(1).Infof("pollPattern(%v): starting log pattern poll loop", pattern) for { select { case <-t.ctx.Done(): return case <-t.logPatternPollWaker.Wake(): - if err := t.PollLogPatterns(); err != nil { - glog.Info(err) + if err := t.doPatternGlob(pattern); err != nil { + glog.Infof("pollPattern(%v): glob failed: %v", pattern, err) } } } }() } -func (t *Tailer) PollLogPatterns() error { - t.globPatternsMu.RLock() - defer t.globPatternsMu.RUnlock() - for pattern := range t.globPatterns { - if err := t.doPatternGlob(pattern); err != nil { - return err - } - } - return nil -} - // doPatternGlob matches a glob-style pattern against the filesystem and issues // a TailPath for any files that match. func (t *Tailer) doPatternGlob(pattern string) error { @@ -384,17 +372,17 @@ func (t *Tailer) doPatternGlob(pattern string) error { if err != nil { return err } - glog.V(1).Infof("glob matches: %v", matches) + glog.V(1).Infof("doPatternGlob(%v): glob matches: %v", pattern, matches) for _, pathname := range matches { if t.Ignore(pathname) { continue } absPath, err := filepath.Abs(pathname) if err != nil { - glog.V(2).Infof("Couldn't get absolute path for %q: %s", pathname, err) + glog.V(2).Infof("doPatternGlob(%v): couldn't get absolute path for %q: %s", pattern, pathname, err) continue } - glog.V(2).Infof("watched path is %q", absPath) + glog.V(2).Infof("doPatternGlob(%v): tailable path is %q", pattern, absPath) if err := t.TailPath(absPath); err != nil { glog.Info(err) } @@ -421,7 +409,8 @@ func (t *Tailer) PollLogStreamsForCompletion() error { // StartPollLogStreamsForCompletion runs a permanent goroutine to poll for // completed LogStreams. func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync.WaitGroup) { - if t.logstreamPollWaker == nil { + // Uses the log pattern poll waker for maintenance. + if t.logPatternPollWaker == nil { glog.Info("Log completion polling disabled by no waker") return } @@ -437,7 +426,7 @@ func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync. select { case <-ctx.Done(): return - case <-t.logstreamPollWaker.Wake(): + case <-t.logPatternPollWaker.Wake(): if err := t.PollLogStreamsForCompletion(); err != nil { glog.Info(err) } diff --git a/internal/tailer/tail_test.go b/internal/tailer/tail_test.go index 96ba76f78..ed95580f3 100644 --- a/internal/tailer/tail_test.go +++ b/internal/tailer/tail_test.go @@ -177,35 +177,28 @@ func TestHandleLogUpdatePartialLine(t *testing.T) { testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) } +// Test that broken files are skipped. func TestTailerUnreadableFile(t *testing.T) { - // Test broken files are skipped. + t.Skip("race condition testing for the absence of a log") ta := makeTestTail(t) - brokenfile := filepath.Join(ta.tmpDir, "brokenlog") - logfile := filepath.Join(ta.tmpDir, "log") - testutil.FatalIfErr(t, ta.AddPattern(brokenfile)) - testutil.FatalIfErr(t, ta.AddPattern(logfile)) + brokenlog := filepath.Join(ta.tmpDir, "brokenlog") + goodlog := filepath.Join(ta.tmpDir, "goodlog") + testutil.FatalIfErr(t, ta.AddPattern(brokenlog)) + testutil.FatalIfErr(t, ta.AddPattern(goodlog)) + + logCountCheck := testutil.ExpectExpvarDeltaWithDeadline(t, "log_count", 1) glog.Info("create logs") - testutil.FatalIfErr(t, os.Symlink("/nonexistent", brokenfile)) - f := testutil.TestOpenFile(t, logfile) + testutil.FatalIfErr(t, os.Symlink("/nonexistent", brokenlog)) + f := testutil.TestOpenFile(t, goodlog) defer f.Close() - ta.awakenPattern(1, 1) - - testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) - - glog.Info("write string") - testutil.WriteString(t, f, "\n") - ta.awakenStreams(1, 1) + // We started with one pattern waker from `makeTestTail`, but we added two + // patterns. There's also the completion poller. Collect them all. + ta.awakenPattern(1, 4) - ta.stop() - - received := testutil.LinesReceived(ta.lines) - expected := []*logline.LogLine{ - {Context: context.Background(), Filename: logfile, Line: ""}, - } - testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) + logCountCheck() } func TestTailerInitErrors(t *testing.T) { diff --git a/internal/waker/testwaker.go b/internal/waker/testwaker.go index 5f69353ee..6542c6ee1 100644 --- a/internal/waker/testwaker.go +++ b/internal/waker/testwaker.go @@ -53,7 +53,7 @@ func NewTest(ctx context.Context, wait int, name string) (Waker, WakeFunc) { initDone := make(chan struct{}) go func() { defer close(initDone) - glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees to call Wake()", t.name, wait) + glog.Infof("TestWaker(%s) init waiting for %d wakees to call Wake()", t.name, wait) for i := 0; i < wait; i++ { <-t.wakeeDone } @@ -68,17 +68,17 @@ func NewTest(ctx context.Context, wait int, name string) (Waker, WakeFunc) { t.waiting <- struct{}{} } // First wait for `t.n` wakees to have called `Wake`, synchronising them. - glog.Infof("TestWaker(%s) waiting for %d wakees to receive from the wake chan", t.name, wake) + glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees to receive from the wake chan", t.name, wake) for i := 0; i < wake; i++ { <-t.wakeeReady } t.broadcastWakeAndReset() // Now `awaken` blocks here, as we wait for them in turn to return to another call to Wake, in their polling loops. We wait for only a count of `after` routines this time, as some may exit. - glog.Infof("TestWaker(%s) waiting for %d wakees to call Wake()", t.name, wait) + glog.InfoDepthf(1, "TestWaker(%s) waiting for %d wakees to call Wake()", t.name, wait) for i := 0; i < wait; i++ { <-t.wakeeDone } - glog.Infof("TestWaker(%s): Wakees returned, yielding to TestWaker", t.name) + glog.InfoDepthf(1, "TestWaker(%s): Wakees returned, yielding to TestWaker", t.name) } return t, awaken } From c172b6cc0b801c955e454f4fd05b33d50d880443 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sat, 25 May 2024 16:20:47 +0100 Subject: [PATCH 17/25] Move the stale log gc off the subroutine waitgroup. This is not a routine we wait for completion of to shut down the tailer, it's shut down when the tailer is exiting. Move the stdin check to logstream so it can use it too. --- internal/tailer/logstream/logstream.go | 15 ++++++- internal/tailer/tail.go | 55 ++++++++++++-------------- 2 files changed, 39 insertions(+), 31 deletions(-) diff --git a/internal/tailer/logstream/logstream.go b/internal/tailer/logstream/logstream.go index 1b30d347e..bbdfe7c71 100644 --- a/internal/tailer/logstream/logstream.go +++ b/internal/tailer/logstream/logstream.go @@ -42,6 +42,8 @@ type LogStream interface { // defaultReadBufferSize the size of the buffer for reading bytes into. const defaultReadBufferSize = 4096 +const stdinPattern = "-" + var ( ErrUnsupportedURLScheme = errors.New("unsupported URL scheme") ErrUnsupportedFileType = errors.New("unsupported file type") @@ -87,12 +89,13 @@ func New(ctx context.Context, wg *sync.WaitGroup, waker waker.Waker, pathname st path = u.Path } var fi os.FileInfo - if path == "-" { + if IsStdinPattern(path) { fi, err = os.Stdin.Stat() if err != nil { logErrors.Add(path, 1) return nil, err } + return newPipeStream(ctx, wg, waker, path, fi, lines) } else { fi, err = os.Stat(path) if err != nil { @@ -112,3 +115,13 @@ func New(ctx context.Context, wg *sync.WaitGroup, waker waker.Waker, pathname st return nil, fmt.Errorf("%w: %q", ErrUnsupportedFileType, pathname) } } + +func IsStdinPattern(pattern string) bool { + if pattern == stdinPattern { + return true + } + if pattern == "/dev/stdin" { + return true + } + return false +} diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 326a33cb7..0069e6327 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -29,8 +29,11 @@ var logCount = expvar.NewInt("log_count") // Tailer polls the filesystem for log sources that match given // `LogPathPatterns` and creates `LogStream`s to tail them. type Tailer struct { - ctx context.Context - wg sync.WaitGroup // Wait for our subroutines to finish + ctx context.Context + cancel context.CancelFunc + + wg sync.WaitGroup // Wait for our subroutines to finish + lines chan<- *logline.LogLine logPatterns []string @@ -46,11 +49,11 @@ type Tailer struct { logstreamsMu sync.RWMutex // protects `logstreams`. logstreams map[string]logstream.LogStream // Map absolte pathname to logstream reading that pathname. + staleLogGcWaker waker.Waker // Used to wake stale log GC + initDone chan struct{} } -const stdinPattern = "-" - // Option configures a new Tailer. type Option interface { apply(*Tailer) error @@ -92,7 +95,7 @@ type staleLogGcWaker struct { } func (opt staleLogGcWaker) apply(t *Tailer) error { - t.StartStaleLogstreamExpirationLoop(opt.Waker) + t.staleLogGcWaker = opt.Waker return nil } @@ -138,12 +141,12 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, return nil, ErrNeedsWaitgroup } t := &Tailer{ - ctx: ctx, lines: lines, initDone: make(chan struct{}), globPatterns: make(map[string]struct{}), logstreams: make(map[string]logstream.LogStream), } + t.ctx, t.cancel = context.WithCancel(ctx) defer close(t.initDone) if err := t.SetOption(options...); err != nil { return nil, err @@ -156,6 +159,7 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, } // Start the routine for checking if logstreams have completed. t.startPollLogStreamsForCompletion(ctx, wg) + t.StartStaleLogstreamExpirationLoop(ctx, wg) // Setup for shutdown, once all routines are finished. subsDone := make(chan struct{}) wg.Add(1) @@ -216,7 +220,7 @@ func (t *Tailer) AddPattern(pattern string) error { case "", "file": // Leave path alone; may contain globs } - if isStdinPattern(pattern) { + if logstream.IsStdinPattern(pattern) { // stdin is not really a socket, but it is handled by this codepath and should not be in the globs. glog.V(2).Infof("AddPattern(%v): is stdin", pattern) return t.TailPath(pattern) @@ -307,25 +311,24 @@ func (t *Tailer) ExpireStaleLogstreams() error { } // StartStaleLogstreamExpirationLoop runs a permanent goroutine to expire stale logstreams. -func (t *Tailer) StartStaleLogstreamExpirationLoop(waker waker.Waker) { - if waker == nil { - glog.Info("Log handle expiration disabled") +func (t *Tailer) StartStaleLogstreamExpirationLoop(ctx context.Context, wg *sync.WaitGroup) { + if t.staleLogGcWaker == nil { + glog.InfoContext(ctx, "Log handle expiration disabled") return } - t.wg.Add(1) + wg.Add(1) go func() { - defer t.wg.Done() + defer wg.Done() <-t.initDone if t.oneShot { - glog.Info("No gc loop in oneshot mode.") + glog.InfoContext(ctx, "No gc loop in oneshot mode.") return } - // glog.Infof("Starting log handle expiry loop every %s", duration.String()) for { select { - case <-t.ctx.Done(): + case <-ctx.Done(): return - case <-waker.Wake(): + case <-t.staleLogGcWaker.Wake(): if err := t.ExpireStaleLogstreams(); err != nil { glog.Info(err) } @@ -334,7 +337,9 @@ func (t *Tailer) StartStaleLogstreamExpirationLoop(waker waker.Waker) { }() } -// pollLogPattern runs a permanent goroutine to poll for new log files that match `pattern`. +// pollLogPattern runs a permanent goroutine to poll for new log files that +// match `pattern`. It is on the subroutine waitgroup as we do not want to +// shut down the tailer when there are outstanding patterns to poll for. func (t *Tailer) pollLogPattern(pattern string) { if err := t.doPatternGlob(pattern); err != nil { glog.Infof("pollPattern(%v): glob failed: %v", pattern, err) @@ -407,11 +412,11 @@ func (t *Tailer) PollLogStreamsForCompletion() error { } // StartPollLogStreamsForCompletion runs a permanent goroutine to poll for -// completed LogStreams. +// completed LogStreams. It is on the parent waitgroup as it should exit only once the tailer is shutting down. func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync.WaitGroup) { // Uses the log pattern poll waker for maintenance. if t.logPatternPollWaker == nil { - glog.Info("Log completion polling disabled by no waker") + glog.InfoContext(ctx, "Log completion polling disabled by no waker") return } wg.Add(1) @@ -419,7 +424,7 @@ func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync. defer wg.Done() <-t.initDone if t.oneShot { - glog.Info("No logstream completion polling loop in oneshot mode.") + glog.InfoContext(ctx, "No logstream completion polling loop in oneshot mode.") return } for { @@ -434,13 +439,3 @@ func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync. } }() } - -func isStdinPattern(pattern string) bool { - if pattern == stdinPattern { - return true - } - if pattern == "/dev/stdin" { - return true - } - return false -} From e06012d8fe4819280ecaadfe7cd69fa5bb75c10b Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sat, 25 May 2024 16:30:36 +0100 Subject: [PATCH 18/25] Use a cancelfunc instead of another channel to shut down the Tailer. --- internal/tailer/tail.go | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 0069e6327..e6c7473a2 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -160,27 +160,28 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, // Start the routine for checking if logstreams have completed. t.startPollLogStreamsForCompletion(ctx, wg) t.StartStaleLogstreamExpirationLoop(ctx, wg) - // Setup for shutdown, once all routines are finished. - subsDone := make(chan struct{}) + + // This goroutine cancels the Tailer if all of our dependent subroutines are done. + // These are any live logstreams, and any log pattern pollers. wg.Add(1) go func() { defer wg.Done() <-t.initDone t.wg.Wait() - close(subsDone) + t.cancel() }() + + // This goroutine awaits cancellation, then cleans up the tailer. wg.Add(1) go func() { defer wg.Done() <-t.initDone - select { - case <-subsDone: - case <-t.ctx.Done(): - } + <-t.ctx.Done() t.wg.Wait() glog.V(1).InfoContextf(ctx, "tailer finished") close(t.lines) }() + return t, nil } From 455da56e8523b04ca37f6df9ab466166d00a74f1 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 12:22:16 +0100 Subject: [PATCH 19/25] Cancel the `mtail` context at shutdown, to shut down child goroutines. --- internal/mtail/mtail.go | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/internal/mtail/mtail.go b/internal/mtail/mtail.go index 91750e547..0e3cf2b49 100644 --- a/internal/mtail/mtail.go +++ b/internal/mtail/mtail.go @@ -29,9 +29,12 @@ import ( // Server contains the state of the main mtail program. type Server struct { - ctx context.Context + ctx context.Context + cancel context.CancelFunc + + wg sync.WaitGroup // wait for main processes to shutdown + store *metrics.Store // Metrics storage - wg sync.WaitGroup // wait for main processes to shutdown tOpts []tailer.Option // options for constructing `t` t *tailer.Tailer // t manages log patterns and log streams, which sends lines to the VMs @@ -172,13 +175,13 @@ func (m *Server) initHTTPServer() error { // block until quit, once TestServer.PollWatched is addressed. func New(ctx context.Context, store *metrics.Store, options ...Option) (*Server, error) { m := &Server{ - ctx: ctx, store: store, lines: make(chan *logline.LogLine), // Using a non-pedantic registry means we can be looser with metrics that // are not fully specified at startup. reg: prometheus.NewRegistry(), } + m.ctx, m.cancel = context.WithCancel(ctx) m.rOpts = append(m.rOpts, runtime.PrometheusRegisterer(m.reg)) // TODO(jaq): Should these move to initExporter? @@ -234,7 +237,7 @@ func (m *Server) SetOption(options ...Option) error { // TODO(jaq): remove this once the test server is able to trigger polls on the components. func (m *Server) Run() error { m.wg.Wait() - m.e.Stop() + m.cancel() if m.compileOnly { glog.Info("compile-only is set, exiting") return nil From 6e3f971836e87f8e5f873227899449a96e6cfeb2 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 12:43:39 +0100 Subject: [PATCH 20/25] Move the stream cleanup onto the GC poller. Rename the waker option and the goroutine launcher as it's not just for stale logs anymore. Fix tests that were relying on the pattern poller for log completion. --- cmd/mtail/main.go | 2 +- internal/mtail/basic_tail_integration_test.go | 4 +- .../log_deletion_integration_unix_test.go | 2 +- .../mtail/log_rotation_integration_test.go | 3 +- .../log_rotation_integration_unix_test.go | 2 +- internal/mtail/options.go | 12 +- internal/mtail/testing.go | 5 + internal/tailer/tail.go | 115 +++++++----------- internal/tailer/tail_unix_test.go | 8 +- 9 files changed, 65 insertions(+), 88 deletions(-) diff --git a/cmd/mtail/main.go b/cmd/mtail/main.go index b3dc7b0a9..1637df286 100644 --- a/cmd/mtail/main.go +++ b/cmd/mtail/main.go @@ -182,7 +182,7 @@ func main() { } if *staleLogGcTickInterval > 0 { staleLogGcWaker := waker.NewTimed(ctx, *staleLogGcTickInterval) - opts = append(opts, mtail.StaleLogGcWaker(staleLogGcWaker)) + opts = append(opts, mtail.GcWaker(staleLogGcWaker)) } if *pollInterval > 0 { logStreamPollWaker := waker.NewTimed(ctx, *pollInterval) diff --git a/internal/mtail/basic_tail_integration_test.go b/internal/mtail/basic_tail_integration_test.go index 25b6d9fd0..1bfc95f9f 100644 --- a/internal/mtail/basic_tail_integration_test.go +++ b/internal/mtail/basic_tail_integration_test.go @@ -21,7 +21,7 @@ func TestBasicTail(t *testing.T) { } logDir := testutil.TestTempDir(t) - m, stopM := mtail.TestStartServer(t, 2, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) + m, stopM := mtail.TestStartServer(t, 1, 1, mtail.LogPathPatterns(logDir+"/*"), mtail.ProgramPath("../../examples/linecount.mtail")) defer stopM() logFile := filepath.Join(logDir, "log") @@ -31,7 +31,7 @@ func TestBasicTail(t *testing.T) { f := testutil.TestOpenFile(t, logFile) defer f.Close() - m.AwakenPatternPollers(2, 2) // Find `logFile` + m.AwakenPatternPollers(1, 1) // Find `logFile` m.AwakenLogStreams(1, 1) // Force a sync to EOF for i := 1; i <= 3; i++ { diff --git a/internal/mtail/log_deletion_integration_unix_test.go b/internal/mtail/log_deletion_integration_unix_test.go index d02d032dc..0d7a845ca 100644 --- a/internal/mtail/log_deletion_integration_unix_test.go +++ b/internal/mtail/log_deletion_integration_unix_test.go @@ -39,6 +39,6 @@ func TestLogDeletion(t *testing.T) { m.AwakenLogStreams(1, 0) // run stream to observe it's missing logCloseCheck() - m.AwakenPatternPollers(1, 1) + m.AwakenGcPoller(1, 1) logCountCheck() } diff --git a/internal/mtail/log_rotation_integration_test.go b/internal/mtail/log_rotation_integration_test.go index 7bf0c452c..398168761 100644 --- a/internal/mtail/log_rotation_integration_test.go +++ b/internal/mtail/log_rotation_integration_test.go @@ -54,6 +54,7 @@ func TestLogRotationBySoftLinkChange(t *testing.T) { defer trueLog2.Close() m.AwakenPatternPollers(1, 1) m.AwakenLogStreams(1, 1) + m.AwakenGcPoller(1, 1) logClosedCheck := m.ExpectMapExpvarDeltaWithDeadline("log_closes_total", logFilepath, 1) logCompletedCheck := m.ExpectExpvarDeltaWithDeadline("log_count", -1) testutil.FatalIfErr(t, os.Remove(logFilepath)) @@ -63,7 +64,7 @@ func TestLogRotationBySoftLinkChange(t *testing.T) { m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. m.AwakenLogStreams(1, 0) logClosedCheck() // barrier until filestream closes fd - m.AwakenPatternPollers(1, 1) + m.AwakenGcPoller(1, 1) logCompletedCheck() // barrier until the logstream is removed from tailer } testutil.FatalIfErr(t, os.Symlink(logFilepath+".true2", logFilepath)) diff --git a/internal/mtail/log_rotation_integration_unix_test.go b/internal/mtail/log_rotation_integration_unix_test.go index a3a240f3e..c772abcfc 100644 --- a/internal/mtail/log_rotation_integration_unix_test.go +++ b/internal/mtail/log_rotation_integration_unix_test.go @@ -69,7 +69,7 @@ func TestLogRotationByRename(t *testing.T) { m.AwakenPatternPollers(1, 1) // simulate race condition with this poll. m.AwakenLogStreams(1, 0) logClosedCheck() // barrier until filestream closes fd - m.AwakenPatternPollers(1, 1) + m.AwakenGcPoller(1, 1) logCompletedCheck() // barrier until the logstream is removed from tailer } glog.Info("create") diff --git a/internal/mtail/options.go b/internal/mtail/options.go index 71dc062b0..5d4b3699d 100644 --- a/internal/mtail/options.go +++ b/internal/mtail/options.go @@ -109,17 +109,17 @@ func (opt overrideLocation) apply(m *Server) error { return nil } -// StaleLogGcWaker triggers garbage collection runs for stale logs in the tailer. -func StaleLogGcWaker(w waker.Waker) Option { - return &staleLogGcWaker{w} +// GcWaker triggers garbage collection runs for stale logs in the tailer. +func GcWaker(w waker.Waker) Option { + return &gcWaker{w} } -type staleLogGcWaker struct { +type gcWaker struct { waker.Waker } -func (opt staleLogGcWaker) apply(m *Server) error { - m.tOpts = append(m.tOpts, tailer.StaleLogGcWaker(opt.Waker)) +func (opt gcWaker) apply(m *Server) error { + m.tOpts = append(m.tOpts, tailer.GcWaker(opt.Waker)) return nil } diff --git a/internal/mtail/testing.go b/internal/mtail/testing.go index edd70f2c5..25c4670b7 100644 --- a/internal/mtail/testing.go +++ b/internal/mtail/testing.go @@ -34,6 +34,9 @@ type TestServer struct { // method, synchronising the pattern poll with the test. AwakenPatternPollers waker.WakeFunc // the glob awakens + gcWaker waker.Waker // activate the cleanup routines + AwakenGcPoller waker.WakeFunc + tb testing.TB cancel context.CancelFunc @@ -65,9 +68,11 @@ func TestMakeServer(tb testing.TB, patternWakers int, streamWakers int, options } ts.streamWaker, ts.AwakenLogStreams = waker.NewTest(ctx, streamWakers, "streams") ts.patternWaker, ts.AwakenPatternPollers = waker.NewTest(ctx, patternWakers, "patterns") + ts.gcWaker, ts.AwakenGcPoller = waker.NewTest(ctx, 1, "gc") options = append(options, LogstreamPollWaker(ts.streamWaker), LogPatternPollWaker(ts.patternWaker), + GcWaker(ts.gcWaker), ) var err error ts.Server, err = New(ctx, metrics.NewStore(), options...) diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index e6c7473a2..9d03dd15e 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -49,7 +49,7 @@ type Tailer struct { logstreamsMu sync.RWMutex // protects `logstreams`. logstreams map[string]logstream.LogStream // Map absolte pathname to logstream reading that pathname. - staleLogGcWaker waker.Waker // Used to wake stale log GC + gcWaker waker.Waker // Used to wake stale log and completion pollers initDone chan struct{} } @@ -85,8 +85,8 @@ func (opt IgnoreRegex) apply(t *Tailer) error { return t.SetIgnorePattern(string(opt)) } -// StaleLogGcWaker triggers garbage collection runs for stale logs in the tailer. -func StaleLogGcWaker(w waker.Waker) Option { +// GcWaker triggers garbage collection runs for stale logs in the tailer. +func GcWaker(w waker.Waker) Option { return &staleLogGcWaker{w} } @@ -95,7 +95,7 @@ type staleLogGcWaker struct { } func (opt staleLogGcWaker) apply(t *Tailer) error { - t.staleLogGcWaker = opt.Waker + t.gcWaker = opt.Waker return nil } @@ -158,8 +158,7 @@ func New(ctx context.Context, wg *sync.WaitGroup, lines chan<- *logline.LogLine, } } // Start the routine for checking if logstreams have completed. - t.startPollLogStreamsForCompletion(ctx, wg) - t.StartStaleLogstreamExpirationLoop(ctx, wg) + t.StartGcPoller(ctx) // This goroutine cancels the Tailer if all of our dependent subroutines are done. // These are any live logstreams, and any log pattern pollers. @@ -299,45 +298,6 @@ func (t *Tailer) TailPath(pathname string) error { return nil } -// ExpireStaleLogstreams removes logstreams that have had no reads for 1h or more. -func (t *Tailer) ExpireStaleLogstreams() error { - t.logstreamsMu.Lock() - defer t.logstreamsMu.Unlock() - for _, v := range t.logstreams { - if time.Since(v.LastReadTime()) > (time.Hour * 24) { - v.Stop() - } - } - return nil -} - -// StartStaleLogstreamExpirationLoop runs a permanent goroutine to expire stale logstreams. -func (t *Tailer) StartStaleLogstreamExpirationLoop(ctx context.Context, wg *sync.WaitGroup) { - if t.staleLogGcWaker == nil { - glog.InfoContext(ctx, "Log handle expiration disabled") - return - } - wg.Add(1) - go func() { - defer wg.Done() - <-t.initDone - if t.oneShot { - glog.InfoContext(ctx, "No gc loop in oneshot mode.") - return - } - for { - select { - case <-ctx.Done(): - return - case <-t.staleLogGcWaker.Wake(): - if err := t.ExpireStaleLogstreams(); err != nil { - glog.Info(err) - } - } - } - }() -} - // pollLogPattern runs a permanent goroutine to poll for new log files that // match `pattern`. It is on the subroutine waitgroup as we do not want to // shut down the tailer when there are outstanding patterns to poll for. @@ -396,47 +356,58 @@ func (t *Tailer) doPatternGlob(pattern string) error { return nil } -// PollLogStreamsForCompletion looks at the existing paths and checks if they're already -// complete, removing it from the map if so. -func (t *Tailer) PollLogStreamsForCompletion() error { - t.logstreamsMu.Lock() - defer t.logstreamsMu.Unlock() - for name, l := range t.logstreams { - if l.IsComplete() { - glog.Infof("%s is complete", name) - delete(t.logstreams, name) - logCount.Add(-1) - continue - } - } - return nil -} - -// StartPollLogStreamsForCompletion runs a permanent goroutine to poll for -// completed LogStreams. It is on the parent waitgroup as it should exit only once the tailer is shutting down. -func (t *Tailer) startPollLogStreamsForCompletion(ctx context.Context, wg *sync.WaitGroup) { - // Uses the log pattern poll waker for maintenance. - if t.logPatternPollWaker == nil { - glog.InfoContext(ctx, "Log completion polling disabled by no waker") +// StartGcPoller runs a permanent goroutine to expire stale logstreams and clean up completed streams. This background goroutine isn't waited for during shutdown. +func (t *Tailer) StartGcPoller(ctx context.Context) { + if t.gcWaker == nil { + glog.InfoContext(ctx, "stream gc disabled because no waker") return } - wg.Add(1) go func() { - defer wg.Done() <-t.initDone if t.oneShot { - glog.InfoContext(ctx, "No logstream completion polling loop in oneshot mode.") + glog.InfoContext(ctx, "No gc loop in oneshot mode.") return } for { select { case <-ctx.Done(): return - case <-t.logPatternPollWaker.Wake(): - if err := t.PollLogStreamsForCompletion(); err != nil { + case <-t.gcWaker.Wake(): + if err := t.ExpireStaleLogstreams(); err != nil { + glog.Info(err) + } + if err := t.RemoveCompletedLogstreams(); err != nil { glog.Info(err) } } } }() } + +// RemoveCompletedLogstreams checks if current logstreams have completed, +// removing it from the map if so. +func (t *Tailer) RemoveCompletedLogstreams() error { + t.logstreamsMu.Lock() + defer t.logstreamsMu.Unlock() + for name, l := range t.logstreams { + if l.IsComplete() { + glog.Infof("%s is complete", name) + delete(t.logstreams, name) + logCount.Add(-1) + continue + } + } + return nil +} + +// ExpireStaleLogstreams removes logstreams that have had no reads for 1h or more. +func (t *Tailer) ExpireStaleLogstreams() error { + t.logstreamsMu.Lock() + defer t.logstreamsMu.Unlock() + for _, v := range t.logstreams { + if time.Since(v.LastReadTime()) > (time.Hour * 24) { + v.Stop() + } + } + return nil +} diff --git a/internal/tailer/tail_unix_test.go b/internal/tailer/tail_unix_test.go index 421e89d36..57e00002b 100644 --- a/internal/tailer/tail_unix_test.go +++ b/internal/tailer/tail_unix_test.go @@ -36,26 +36,26 @@ func TestTailerOpenRetries(t *testing.T) { if err := ta.TailPath(logfile); err == nil || !os.IsPermission(err) { t.Fatalf("Expected a permission denied error here: %s", err) } - testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) ta.awakenPattern(1, 1) glog.Info("remove") if err := os.Remove(logfile); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) ta.awakenPattern(1, 1) glog.Info("openfile") f, err := os.OpenFile(logfile, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0) //nolint:staticcheck // test code defer f.Close() testutil.FatalIfErr(t, err) - testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) ta.awakenPattern(1, 1) glog.Info("chmod") if err := os.Chmod(logfile, 0o666); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.PollLogStreamsForCompletion()) + testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) ta.awakenPattern(1, 1) ta.awakenStreams(1, 1) // force sync to EOF glog.Info("write string") From eb2957864c935ad2bcd17236d4c053bff7671050 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 12:45:59 +0100 Subject: [PATCH 21/25] Downgrade some log messages. --- internal/tailer/logstream/cancel.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/tailer/logstream/cancel.go b/internal/tailer/logstream/cancel.go index 26377caf1..7fd9053da 100644 --- a/internal/tailer/logstream/cancel.go +++ b/internal/tailer/logstream/cancel.go @@ -18,9 +18,9 @@ type ReadDeadliner interface { func SetReadDeadlineOnDone(ctx context.Context, d ReadDeadliner) { go func() { <-ctx.Done() - glog.Info("cancelled, setting read deadline to interrupt read") + glog.V(1).Info("cancelled, setting read deadline to interrupt read") if err := d.SetReadDeadline(time.Now()); err != nil { - glog.Infof("SetReadDeadline() -> %v", err) + glog.V(1).Infof("SetReadDeadline() -> %v", err) } }() } From 820798f894b25f9314327141eba91f36fc89af02 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 12:58:35 +0100 Subject: [PATCH 22/25] chore: Lint fixes. --- internal/mtail/log_glob_integration_test.go | 1 - internal/tailer/logstream/logstream.go | 14 ++++++-------- internal/tailer/tail.go | 11 +++++------ internal/waker/testwaker.go | 2 -- 4 files changed, 11 insertions(+), 17 deletions(-) diff --git a/internal/mtail/log_glob_integration_test.go b/internal/mtail/log_glob_integration_test.go index 42f104522..ec0b707e1 100644 --- a/internal/mtail/log_glob_integration_test.go +++ b/internal/mtail/log_glob_integration_test.go @@ -91,7 +91,6 @@ func TestGlobAfterStart(t *testing.T) { log := testutil.TestOpenFile(t, tt.name) defer log.Close() m.AwakenPatternPollers(1, 1) - //m.AwakenLogStreams(0, 1) // wait for zero, wake 1 as we're in a loop } logCountCheck() } diff --git a/internal/tailer/logstream/logstream.go b/internal/tailer/logstream/logstream.go index bbdfe7c71..fd73e6b17 100644 --- a/internal/tailer/logstream/logstream.go +++ b/internal/tailer/logstream/logstream.go @@ -88,20 +88,18 @@ func New(ctx context.Context, wg *sync.WaitGroup, waker waker.Waker, pathname st case "", "file": path = u.Path } - var fi os.FileInfo if IsStdinPattern(path) { - fi, err = os.Stdin.Stat() + fi, err := os.Stdin.Stat() if err != nil { logErrors.Add(path, 1) return nil, err } return newPipeStream(ctx, wg, waker, path, fi, lines) - } else { - fi, err = os.Stat(path) - if err != nil { - logErrors.Add(path, 1) - return nil, err - } + } + fi, err := os.Stat(path) + if err != nil { + logErrors.Add(path, 1) + return nil, err } switch m := fi.Mode(); { case m.IsRegular(): diff --git a/internal/tailer/tail.go b/internal/tailer/tail.go index 9d03dd15e..f1e59c2e4 100644 --- a/internal/tailer/tail.go +++ b/internal/tailer/tail.go @@ -224,12 +224,11 @@ func (t *Tailer) AddPattern(pattern string) error { // stdin is not really a socket, but it is handled by this codepath and should not be in the globs. glog.V(2).Infof("AddPattern(%v): is stdin", pattern) return t.TailPath(pattern) - } else { - path, err = filepath.Abs(path) - if err != nil { - glog.V(2).Infof("AddPattern(%v): couldn't canonicalize path: %v", path, err) - return err - } + } + path, err = filepath.Abs(path) + if err != nil { + glog.V(2).Infof("AddPattern(%v): couldn't canonicalize path: %v", path, err) + return err } glog.V(2).Infof("AddPattern(%v): is a file-like pattern", path) t.globPatternsMu.Lock() diff --git a/internal/waker/testwaker.go b/internal/waker/testwaker.go index 6542c6ee1..5a141af62 100644 --- a/internal/waker/testwaker.go +++ b/internal/waker/testwaker.go @@ -20,8 +20,6 @@ type testWaker struct { ctx context.Context - n int - name string wakeeReady chan struct{} From 95a23a69e7d17cda486603bfb5139b25ca08e644 Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 16:39:01 +0100 Subject: [PATCH 23/25] Remove context from struct. We pass the context to the functions so we don't need to keep it in here. --- internal/tailer/logstream/pipestream.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/internal/tailer/logstream/pipestream.go b/internal/tailer/logstream/pipestream.go index df49e8947..d0f05548f 100644 --- a/internal/tailer/logstream/pipestream.go +++ b/internal/tailer/logstream/pipestream.go @@ -17,7 +17,6 @@ import ( ) type pipeStream struct { - ctx context.Context lines chan<- *logline.LogLine pathname string // Given name for the underlying named pipe on the filesystem @@ -30,7 +29,7 @@ type pipeStream struct { // newPipeStream creates a new stream reader for Unix Pipes. // `pathname` must already be verified as clean. func newPipeStream(ctx context.Context, wg *sync.WaitGroup, waker waker.Waker, pathname string, fi os.FileInfo, lines chan<- *logline.LogLine) (LogStream, error) { - ps := &pipeStream{ctx: ctx, pathname: pathname, lastReadTime: time.Now(), lines: lines} + ps := &pipeStream{pathname: pathname, lastReadTime: time.Now(), lines: lines} if err := ps.stream(ctx, wg, waker, fi); err != nil { return nil, err } @@ -87,8 +86,7 @@ func (ps *pipeStream) stream(ctx context.Context, wg *sync.WaitGroup, waker wake if n > 0 { total += n - //nolint:contextcheck - decodeAndSend(ps.ctx, ps.lines, ps.pathname, n, b[:n], partial) + decodeAndSend(ctx, ps.lines, ps.pathname, n, b[:n], partial) // Update the last read time if we were able to read anything. ps.mu.Lock() ps.lastReadTime = time.Now() From 5e470acdfce8d4b6854fecb195e1ab4990decacc Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 16:39:29 +0100 Subject: [PATCH 24/25] chore: Fix linter warning. --- internal/tailer/logstream/pipestream_unix_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/tailer/logstream/pipestream_unix_test.go b/internal/tailer/logstream/pipestream_unix_test.go index 6918c3a8c..7f6fad9eb 100644 --- a/internal/tailer/logstream/pipestream_unix_test.go +++ b/internal/tailer/logstream/pipestream_unix_test.go @@ -54,7 +54,7 @@ func TestPipeStreamReadCompletedBecauseClosed(t *testing.T) { received := testutil.LinesReceived(lines) expected := []*logline.LogLine{ - {context.TODO(), name, "1"}, + {Context: context.TODO(), Filename: name, Line: "1"}, } testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) @@ -97,7 +97,7 @@ func TestPipeStreamReadCompletedBecauseCancel(t *testing.T) { received := testutil.LinesReceived(lines) expected := []*logline.LogLine{ - {context.TODO(), name, "1"}, + {Context: context.TODO(), Filename: name, Line: "1"}, } testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) @@ -135,7 +135,7 @@ func TestPipeStreamReadURL(t *testing.T) { received := testutil.LinesReceived(lines) expected := []*logline.LogLine{ - {context.TODO(), name, "1"}, + {Context: context.TODO(), Filename: name, Line: "1"}, } testutil.ExpectNoDiff(t, expected, received, testutil.IgnoreFields(logline.LogLine{}, "Context")) From e99f7e5846f61f59051ecd24104e8e47488cf1bf Mon Sep 17 00:00:00 2001 From: Jamie Wilkinson Date: Sun, 26 May 2024 16:39:43 +0100 Subject: [PATCH 25/25] test: Fix a race condition waiting for the pattern waker attached to the directory. --- internal/tailer/tail_unix_test.go | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/internal/tailer/tail_unix_test.go b/internal/tailer/tail_unix_test.go index 57e00002b..384806540 100644 --- a/internal/tailer/tail_unix_test.go +++ b/internal/tailer/tail_unix_test.go @@ -36,28 +36,31 @@ func TestTailerOpenRetries(t *testing.T) { if err := ta.TailPath(logfile); err == nil || !os.IsPermission(err) { t.Fatalf("Expected a permission denied error here: %s", err) } - testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) - ta.awakenPattern(1, 1) + + // There testTail includes a pattern poller for tmpDir. Make sure we wait for both. + ta.awakenPattern(1, 2) + glog.Info("remove") if err := os.Remove(logfile); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) - ta.awakenPattern(1, 1) + ta.awakenPattern(2, 2) + glog.Info("openfile") f, err := os.OpenFile(logfile, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0) + testutil.FatalIfErr(t, err) //nolint:staticcheck // test code defer f.Close() - testutil.FatalIfErr(t, err) - testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) - ta.awakenPattern(1, 1) + + ta.awakenPattern(2, 2) glog.Info("chmod") if err := os.Chmod(logfile, 0o666); err != nil { t.Fatal(err) } - testutil.FatalIfErr(t, ta.RemoveCompletedLogstreams()) - ta.awakenPattern(1, 1) + + ta.awakenPattern(2, 2) // discover the logfile ta.awakenStreams(1, 1) // force sync to EOF + glog.Info("write string") testutil.WriteString(t, f, "\n") ta.awakenStreams(1, 1)