TestConsumerDelivery is failing

[rubvs]

Unit tests are failing after updating franz-go from v1.11.0 to v1.18.0

• Version Bump: build(deps): bump the franz-go group across 1 directory with 3 updates #589
• Error: https://github.com/elastic/apm-queue/actions/runs/11713914964/job/32627594221?pr=589#step:4:47

[simitt]

@rubvs is the test flaky or consistently failing?

[raultorrecilla]

@rubvs why is this in blocked now? can't remember sorry

[rubvs]

Original error log upgrading from franz-go 1.17 to 1.18+

=== RUN   TestConsumerDelivery
=== RUN   TestConsumerDelivery/12_produced_1_poll_AMOD
panic: test timed out after 10m0s
        running tests:
                TestConsumerDelivery (10m0s)
                TestConsumerDelivery/12_produced_1_poll_AMOD (10m0s)

goroutine 5417 [running]:
testing.(*M).startAlarm.func1()
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:2373 +0x1dc
created by time.goFunc
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/time/sleep.go:215 +0x44

goroutine 1 [chan receive, 6 minutes]:
testing.(*T).Run(0xc0001bb520, {0x1039f2a8f, 0x14}, 0x103e01a68)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1751 +0x600
testing.runTests.func1(0xc0001bb520)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:2168 +0x84
testing.tRunner(0xc0001bb520, 0xc000049ad8)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1690 +0x188
testing.runTests(0xc0001b82a0, {0x1044fc300, 0x21, 0x21}, {0xc0002853b0?, 0x102e56f40?, 0x104502d20?})
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:2166 +0x6e4
testing.(*M).Run(0xc000287ae0)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:2034 +0xb78
main.main()
        _testmain.go:111 +0x114

goroutine 19 [chan receive, 6 minutes]:
testing.(*T).Run(0xc0001bb6c0, {0x1039f5bdb, 0x17}, 0xc00019e810)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1751 +0x600
github.com/elastic/apm-queue/v2/kafka.TestConsumerDelivery(0xc0001bb6c0)
        /Users/rubenvanstaden/issue/apm_queue/595/apm-queue/kafka/consumer_test.go:283 +0x4c8
testing.tRunner(0xc0001bb6c0, 0x103e01a68)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1690 +0x188
created by testing.(*T).Run in goroutine 1
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1743 +0x5e4

goroutine 20 [semacquire, 6 minutes]:
sync.runtime_Semacquire(0xc000300188?)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/runtime/sema.go:71 +0x2c
sync.(*WaitGroup).Wait(0xc000300180)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/sync/waitgroup.go:118 +0x78
github.com/twmb/franz-go/pkg/kgo.(*Client).ProduceSync(0xc00033c008, {0x103e15288, 0xc0003360f0}, {0xc000313930, 0x1, 0x103cfc7a0?})
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/producer.go:325 +0x1cc
github.com/elastic/apm-queue/v2/kafka.produceRecord({0x103e15288, 0xc0003360f0}, {0x103e206c8, 0xc0001bb860}, 0xc00033c008, 0xc00034c000)
        /Users/rubenvanstaden/issue/apm_queue/595/apm-queue/kafka/consumer_test.go:924 +0x7c
github.com/elastic/apm-queue/v2/kafka.TestConsumerDelivery.func1(0xc0001bb860)
        /Users/rubenvanstaden/issue/apm_queue/595/apm-queue/kafka/consumer_test.go:338 +0x5c0
testing.tRunner(0xc0001bb860, 0xc00019e810)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1690 +0x188
created by testing.(*T).Run in goroutine 19
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/testing/testing.go:1743 +0x5e4

goroutine 21 [IO wait]:
internal/poll.runtime_pollWait(0x14d0ce2d0, 0x72)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/runtime/netpoll.go:351 +0xa0
internal/poll.(*pollDesc).wait(0xc0001fb720, 0x72, 0x0)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
internal/poll.(*pollDesc).waitRead(...)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0001fb700)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_unix.go:620 +0x3a8
net.(*netFD).accept(0xc0001fb700)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/fd_unix.go:172 +0x38
net.(*TCPListener).accept(0xc0001b1d00)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock_posix.go:159 +0x40
net.(*TCPListener).Accept(0xc0001b1d00)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock.go:372 +0x68
github.com/twmb/franz-go/pkg/kfake.(*broker).listen(0xc0002857a0)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:243 +0xdc
created by github.com/twmb/franz-go/pkg/kfake.NewCluster in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:186 +0xebc

