Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test timeout in TestReconnect2 #1208

Closed
marten-seemann opened this issue Sep 29, 2021 · 3 comments · Fixed by #1268
Closed

test timeout in TestReconnect2 #1208

marten-seemann opened this issue Sep 29, 2021 · 3 comments · Fixed by #1268
Labels
kind/bug A bug in existing code (including security flaws)

Comments

@marten-seemann
Copy link
Contributor

=== RUN   TestReconnect2
  2021/09/29 14:37:43 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/lucas-clemente/quic-go/wiki/UDP-Receive-Buffer-Size for details.
  panic: test timed out after 10m0s
  
  goroutine 1247 [running]:
  testing.(*M).startAlarm.func1()
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1788 +0xcb
  created by time.goFunc
  	/opt/hostedtoolcache/go/1.17.1/x64/src/time/sleep.go:180 +0x37
  
  goroutine 1 [chan receive, 9 minutes]:
  testing.(*T).Run(0xa4825a0, {0x8842afa, 0xe}, 0x8a1e8d0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1307 +0x359
  testing.runTests.func1(0xa4825a0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1598 +0x5e
  testing.tRunner(0xa4825a0, 0xa44fe70)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1259 +0xeb
  testing.runTests(0xa496c00, {0x9001ff0, 0x2, 0x2}, {0xc04d3d03eb186370, 0x8bb3986c44, 0x900ab00})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1596 +0x39a
  testing.(*M).Run(0xa4aa190)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1504 +0x581
  main.main()
  	_testmain.go:45 +0x136
  
  goroutine 6 [select, 9 minutes]:
  github.com/ipfs/go-log/writer.(*MirrorWriter).logRoutine(0xa5125a0)
  	/home/runner/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:71 +0xe3
  created by github.com/ipfs/go-log/writer.NewMirrorWriter
  	/home/runner/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:36 +0xbb
  
  goroutine 30 [semacquire, 9 minutes]:
  sync.runtime_Semacquire(0xb57ffe8)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/sema.go:56 +0x36
  sync.(*WaitGroup).Wait(0xb57ffe0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/sync/waitgroup.go:130 +0x87
  github.com/libp2p/go-libp2p/p2p/test/reconnects.SubtestConnSendDisc(0xa482690, {0xa9b1f94, 0x2, 0x2})
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:202 +0x32f
  github.com/libp2p/go-libp2p/p2p/test/reconnects.TestReconnect2(0xa482690)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:120 +0x2d2
  testing.tRunner(0xa482690, 0x8a1e8d0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1259 +0xeb
  created by testing.(*T).Run
  	/opt/hostedtoolcache/go/1.17.1/x64/src/testing/testing.go:1306 +0x33a
  
  goroutine 12 [select, 9 minutes]:
  github.com/libp2p/go-libp2p-peerstore/pstoremem.(*memoryAddrBook).background(0xa5c8900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-peerstore@v0.2.8/pstoremem/addr_book.go:93 +0xeb
  created by github.com/libp2p/go-libp2p-peerstore/pstoremem.NewAddrBook
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-peerstore@v0.2.8/pstoremem/addr_book.go:83 +0x1b1
  
  goroutine 13 [select, 5 minutes]:
  github.com/libp2p/go-libp2p-swarm.(*DialBackoff).background(0xa519f30, {0x8adbd68, 0xa89a990})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_dial.go:123 +0xdf
  created by github.com/libp2p/go-libp2p-swarm.(*DialBackoff).init
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_dial.go:116 +0x70
  
  goroutine 14 [IO wait, 9 minutes]:
  internal/poll.runtime_pollWait(0xe7b814a8, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xa510424, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).Accept(0xa510410)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:402 +0x215
  net.(*netFD).accept(0xa510410)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/fd_unix.go:173 +0x27
  net.(*TCPListener).accept(0xa8c4010)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/tcpsock_posix.go:140 +0x27
  net.(*TCPListener).Accept(0xa8c4010)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/tcpsock.go:262 +0x37
  github.com/multiformats/go-multiaddr/net.(*maListener).Accept(0xa8c4050)
  	/home/runner/go/pkg/mod/github.com/multiformats/go-multiaddr@v0.4.0/net/net.go:243 +0x2a
  github.com/libp2p/go-tcp-transport.(*tcpListener).Accept(0xa8c4070)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.3.0/tcp.go:83 +0x2a
  github.com/libp2p/go-tcp-transport.(*tracingListener).Accept(0xa40d810)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.3.0/metrics.go:261 +0x26
  github.com/libp2p/go-libp2p-transport-upgrader.(*listener).handleIncoming(0xa89aae0)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/listener.go:73 +0xbf
  created by github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).UpgradeListener
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/upgrader.go:48 +0x1a7
  
  goroutine 15 [chan receive, 9 minutes]:
  github.com/libp2p/go-libp2p-transport-upgrader.(*listener).Accept(0xa89aae0)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/listener.go:151 +0x4a
  github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr.func2({0x8adbf08, 0xa89aae0}, 0xa519e60, {0x8aea0b4, 0xa8c4040}, {0x8aea0b4, 0xa496470})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:94 +0x13d
  created by github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:79 +0x232
  
  goroutine 16 [select]:
  github.com/libp2p/go-libp2p-quic-transport.(*reuse).gc(0xa89c630)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:91 +0x12c
  created by github.com/libp2p/go-libp2p-quic-transport.newReuse
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:69 +0xf9
  
  goroutine 33 [select]:
  github.com/libp2p/go-libp2p-quic-transport.(*reuse).gc(0xa89c648)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:91 +0x12c
  created by github.com/libp2p/go-libp2p-quic-transport.newReuse
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:69 +0xf9
  
  goroutine 34 [IO wait, 9 minutes]:
  internal/poll.runtime_pollWait(0xe7b81410, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xa510514, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).RawRead(0xa510500, 0xb6e91e0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:554 +0x131
  net.(*rawConn).Read(0xa40d8a8, 0xb6e91e0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/rawconn.go:43 +0x3f
  golang.org/x/net/internal/socket.(*Conn).recvMsgs(0xa8c47b0, {0xa51e580, 0x8, 0x8}, 0x0)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/internal/socket/rawconn_mmsg.go:32 +0x1e3
  golang.org/x/net/internal/socket.(*Conn).RecvMsgs(...)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/internal/socket/socket.go:267
  golang.org/x/net/ipv4.(*payloadHandler).ReadBatch(0xa89ac98, {0xa51e580, 0x8, 0x8}, 0x0)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/ipv4/batch.go:80 +0x63
  github.com/lucas-clemente/quic-go.(*oobConn).ReadPacket(0xa5b5140)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/conn_oob.go:151 +0x6b1
  github.com/lucas-clemente/quic-go.(*packetHandlerMap).listen(0xa576620)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/packet_handler_map.go:329 +0x59
  created by github.com/lucas-clemente/quic-go.newPacketHandlerMap
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/packet_handler_map.go:145 +0x281
  
  goroutine 35 [select, 9 minutes]:
  github.com/lucas-clemente/quic-go.(*baseServer).run(0xa8c6060)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:230 +0xde
  created by github.com/lucas-clemente/quic-go.listen
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:216 +0x5fe
  
  goroutine 36 [select, 9 minutes]:
  github.com/lucas-clemente/quic-go.(*baseServer).accept(0xa8c6060, {0x8adbd88, 0xa4320c0})
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:268 +0x99
  github.com/lucas-clemente/quic-go.(*baseServer).Accept(0xa8c6060, {0x8adbd88, 0xa4320c0})
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:264 +0x31
  github.com/libp2p/go-libp2p-quic-transport.(*listener).Accept(0xa89ad20)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/listener.go:64 +0x3e
  github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr.func2({0x8adbee8, 0xa89ad20}, 0xa519e60, {0x8aea0b4, 0xa8c4810}, {0x8aea0b4, 0xa8c4770})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:94 +0x13d
  created by github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:79 +0x232
  
  goroutine 38 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*ObservedAddrManager).worker(0xa4718c0)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/obsaddr.go:258 +0x1a8
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.NewObservedAddrManager
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/obsaddr.go:158 +0x42a
  
  goroutine 39 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*IDService).loop(0xa507300)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:203 +0x505
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.NewIDService
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:150 +0x2cd
  
  goroutine 40 [select, 9 minutes]:
  github.com/libp2p/go-libp2p-peerstore/pstoremem.(*memoryAddrBook).background(0xa5c9200)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-peerstore@v0.2.8/pstoremem/addr_book.go:93 +0xeb
  created by github.com/libp2p/go-libp2p-peerstore/pstoremem.NewAddrBook
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-peerstore@v0.2.8/pstoremem/addr_book.go:83 +0x1b1
  
  goroutine 41 [select, 5 minutes]:
  github.com/libp2p/go-libp2p-swarm.(*DialBackoff).background(0xa8d81f0, {0x8adbd68, 0xa89b470})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_dial.go:123 +0xdf
  created by github.com/libp2p/go-libp2p-swarm.(*DialBackoff).init
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_dial.go:116 +0x70
  
  goroutine 42 [IO wait, 9 minutes]:
  internal/poll.runtime_pollWait(0xe7b81378, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xa510654, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).Accept(0xa510640)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:402 +0x215
  net.(*netFD).accept(0xa510640)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/fd_unix.go:173 +0x27
  net.(*TCPListener).accept(0xa8c4f20)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/tcpsock_posix.go:140 +0x27
  net.(*TCPListener).Accept(0xa8c4f20)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/tcpsock.go:262 +0x37
  github.com/multiformats/go-multiaddr/net.(*maListener).Accept(0xa8c4f60)
  	/home/runner/go/pkg/mod/github.com/multiformats/go-multiaddr@v0.4.0/net/net.go:243 +0x2a
  github.com/libp2p/go-tcp-transport.(*tcpListener).Accept(0xa8c4f80)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.3.0/tcp.go:83 +0x2a
  github.com/libp2p/go-tcp-transport.(*tracingListener).Accept(0xa40dad8)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.3.0/metrics.go:261 +0x26
  github.com/libp2p/go-libp2p-transport-upgrader.(*listener).handleIncoming(0xa89b5c0)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/listener.go:73 +0xbf
  created by github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).UpgradeListener
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/upgrader.go:48 +0x1a7
  
  goroutine 43 [chan receive, 9 minutes]:
  github.com/libp2p/go-libp2p-transport-upgrader.(*listener).Accept(0xa89b5c0)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.5.0/listener.go:151 +0x4a
  github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr.func2({0x8adbf08, 0xa89b5c0}, 0xa8d8120, {0x8aea0b4, 0xa8c4f50}, {0x8aea0b4, 0xa496470})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:94 +0x13d
  created by github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:79 +0x232
  
  goroutine 44 [select]:
  github.com/libp2p/go-libp2p-quic-transport.(*reuse).gc(0xa89d068)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:91 +0x12c
  created by github.com/libp2p/go-libp2p-quic-transport.newReuse
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:69 +0xf9
  
  goroutine 45 [select]:
  github.com/libp2p/go-libp2p-quic-transport.(*reuse).gc(0xa89d080)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:91 +0x12c
  created by github.com/libp2p/go-libp2p-quic-transport.newReuse
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/reuse.go:69 +0xf9
  
  goroutine 46 [IO wait, 9 minutes]:
  internal/poll.runtime_pollWait(0xe7b812e0, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xa510744, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).RawRead(0xa510730, 0xb7cb040)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:554 +0x131
  net.(*rawConn).Read(0xa40db68, 0xb7cb040)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/rawconn.go:43 +0x3f
  golang.org/x/net/internal/socket.(*Conn).recvMsgs(0xa8c5690, {0xa51e9a0, 0x8, 0x8}, 0x0)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/internal/socket/rawconn_mmsg.go:32 +0x1e3
  golang.org/x/net/internal/socket.(*Conn).RecvMsgs(...)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/internal/socket/socket.go:267
  golang.org/x/net/ipv4.(*payloadHandler).ReadBatch(0xa89b778, {0xa51e9a0, 0x8, 0x8}, 0x0)
  	/home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210813160813-60bc85c4be6d/ipv4/batch.go:80 +0x63
  github.com/lucas-clemente/quic-go.(*oobConn).ReadPacket(0xa8f2a00)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/conn_oob.go:151 +0x6b1
  github.com/lucas-clemente/quic-go.(*packetHandlerMap).listen(0xa577030)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/packet_handler_map.go:329 +0x59
  created by github.com/lucas-clemente/quic-go.newPacketHandlerMap
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/packet_handler_map.go:145 +0x281
  
  goroutine 47 [select, 9 minutes]:
  github.com/lucas-clemente/quic-go.(*baseServer).run(0xa8c6120)
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:230 +0xde
  created by github.com/lucas-clemente/quic-go.listen
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:216 +0x5fe
  
  goroutine 48 [select, 9 minutes]:
  github.com/lucas-clemente/quic-go.(*baseServer).accept(0xa8c6120, {0x8adbd88, 0xa4320c0})
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:268 +0x99
  github.com/lucas-clemente/quic-go.(*baseServer).Accept(0xa8c6120, {0x8adbd88, 0xa4320c0})
  	/home/runner/go/pkg/mod/github.com/lucas-clemente/quic-go@v0.23.0/server.go:264 +0x31
  github.com/libp2p/go-libp2p-quic-transport.(*listener).Accept(0xa89b800)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-quic-transport@v0.13.0/listener.go:64 +0x3e
  github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr.func2({0x8adbee8, 0xa89b800}, 0xa8d8120, {0x8aea0b4, 0xa8c56f0}, {0x8aea0b4, 0xa8c5660})
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:94 +0x13d
  created by github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_listen.go:79 +0x232
  
  goroutine 52 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*ObservedAddrManager).worker(0xa471c20)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/obsaddr.go:258 +0x1a8
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.NewObservedAddrManager
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/obsaddr.go:158 +0x42a
  
  goroutine 53 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*IDService).loop(0xa9a6080)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:203 +0x505
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.NewIDService
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:150 +0x2cd
  
  goroutine 988 [IO wait]:
  internal/poll.runtime_pollWait(0xe7b811b0, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xb47f3c4, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).Read(0xb47f3b0, {0xb57fb20, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:167 +0x1d4
  net.(*netFD).Read(0xb47f3b0, {0xb57fb20, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/fd_posix.go:56 +0x3f
  net.(*conn).Read(0xb2f55d8, {0xb57fb20, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/net.go:183 +0x4f
  io.ReadAtLeast({0xe7aff1a0, 0xb7d2d80}, {0xb57fb20, 0xc, 0xc}, 0xc)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/io/io.go:328 +0x97
  io.ReadFull(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/io/io.go:347
  github.com/libp2p/go-yamux/v2.(*Session).recvLoop(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:583 +0xa3
  github.com/libp2p/go-yamux/v2.(*Session).recv(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:562 +0x21
  created by github.com/libp2p/go-yamux/v2.newSession
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:132 +0x4b0
  
  goroutine 100 [chan receive, 9 minutes]:
  github.com/libp2p/go-flow-metrics.(*sweeper).run(0x900ac40)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-flow-metrics@v0.0.3/sweeper.go:40 +0x4a
  created by github.com/libp2p/go-flow-metrics.(*sweeper).start
  	/home/runner/go/pkg/mod/github.com/libp2p/go-flow-metrics@v0.0.3/sweeper.go:36 +0x6c
  
  goroutine 996 [select, 9 minutes]:
  github.com/libp2p/go-yamux/v2.(*Session).AcceptStream(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:232 +0xcf
  github.com/libp2p/go-libp2p-yamux.(*conn).AcceptStream(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-yamux@v0.5.4/conn.go:35 +0x21
  github.com/libp2p/go-libp2p-swarm.(*Conn).start.func1(0xa8c6b40)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_conn.go:107 +0xcb
  created by github.com/libp2p/go-libp2p-swarm.(*Conn).start
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_conn.go:102 +0x33
  
  goroutine 1019 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*peerHandler).loop(0xb800d40, {0x8adbd68, 0xb6ef2c0}, 0xb6fe7c0)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/peer_loop.go:90 +0xcb
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.(*peerHandler).start
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/peer_loop.go:72 +0x8d
  
  goroutine 1076 [chan receive, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/test/reconnects.SubtestConnSendDisc.func1(0xb57ffe0, 0xb2f5360, {0x8aeaa4c, 0xb7da3a0}, 0xb59ff00, 0xb5894b0, 0x1)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:192 +0x210
  created by github.com/libp2p/go-libp2p/p2p/test/reconnects.SubtestConnSendDisc
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:182 +0x189
  
  goroutine 1011 [select, 9 minutes]:
  github.com/libp2p/go-yamux/v2.(*Session).AcceptStream(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:232 +0xcf
  github.com/libp2p/go-libp2p-yamux.(*conn).AcceptStream(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-yamux@v0.5.4/conn.go:35 +0x21
  github.com/libp2p/go-libp2p-swarm.(*Conn).start.func1(0xa8c6ba0)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_conn.go:107 +0xcb
  created by github.com/libp2p/go-libp2p-swarm.(*Conn).start
  	/home/runner/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.6.0/swarm_conn.go:102 +0x33
  
  goroutine 1088 [chan send, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/test/reconnects.newSender.func1.1({0x8aeaa4c, 0xb7da3a0}, {0xb7d6b80, 0xb7d6bc0, 0xb7d6c00, 0xb7d6c40, 0xb7d6c80})
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:63 +0x39
  github.com/libp2p/go-libp2p/p2p/test/reconnects.newSender.func1({0x8aeaa4c, 0xb7da3a0})
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:86 +0x759
  created by github.com/libp2p/go-libp2p/p2p/test/reconnects.SubtestConnSendDisc.func1
  	/home/runner/work/go-libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:185 +0x85
  
  goroutine 1002 [select]:
  github.com/libp2p/go-yamux/v2.(*Session).sendLoop(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:506 +0x1b6
  github.com/libp2p/go-yamux/v2.(*Session).send(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:452 +0x21
  created by github.com/libp2p/go-yamux/v2.newSession
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:133 +0x4ce
  
  goroutine 1034 [select, 9 minutes]:
  github.com/libp2p/go-libp2p/p2p/protocol/identify.(*peerHandler).loop(0xb801140, {0x8adbd68, 0xb6ef3e0}, 0xb6feaa0)
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/peer_loop.go:90 +0xcb
  created by github.com/libp2p/go-libp2p/p2p/protocol/identify.(*peerHandler).start
  	/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/peer_loop.go:72 +0x8d
  
  goroutine 989 [select]:
  github.com/libp2p/go-yamux/v2.(*Session).sendLoop(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:506 +0x1b6
  github.com/libp2p/go-yamux/v2.(*Session).send(0xab6a870)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:452 +0x21
  created by github.com/libp2p/go-yamux/v2.newSession
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:133 +0x4ce
  
  goroutine 1001 [IO wait]:
  internal/poll.runtime_pollWait(0xe7b81248, 0x72)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/runtime/netpoll.go:229 +0x8e
  internal/poll.(*pollDesc).wait(0xb47f004, 0x72, 0x0)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:84 +0x37
  internal/poll.(*pollDesc).waitRead(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_poll_runtime.go:89
  internal/poll.(*FD).Read(0xb47eff0, {0xb57fbc0, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/internal/poll/fd_unix.go:167 +0x1d4
  net.(*netFD).Read(0xb47eff0, {0xb57fbc0, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/fd_posix.go:56 +0x3f
  net.(*conn).Read(0xb2f5700, {0xb57fbc0, 0xc, 0xc})
  	/opt/hostedtoolcache/go/1.17.1/x64/src/net/net.go:183 +0x4f
  io.ReadAtLeast({0xe7aff1a0, 0xb6eec30}, {0xb57fbc0, 0xc, 0xc}, 0xc)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/io/io.go:328 +0x97
  io.ReadFull(...)
  	/opt/hostedtoolcache/go/1.17.1/x64/src/io/io.go:347
  github.com/libp2p/go-yamux/v2.(*Session).recvLoop(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:583 +0xa3
  github.com/libp2p/go-yamux/v2.(*Session).recv(0xab6a900)
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:562 +0x21
  created by github.com/libp2p/go-yamux/v2.newSession
  	/home/runner/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.2.0/session.go:132 +0x4b0
  FAIL	github.com/libp2p/go-libp2p/p2p/test/reconnects	600.029s
@marten-seemann marten-seemann added the kind/bug A bug in existing code (including security flaws) label Sep 29, 2021
@marten-seemann
Copy link
Contributor Author

marten-seemann commented Dec 16, 2021

The problem here is the following: We have two hosts that are connected by a single TCP connection (the failure doesn't happen when using QUIC). When this connection is closed on the first host, in the vast majority of cases, the second host notices this quite quickly (the TCP connection closed, or rather, reset). Occasionally, the second host doesn't notice that the connection is closed though.

Minimal reproducer:

func TestConnectHang(t *testing.T) {
	h1, err := bhost.NewHost(swarmt.GenSwarm(t, swarmt.OptDisableQUIC), nil)
	require.NoError(t, err)
	h2, err := bhost.NewHost(swarmt.GenSwarm(t, swarmt.OptDisableQUIC), nil)
	require.NoError(t, err)

	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
	defer cancel()
	require.NoError(t, h1.Connect(ctx, peer.AddrInfo{ID: h2.ID(), Addrs: h2.Addrs()}))
	require.Len(t, h1.Network().Conns(), 1)
	require.Len(t, h2.Network().Conns(), 1)

	h2.SetStreamHandler(protocol.TestingID, func(str network.Stream) {
		io.ReadAll(str)
	})
	str, err := h1.NewStream(ctx, h2.ID(), protocol.TestingID)
	require.NoError(t, err)
	_, err = str.Write([]byte("foobar"))
	require.NoError(t, err)
	require.NoError(t, str.CloseWrite())

	fmt.Println(h1.Network().Conns()[0])
	require.NoError(t, h1.Network().Conns()[0].Close())
	require.Eventually(t, func() bool { return len(h1.Network().Conns()) == 0 }, 10*time.Second, 10*time.Millisecond)
	require.Eventually(t, func() bool { return len(h2.Network().Conns()) == 0 }, 10*time.Second, 10*time.Millisecond)
}

output (that's the last Eventually failing):

=== RUN   TestConnectHang
<swarm.Conn[*tcp.TcpTransport] /ip4/127.0.0.1/tcp/57237 (12D3KooWB1SFhGLrzyQKptrFxkC7KYY9pHCgQ9BXu4YacPgKaNo2) <-> /ip4/127.0.0.1/tcp/57238 (12D3KooWFrC4Ffr2NwCQaVWjyiD66mkyZ4952g2MahnE8MW3XkED)>
    reconnect_test.go:138: 
                Error Trace:    reconnect_test.go:138
                Error:          Condition never satisfied
                Test:           TestConnectHang
--- FAIL: TestConnectHang (10.02s)

The interesting thing is that both TCP RSTs are sent, so both connections should be closed.
pcap: conn-hanging.pcapng.gz
Screen Shot 2021-12-16 at 12 35 41

From a go routine dump it looks like the ReadFull in https://github.com/libp2p/go-yamux/blob/959e04413929c5c82f518e992954e42076676d05/session.go#L584 is hanging:

goroutine profile: total 7421
1482 @ 0x1039716 0x1007b8c 0x10075f8 0x1378685 0x16f3756 0x1069b61
#       0x1378684       github.com/libp2p/go-libp2p-transport-upgrader.(*listener).Accept+0x44  /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.6.0/listener.go:151
#       0x16f3755       github.com/libp2p/go-libp2p-swarm.(*Swarm).AddListenAddr.func2+0xf5     /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.9.0/swarm_listen.go:94

1482 @ 0x1039716 0x1031fd3 0x10641a9 0x1097832 0x109ab8c 0x109ab79 0x12574f5 0x126ec68 0x126de7d 0x1369f33 0x1456e8d 0x1456962 0x1377b10 0x1069b61
#       0x10641a8       internal/poll.runtime_pollWait+0x88                                             /usr/local/opt/go/libexec/src/runtime/netpoll.go:234
#       0x1097831       internal/poll.(*pollDesc).wait+0x31                                             /usr/local/opt/go/libexec/src/internal/poll/fd_poll_runtime.go:84
#       0x109ab8b       internal/poll.(*pollDesc).waitRead+0x22b                                        /usr/local/opt/go/libexec/src/internal/poll/fd_poll_runtime.go:89
#       0x109ab78       internal/poll.(*FD).Accept+0x218                                                /usr/local/opt/go/libexec/src/internal/poll/fd_unix.go:402
#       0x12574f4       net.(*netFD).accept+0x34                                                        /usr/local/opt/go/libexec/src/net/fd_unix.go:173
#       0x126ec67       net.(*TCPListener).accept+0x27                                                  /usr/local/opt/go/libexec/src/net/tcpsock_posix.go:140
#       0x126de7c       net.(*TCPListener).Accept+0x3c                                                  /usr/local/opt/go/libexec/src/net/tcpsock.go:262
#       0x1369f32       github.com/multiformats/go-multiaddr/net.(*maListener).Accept+0x32              /Users/marten/src/go/pkg/mod/github.com/multiformats/go-multiaddr@v0.4.0/net/net.go:243
#       0x1456e8c       github.com/libp2p/go-tcp-transport.(*tcpListener).Accept+0x2c                   /Users/marten/src/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.4.0/tcp.go:81
#       0x1456961       github.com/libp2p/go-tcp-transport.(*tracingListener).Accept+0x21               /Users/marten/src/go/pkg/mod/github.com/libp2p/go-tcp-transport@v0.4.0/metrics.go:261
#       0x1377b0f       github.com/libp2p/go-libp2p-transport-upgrader.(*listener).handleIncoming+0x10f /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.6.0/listener.go:73

1482 @ 0x1039716 0x1049212 0x14aa168 0x1069b61
#       0x14aa167       github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).loop+0x507       /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/protocol/identify/id.go:221

1482 @ 0x1039716 0x1049212 0x14b0d33 0x1069b61
#       0x14b0d32       github.com/libp2p/go-libp2p/p2p/protocol/identify.(*ObservedAddrManager).worker+0x1d2   /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/protocol/identify/obsaddr.go:258

1482 @ 0x1039716 0x1049212 0x16ef030 0x1069b61
#       0x16ef02f       github.com/libp2p/go-libp2p-swarm.(*DialBackoff).background+0xef        /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.9.0/swarm_dial.go:123

2 @ 0x1039716 0x1049212 0x159aada 0x1069b61
#       0x159aad9       github.com/libp2p/go-libp2p-peerstore/pstoremem.(*memoryAddrBook).background+0xf9       /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-peerstore@v0.6.0/pstoremem/addr_book.go:94

1 @ 0x1039716 0x1007b8c 0x10075b8 0x1101a75 0x110368e 0x1100e22 0x110353f 0x110229d 0x16fc74b 0x1039347 0x1069b61
#       0x1101a74       testing.(*T).Run+0x374          /usr/local/opt/go/libexec/src/testing/testing.go:1307
#       0x110368d       testing.runTests.func1+0x6d     /usr/local/opt/go/libexec/src/testing/testing.go:1598
#       0x1100e21       testing.tRunner+0x101           /usr/local/opt/go/libexec/src/testing/testing.go:1259
#       0x110353e       testing.runTests+0x43e          /usr/local/opt/go/libexec/src/testing/testing.go:1596
#       0x110229c       testing.(*M).Run+0x51c          /usr/local/opt/go/libexec/src/testing/testing.go:1504
#       0x16fc74a       main.main+0x14a                 _testmain.go:51
#       0x1039346       runtime.main+0x226              /usr/local/opt/go/libexec/src/runtime/proc.go:255

1 @ 0x1039716 0x1007b8c 0x10075f8 0x1594368 0x1069b61
#       0x1594367       github.com/libp2p/go-flow-metrics.(*sweeper).run+0x47   /Users/marten/src/go/pkg/mod/github.com/libp2p/go-flow-metrics@v0.0.3/sweeper.go:40

1 @ 0x1039716 0x1007b8c 0x10075f8 0x16fc357 0x1069b61
#       0x16fc356       github.com/libp2p/go-libp2p/p2p/test/reconnects.waitForClose.func1+0x96 /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:388

1 @ 0x1039716 0x1031fd3 0x10641a9 0x1097832 0x1098b9a 0x1098b88 0x1255d69 0x1267a45 0x109479a 0x12f4fc5 0x12f4f9d 0x12f4ebe 0x1069b61
#       0x10641a8       internal/poll.runtime_pollWait+0x88                     /usr/local/opt/go/libexec/src/runtime/netpoll.go:234
#       0x1097831       internal/poll.(*pollDesc).wait+0x31                     /usr/local/opt/go/libexec/src/internal/poll/fd_poll_runtime.go:84
#       0x1098b99       internal/poll.(*pollDesc).waitRead+0x259                /usr/local/opt/go/libexec/src/internal/poll/fd_poll_runtime.go:89
#       0x1098b87       internal/poll.(*FD).Read+0x247                          /usr/local/opt/go/libexec/src/internal/poll/fd_unix.go:167
#       0x1255d68       net.(*netFD).Read+0x28                                  /usr/local/opt/go/libexec/src/net/fd_posix.go:56
#       0x1267a44       net.(*conn).Read+0x44                                   /usr/local/opt/go/libexec/src/net/net.go:183
#       0x1094799       io.ReadAtLeast+0x99                                     /usr/local/opt/go/libexec/src/io/io.go:328
#       0x12f4fc4       io.ReadFull+0xc4                                        /usr/local/opt/go/libexec/src/io/io.go:347
#       0x12f4f9c       github.com/libp2p/go-yamux/v2.(*Session).recvLoop+0x9c  /Users/marten/src/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.3.0/session.go:584
#       0x12f4ebd       github.com/libp2p/go-yamux/v2.(*Session).recv+0x1d      /Users/marten/src/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.3.0/session.go:563

1 @ 0x1039716 0x1049212 0x12f3019 0x12f9539 0x16edd42 0x1069b61
#       0x12f3018       github.com/libp2p/go-yamux/v2.(*Session).AcceptStream+0xb8      /Users/marten/src/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.3.0/session.go:233
#       0x12f9538       github.com/libp2p/go-libp2p-yamux.(*conn).AcceptStream+0x18     /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-yamux@v0.7.0/conn.go:35
#       0x16edd41       github.com/libp2p/go-libp2p-swarm.(*Conn).start.func1+0xa1      /Users/marten/src/go/pkg/mod/github.com/libp2p/go-libp2p-swarm@v0.9.0/swarm_conn.go:108

1 @ 0x1039716 0x1049212 0x12f498b 0x12f475e 0x1069b61
#       0x12f498a       github.com/libp2p/go-yamux/v2.(*Session).sendLoop+0x1ea /Users/marten/src/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.3.0/session.go:507
#       0x12f475d       github.com/libp2p/go-yamux/v2.(*Session).send+0x1d      /Users/marten/src/go/pkg/mod/github.com/libp2p/go-yamux/v2@v2.3.0/session.go:453

1 @ 0x1039716 0x1049212 0x14b358a 0x1069b61
#       0x14b3589       github.com/libp2p/go-libp2p/p2p/protocol/identify.(*peerHandler).loop+0x109     /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/protocol/identify/peer_loop.go:90

1 @ 0x1039716 0x1049212 0x14bcff0 0x1069b61
#       0x14bcfef       github.com/ipfs/go-log/writer.(*MirrorWriter).logRoutine+0x10f  /Users/marten/src/go/pkg/mod/github.com/ipfs/go-log@v1.0.5/writer/writer.go:71

1 @ 0x1063d65 0x113d735 0x113d54d 0x113a6cb 0x16fbfeb 0x16f9d8f 0x1100e22 0x1069b61
#       0x1063d64       runtime/pprof.runtime_goroutineProfileWithLabels+0x24                           /usr/local/opt/go/libexec/src/runtime/mprof.go:746
#       0x113d734       runtime/pprof.writeRuntimeProfile+0xb4                                          /usr/local/opt/go/libexec/src/runtime/pprof/pprof.go:724
#       0x113d54c       runtime/pprof.writeGoroutine+0x4c                                               /usr/local/opt/go/libexec/src/runtime/pprof/pprof.go:684
#       0x113a6ca       runtime/pprof.(*Profile).WriteTo+0x14a                                          /usr/local/opt/go/libexec/src/runtime/pprof/pprof.go:331
#       0x16fbfea       github.com/libp2p/go-libp2p/p2p/test/reconnects.waitForClose+0x10a              /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:409
#       0x16f9d8e       github.com/libp2p/go-libp2p/p2p/test/reconnects.TestConnectHangHost+0x5ce       /Users/marten/src/go/src/github.com/libp2p/go-libp2p/p2p/test/reconnects/reconnect_test.go:185
#       0x1100e21       testing.tRunner+0x101                                                           /usr/local/opt/go/libexec/src/testing/testing.go:1259

    reconnect_test.go:410: fail
--- FAIL: TestConnectHangHost (10.03s)

@marten-seemann
Copy link
Contributor Author

Interestingly, when I implement the same reproducer with two Swarms instead of two Hosts, this failure can't be reproduced.
As far as I can tell, the only difference between these two cases is that when using a Host, multistream is negotiating the application protocol. However, at the time this failure occurs, protocol negotiation is long over, so there shouldn't be any difference.

@marten-seemann
Copy link
Contributor Author

Update: This only fails on OSX. Here's a reproducer that only uses standard library packages: https://gist.github.com/marten-seemann/176b6bfc7115cf3984eb6756f35252cf.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug A bug in existing code (including security flaws)
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant