From 706f7ce6c85145bd1785b2c252dd50c555585579 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 2 Jul 2025 10:16:44 +0000 Subject: [PATCH 1/2] fix(agent/agentcontainers): avoid logspam in API updaterLoop Fixes #18709 --- agent/agentcontainers/api.go | 9 ++- agent/agentcontainers/api_test.go | 99 +++++++++++++++++++++++++++++++ 2 files changed, 107 insertions(+), 1 deletion(-) diff --git a/agent/agentcontainers/api.go b/agent/agentcontainers/api.go index d96b29f863188..9601beb3f13c2 100644 --- a/agent/agentcontainers/api.go +++ b/agent/agentcontainers/api.go @@ -449,6 +449,7 @@ func (api *API) updaterLoop() { // We utilize a TickerFunc here instead of a regular Ticker so that // we can guarantee execution of the updateContainers method after // advancing the clock. + var prevErr error ticker := api.clock.TickerFunc(api.ctx, api.updateInterval, func() error { done := make(chan error, 1) var sent bool @@ -467,8 +468,14 @@ func (api *API) updaterLoop() { if errors.Is(err, context.Canceled) { api.logger.Warn(api.ctx, "updater loop ticker canceled", slog.Error(err)) } else { - api.logger.Error(api.ctx, "updater loop ticker failed", slog.Error(err)) + // Avoid excessive logging of the same error. + if prevErr == nil || prevErr.Error() != err.Error() { + api.logger.Error(api.ctx, "updater loop ticker failed", slog.Error(err)) + } } + prevErr = err + } else { + prevErr = nil } default: api.logger.Debug(api.ctx, "updater loop ticker skipped, update in progress") diff --git a/agent/agentcontainers/api_test.go b/agent/agentcontainers/api_test.go index e6103d8bfd2b4..37ce66e2c150b 100644 --- a/agent/agentcontainers/api_test.go +++ b/agent/agentcontainers/api_test.go @@ -26,6 +26,7 @@ import ( "golang.org/x/xerrors" "cdr.dev/slog" + "cdr.dev/slog/sloggers/sloghuman" "cdr.dev/slog/sloggers/slogtest" "github.com/coder/coder/v2/agent/agentcontainers" "github.com/coder/coder/v2/agent/agentcontainers/acmock" @@ -342,6 +343,104 @@ func (f *fakeExecer) getLastCommand() *exec.Cmd { func TestAPI(t *testing.T) { t.Parallel() + t.Run("NoUpdaterLoopLogspam", func(t *testing.T) { + t.Parallel() + + var ( + ctx = testutil.Context(t, testutil.WaitShort) + logbuf strings.Builder + logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug).AppendSinks(sloghuman.Sink(&logbuf)) + mClock = quartz.NewMock(t) + tickerTrap = mClock.Trap().TickerFunc("updaterLoop") + firstErr = xerrors.New("first error") + secondErr = xerrors.New("second error") + fakeCLI = &fakeContainerCLI{ + listErr: firstErr, + } + ) + + api := agentcontainers.NewAPI(logger, + agentcontainers.WithClock(mClock), + agentcontainers.WithContainerCLI(fakeCLI), + ) + api.Start() + defer api.Close() + + // Make sure the ticker function has been registered + // before advancing the clock. + tickerTrap.MustWait(ctx).MustRelease(ctx) + tickerTrap.Close() + + logbuf.Reset() + + // First tick should handle the error. + _, aw := mClock.AdvanceNext() + aw.MustWait(ctx) + + // Verify first error is logged. + got := logbuf.String() + t.Logf("got log: %q", got) + require.Contains(t, got, "updater loop ticker failed", "first error should be logged") + require.Contains(t, got, "first error", "should contain first error message") + logbuf.Reset() + + // Second tick should handle the same error without logging it again. + _, aw = mClock.AdvanceNext() + aw.MustWait(ctx) + + // Verify same error is not logged again. + got = logbuf.String() + t.Logf("got log: %q", got) + require.Empty(t, got, "same error should not be logged again") + + // Change to a different error. + fakeCLI.listErr = secondErr + + // Third tick should handle the different error and log it. + _, aw = mClock.AdvanceNext() + aw.MustWait(ctx) + + // Verify different error is logged. + got = logbuf.String() + t.Logf("got log: %q", got) + require.Contains(t, got, "updater loop ticker failed", "different error should be logged") + require.Contains(t, got, "second error", "should contain second error message") + logbuf.Reset() + + // Clear the error to simulate success. + fakeCLI.listErr = nil + + // Fourth tick should succeed. + _, aw = mClock.AdvanceNext() + aw.MustWait(ctx) + + // Fifth tick should continue to succeed. + _, aw = mClock.AdvanceNext() + aw.MustWait(ctx) + + // Verify successful operations are logged properly. + got = logbuf.String() + t.Logf("got log: %q", got) + gotSuccessCount := strings.Count(got, "containers updated successfully") + require.GreaterOrEqual(t, gotSuccessCount, 2, "should have successful update got") + require.NotContains(t, got, "updater loop ticker failed", "no errors should be logged during success") + logbuf.Reset() + + // Reintroduce the original error. + fakeCLI.listErr = firstErr + + // Sixth tick should handle the error after success and log it. + _, aw = mClock.AdvanceNext() + aw.MustWait(ctx) + + // Verify error after success is logged. + got = logbuf.String() + t.Logf("got log: %q", got) + require.Contains(t, got, "updater loop ticker failed", "error after success should be logged") + require.Contains(t, got, "first error", "should contain first error message") + logbuf.Reset() + }) + // List tests the API.getContainers method using a mock // implementation. It specifically tests caching behavior. t.Run("List", func(t *testing.T) { From ec4743e864d29aadccecba7fd5ed1c9ed2061ac8 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 2 Jul 2025 10:35:27 +0000 Subject: [PATCH 2/2] appease linter... --- agent/agentcontainers/api.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/agent/agentcontainers/api.go b/agent/agentcontainers/api.go index 9601beb3f13c2..d749bf88a522e 100644 --- a/agent/agentcontainers/api.go +++ b/agent/agentcontainers/api.go @@ -467,11 +467,11 @@ func (api *API) updaterLoop() { if err != nil { if errors.Is(err, context.Canceled) { api.logger.Warn(api.ctx, "updater loop ticker canceled", slog.Error(err)) - } else { - // Avoid excessive logging of the same error. - if prevErr == nil || prevErr.Error() != err.Error() { - api.logger.Error(api.ctx, "updater loop ticker failed", slog.Error(err)) - } + return nil + } + // Avoid excessive logging of the same error. + if prevErr == nil || prevErr.Error() != err.Error() { + api.logger.Error(api.ctx, "updater loop ticker failed", slog.Error(err)) } prevErr = err } else {