search

go-zeromq / zmq4

[WIP] Pure-Go implementation of ZeroMQ-4
BSD 3-Clause "New" or "Revised" License
344 stars 57 forks source link

Deadlock detected by TestConnReaperDeadlock #149

Closed egorse closed 9 months ago

egorse commented 11 months ago

Running while go test -timeout 30s -run ^TestConnReaperDeadlock$; do echo .; done with v0.16.0 eventually may get test failed by timeout

The output is next:

panic: test timed out after 30s
running tests:
    TestConnReaperDeadlock (30s)

goroutine 42 [running]:
testing.(*M).startAlarm.func1()
    /usr/local/go/src/testing/testing.go:2259 +0x3b9
created by time.goFunc
    /usr/local/go/src/time/sleep.go:176 +0x2d

goroutine 1 [chan receive]:
testing.(*T).Run(0xc00020d380, {0x5f1463?, 0x4d20bc?}, 0x5fe1e8)
    /usr/local/go/src/testing/testing.go:1649 +0x3c8
testing.runTests.func1(0x770c60?)
    /usr/local/go/src/testing/testing.go:2054 +0x3e
testing.tRunner(0xc00020d380, 0xc0000c3c48)
    /usr/local/go/src/testing/testing.go:1595 +0xff
testing.runTests(0xc0000a0140?, {0x76b8c0, 0x21, 0x21}, {0x414a85?, 0xc0000c3d08?, 0x770440?})
    /usr/local/go/src/testing/testing.go:2052 +0x445
testing.(*M).Run(0xc0000a0140)
    /usr/local/go/src/testing/testing.go:1925 +0x636
main.main()
    _testmain.go:115 +0x19c

goroutine 19 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000fa3d0, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0xc0000dc640?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a4480)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 20 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000fa610, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a47e0)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 21 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000fa850, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a4b40)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 23 [select]:
github.com/go-zeromq/zmq4.(*repWriter).run(0xc0000fab40)
    /home/egorse/projects/public/zmq4-tag/rep.go:272 +0xf4
created by github.com/go-zeromq/zmq4.newRepWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/rep.go:232 +0xd6

goroutine 24 [select]:
github.com/go-zeromq/zmq4.(*repWriter).run(0xc0000facc0)
    /home/egorse/projects/public/zmq4-tag/rep.go:272 +0xf4
created by github.com/go-zeromq/zmq4.newRepWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/rep.go:232 +0xd6

goroutine 25 [select]:
github.com/go-zeromq/zmq4.(*repWriter).run(0xc0000fae40)
    /home/egorse/projects/public/zmq4-tag/rep.go:272 +0xf4
created by github.com/go-zeromq/zmq4.newRepWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/rep.go:232 +0xd6

goroutine 27 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000faf90, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0xc0000dd680?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a52c0)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 28 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000fb1d0, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a5620)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 29 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0000fb410, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*pubMWriter).run(0xc0000a5980)
    /home/egorse/projects/public/zmq4-tag/pub.go:245 +0x225
created by github.com/go-zeromq/zmq4.newPubMWriter in goroutine 1
    /home/egorse/projects/public/zmq4-tag/pub.go:237 +0x15a

goroutine 30 [semacquire]:
sync.runtime_Semacquire(0x454ebc?)
    /usr/local/go/src/runtime/sema.go:62 +0x25
sync.(*WaitGroup).Wait(0x20?)
    /usr/local/go/src/sync/waitgroup.go:116 +0x48
golang.org/x/sync/errgroup.(*Group).Wait(0xc000238200)
    /home/egorse/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:53 +0x25
github.com/go-zeromq/zmq4.(*routerMWriter).write(0xc0000fbf00, {0x633598, 0xc0000f43f0}, {{0xc000212820, 0x3, 0x3}, 0x0, 0x0, {0x0, 0x0}})
    /home/egorse/projects/public/zmq4-tag/router.go:242 +0x2ed
github.com/go-zeromq/zmq4.(*routerSocket).Send(0xc000092408, {{0xc000212820, 0x3, 0x3}, 0x0, 0x0, {0x0, 0x0}})
    /home/egorse/projects/public/zmq4-tag/router.go:40 +0xdb
github.com/go-zeromq/zmq4_test.TestConnReaperDeadlock(0xc00020d520)
    /home/egorse/projects/public/zmq4-tag/socket_test.go:217 +0x77f
testing.tRunner(0xc00020d520, 0x5fe1e8)
    /usr/local/go/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
    /usr/local/go/src/testing/testing.go:1648 +0x3ad

goroutine 32 [IO wait]:
internal/poll.runtime_pollWait(0x7fb11099ce38, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc0000f6380?, 0xc000139d50?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0000f6380)
    /usr/local/go/src/internal/poll/fd_unix.go:611 +0x2ac
