Sync protocol gets stuck and node requires a restart.

[DamianStraszak]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

We use substrate (branch polkadot-v0.9.26) on our testnet (Aleph Zero testnet) and quite often (some nodes get that every couple of days) experience a problem with the sync protocol getting stuck. The way it looks like is that till some point everything works OK, after which the node enters a strange state and keeps logging:
2022-08-11 13:12:51 ⚙️ Syncing 0.0 bps, target=#7930720 (26 peers), best: #7927340 (0xa832…7ebb), finalized #7927337 (0x292d…fd2a), ⬇ 2.9kiB/s ⬆ 0.4kiB/s
without making any progress anymore. Restarting the node always helps.

So far we haven't really found any plausible explanation for this -- it doesn't seem to be happening at any specific blocks -- different nodes get stuck on different blocks. We found a strange way to (sometimes) reproduce it -- run a node on a laptop, then hibernate it for some time, and then turn it back on -- once the node reconnects and tries to sync, it gets stuck in the same way (and restart is necessary). This way we were able to produce the attached log (it has trace logs on sync). Attached below.
verbose-logs.log

This is however not a typical situation in which the problem arises (i.e. long network disconnect) -- in fact normally nodes work normally and just like that they stop syncing :/

The main difference between AlephZero and Polkadot and standard parachain nodes is that we have low block-time (1sec) and that we use Aura + AlephBFT instead of Babe + Grandpa. However, the latter shouldn't really matter because this affects mostly non-validator nodes, who don't even run any consensus code.

Our only guess was that maybe this is because we don't have this fix #11817 in our substrate dependency, but by inspecting the code it doesn't seem that it could have such an effect...

We would appreciate any help in finding out what the culprit of that could be... Thanks!

Steps to reproduce

No response

[bkchr]

Have you run the node the entire time with sync=trace? There are gaps in the logs after the POWER_OFF. I would expect that we see disconnect messages or connect messages afterwards.

[DamianStraszak]

Thanks @bkchr -- these are indeed full sync=trace logs, but your response is likely on point. Should these disconnects be due to reputation change?

If that's the case, then here is my question (asking for a friend ofc :P) suppose "someone" got rid of the ReputationChange for block_request_handler as in this PR https://github.com/Cardinal-Cryptography/substrate/pull/12/files -- could this cause such issues? In other words, is the sole purpose of the reputation system to make it harder for dishonest nodes to spam honest ones, or it has also other functions, like forcing pairs of honest nodes to disconnect and reconnect from time to time? The latter would be quite a surprise to me, but it would explain the problem.

And thank you again for the answer, this is exactly the kind of hint I was dreaming about :)

[bkchr]

Thanks @bkchr -- these are indeed full sync=trace logs, but your response is likely on point. Should these disconnects be due to reputation change?

I don't know for sure, however I would expect that you see disconnects when a connection is closed. As you see in the logs the number of peers is decreasing, but there should be logs when this happens:

substrate/client/network/src/protocol.rs

Lines 558 to 562 in 40703f4

	if self.important_peers.contains(&peer) {
	warn!(target: "sync", "Reserved peer {} disconnected", peer);
	} else {
	debug!(target: "sync", "{} disconnected", peer);
	}

[DamianStraszak]

Oh, you are right, I'm sorry :/ The full sync=trace starts around 13:13:44 in these logs -- it was enabled via system_addLogFilter RPC call on the fly. Would it be helpful if I got full sync=trace logs?

[bkchr]

Would it be helpful if I got full sync=trace logs?

Yes that would helpful.

[DamianStraszak]

stuck.zip
Here are the full logs. Important timestamps (note that the node process is running without interruptions):

1. 11:03:02.161 -- I have disconnected the node from the network.
2. 12:15:04.731 -- I have connected the node back. It starts syncing initially
3. 12:15:13.220 -- somewhere around here sync gets stuck on block 9082823

Note that these are new logs -- not just a more verbose version of the previous ones. I generated them by running our testnet node inside a docker, then disconnecting network from the docker for 1h, and reconnecting.

Let me know if I can provide any other information that could help -- I can rerun with additional logs if necessary.

Thank you for helping!

[arkpar]

What substrate commit are you on? Does it have #11763 and #11815?

[DamianStraszak]

Thanks @arkpar -- we don't have these commits, we use the polkadot-v0.9.26 branch and it seems these entered in polkadot-v0.9.27. Do you suspect updating to polkadot-v0.9.27 or polkadot-v0.9.28 should help?

[bkchr]

#11763

I forgot this pr and it could help with the issue you are seeing. Could you please try?

[DamianStraszak]

Thanks @arkpar and @bkchr -- after few days of the testnet running on the new version there seems to be no stuck nodes anymore. I think the issue can be closed.

[bkchr]

Ty for reporting back!