bootstrap triggers a debug_assert

[stormshield-frb]

Summary

We are encountering a strange bug in protocols/kad/src/handler.rs:queue_new_stream : the debug_assert is reached.

rust-libp2p/protocols/kad/src/handler.rs

Lines 582 to 585 in 4d7a535

	debug_assert!(
	result.is_ok(),
	"Expected to not create more streams than allowed"
	);

After doing some heavy diagnostics, we have concluded there does not seem to be a bug with FuturesMap (as we thought at first).

Indeed, for some reason (that we do not fully understand, and we do not know if it is normal or not), a bootstrap request seems to trigger multiple FindeNodeReq on the same Connection, with the same QueryId and at the same time, resulting in :

1. multiple FindeNodeReq being handled in on_behaviour_event
2. which calls self.pending_messages.push_back
3. which is itself processed in the poll method of Handler
4. which calls self.pending_messages.pop_front
5. which calls self.queue_new_stream
6. which call self.outbound_substreams.try_push
7. which returns an error

Expected behavior

The debug_assert should not be reached, no matter the circumstances.

Actual behavior

The debug_assert is reached.

Relevant log output

No response

Possible Solution

Our thought is: is it really Expected to not create more streams than allowed ? From our perspective, there could be some reasons why we try to create a stream even if there is already one for the corresponding request.

Indeed, is there something preventing the libp2p to not emit HandlerIn event on the same Handler and with the same QueryId while the previous one has not been handled ? It does not seem to be the case when reading the on_behaviour_event implementation with all the self.pending_messages.push_back().

Honestly, we are not quite sure where this error is coming from. The peer that was trying to be reached did trigger the timeout of the TimeoutFuture so maybe it is related, but we are not sure.

Version

master branch from yesterday (11/27/2023): dfce3cc

Would you like to work on fixing this bug ?

Yes

[thomaseizinger]

Thank you for the detailed report @stormshield-frb !

This is almost certainly related to #4901. I'll look at the code in more detail and see if I can find anything.

[thomaseizinger]

Our thought is: is it really Expected to not create more streams than allowed ? From our perspective, there could be some reasons why we try to create a stream even if there is already one for the corresponding request.

When I wrote this debug-assert, I didn't think that the same query could actually be sent multiple times (i.e. QueryId not being unique). Thus, the only possible error path would be that the FuturesMap is full which shouldn't happen because we've checked the size before.

I'll send a quick patch that differentiates these errors more precisely so we can confirm that.

cc @mxinden We might need your input here.