go-libp2p icon indicating copy to clipboard operation
go-libp2p copied to clipboard

autorelay: flaky TestMaxAge

Open marten-seemann opened this issue 1 year ago • 1 comments

https://github.com/libp2p/go-libp2p/runs/7748138576?check_suite_focus=true

  === RUN   TestMaxAge
      autorelay_test.go:404: 
          	Error Trace:	/home/runner/work/go-libp2p/go-libp2p/p2p/host/autorelay/autorelay_test.go:404
          	Error:      	Condition never satisfied
          	Test:       	TestMaxAge
  --- FAIL: TestMaxAge (6.52s)

marten-seemann avatar Aug 09 '22 14:08 marten-seemann

This test is so flaky that fixing it will need to be a P0.

marten-seemann avatar Aug 09 '22 14:08 marten-seemann

Log output of a failed run:

=== RUN   TestMaxAge
2022-08-10T09:40:48.841+0200	DEBUG	autorelay	autorelay/relay_finder.go:653	starting relay finder
2022-08-10T09:40:48.841+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWAGEPewgrHmWnvmbt1GArsWGBXBiQo1mEu23tb2iJdZRd"}
2022-08-10T09:40:48.841+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWSjUQeHBQBrkrxFDJR7cHShHiEtUwRyvq2dfegDar2UH4"}
2022-08-10T09:40:48.841+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWFvvevPfYzG6iQ63t7s7cYkxTjzBYGZvFhgQUqkt4Lxfu"}
2022-08-10T09:40:48.841+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWFuhZDV9yucDace2RPKfqy7nZ8JoMpGpBjqxoRMF5VkLf"}
2022-08-10T09:40:48.847+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWFuhZDV9yucDace2RPKfqy7nZ8JoMpGpBjqxoRMF5VkLf", "supports circuit v2": true}
2022-08-10T09:40:48.848+0200	DEBUG	autorelay	autorelay/relay_finder.go:484	adding new relay	{"id": "12D3KooWFuhZDV9yucDace2RPKfqy7nZ8JoMpGpBjqxoRMF5VkLf"}
2022-08-10T09:40:48.848+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWSjUQeHBQBrkrxFDJR7cHShHiEtUwRyvq2dfegDar2UH4", "supports circuit v2": true}
2022-08-10T09:40:48.849+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWAGEPewgrHmWnvmbt1GArsWGBXBiQo1mEu23tb2iJdZRd", "supports circuit v2": true}
2022-08-10T09:40:48.849+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWFvvevPfYzG6iQ63t7s7cYkxTjzBYGZvFhgQUqkt4Lxfu", "supports circuit v2": true}
2022-08-10T09:40:48.849+0200	DEBUG	autorelay	autorelay/relay_finder.go:224	not enough candidates. Resetting timer	{"num": 3, "desired": 4}
2022-08-10T09:40:48.849+0200	DEBUG	autorelay	autorelay/relay_finder.go:224	not enough candidates. Resetting timer	{"num": 3, "desired": 4}
2022-08-10T09:40:49.073+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooW9qsLYyDksc44nmTbx8hvFbnRaQKCJ3MprPpvxXjh5KAG"}
2022-08-10T09:40:49.073+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWNFNpEoYj54LJwF2Qfbz8bb1hR9zqMS6AJuShqp8vxEBr"}
2022-08-10T09:40:49.073+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWEBym6mfkpvBxtoGY2EyvarEtUz9A7Y2GWfQnVvuxef5T"}
2022-08-10T09:40:49.074+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWDMTygVfb3qkVEVQXGxuRS5NyhEdLWqCEGWsQutJDndcJ"}
2022-08-10T09:40:49.087+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooW9qsLYyDksc44nmTbx8hvFbnRaQKCJ3MprPpvxXjh5KAG", "supports circuit v2": true}
2022-08-10T09:40:49.087+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWEBym6mfkpvBxtoGY2EyvarEtUz9A7Y2GWfQnVvuxef5T", "supports circuit v2": true}
2022-08-10T09:40:49.087+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWNFNpEoYj54LJwF2Qfbz8bb1hR9zqMS6AJuShqp8vxEBr", "supports circuit v2": true}
2022-08-10T09:40:49.088+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWDMTygVfb3qkVEVQXGxuRS5NyhEdLWqCEGWsQutJDndcJ", "supports circuit v2": true}
2022-08-10T09:40:49.103+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWSjUQeHBQBrkrxFDJR7cHShHiEtUwRyvq2dfegDar2UH4"}
2022-08-10T09:40:49.103+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWAGEPewgrHmWnvmbt1GArsWGBXBiQo1mEu23tb2iJdZRd"}
2022-08-10T09:40:49.103+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWFvvevPfYzG6iQ63t7s7cYkxTjzBYGZvFhgQUqkt4Lxfu"}
    autorelay_test.go:421: 
        	Error Trace:	/home/parallels/src/go/src/github.com/libp2p/go-libp2p/p2p/host/autorelay/autorelay_test.go:421
        	Error:      	Condition never satisfied
        	Test:       	TestMaxAge
2022-08-10T09:40:52.121+0200	DEBUG	autorelay	autorelay/relay_finder.go:667	stopping relay finder
--- FAIL: TestMaxAge (3.39s)

