app/youtube tests fail on an idle machine: deadlines too tight for the work asserted

[paskal]

Three tests bound Service.Do with a context deadline barely longer than the work it has to finish, then assert on something that only holds if the work completed. A fourth, TestChannel_Get, has the same flavour of problem with an HTTP client timeout.

Three of the four fail on a completely idle machine: TestService_Do, TestService_DoIsAllowedFilter and TestChannel_Get. The fourth, TestService_DoYtDlpUpdateOnStartup, needs CPU contention before it will fail at all.

All figures below are from 362ae37, darwin/arm64, 8 cores, go1.26.5.

Reproduction

Idle machine, nothing else running:

go test -race -count=20 -run 'TestService_Do$'             ./app/youtube       # 9 of 20 failed
go test -race -count=30 -run TestService_DoIsAllowedFilter ./app/youtube       # 10 of 30 failed
go test -race -count=30 -run TestChannel_Get               ./app/youtube/feed  # 1 of 30 failed

-count reuses one process, so TestService_Do was also run as 15 separate -count=1 processes, the shape CI actually uses: 3 of 15 failed.

TestService_DoYtDlpUpdateOnStartup does not reproduce idle (0 of 30). It needs contention:

for i in $(seq 1 16); do (while :; do :; done) & done      # 16 busy loops on 8 cores
go test -race -count=30 -run TestService_DoYtDlpUpdateOnStartup ./app/youtube   # 1 of 30 failed
go test -race -count=30 -run TestChannel_Get ./app/youtube/feed                 # 3 of 30 failed
kill %1 %2 %3 %4 %5 %6 %7 %8 %9 %10 %11 %12 %13 %14 %15 %16

TestService_Do and TestService_DoIsAllowedFilter

Both set CheckDuration: 500ms (app/youtube/service_test.go:128 and :229) under a 900ms deadline (:135 and :235), so the initial pass and exactly one tick pass must both finish inside 900ms. Two separate assertions break.

The error text, app/youtube/service_test.go:139 and :239:

require.EqualError(t, err, "youtube service stopped: context deadline exceeded")

Do has three returns on a cancelled context and only one produces that string:

• app/youtube/service.go:113 wraps the initial procChannels as failed to process channels: %w
• app/youtube/service.go:119 is the outer select, returning youtube service stopped: %w
• app/youtube/service.go:127 wraps the tick's procChannels as failed to process channels: %w

Whichever the deadline lands in decides the message, and it is often 113 or 127:

    service_test.go:139:
        Error:  Error message not equal:
                expected: "youtube service stopped: context deadline exceeded"
                actual  : "failed to process channels: processing channels stopped: context deadline exceeded"

7 of the 9 TestService_Do failures and 8 of the 10 TestService_DoIsAllowedFilter failures were this.

The call count, app/youtube/service_test.go:141 and :241:

require.Len(t, chans.GetCalls(), 4)

When the tick pass does not run, only the initial pass's two calls are recorded:

    service_test.go:141:
        Error:  "[{...channel1 channel} {...channel2 playlist}]" should have 4 item(s), but has 2

That was the remaining 2 of 9 and 2 of 10.

TestService_DoYtDlpUpdateOnStartup

Do runs the startup update first, at app/youtube/service.go:98-100, via exec.CommandContext(ctx, "sh", "-c", updCmd) at :601. The subtest sets YtDlpUpdCommand: "touch " + markerFile under a 600ms deadline (app/youtube/service_test.go:52) and asserts the marker exists at :56. The command shares the test's context, so expiry kills it mid-flight:

WARN failed to execute yt-dlp update command touch /var/folders/.../ytdlp-updated: signal: killed
    service_test.go:56:
        Error:    unable to find file ".../ytdlp-updated"
        Messages: yt-dlp update command should run on startup

signal: killed is CommandContext reaping the subprocess, so it is the deadline rather than a slow touch.

TestChannel_Get

app/youtube/feed/feed_test.go:27 builds &http.Client{Timeout: time.Second} against a local httptest server serving a 15-entry document; :31 requires no error:

    feed_test.go:31:
        Error: Received unexpected error:
               failed to decode UCPU28A9z_ka_R5dQfecHJlA: context deadline exceeded
               (Client.Timeout or context cancellation while reading body)

