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

Paul Gevers Thu, 30 Mar 2023 12:06:20 -0700

Source: kel-agent
Version: 0.4.6-2
Severity: serious
Control: tags -1 bookworm-ignore
User: debian...@lists.debian.org
Usertags: regression


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

OpenPGP_signature
Description: OpenPGP digital signature

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

Reply via email to