#1033710 kel-agent: autopkgtest regression: panic: test timed out after 10m0s

#1033710#5
Date:
2023-03-30 19:02:10 UTC
From:
To:
Dear maintainer(s),

Your package has an autopkgtest, great. However, it fails since June
2022, which aligns roughly with the upload of version 0.4.6-1. It seems
that 0.4.6-2 was alowed to migrate because version 0.2.2-1 regressed in
testing at the same time. Can you please investigate the situation and
fix it? I copied some of the output at the bottom of this report. I note
that I see the following in the build logs:
"""
     suite_test.go:29: These integration tests freeze when building in
sbuild chroot
--- SKIP: TestIntegrationSuite (0.00s)
"""
so it might be that the "solution" for building has to be applied for
autopkgtesting as well.

The release team has announced [1] that failing autopkgtest on amd64 and
arm64 are considered RC in testing. [Release Team member hat on] Because
we're currently in the hard freeze for bookworm, I have marked this bug
as bookworm-ignore. Targeted fixes are still welcome.

More information about this bug and the reason for filing it can be
found on
https://wiki.debian.org/ContinuousIntegration/RegressionEmailInformation

Paul

[1] https://lists.debian.org/debian-devel-announce/2019/07/msg00002.html

https://ci.debian.net/data/autopkgtest/testing/amd64/k/kel-agent/32233832/log.gz

make[1]: Leaving directory
'/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp'
    dh_auto_test -O--builddirectory=_build -O--buildsystem=golang
	cd _build && go test -vet=off -v -p 64 github.com/k0swe/kel-agent
github.com/k0swe/kel-agent/integration
github.com/k0swe/kel-agent/internal/config
github.com/k0swe/kel-agent/internal/ws
github.com/k0swe/kel-agent/internal/wsjtx_wrapper
?   	github.com/k0swe/kel-agent	[no test files]
=== RUN   TestIntegrationSuite
=== RUN   TestIntegrationSuite/TestReceive
     wsjtx-fake.go:28: fake is connected to 127.0.0.1:2237
     suite_test.go:65: suite reports fake is connected
=== RUN   TestIntegrationSuite/TestReceive/clear
=== CONT  TestIntegrationSuite/TestReceive
     wsjtx-fake.go:37: sending message
     wsjtx-fake.go:43: listening for receives
panic: test timed out after 10m0s

goroutine 19 [running]:
testing.(*M).startAlarm.func1()
	/usr/lib/go-1.19/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	/usr/lib/go-1.19/src/time/sleep.go:176 +0x32

goroutine 1 [chan receive, 9 minutes]:
testing.(*T).Run(0xc00013e820, {0x8c7845?, 0x50e005?}, 0x8fb620)
	/usr/lib/go-1.19/src/testing/testing.go:1494 +0x37a
testing.runTests.func1(0xc00011d440?)
	/usr/lib/go-1.19/src/testing/testing.go:1846 +0x6e
testing.tRunner(0xc00013e820, 0xc00014fcd8)
	/usr/lib/go-1.19/src/testing/testing.go:1446 +0x10b
testing.runTests(0xc000001220?, {0xbfb9a0, 0x1, 0x1}, {0x7f83d4d14108?,
0x40?, 0xc0a020?})
	/usr/lib/go-1.19/src/testing/testing.go:1844 +0x456
testing.(*M).Run(0xc000001220)
	/usr/lib/go-1.19/src/testing/testing.go:1726 +0x5d9
main.main()
	_testmain.go:47 +0x1aa

goroutine 6 [chan receive, 9 minutes]:
testing.(*T).Run(0xc00013e9c0, {0x8181fa?, 0xc00013e9c0?}, 0xc00025c000)
	/usr/lib/go-1.19/src/testing/testing.go:1494 +0x37a
github.com/stretchr/testify/suite.runTests({0x978da0, 0xc00013e9c0},
{0xc000012a98?, 0x1, 0x1})
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/stretchr/testify/suite/suite.go:220 +0x128
github.com/stretchr/testify/suite.Run(0xc00013e9c0, {0x974878,
0xc00011f450})
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/stretchr/testify/suite/suite.go:193 +0x6e5
github.com/k0swe/kel-agent/integration.TestIntegrationSuite(0xc00013e9c0)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/integration/suite_test.go:31 +0x8a
testing.tRunner(0xc00013e9c0, 0x8fb620)
	/usr/lib/go-1.19/src/testing/testing.go:1446 +0x10b
created by testing.(*T).Run
	/usr/lib/go-1.19/src/testing/testing.go:1493 +0x35f