net.(*netFD).accept(0xc0000f6380)
    /usr/local/go/src/net/fd_unix.go:172 +0x29
net.(*TCPListener).accept(0xc0000c02a0)
    /usr/local/go/src/net/tcpsock_posix.go:152 +0x1e
net.(*TCPListener).Accept(0xc0000c02a0)
    /usr/local/go/src/net/tcpsock.go:315 +0x30
github.com/go-zeromq/zmq4.(*socket).accept(0xc00020da00)
    /home/egorse/projects/public/zmq4-tag/socket.go:207 +0xa9
created by github.com/go-zeromq/zmq4.(*socket).Listen in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:193 +0x145

goroutine 33 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x7fb11011a530?, 0x18?, 0x415132?)
    /usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000fbf10)
    /usr/local/go/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(...)
    /usr/local/go/src/sync/mutex.go:90
github.com/go-zeromq/zmq4.(*routerMWriter).rmConn(0xc0000fbf00, 0xc000100320)
    /home/egorse/projects/public/zmq4-tag/router.go:211 +0x5a
github.com/go-zeromq/zmq4.(*socket).rmConn(0xc00020da00, 0xc000100320)
    /home/egorse/projects/public/zmq4-tag/socket.go:323 +0x223
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc00020da00)
    /home/egorse/projects/public/zmq4-tag/socket.go:387 +0x16b
created by github.com/go-zeromq/zmq4.(*socket).Listen in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:194 +0x187

goroutine 10 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x48f5e0?, 0x0?, 0xc000056c68?)
    /usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000b8840)
    /usr/local/go/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(0x52fc65?)
    /usr/local/go/src/sync/mutex.go:90 +0x32
github.com/go-zeromq/zmq4.(*socket).scheduleRmConn(0xc00020da00, 0xc0000a0960)
    /home/egorse/projects/public/zmq4-tag/socket.go:328 +0x33
github.com/go-zeromq/zmq4.(*Conn).notifyOnCloseError(...)
    /home/egorse/projects/public/zmq4-tag/conn.go:500
github.com/go-zeromq/zmq4.(*Conn).SetClosed(0xc000014298?)
    /home/egorse/projects/public/zmq4-tag/conn.go:472 +0x3c
github.com/go-zeromq/zmq4.(*Conn).checkIO(0x632660?, {0x632300, 0x764000})
    /home/egorse/projects/public/zmq4-tag/conn.go:486 +0xa5
github.com/go-zeromq/zmq4.(*Conn).read(0xc0000a0960)
    /home/egorse/projects/public/zmq4-tag/conn.go:385 +0x671
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc0000a0960)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 11 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x48f5e0?, 0x80?, 0xc000057c68?)
    /usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000b8840)
    /usr/local/go/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(0x52fc65?)
    /usr/local/go/src/sync/mutex.go:90 +0x32
github.com/go-zeromq/zmq4.(*socket).scheduleRmConn(0xc00020da00, 0xc000100e60)
    /home/egorse/projects/public/zmq4-tag/socket.go:328 +0x33
github.com/go-zeromq/zmq4.(*Conn).notifyOnCloseError(...)
    /home/egorse/projects/public/zmq4-tag/conn.go:500
github.com/go-zeromq/zmq4.(*Conn).SetClosed(0xc000014318?)
    /home/egorse/projects/public/zmq4-tag/conn.go:472 +0x3c
github.com/go-zeromq/zmq4.(*Conn).checkIO(0x632660?, {0x632300, 0x764000})
    /home/egorse/projects/public/zmq4-tag/conn.go:486 +0xa5
github.com/go-zeromq/zmq4.(*Conn).read(0xc000100e60)
    /home/egorse/projects/public/zmq4-tag/conn.go:385 +0x671
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc000100e60)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 71 [IO wait]:
internal/poll.runtime_pollWait(0x7fb11099c298, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000288180?, 0xc000284268?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000288180, {0xc000284268, 0x2, 0x2})
    /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000288180, {0xc000284268?, 0x0?, 0x0?})
    /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00028c078, {0xc000284268?, 0x7fb11011a488?, 0x7fb158f4cf18?})
    /usr/local/go/src/net/net.go:179 +0x45
io.ReadAtLeast({0x632660, 0xc00028c078}, {0xc000284268, 0x2, 0x2}, 0x2)
    /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
    /usr/local/go/src/io/io.go:354
github.com/go-zeromq/zmq4.(*Conn).read(0xc000290f00)
    /home/egorse/projects/public/zmq4-tag/conn.go:383 +0xf0
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc000290f00)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 35 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x48f5e0?, 0x80?, 0xc000055c68?)
    /usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000b8840)
    /usr/local/go/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(0x52fc65?)
    /usr/local/go/src/sync/mutex.go:90 +0x32
