Flaky Unit Tests

[fgrosse]

Describe the bug

When running unit tests on the current main branch (b636b16) they will randomly fail from time to time.

To Reproduce

❯ git checkout main
❯ git rev-parse HEAD
b636b1633b2c167ff4e2209ae1953a1c0843c303

❯ go test -count=10 -timeout=10s ./mcp
panic: test timed out after 10s
	running tests:
		TestClientReplay (2s)
		TestClientReplay/default (2s)
...

Expected behavior

Unit tests should be deterministic and fail or succeed in a predictable and repeatable manner

Logs

N/A

Additional context

This is a follow-up from #480 (comment) where CI pipelines failed and I looked into unit tests on the main branch to know where the issue is coming from.

[fgrosse]

Full stack trace for a failure is available here: #480 (comment)

GitHub did not allow me to add those to the MR description due to size restrictions.

[fgrosse]

I am investigating the issue now

[fgrosse]

Using https://github.com/uber-go/goleak on main I see there is at least an issue with leaking goroutines in tests. The first indicator for that was the high amount of goroutines in the timeout stack traces.(e.g. goroutine 5204).

I will focus my investigation now on the main branch so understand whats the root cause of flaky tests. I also noticed tests are much slower than I would expect with end-to-end unit tests taking seconds:

❯ go test -count=1 -timeout=10s -v -json ./mcp | jq -r 'select(.Test and .Elapsed and .Elapsed > 0) | [.Test, .Elapsed] | @csv' | column -tx -s,
"TestServerConformance"                                          0.01
"TestEndToEnd/resource_subscriptions"                            1
"TestEndToEnd"                                                   1
"TestKeepAlive"                                                  0.3
"TestKeepAliveFailure"                                           0.03
"TestPointerArgEquivalence/empty"                                0.01
"TestPointerArgEquivalence"                                      0.01
"TestStreamableClientGETHandling"                                0.01
"TestStreamableServerShutdown/stateless_with_keepalive"          0.05
"TestStreamableServerShutdown"                                   0.05
"TestClientReplay/default"                                       1.45
"TestClientReplay/no_retries"                                    0.01
"TestClientReplay"                                               1.46
"TestServerTransportCleanup"                                     0.01
"TestStreamableServerTransport"                                  0.01
"TestStreamableStateless"                                        0.01
"TestServerInterrupt"                                            0.03
"TestStdioContextCancellation"                                   0.1
"TestCmdTransport"                                               0.01
"TestCommandTransportTerminateDuration/default_duration_(zero)"  0.05
"TestCommandTransportTerminateDuration/below_minimum_duration"   0.05
"TestCommandTransportTerminateDuration/custom_valid_duration"    0.2
"TestCommandTransportTerminateDuration"                          0.31

[findleyr]

Thanks. It's quite possible that TestClientReplay has a race; that's a very complicated test involving a proxy power cut...

Also, agree that TestEndToEnd should not take 1s.

I'm happy to help investigate, as I'm familiar with the concurrency model. If you want to highlight tests with goroutine leaks, I can look into them (one possibility is that they're simply missing a Wait on the other side of the connection, but we want to be sure).

I would say 5200 goroutines is not necessarily a sign of a leak, considering that most tests are integration tests and there's a fair bit of concurrency in serving.

[fgrosse]

I have used https://github.com/uber-go/goleak to see if a test leaks routines and then used the following script to invoke tests individually to see which ones fail now (goleak will fail tests if it detects a leak)

diff --git a/mcp/cmd_test.go b/mcp/cmd_test.go
index cbaadcb..15f956a 100644
--- a/mcp/cmd_test.go
+++ b/mcp/cmd_test.go
@@ -18,6 +18,7 @@ import (

        "github.com/google/go-cmp/cmp"
        "github.com/modelcontextprotocol/go-sdk/mcp"
+       "go.uber.org/goleak"
 )

 func TestMain(m *testing.M) {
+       goleak.VerifyTestMain(m)
+

After applying this change run:

❯ for t in $(go test -run=Nothing -list=. ./mcp | grep -v ok); do go test ./mcp -run="$t" > /dev/null && echo -n . || echo -e "\nDetected leak: $t"; done
.............
Detected leak: TestMiddleware
.......
Detected leak: TestSynchronousNotifications
..
Detected leak: TestComplete
........................
Detected leak: TestClientReplay

Detected leak: TestServerTransportCleanup
...
Detected leak: TestStreamableStateless

Detected leak: TestStreamableGET
..
Detected leak: TestBatchFraming

Detected leak: TestIOConnRead
.
Detected leak: TestServerRunContextCancel

Detected leak: TestServerInterrupt
.^C
Detected leak: TestCmdTransport
.........
Detected leak: Example_roots
......
Detected leak: ExampleStreamableHTTPHandler

Detected leak: ExampleStreamableHTTPHandler_middleware
..
Detected leak: ExampleLoggingTransport

One interesting observation here: running tests like this showed also when a test was hanging. There is a ^C in the output because I had to press ctrl+c once to proceed from a hanging command (TestCommandTransport), so I will focus my investigation there later.

I then started to fix those leaks, which are usually caused by not closing sessions in unit tests, so the goroutine in newIOConn would just hang indefinitely.

I would say 5200 goroutines is not necessarily a sign of a leak, considering that most tests are integration tests and there's a fair bit of concurrency in serving.

I agree, however it was just the first example I picked. In my tests, I would get failures with 16k goroutines. My working theory is that this + the network connections they hold have an effect somehow leading to more flakyness.

[findleyr]

Thanks, I'm working through these and most are indeed a lack of client.Close(); server.Wait(), which I am fixing.

Will go through all.

[fgrosse]

I already have the code for most of them ready but I guess even if we did duplicate that work thats okay and we can compare to make sure we got all.

[findleyr]

After looking at these and verifying that they're related to the test harness, I no longer thing this is a release blocker.