goroutine 7 [select, 9 minutes]:
github.com/k0swe/kel-agent/internal/wsjtx_wrapper.(*Handler).ListenToWsjtx(0xc000244460,
0x8fb620?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/wsjtx_wrapper/wsjtx.go:53 +0x1a9
created by github.com/k0swe/kel-agent/internal/ws.newHub
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/hub.go:54 +0x17b

goroutine 8 [select, 9 minutes]:
github.com/k0swe/kel-agent/internal/ws.(*Hub).run(0xc0001098c0)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/hub.go:71 +0x12f
created by github.com/k0swe/kel-agent/internal/ws.Start
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/server.go:27 +0x14a

goroutine 9 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f83a7fcdb28, 0x72)
	/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000246100?, 0x400000?, 0x0)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000246100)
	/usr/lib/go-1.19/src/internal/poll/fd_unix.go:614 +0x234
net.(*netFD).accept(0xc000246100)
	/usr/lib/go-1.19/src/net/fd_unix.go:172 +0x35
net.(*TCPListener).accept(0xc000012a80)
	/usr/lib/go-1.19/src/net/tcpsock_posix.go:142 +0x28
net.(*TCPListener).Accept(0xc000012a80)
	/usr/lib/go-1.19/src/net/tcpsock.go:288 +0x3d
net/http.(*Server).Serve(0xc000248000, {0x975ec0, 0xc000012a80})
	/usr/lib/go-1.19/src/net/http/server.go:3070 +0x385
net/http.(*Server).ListenAndServe(0xc000248000)
	/usr/lib/go-1.19/src/net/http/server.go:2999 +0x7d
net/http.ListenAndServe(...)
	/usr/lib/go-1.19/src/net/http/server.go:3255
github.com/k0swe/kel-agent/internal/ws.Start.func2()
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/server.go:49 +0x18f
created by github.com/k0swe/kel-agent/internal/ws.Start
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/server.go:43 +0x611

goroutine 18 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f83a7fcdc18, 0x72)
	/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000246000?, 0xc000345b38?, 0x0)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).ReadFromInet4(0xc000246000, {0xc000345b38, 0x400,
0x400}, 0x0?)
	/usr/lib/go-1.19/src/internal/poll/fd_unix.go:250 +0x1e5
net.(*netFD).readFromInet4(0xc000246000, {0xc000345b38?, 0x0?,
0xc000345a08?}, 0x1?)
	/usr/lib/go-1.19/src/net/fd_posix.go:66 +0x29
net.(*UDPConn).readFrom(0xc000300000?, {0xc000345b38?, 0x0?,
0xc000345af0?}, 0xc0002359e0)
	/usr/lib/go-1.19/src/net/udpsock_posix.go:52 +0x1b8
net.(*UDPConn).readFromUDP(0xc000014d28, {0xc000345b38?, 0x400?, 0x0?},
0x0?)
	/usr/lib/go-1.19/src/net/udpsock.go:149 +0x31
net.(*UDPConn).ReadFromUDP(...)
	/usr/lib/go-1.19/src/net/udpsock.go:141
github.com/k0swe/wsjtx-go.(*Server).ListenToWsjtx(0xc000244460,
0xc00018e000, 0xc00018e060)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/wsjtx-go/server.go:81 +0x13a
created by
github.com/k0swe/kel-agent/internal/wsjtx_wrapper.(*Handler).ListenToWsjtx
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/wsjtx_wrapper/wsjtx.go:50 +0x12a

goroutine 67 [select]:
github.com/k0swe/kel-agent/internal/ws.(*Client).writePump(0xc0002c0018)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/client.go:89 +0x119
created by github.com/k0swe/kel-agent/internal/ws.Server.serveWs
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/client.go:129 +0x225

goroutine 68 [IO wait]:
internal/poll.runtime_pollWait(0x7f83a7fcd948, 0x72)
	/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000382000?, 0xc0002c2000?, 0x0)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000382000, {0xc0002c2000, 0x400, 0x400})
	/usr/lib/go-1.19/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000382000, {0xc0002c2000?, 0x72?, 0x0?})
	/usr/lib/go-1.19/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000386000, {0xc0002c2000?, 0xc0a020?, 0xc000285ce0?})
	/usr/lib/go-1.19/src/net/net.go:183 +0x45
bufio.(*Reader).fill(0xc000288240)
	/usr/lib/go-1.19/src/bufio/bufio.go:106 +0xff
bufio.(*Reader).Peek(0xc000288240, 0x2)
	/usr/lib/go-1.19/src/bufio/bufio.go:144 +0x5d