github.com/go-zeromq/zmq4.(*socket).scheduleRmConn(0xc00020da00, 0xc0001ba000)
    /home/egorse/projects/public/zmq4-tag/socket.go:328 +0x33
github.com/go-zeromq/zmq4.(*Conn).notifyOnCloseError(...)
    /home/egorse/projects/public/zmq4-tag/conn.go:500
github.com/go-zeromq/zmq4.(*Conn).SetClosed(0xc00019c178?)
    /home/egorse/projects/public/zmq4-tag/conn.go:472 +0x3c
github.com/go-zeromq/zmq4.(*Conn).checkIO(0x632660?, {0x632300, 0x764000})
    /home/egorse/projects/public/zmq4-tag/conn.go:486 +0xa5
github.com/go-zeromq/zmq4.(*Conn).read(0xc0001ba000)
    /home/egorse/projects/public/zmq4-tag/conn.go:385 +0x671
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc0001ba000)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 36 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc000238110, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc0002304e0)
    /home/egorse/projects/public/zmq4-tag/socket.go:379 +0x107
created by github.com/go-zeromq/zmq4.(*socket).Dial in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:269 +0x3db

goroutine 38 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0001b4450, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc0001b6b60)
    /home/egorse/projects/public/zmq4-tag/socket.go:379 +0x107
created by github.com/go-zeromq/zmq4.(*socket).Dial in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:269 +0x3db

goroutine 72 [IO wait]:
internal/poll.runtime_pollWait(0x7fb11099c0a8, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000288200?, 0xc000014330?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000288200, {0xc000014330, 0x2, 0x2})
    /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000288200, {0xc000014330?, 0x0?, 0x0?})
    /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00028c080, {0xc000014330?, 0x7fb158f55280?, 0x7fb158f4c108?})
    /usr/local/go/src/net/net.go:179 +0x45
io.ReadAtLeast({0x632660, 0xc00028c080}, {0xc000014330, 0x2, 0x2}, 0x2)
    /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
    /usr/local/go/src/io/io.go:354
github.com/go-zeromq/zmq4.(*Conn).read(0xc000291360)
    /home/egorse/projects/public/zmq4-tag/conn.go:383 +0xf0
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc000291360)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 40 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0001b4510, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc0001b6ea0)
    /home/egorse/projects/public/zmq4-tag/socket.go:379 +0x107
created by github.com/go-zeromq/zmq4.(*socket).Dial in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:269 +0x3db

goroutine 73 [IO wait]:
internal/poll.runtime_pollWait(0x7fb1100d7e90, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000288280?, 0xc0000b8a68?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000288280, {0xc0000b8a68, 0x2, 0x2})
    /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000288280, {0xc0000b8a68?, 0x0?, 0x0?})
    /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00028c088, {0xc0000b8a68?, 0x7fb110999658?, 0x7fb158f4c5b8?})
    /usr/local/go/src/net/net.go:179 +0x45
io.ReadAtLeast({0x632660, 0xc00028c088}, {0xc0000b8a68, 0x2, 0x2}, 0x2)
    /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
    /usr/local/go/src/io/io.go:354
github.com/go-zeromq/zmq4.(*Conn).read(0xc0002917c0)
    /home/egorse/projects/public/zmq4-tag/conn.go:383 +0xf0
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc0002917c0)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 12 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc0001b45d0, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc0001b71e0)
    /home/egorse/projects/public/zmq4-tag/socket.go:379 +0x107
created by github.com/go-zeromq/zmq4.(*socket).Dial in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:269 +0x3db

goroutine 74 [IO wait]:
internal/poll.runtime_pollWait(0x7fb1100d7ca0, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000288300?, 0xc00019c398?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000288300, {0xc00019c398, 0x2, 0x2})
    /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000288300, {0xc00019c398?, 0x0?, 0x0?})
    /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00028c090, {0xc00019c398?, 0x7fb1101179e0?, 0x7fb158f4ca68?})
    /usr/local/go/src/net/net.go:179 +0x45
io.ReadAtLeast({0x632660, 0xc00028c090}, {0xc00019c398, 0x2, 0x2}, 0x2)
    /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
    /usr/local/go/src/io/io.go:354
github.com/go-zeromq/zmq4.(*Conn).read(0xc000291c20)
    /home/egorse/projects/public/zmq4-tag/conn.go:383 +0xf0
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc000291c20)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 55 [sync.Cond.Wait]:
sync.runtime_notifyListWait(0xc000016250, 0x0)
    /usr/local/go/src/runtime/sema.go:527 +0x159