goroutine 22 [IO wait]:
internal/poll.runtime_pollWait(0x14d0ce1b8, 0x72)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/runtime/netpoll.go:351 +0xa0
internal/poll.(*pollDesc).wait(0xc0001fb820, 0x72, 0x0)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
internal/poll.(*pollDesc).waitRead(...)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0001fb800)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_unix.go:620 +0x3a8
net.(*netFD).accept(0xc0001fb800)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/fd_unix.go:172 +0x38
net.(*TCPListener).accept(0xc0001b1d40)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock_posix.go:159 +0x40
net.(*TCPListener).Accept(0xc0001b1d40)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock.go:372 +0x68
github.com/twmb/franz-go/pkg/kfake.(*broker).listen(0xc000285860)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:243 +0xdc
created by github.com/twmb/franz-go/pkg/kfake.NewCluster in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:186 +0xebc

goroutine 23 [IO wait]:
internal/poll.runtime_pollWait(0x14d0ce0a0, 0x72)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/runtime/netpoll.go:351 +0xa0
internal/poll.(*pollDesc).wait(0xc0001fb8a0, 0x72, 0x0)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:84 +0xb8
internal/poll.(*pollDesc).waitRead(...)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0001fb880)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/internal/poll/fd_unix.go:620 +0x3a8
net.(*netFD).accept(0xc0001fb880)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/fd_unix.go:172 +0x38
net.(*TCPListener).accept(0xc0001b1d80)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock_posix.go:159 +0x40
net.(*TCPListener).Accept(0xc0001b1d80)
        /Users/rubenvanstaden/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.9.darwin-arm64/src/net/tcpsock.go:372 +0x68
github.com/twmb/franz-go/pkg/kfake.(*broker).listen(0xc000285920)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:243 +0xdc
created by github.com/twmb/franz-go/pkg/kfake.NewCluster in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:186 +0xebc

goroutine 24 [select]:
github.com/twmb/franz-go/pkg/kfake.(*Cluster).run(0xc0001bba00)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:272 +0x154
created by github.com/twmb/franz-go/pkg/kfake.NewCluster in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go/pkg/kfake@v0.0.0-20240122000745-a2d69ce07790/cluster.go:189 +0x12d8

goroutine 33 [select]:
github.com/twmb/franz-go/pkg/kgo.(*Client).updateMetadataLoop(0xc00033c008)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/metadata.go:294 +0xd00
created by github.com/twmb/franz-go/pkg/kgo.NewClient in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/client.go:562 +0xfdc

goroutine 34 [select]:
github.com/twmb/franz-go/pkg/kgo.(*Client).reapConnectionsLoop(0xc00033c008)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/broker.go:604 +0x180
created by github.com/twmb/franz-go/pkg/kgo.NewClient in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/client.go:563 +0x1040

goroutine 35 [select, 6 minutes]:
github.com/twmb/franz-go/pkg/kgo.(*Client).pushMetrics(0xc00033c008)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/metrics_714.go:29 +0xfc
created by github.com/twmb/franz-go/pkg/kgo.NewClient in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/client.go:564 +0x10a4

goroutine 36 [select]:
github.com/twmb/franz-go/pkg/kgo.(*Client).waitUnknownTopic(0xc00033c008, {0x103e15288, 0xc0003360f0}, {0x103e15288, 0xc0003360f0}, {0x1039eef2f, 0x10}, 0xc000318db0)
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/producer.go:1073 +0x384
created by github.com/twmb/franz-go/pkg/kgo.(*Client).addUnknownTopicRecord in goroutine 20
        /Users/rubenvanstaden/go/pkg/mod/github.com/twmb/franz-go@v1.19.3/pkg/kgo/producer.go:1039 +0x510
FAIL    github.com/elastic/apm-queue/v2/kafka   600.476s
testing: warning: no tests to run
PASS
ok      github.com/elastic/apm-queue/v2/queuecontext    1.208s [no tests to run]
2025-05-16T11:29:42.458-0400    INFO    systemtest/main_test.go:40      skipping system tests, pass -run-system-tests to enable
ok      github.com/elastic/apm-queue/v2/systemtest      1.628s
FAIL

This turned out not be a concurrency issue in apm-queue or franz-go. The root cause stems from dependabot upgrading franz-go, but not the kfake subpackage, which is not versioned. Manually upgrading solves this issue related to the TestConsumerDelivery test.

go get -u github.com/twmb/franz-go/pkg/kfake