go-libp2p
go-libp2p copied to clipboard
Published
20 hours ago •
libp2p
libp2p
identify: flaky TestIDService
This happened on OSX on GH Actions:
=== RUN TestIDService
id_test.go:86: test peer1 has peer2 addrs correctly
id_test.go:101: test peer2 has peer1 addrs correctly
id_test.go:114: testing addrs just after disconnect
id_test.go:123: testing addrs after TTL expiration
id_test.go:86: test peer1 has peer2 addrs correctly
id_test.go:101: test peer2 has peer1 addrs correctly
id_test.go:114: testing addrs just after disconnect
id_test.go:123: testing addrs after TTL expiration
id_test.go:86: test peer1 has peer2 addrs correctly
id_test.go:101: test peer2 has peer1 addrs correctly
id_test.go:114: testing addrs just after disconnect
id_test.go:117: expected: [/ip4/127.0.0.1/tcp/45355 /ip4/127.0.0.1/udp/45352/quic]
id_test.go:117: actual: []
id_test.go:117: dont have the same addresses
--- FAIL: TestIDService (5.53s)
This is probably just another variant of this test failure:
=== RUN TestIDService
id_test.go:86: test peer1 has peer2 addrs correctly
id_test.go:101: test peer2 has peer1 addrs correctly
id_test.go:102: expected: [/ip4/127.0.0.1/udp/54835/quic /ip4/127.0.0.1/tcp/49483]
id_test.go:102: actual: [/ip4/1.2.3.4/tcp/1234]
id_test.go:102: dont have the same addresses
--- FAIL: TestIDService (0.66s)
=== RUN TestIDService
id_test.go:195: test peer1 has peer2 addrs correctly
id_test.go:208: test peer2 has peer1 addrs correctly
id_test.go:209:
Error Trace: id_test.go:41
id_test.go:209
Error: elements differ
extra elements in list A:
([]interface {}) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 ad 55 |.......U|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 c5 64 cc 03 |........d..|
}
})
}
extra elements in list B:
([]interface {}) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
listA:
([]multiaddr.Multiaddr) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 ad 55 |.......U|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 c5 64 cc 03 |........d..|
}
})
}
listB:
([]multiaddr.Multiaddr) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
Test: TestIDService
Messages: 12D3KooWCv935r3ropYhUe5yMCp9QiUoc9A6cZpYQ5x84DqEPbwb did not have addr for 12D3KooWM4yJB31d4hF2F9Vdwuj9WFo1qonoySyw4bVAQ9a9d21o
id_test.go:210: peerstore has no signed record for peer 12D3KooWM4yJB31d4hF2F9Vdwuj9WFo1qonoySyw4bVAQ9a9d21o
--- FAIL: TestIDService (0.05s)
And here with a race condition:
=== RUN TestIDService
2022-11-11T07:40:51.153Z DEBUG net/identify identify/id.go:412 /ipfs/id/1.0.0 sent message to 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN /ip4/127.0.0.1/udp/57628/quic
2022-11-11T07:40:51.156Z DEBUG net/identify identify/id.go:444 /ipfs/id/1.0.0 received message from 12D3KooWKwAUcxwuwbwAe7nwqHA39AcwiEPASzQqsqx2sHWAJP3z /ip4/127.0.0.1/udp/38869/quic
2022-11-11T07:40:51.158Z DEBUG net/identify identify/id.go:637 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN received listen addrs for 12D3KooWKwAUcxwuwbwAe7nwqHA39AcwiEPASzQqsqx2sHWAJP3z: [/ip4/127.0.0.1/tcp/41405 /ip4/127.0.0.1/udp/38869/quic]
id_test.go:199: test peer1 has peer2 addrs correctly
2022-11-11T07:40:51.166Z DEBUG net/identify identify/id.go:412 /ipfs/id/1.0.0 sent message to 12D3KooWKwAUcxwuwbwAe7nwqHA39AcwiEPASzQqsqx2sHWAJP3z /ip4/127.0.0.1/udp/38869/quic
2022-11-11T07:40:51.167Z INFO net/identify identify/id.go:369 failed negotiate identify protocol with peer {"peer": "12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN", "error": "stream reset"}
2022-11-11T07:40:51.167Z WARN net/identify identify/id.go:334 failed to identify 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN: stream reset
id_test.go:212: test peer2 has peer1 addrs correctly
id_test.go:213:
Error Trace: /home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213
Error: elements differ
extra elements in list A:
([]interface {}) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 b5 27 |.......'|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 e1 1c cc 03 |...........|
}
})
}
extra elements in list B:
([]interface {}) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
listA:
([]multiaddr.Multiaddr) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 b5 27 |.......'|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 e1 1c cc 03 |...........|
}
})
}
listB:
([]multiaddr.Multiaddr) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
Test: TestIDService
Messages: 12D3KooWKwAUcxwuwbwAe7nwqHA39AcwiEPASzQqsqx2sHWAJP3z did not have addr for 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN
id_test.go:213:
Error Trace: /home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213
Error: Should be true
Test: TestIDService
2022-11-11T07:40:51.170Z DEBUG net/identify identify/id.go:444 /ipfs/id/1.0.0 received message from 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN /ip4/127.0.0.1/udp/57628/quic
2022-11-11T07:40:51.171Z DEBUG net/identify identify/id.go:637 12D3KooWKwAUcxwuwbwAe7nwqHA39AcwiEPASzQqsqx2sHWAJP3z received listen addrs for 12D3KooWDD9fga7C4XfNWC5RbNtBBmV4dYBHGKkj8KxUpTSud6jN: [/ip4/127.0.0.1/tcp/46375 /ip4/127.0.0.1/udp/57628/quic]
==================
WARNING: DATA RACE
Write at 0x000002073838 by goroutine 8:
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.TestIDService.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:156 +0x32
testing.(*common).Cleanup.func1()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1034 +0x193
testing.(*common).runCleanup()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1203 +0x143
testing.tRunner.func2()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1433 +0x4f
runtime.deferCallSave()
/opt/hostedtoolcache/go/1.18.7/x64/src/runtime/panic.go:750 +0x81
testing.(*T).FailNow()
<autogenerated>:1 +0x37
github.com/stretchr/testify/require.True()
/home/runner/go/pkg/mod/github.com/stretchr/[email protected]/require/require.go:1825 +0xb4
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.testKnowsAddrs()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45 +0x204
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.TestIDService()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213 +0xbce
testing.tRunner()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1439 +0x213
testing.(*T).Run.func1()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1486 +0x47
Previous read at 0x000002073838 by goroutine 64:
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).consumeMessage()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:615 +0x35a
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).handleIdentifyResponse()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:446 +0x8ea
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).identifyConn()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:374 +0x4f0
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).IdentifyWait.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:333 +0xc8
Goroutine 8 (running) created at:
testing.(*T).Run()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1486 +0x724
testing.runTests.func1()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1839 +0x99
testing.tRunner()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1439 +0x213
testing.runTests()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1837 +0x7e4
testing.(*M).Run()
/opt/hostedtoolcache/go/1.18.7/x64/src/testing/testing.go:1719 +0xa71
main.main()
_testmain.go:91 +0x2e4
Goroutine 64 (finished) created at:
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).IdentifyWait()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:331 +0x389
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*netNotifiee).Connected()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:783 +0x44
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).addConn.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:321 +0x64
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).notifyAll()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:573 +0xe9
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).addConn()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:320 +0x6e4
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).AddListenAddr.func2.2()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm_listen.go:134 +0xda
==================
testing.go:1312: race detected during execution of test
--- FAIL: TestIDService (0.08s)
https://github.com/libp2p/go-libp2p/actions/runs/3654765047/jobs/6175469687
=== RUN TestIDService
2022-12-09T05:41:33.666Z DEBUG net/identify identify/id.go:412 /ipfs/id/1.0.0 sent message to 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP /ip4/127.0.0.1/udp/55016/quic
2022-12-09T05:41:33.667Z DEBUG net/identify identify/id.go:444 /ipfs/id/1.0.0 received message from 12D3KooWKfKoL5rTtnQEx5JvYXCgAdogLb1YCFWf4PZdTmsXstGo /ip4/127.0.0.1/udp/43659/quic
2022-12-09T05:41:33.668Z DEBUG net/identify identify/id.go:637 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP received listen addrs for 12D3KooWKfKoL5rTtnQEx5JvYXCgAdogLb1YCFWf4PZdTmsXstGo: [/ip4/127.0.0.1/tcp/35247 /ip4/127.0.0.1/udp/43659/quic]
id_test.go:199: test peer1 has peer2 addrs correctly
2022-12-09T05:41:33.669Z DEBUG net/identify identify/id.go:412 /ipfs/id/1.0.0 sent message to 12D3KooWKfKoL5rTtnQEx5JvYXCgAdogLb1YCFWf4PZdTmsXstGo /ip4/127.0.0.1/udp/43659/quic
2022-12-09T05:41:33.670Z DEBUG net/identify identify/id.go:444 /ipfs/id/1.0.0 received message from 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP /ip4/127.0.0.1/udp/55016/quic
2022-12-09T05:41:33.670Z DEBUG net/identify identify/id.go:354 error opening identify stream {"error": "read tcp4 127.0.0.1:35247->127.0.0.1:41425: read: connection reset by peer"}
2022-12-09T05:41:33.670Z WARN net/identify identify/id.go:334 failed to identify 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP: read tcp4 127.0.0.1:35247->127.0.0.1:41425: read: connection reset by peer
id_test.go:212: test peer2 has peer1 addrs correctly
id_test.go:213:
Error Trace: /home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213
Error: elements differ
extra elements in list A:
([]interface {}) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 a1 d1 |........|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 d6 e8 cc 03 |...........|
}
})
}
extra elements in list B:
([]interface {}) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
listA:
([]multiaddr.Multiaddr) (len=2) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 7f 00 00 01 06 a1 d1 |........|
}
}),
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=11) {
00000000 04 7f 00 00 01 91 02 d6 e8 cc 03 |...........|
}
})
}
listB:
([]multiaddr.Multiaddr) (len=1) {
(*multiaddr.multiaddr)({
bytes: ([]uint8) (len=8) {
00000000 04 01 02 03 04 06 04 d2 |........|
}
})
}
Test: TestIDService
Messages: 12D3KooWKfKoL5rTtnQEx5JvYXCgAdogLb1YCFWf4PZdTmsXstGo did not have addr for 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP
2022-12-09T05:41:33.672Z DEBUG net/identify identify/id.go:637 12D3KooWKfKoL5rTtnQEx5JvYXCgAdogLb1YCFWf4PZdTmsXstGo received listen addrs for 12D3KooWCo2WJhDx9kTDSNpYGzUWLgKfdvYgUjGeUXZnbwBdjtSP: [/ip4/127.0.0.1/tcp/41425 /ip4/127.0.0.1/udp/55016/quic]
id_test.go:213:
Error Trace: /home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213
Error: Should be true
Test: TestIDService
==================
WARNING: DATA RACE
Write at 0x0000020fc7e8 by goroutine 171:
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.TestIDService.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:156 +0x32
testing.(*common).Cleanup.func1()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1041 +0x193
testing.(*common).runCleanup()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1210 +0x143
testing.tRunner.func2()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1440 +0x52
runtime.deferCallSave()
/opt/hostedtoolcache/go/1.19.3/x64/src/runtime/panic.go:796 +0x87
testing.(*T).FailNow()
<autogenerated>:1 +0x37
github.com/stretchr/testify/require.True()
/home/runner/go/pkg/mod/github.com/stretchr/[email protected]/require/require.go:1825 +0xb4
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.testKnowsAddrs()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:45 +0x204
github.com/libp2p/go-libp2p/p2p/protocol/identify_test.TestIDService()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id_test.go:213 +0xbe4
testing.tRunner()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1446 +0x216
testing.(*T).Run.func1()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1493 +0x47
Previous read at 0x0000020fc7e8 by goroutine 240:
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).consumeMessage()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:615 +0x368
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).handleIdentifyResponse()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:446 +0x8e9
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).identifyConn()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:374 +0x4fc
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).IdentifyWait.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:333 +0xc8
Goroutine 171 (running) created at:
testing.(*T).Run()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1493 +0x75d
testing.runTests.func1()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1846 +0x99
testing.tRunner()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1446 +0x216
testing.runTests()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1844 +0x7ec
testing.(*M).Run()
/opt/hostedtoolcache/go/1.19.3/x64/src/testing/testing.go:1726 +0xa84
main.main()
_testmain.go:91 +0x2e9
Goroutine 240 (finished) created at:
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*idService).IdentifyWait()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:331 +0x38d
github.com/libp2p/go-libp2p/p2p/protocol/identify.(*netNotifiee).Connected()
/home/runner/work/go-libp2p/go-libp2p/p2p/protocol/identify/id.go:783 +0x44
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).addConn.func1()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:327 +0x64
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).notifyAll()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:579 +0xe9
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).addConn()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm.go:326 +0x706
github.com/libp2p/go-libp2p/p2p/net/swarm.(*Swarm).AddListenAddr.func2.2()
/home/runner/work/go-libp2p/go-libp2p/p2p/net/swarm/swarm_listen.go:138 +0xda
==================
testing.go:1319: race detected during execution of test
--- FAIL: TestIDService (0.07s)