And here's a successful one:

=== RUN   TestMaxAge
2022-08-10T09:40:48.353+0200	DEBUG	autorelay	autorelay/relay_finder.go:653	starting relay finder
2022-08-10T09:40:48.353+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWLgqboVQBLma9vwP2Gm6Kyen6dDeKJcjxx69PjyRJmWMn"}
2022-08-10T09:40:48.353+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWLmnaANVd1RGD3c2uRAVdBipLMbbc6AP6zSkHsYCgbfC4"}
2022-08-10T09:40:48.353+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWHM1SeAFUSRTf35NhhKPVEumweeBfU2dEoTpjUNTV3wvH"}
2022-08-10T09:40:48.353+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWB6eYY8AfnMTwJjzAsDuivY4dxQx7vayEsiyS7ZYG8U2J"}
2022-08-10T09:40:48.358+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWB6eYY8AfnMTwJjzAsDuivY4dxQx7vayEsiyS7ZYG8U2J", "supports circuit v2": true}
2022-08-10T09:40:48.358+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWLgqboVQBLma9vwP2Gm6Kyen6dDeKJcjxx69PjyRJmWMn", "supports circuit v2": true}
2022-08-10T09:40:48.358+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWLmnaANVd1RGD3c2uRAVdBipLMbbc6AP6zSkHsYCgbfC4", "supports circuit v2": true}
2022-08-10T09:40:48.359+0200	DEBUG	autorelay	autorelay/relay_finder.go:484	adding new relay	{"id": "12D3KooWB6eYY8AfnMTwJjzAsDuivY4dxQx7vayEsiyS7ZYG8U2J"}
2022-08-10T09:40:48.361+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWHM1SeAFUSRTf35NhhKPVEumweeBfU2dEoTpjUNTV3wvH", "supports circuit v2": true}
2022-08-10T09:40:48.361+0200	DEBUG	autorelay	autorelay/relay_finder.go:224	not enough candidates. Resetting timer	{"num": 3, "desired": 4}
2022-08-10T09:40:48.361+0200	DEBUG	autorelay	autorelay/relay_finder.go:224	not enough candidates. Resetting timer	{"num": 3, "desired": 4}
2022-08-10T09:40:48.605+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWQ2MzXSo2RnX58mWM3e3gie1s9t4h247mxARbLemApZhS"}
2022-08-10T09:40:48.605+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWQEDLW9RGKM8emjFqm32JvV2qw91DhbDM77hxHU3CYXZG"}
2022-08-10T09:40:48.605+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWKMt7cVLLJLQ6Z9JjVfFCSTpghzLNaq3Bfphi4jkkiwih"}
2022-08-10T09:40:48.605+0200	DEBUG	autorelay	autorelay/relay_finder.go:246	found node	{"id": "12D3KooWBb6u2HpFdCH2kU1wm2gLHnrdvyrMaMFexpJRC9a7MWUj"}
2022-08-10T09:40:48.609+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWQ2MzXSo2RnX58mWM3e3gie1s9t4h247mxARbLemApZhS", "supports circuit v2": true}
2022-08-10T09:40:48.609+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWBb6u2HpFdCH2kU1wm2gLHnrdvyrMaMFexpJRC9a7MWUj", "supports circuit v2": true}
2022-08-10T09:40:48.609+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWKMt7cVLLJLQ6Z9JjVfFCSTpghzLNaq3Bfphi4jkkiwih", "supports circuit v2": true}
2022-08-10T09:40:48.609+0200	DEBUG	autorelay	autorelay/relay_finder.go:336	node supports relay protocol	{"peer": "12D3KooWQEDLW9RGKM8emjFqm32JvV2qw91DhbDM77hxHU3CYXZG", "supports circuit v2": true}
2022-08-10T09:40:48.623+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWHM1SeAFUSRTf35NhhKPVEumweeBfU2dEoTpjUNTV3wvH"}
2022-08-10T09:40:48.623+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWLgqboVQBLma9vwP2Gm6Kyen6dDeKJcjxx69PjyRJmWMn"}
2022-08-10T09:40:48.623+0200	DEBUG	autorelay	autorelay/relay_finder.go:184	deleting candidate due to age	{"id": "12D3KooWLmnaANVd1RGD3c2uRAVdBipLMbbc6AP6zSkHsYCgbfC4"}
2022-08-10T09:40:48.627+0200	DEBUG	autorelay	autorelay/relay_finder.go:154	disconnected from relay	{"id": "12D3KooWB6eYY8AfnMTwJjzAsDuivY4dxQx7vayEsiyS7ZYG8U2J"}
2022-08-10T09:40:48.628+0200	DEBUG	autorelay	autorelay/relay_finder.go:484	adding new relay	{"id": "12D3KooWKMt7cVLLJLQ6Z9JjVfFCSTpghzLNaq3Bfphi4jkkiwih"}
2022-08-10T09:40:48.728+0200	DEBUG	autorelay	autorelay/relay_finder.go:667	stopping relay finder
--- PASS: TestMaxAge (0.49s)

marten-seemann avatar Aug 10 '22 10:08 marten-seemann