sync.(*Cond).Wait(0x0?)
    /usr/local/go/src/sync/cond.go:70 +0x85
github.com/go-zeromq/zmq4.(*socket).connReaper(0xc000126d00)
    /home/egorse/projects/public/zmq4-tag/socket.go:379 +0x107
created by github.com/go-zeromq/zmq4.(*socket).Dial in goroutine 30
    /home/egorse/projects/public/zmq4-tag/socket.go:269 +0x3db

goroutine 75 [IO wait]:
internal/poll.runtime_pollWait(0x7fb1100d7ab0, 0x72)
    /usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000288500?, 0xc000284408?, 0x0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000288500, {0xc000284408, 0x2, 0x2})
    /usr/local/go/src/internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc000288500, {0xc000284408?, 0x0?, 0x0?})
    /usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc00028c098, {0xc000284408?, 0x7fb11011a488?, 0x7fb158f4cf18?})
    /usr/local/go/src/net/net.go:179 +0x45
io.ReadAtLeast({0x632660, 0xc00028c098}, {0xc000284408, 0x2, 0x2}, 0x2)
    /usr/local/go/src/io/io.go:335 +0x90
io.ReadFull(...)
    /usr/local/go/src/io/io.go:354
github.com/go-zeromq/zmq4.(*Conn).read(0xc0002b40a0)
    /home/egorse/projects/public/zmq4-tag/conn.go:383 +0xf0
github.com/go-zeromq/zmq4.(*routerQReader).listen(0xc000212500, {0x633528, 0xc000212460}, 0xc0002b40a0)
    /home/egorse/projects/public/zmq4-tag/router.go:161 +0x172
created by github.com/go-zeromq/zmq4.(*routerQReader).addConn in goroutine 32
    /home/egorse/projects/public/zmq4-tag/router.go:122 +0xa5

goroutine 57 [sync.Mutex.Lock]:
sync.runtime_SemacquireMutex(0x5c0f00?, 0x0?, 0xc000051dd0?)
    /usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000b8840)
    /usr/local/go/src/sync/mutex.go:171 +0x15d
sync.(*Mutex).Lock(0x10?)
    /usr/local/go/src/sync/mutex.go:90 +0x32
github.com/go-zeromq/zmq4.(*socket).scheduleRmConn(0xc00020da00, 0xc000290000)
    /home/egorse/projects/public/zmq4-tag/socket.go:328 +0x33
github.com/go-zeromq/zmq4.(*Conn).notifyOnCloseError(...)
    /home/egorse/projects/public/zmq4-tag/conn.go:500
github.com/go-zeromq/zmq4.(*Conn).SetClosed(0x632640?)
    /home/egorse/projects/public/zmq4-tag/conn.go:472 +0x3c
github.com/go-zeromq/zmq4.(*Conn).checkIO(0x0?, {0x632640, 0xc000212a00})
    /home/egorse/projects/public/zmq4-tag/conn.go:492 +0xfe
github.com/go-zeromq/zmq4.(*Conn).send(0xc000290000, 0xa0?, {0x0, 0x0, 0x0}, 0x8?)
    /home/egorse/projects/public/zmq4-tag/conn.go:362 +0x13c
github.com/go-zeromq/zmq4.(*Conn).SendMsg(0xc000290000, {{0xc000212838, 0x2, 0x2}, 0x0, 0x0, {0x0, 0x0}})
    /home/egorse/projects/public/zmq4-tag/conn.go:190 +0x137
github.com/go-zeromq/zmq4.(*routerMWriter).write.func1()
    /home/egorse/projects/public/zmq4-tag/router.go:239 +0x34
golang.org/x/sync/errgroup.(*Group).Go.func1()
    /home/egorse/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x56
created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 30
    /home/egorse/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:72 +0x96
exit status 2
FAIL    github.com/go-zeromq/zmq4   30.044s

go-zeromq/zmq4 v0.16.0 go version 1.21.5

egorse commented 10 months ago

Seems that func (w *routerMWriter) write(ctx context.Context, msg Msg) under w.mu.Lock() when calling ww.SendMsg and getting error can reap connection which ends up in func (mw *routerMWriter) rmConn(w *Conn) which requires already locked mw.mu.Lock() and locks connection reaper forever.

Then next call to func (sck *socket) scheduleRmConn(c *Conn) stuck trying to sck.reaperCond.L.Lock(), i.e. by read error.

egorse commented 10 months ago

Synthetic test hard to make but its enough to have two clients dialed to server and then close those clients. Not even needs 5/10 as in TestConnReaperDeadlock. Then you need to make either multiple runs or artificial delays to ensure sequence in prev message.