unexpected goroutines when `ReadAll(response.body)` - false positive?

[tigerinus]

The issue came from a quite common scenario, which is to read all bytes from response body after a HTTP method call.

To demonstrate the issue, run the following test code with go test, which gives found unexpected goroutines:

package main

import (
    "io"
    "net/http"
    "testing"

    "go.uber.org/goleak"
    "gotest.tools/v3/assert"
)

func TestLeak(t *testing.T) {
    defer goleak.VerifyNone(t)

    request, err := http.NewRequest(http.MethodGet, "https://google.com", nil)
    assert.NilError(t, err)

    client := http.Client{}

    response, err := client.Do(request)
    assert.NilError(t, err)

    defer response.Body.Close()

    _, err = io.ReadAll(response.Body)

    assert.NilError(t, err)
}

full test output:

$ go test
--- FAIL: TestLeak (1.26s)
    main_test.go:28: found unexpected goroutines:
        [Goroutine 14 in state IO wait, with internal/poll.runtime_pollWait on top of the stack:
        goroutine 14 [IO wait]:
        internal/poll.runtime_pollWait(0x7f945c1e0398, 0x72)
                /home/wxh/.local/go/src/runtime/netpoll.go:305 +0x89
        internal/poll.(*pollDesc).wait(0xc000154280?, 0xc0000ca000?, 0x0)
                /home/wxh/.local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
        internal/poll.(*pollDesc).waitRead(...)
                /home/wxh/.local/go/src/internal/poll/fd_poll_runtime.go:89
        internal/poll.(*FD).Read(0xc000154280, {0xc0000ca000, 0x2000, 0x2000})
                /home/wxh/.local/go/src/internal/poll/fd_unix.go:167 +0x25a
        net.(*netFD).Read(0xc000154280, {0xc0000ca000?, 0xc00017edd8?, 0xc0004d5808?})
                /home/wxh/.local/go/src/net/fd_posix.go:55 +0x29
        net.(*conn).Read(0xc00009c000, {0xc0000ca000?, 0xc0000c68f0?, 0x2c?})
                /home/wxh/.local/go/src/net/net.go:183 +0x45
        crypto/tls.(*atLeastReader).Read(0xc0002d4138, {0xc0000ca000?, 0x0?, 0x29f6540f238f2947?})
                /home/wxh/.local/go/src/crypto/tls/conn.go:787 +0x3d
        bytes.(*Buffer).ReadFrom(0xc0000a0278, {0x7c3860, 0xc0002d4138})
                /home/wxh/.local/go/src/bytes/buffer.go:202 +0x98
        crypto/tls.(*Conn).readFromUntil(0xc0000a0000, {0x7c3b80?, 0xc00009c000}, 0xc0000a41c0?)
                /home/wxh/.local/go/src/crypto/tls/conn.go:809 +0xe5
        crypto/tls.(*Conn).readRecordOrCCS(0xc0000a0000, 0x0)
                /home/wxh/.local/go/src/crypto/tls/conn.go:616 +0x116
        crypto/tls.(*Conn).readRecord(...)
                /home/wxh/.local/go/src/crypto/tls/conn.go:582
        crypto/tls.(*Conn).Read(0xc0000a0000, {0xc0001cf000, 0x1000, 0x11?})
                /home/wxh/.local/go/src/crypto/tls/conn.go:1287 +0x16f
        bufio.(*Reader).Read(0xc0001af1a0, {0xc0001aad60, 0x9, 0xc0004d5d18?})
                /home/wxh/.local/go/src/bufio/bufio.go:237 +0x1bb
        io.ReadAtLeast({0x7c3760, 0xc0001af1a0}, {0xc0001aad60, 0x9, 0x9}, 0x9)
                /home/wxh/.local/go/src/io/io.go:332 +0x9a
        io.ReadFull(...)
                /home/wxh/.local/go/src/io/io.go:351
        net/http.http2readFrameHeader({0xc0001aad60?, 0x9?, 0xc0004d5df0?}, {0x7c3760?, 0xc0001af1a0?})
                /home/wxh/.local/go/src/net/http/h2_bundle.go:1565 +0x6e
        net/http.(*http2Framer).ReadFrame(0xc0001aad20)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:1829 +0x95
        net/http.(*http2clientConnReadLoop).run(0xc0004d5f98)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:8875 +0x130
        net/http.(*http2ClientConn).readLoop(0xc00009e180)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:8771 +0x6f
        created by net/http.(*http2Transport).newClientConn
                /home/wxh/.local/go/src/net/http/h2_bundle.go:7478 +0xaaa

         Goroutine 37 in state IO wait, with internal/poll.runtime_pollWait on top of the stack:
        goroutine 37 [IO wait]:
        internal/poll.runtime_pollWait(0x7f945c1e02a8, 0x72)
                /home/wxh/.local/go/src/runtime/netpoll.go:305 +0x89
        internal/poll.(*pollDesc).wait(0xc0003ca000?, 0xc000202000?, 0x0)
                /home/wxh/.local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
        internal/poll.(*pollDesc).waitRead(...)
                /home/wxh/.local/go/src/internal/poll/fd_poll_runtime.go:89
        internal/poll.(*FD).Read(0xc0003ca000, {0xc000202000, 0x1300, 0x1300})
                /home/wxh/.local/go/src/internal/poll/fd_unix.go:167 +0x25a
        net.(*netFD).Read(0xc0003ca000, {0xc000202000?, 0xc0004e6798?, 0xc0004c0808?})
                /home/wxh/.local/go/src/net/fd_posix.go:55 +0x29
        net.(*conn).Read(0xc000014028, {0xc000202000?, 0xc000136630?, 0x2c?})
                /home/wxh/.local/go/src/net/net.go:183 +0x45
        crypto/tls.(*atLeastReader).Read(0xc000276288, {0xc000202000?, 0x0?, 0x150fbb8ccb566149?})
                /home/wxh/.local/go/src/crypto/tls/conn.go:787 +0x3d
        bytes.(*Buffer).ReadFrom(0xc0000a0978, {0x7c3860, 0xc000276288})
                /home/wxh/.local/go/src/bytes/buffer.go:202 +0x98
        crypto/tls.(*Conn).readFromUntil(0xc0000a0700, {0x7c3b80?, 0xc000014028}, 0xc0004cc2c0?)
                /home/wxh/.local/go/src/crypto/tls/conn.go:809 +0xe5
        crypto/tls.(*Conn).readRecordOrCCS(0xc0000a0700, 0x0)
                /home/wxh/.local/go/src/crypto/tls/conn.go:616 +0x116
        crypto/tls.(*Conn).readRecord(...)
                /home/wxh/.local/go/src/crypto/tls/conn.go:582
        crypto/tls.(*Conn).Read(0xc0000a0700, {0xc00023c000, 0x1000, 0x11?})
                /home/wxh/.local/go/src/crypto/tls/conn.go:1287 +0x16f
        bufio.(*Reader).Read(0xc00022a2a0, {0xc00020e2e0, 0x9, 0xc0004c0d18?})
                /home/wxh/.local/go/src/bufio/bufio.go:237 +0x1bb
        io.ReadAtLeast({0x7c3760, 0xc00022a2a0}, {0xc00020e2e0, 0x9, 0x9}, 0x9)
                /home/wxh/.local/go/src/io/io.go:332 +0x9a
        io.ReadFull(...)
                /home/wxh/.local/go/src/io/io.go:351
        net/http.http2readFrameHeader({0xc00020e2e0?, 0x9?, 0xc0004c0df0?}, {0x7c3760?, 0xc00022a2a0?})
                /home/wxh/.local/go/src/net/http/h2_bundle.go:1565 +0x6e
        net/http.(*http2Framer).ReadFrame(0xc00020e2a0)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:1829 +0x95
        net/http.(*http2clientConnReadLoop).run(0xc0004c0f98)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:8875 +0x130
        net/http.(*http2ClientConn).readLoop(0xc00019e300)
                /home/wxh/.local/go/src/net/http/h2_bundle.go:8771 +0x6f
        created by net/http.(*http2Transport).newClientConn
                /home/wxh/.local/go/src/net/http/h2_bundle.go:7478 +0xaaa
        ]
FAIL
exit status 1

Does anyone know how to address this issue?

Thanks!

[Antonboom]

+1

[sywhang]

@tigerinus which go version are you using?

[tigerinus]

by the time this issue was filed, I was using 1.19.

[sywhang]

thanks, I just wanted to make sure i'm repro'ing the same error.

The leak here isn't false positive; it's actually leaking a goroutine spawned up by the http client's Transport that sits there idling in keep-alive state. If you close them by calling client.CloseIdleConnections() that should fix the leak.

Hope that helps.