storage: TestMVCCDeleteRangeConcurrentTxn failed

[cockroach-teamcity]

storage.TestMVCCDeleteRangeConcurrentTxn failed with artifacts on master @ 7c8e7012b73a598f3aa1da9bbf422e833706f5d3:

=== RUN   TestMVCCDeleteRangeConcurrentTxn
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/c5eb8fc8b8e683c19f3c3e4238f64094/logTestMVCCDeleteRangeConcurrentTxn4218633289
    test_log_scope.go:79: use -show-logs to present logs inline
    mvcc_test.go:1627: -- test log scope end --
    mvcc_test.go:1627: Leaked goroutine: goroutine 20 [chan receive]:
        github.com/cockroachdb/cockroach/pkg/util/log.flushDaemon()
        	github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:75 +0x5b
        created by github.com/cockroachdb/cockroach/pkg/util/log.init.5
        	github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:41 +0x25
--- FAIL: TestMVCCDeleteRangeConcurrentTxn (5.04s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/storage

This test on roachdash | Improve this report!

Jira issue: CRDB-22554

[nicktrav]

This looks like more of an issue in the logging infrastructure, or a very rare flake that depends on goroutine scheduling.

I did some digging into how the leak detection works. Most tests do defer leaktest.AfterTest(t)() at the very start of the test, which will snapshot the goroutines that at running at the time that function is called. The snapshot should already include the logging goroutines, as they are spawned in an init func in pkg/util/log, here.

At the end of the test, the defer'd leak check func runs and snapshots the current goroutines again. If there's a difference, and it's been 5 seconds (to allow for cleanup goroutines to exit, etc.), the test will error if there's a difference in the snapshots.

That check is firing here, saying that we have a goroutine that was started after the initial leak check function call, that has yet to exit.

The flushDaemon goroutine should always be running at the end of the test, as the goroutine does not exit (side note: I assume this is ok?).

I would have thought that the goroutine would be running before we take the initial snapshot too, as the init func in pkg/util/log should have already run at this point, booting up the goroutine. However, now I'm wondering if the runtime only scheduled the goroutine, and had yet to run it when the snapshot was taken?

For what it's worth, I've been running a stress test and I have yet to see a failure.

$ ./dev test ./pkg/storage --filter TestMVCCDeleteRangeConcurrentTxn --stress
...
543987 runs so far, 0 failures, over 45m50s

I think this is just a flake, either in the logging package or in the leak test, rather than a bug in pkg/storage. Going to send this over to Test Eng to see if there's anything that jumps out, either about the test, or the leak check infrastructure.

[blathers-crl]

cc @cockroachdb/test-eng

[srosenberg]

The flushDaemon goroutine should always be running at the end of the test, as the goroutine does not exit (side note: I assume this is ok?).

Yep, based on my reading, the flushDaemon is intended to run until the process terminates. Incidentally, there is a bug wrt doSync–it's always false.

I would have thought that the goroutine would be running before we take the initial snapshot too, as the init func in pkg/util/log should have already run at this point, booting up the goroutine. However, now I'm wondering if the runtime only scheduled the goroutine, and had yet to run it when the snapshot was taken?

It appears to be a race. Note, there have been similar races [1] as of recently; potentially, it's related to the same change [2] although any other non-determinism could have influenced the scheduling order. The fact remains that these goroutines are created asynchronously from init() without any guarantee that the goroutines will have been started by the time init() returns.

I think this is just a flake, either in the logging package or in the leak test, rather than a bug in pkg/storage. Going to send this over to Test Eng to see if there's anything that jumps out, either about the test, or the leak check infrastructure.

Thanks for sending it over to TestEng. It is indeed a flake. Luckily, these appear to be fairly infrequent. E.g., looking at all the issues in the past 9 months, there are only two hits for flushDaemon; one is the current issue; the other is [3], from 2 weeks ago.

gh issue list --search "Leaked goroutine" --state all  --json number,title,body --jq '.[] | "\(.number)\n \(.body)"'

Note, we could add an exclusion for flushDaemon similar to how sentry-go worker goroutine is excluded from the snapshot [4].

[1] #93464 (comment)
[2] #92930
[3] #93034
[4]

cockroach/pkg/util/leaktest/leaktest.go

Line 58 in 61f7c81

strings.Contains(stack, "sentry-go.(*HTTPTransport).worker") ||

[nicktrav]

Note, we could add an exclusion for flushDaemon similar to how sentry-go worker goroutine is excluded from the snapshot [4].

That sounds reasonable, given that the intention of that goroutine is that it's "always" running, and therefore should never "leak". I will put up a patch, at which point we can probably close this out.

Thanks for digging into it!