github.com/gorilla/websocket.(*Conn).read(0xc0002ac160, 0x1?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:371 +0x2c
github.com/gorilla/websocket.(*Conn).advanceFrame(0xc0002ac160)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:809 +0x7b
github.com/gorilla/websocket.(*Conn).NextReader(0xc0002ac160)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:1009 +0xcc
github.com/gorilla/websocket.(*Conn).ReadMessage(0xc000386000?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:1093 +0x19
github.com/k0swe/kel-agent/internal/ws.(*Client).readPump(0xc0002c0018)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/client.go:65 +0x211
created by github.com/k0swe/kel-agent/internal/ws.Server.serveWs
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/internal/ws/client.go:130 +0x265

goroutine 10 [chan receive, 9 minutes]:
testing.(*T).Run(0xc00013f6c0, {0x8c0fc0?, 0xc3b8a0?}, 0xc000012bb8)
	/usr/lib/go-1.19/src/testing/testing.go:1494 +0x37a
github.com/k0swe/kel-agent/integration.(*integrationTestSuite).TestReceive(0xc00011f450)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/integration/receive_test.go:26 +0x205
reflect.Value.call({0xc00010a840?, 0xc000014d10?, 0xc00013f6c0?},
{0x8c0b5a, 0x4}, {0xc0000f2e70, 0x1, 0xc0000f2d80?})
	/usr/lib/go-1.19/src/reflect/value.go:584 +0x8c5
reflect.Value.Call({0xc00010a840?, 0xc000014d10?, 0xc00011f450?},
{0xc0000f2e70?, 0x7f83d4d1fc98?, 0xd0?})
	/usr/lib/go-1.19/src/reflect/value.go:368 +0xbc
github.com/stretchr/testify/suite.Run.func1(0xc00013f6c0)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/stretchr/testify/suite/suite.go:175 +0x4b6
testing.tRunner(0xc00013f6c0, 0xc00025c000)
	/usr/lib/go-1.19/src/testing/testing.go:1446 +0x10b
created by testing.(*T).Run
	/usr/lib/go-1.19/src/testing/testing.go:1493 +0x35f

goroutine 11 [IO wait]:
internal/poll.runtime_pollWait(0x7f83a7fcd858, 0x72)
	/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000246a80?, 0xc000349770?, 0x0)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000246a80, {0xc000349770, 0x800, 0x800})
	/usr/lib/go-1.19/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000246a80, {0xc000349770?, 0xc000349720?, 0xc0a020?})
	/usr/lib/go-1.19/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000014e40, {0xc000349770?, 0xc0a020?, 0xc0a020?})
	/usr/lib/go-1.19/src/net/net.go:183 +0x45
github.com/k0swe/kel-agent/integration.(*WsjtxFake).handleReceive(0xc0000ff6a0)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/integration/wsjtx-fake.go:53 +0xf9
created by github.com/k0swe/kel-agent/integration.NewFake
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/integration/wsjtx-fake.go:31 +0x1a5

goroutine 12 [IO wait]:
internal/poll.runtime_pollWait(0x7f83a7fcda38, 0x72)
	/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000328080?, 0xc000334000?, 0x0)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000328080, {0xc000334000, 0x1000, 0x1000})
	/usr/lib/go-1.19/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000328080, {0xc000334000?, 0x8a88f05a0e?, 0xc0a020?})
	/usr/lib/go-1.19/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000316008, {0xc000334000?, 0xc000320160?, 0x0?})
	/usr/lib/go-1.19/src/net/net.go:183 +0x45
bufio.(*Reader).fill(0xc0003220c0)
	/usr/lib/go-1.19/src/bufio/bufio.go:106 +0xff
bufio.(*Reader).Peek(0xc0003220c0, 0x2)
	/usr/lib/go-1.19/src/bufio/bufio.go:144 +0x5d
github.com/gorilla/websocket.(*Conn).read(0xc000320160, 0x1?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:371 +0x2c
github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000320160)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:809 +0x7b
github.com/gorilla/websocket.(*Conn).NextReader(0xc000320160)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:1009 +0xcc
github.com/gorilla/websocket.(*Conn).ReadMessage(0xc0000ff6a0?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/gorilla/websocket/conn.go:1093 +0x19
github.com/k0swe/kel-agent/integration.(*integrationTestSuite).TestReceive.func1(0x0?)
	/tmp/autopkgtest-lxc.m1xmj9qe/downtmp/autopkgtest_tmp/_build/src/github.com/k0swe/kel-agent/integration/receive_test.go:31 +0x14e
testing.tRunner(0xc00013fba0, 0xc000012bb8)
	/usr/lib/go-1.19/src/testing/testing.go:1446 +0x10b
created by testing.(*T).Run
	/usr/lib/go-1.19/src/testing/testing.go:1493 +0x35f
FAIL	github.com/k0swe/kel-agent/integration	600.021s
?   	github.com/k0swe/kel-agent/internal/config	[no test files]
?   	github.com/k0swe/kel-agent/internal/ws	[no test files]
?   	github.com/k0swe/kel-agent/internal/wsjtx_wrapper	[no test files]
FAIL