Impact

.github/workflows/ci.yml:28 runs go test -race -v -timeout=100s ... ./... on every push and pull request, so each of these is a chance of a red build that means nothing. The rates above are from this machine; the three most recent CI runs on master all passed, so the rate on GitHub's runners is lower. What is certain is that the failures reproduce on demand and are timing rather than logic.

Options

1. Raise the deadlines. Smallest diff: 900ms and 600ms become a few seconds, and the client timeout goes up. The three Do tests wait out their full deadline either way, so the package gets slower by that much; TestChannel_Get returns as soon as the request succeeds, so it costs nothing there. Narrows the race rather than removing it.
2. Wait on the observable condition. Run Do in a goroutine and use require.Eventually on what is actually being asserted, then cancel and check the error. Removes the race and makes the tests finish as soon as the work is done. Three things to get right:
   • the result needs a buffered channel, and the test has to cancel the context and receive from it before asserting, so Do is not still running against t;
   • app/youtube/service_test.go:99 calls require.NoError inside the downloader mock. require calls FailNow, which is only valid on the test goroutine, so once Do moves off it that check has to become a returned error from the mock instead.
   • the wait condition has to come from the last effect the later assertions depend on. len(chans.GetCalls()) >= 4 is no good: the generated mock appends to calls.Get at app/youtube/mocks/channel.go:62 and only invokes GetFunc at :64, so the count reaches 4 the instant the second pass enters the channel mock, with none of the work done. Cancelling there races the store writes, the six downloader.GetCalls() and the channel1.xml / channel2.xml contents that app/youtube/service_test.go:150-186 goes on to check, and switching the error assertion to ErrorIs does not close that gap, because cancelling mid-pass still returns through app/youtube/service.go:127. procChannels writes each channel's RSS file at the end of that channel's processing, so the second pass rewriting the last channel's file is a condition that does imply the rest.
3. Test procChannels directly. The two behavioural tests are really about what one pass does, not about the ticker: calling procChannels twice with a live context and asserting afterwards removes both the deadline and the scheduling from the picture entirely, leaving a small separate test for the Do loop itself. Largest diff of the four, and the one that makes the assertions unconditional.
4. Loosen the error assertion. Replace the two require.EqualError calls with require.ErrorIs(t, err, context.DeadlineExceeded), which holds on all three exits. Fixes only the error-text mode, not the call count or the marker.

My preference is 3 for TestService_Do and TestService_DoIsAllowedFilter. Everything those two actually check is about one pass, and testing procChannels directly makes every assertion unconditional rather than merely likely; 2 keeps the scheduling in the test and so keeps some of the difficulty. If restructuring those two tests is more than you want, 4 is the minimal change that stops the error-text mode, and leaves the call-count mode to be handled by a longer deadline under 1. For TestService_DoYtDlpUpdateOnStartup, 2 is the right shape, since the marker file is a clean signal to wait on. For TestChannel_Get the one-second client timeout can simply go: the server is in-process. The trade is the fallback timeout that replaces it, 100s under CI's -timeout=100s and Go's default 10 minutes for a bare local go test, so a genuinely hung request fails much later than it does now.

A related choice in the product code

app/youtube/service.go:113 and :127 wrap a cancelled context as failed to process channels, which is what makes the error-text assertion unstable. Worth noting that the cancellation wrap does not currently surface in production: app/main.go:144 calls Do(context.TODO()), which nothing cancels, so neither the 113 nor the 127 path can be reached by a shutdown. The [ERROR] youtube processor failed log at main.go:145 still does its job for genuine failures, which procChannels can return at app/youtube/service.go:243, :253 and :320. So this is a question about what the tests should assert, not a bug.

If you would rather all three exits reported cancellation identically, the change is to check ctx.Err() at 113 and 127 and return fmt.Errorf("youtube service stopped: %w", ctx.Err()) there, keeping the failed to process channels wrapper only for genuine errors. That makes the two existing require.EqualError assertions correct as written. Returning a bare ctx.Err() instead would not, since the expected text comes from the wrapper.