Sync gets stuck

[gumb0]

I saw this several times on Linux - sync doesn't proceed and no log output after with a last message about the bad hash in the discovery packet.

INFO  10-11 15:02:45 eth  client 2 blocks imported in 196 ms (10.1524 blocks/s) in #5340209
INFO  10-11 15:02:48 eth  client 3 blocks imported in 2784 ms (1.07733 blocks/s) in #5340212
INFO  10-11 15:02:49 eth  client 2 blocks imported in 781 ms (2.55817 blocks/s) in #5340214
INFO  10-11 15:02:49 eth  client 1 blocks imported in 375 ms (2.66216 blocks/s) in #5340215
ERROR 10-11 15:07:13 p2p  discov Invalid packet (bad hash) from 78.56.33.225:31313

[gumb0]

This still happens, last time I hit it syncing with Ropsten on Linux

INFO  03-19 23:33:01 eth  client 12 blocks imported in 897 ms (13.3687 blocks/s) in #5216980
INFO  03-19 23:33:02 eth  client 14 blocks imported in 1120 ms (12.4994 blocks/s) in #5216994
INFO  03-19 23:33:02 eth  client 1 blocks imported in 213 ms (4.68174 blocks/s) in #5216995
ERROR 03-20 09:10:40 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-20 09:26:22 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-21 10:36:15 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-21 21:50:19 p2p  discov Invalid packet (too small) from 18.220.165.204:30303
ERROR 03-22 17:15:07 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-22 17:37:25 p2p  discov Invalid packet (too small) from 52.67.177.28:30303
ERROR 03-23 00:36:38 p2p  discov Invalid packet (too small) from 13.229.215.183:30303
ERROR 03-23 00:41:30 p2p  discov Invalid packet (too small) from 13.229.215.183:30303
ERROR 03-23 01:34:15 p2p  discov Invalid packet (too small) from 13.229.215.183:30303
ERROR 03-23 02:03:48 p2p  discov Invalid packet (too small) from 13.229.215.183:30303
ERROR 03-23 12:45:10 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-24 01:39:24 p2p  discov Invalid packet (bad hash) from 37.35.106.196:46673
ERROR 03-25 01:31:28 p2p  discov Invalid packet (too small) from 18.228.193.200:1024
ERROR 03-25 09:05:17 p2p  discov Invalid packet (too small) from 13.125.209.37:30304
ERROR 03-26 06:37:10 p2p  discov Invalid packet (too small) from 54.232.252.86:30303

[halfalicious]

I've managed to sync the first ~3.5M blocks without a problem on my Linux machine, starting from genesis. I had to kill the sync to do some testing but I'll start it up again and see if I can hit this issue and if so, maybe investigate a little bit.

That's bizarre that the bad discovery packets stop syncing, I took a look at the node table code and they should only cause onPacketReceived to return early:

aleth/libp2p/NodeTable.cpp

Lines 453 to 456 in 523c965

	try {
	unique_ptr<DiscoveryDatagram> packet = DiscoveryDatagram::interpretUDP(_from, _packet);
	if (!packet)
	return;

Do you have any theories as to how Aleth can be getting into such a bad state?

[halfalicious]

I've managed to sync the first ~3.5M blocks without a problem on my Linux machine, starting from genesis. I had to kill the sync to do some testing but I'll start it up again and see if I can hit this issue and if so, maybe investigate a little bit.

That's bizarre that the bad discovery packets stop syncing, I took a look at the node table code and they should only cause onPacketReceived to return early:

aleth/libp2p/NodeTable.cpp

Lines 453 to 456 in 523c965
try {
unique_ptr packet = DiscoveryDatagram::interpretUDP(_from, _packet);
if (!packet)
return;

Do you have any theories as to how Aleth can be getting into such a bad state?

Just hit this:

INFO  03-29 02:09:16 eth  client 6 blocks imported in 2212 ms (2.71213 blocks/s) in #4115779
INFO  03-29 02:09:17 eth  client 5 blocks imported in 1617 ms (3.09048 blocks/s) in #4115784
INFO  03-29 02:09:19 eth  client 4 blocks imported in 1801 ms (2.22047 blocks/s) in #4115788
INFO  03-29 02:09:20 eth  client 3 blocks imported in 737 ms (4.06785 blocks/s) in #4115791
INFO  03-29 02:09:21 eth  client 4 blocks imported in 891 ms (4.48552 blocks/s) in #4115795
INFO  03-29 02:09:23 eth  client 5 blocks imported in 1879 ms (2.65995 blocks/s) in #4115800
INFO  03-29 02:09:24 eth  client 4 blocks imported in 1490 ms (2.6842 blocks/s) in #4115804
INFO  03-29 02:09:25 eth  client 3 blocks imported in 801 ms (3.7441 blocks/s) in #4115807
INFO  03-29 02:09:25 eth  client 4 blocks imported in 569 ms (7.02984 blocks/s) in #4115811
INFO  03-29 02:09:26 eth  client 5 blocks imported in 647 ms (7.72664 blocks/s) in #4115816
INFO  03-29 02:09:27 eth  client 6 blocks imported in 1108 ms (5.41271 blocks/s) in #4115822
INFO  03-29 02:09:29 eth  client 5 blocks imported in 1848 ms (2.70519 blocks/s) in #4115827
INFO  03-29 02:09:29 eth  client 1 blocks imported in 66 ms (14.9622 blocks/s) in #4115828
ERROR 03-29 10:04:47 p2p  discov Invalid packet (too small) from 3.8.84.183:30303

I'm going to enable more logging and see if I can hit this again. I might also try to create a test case which sends a bad packet to the node table to see what happens.

[halfalicious]

So it looks like there's more to this than the Node Table simply receiving a bad discovery packet...I tried syncing on Linux and manually sending a nearly-empty UDP packet to Aleth (using Packet Sender), Aleth logged the "invalid packet" message but didn't stop syncing...perhaps the sender has to be a peer? I'll do some more investigation/experimenting..

[halfalicious]

Looking at the logs again in this thread and in each case there's a pretty big time delta between when the last blocks were sync'd and when the bad packet was received, which makes me think that syncing stopping and receiving bad discovery packets are unrelated.

[halfalicious]

I added some instrumentation to Aleth which measures the time since blocks were last sync'd and fires an assert when this time exceeds 1 hour. I ran this private version of Aleth on Ropsten and hit an assert after a few hours, here's the console log (captures the last ~17 minutes of activity): sync_stuck.txt

I've taken a quick look at the log and it looks like Aleth keeps asking the same peer for block bodies (a Parity boot node) but doesn't receive any:

DEBUG 04-23 17:43:29 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:29 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:29 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:29 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:30 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:30 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:31 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:31 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:31 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:31 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:32 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:32 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:32 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:32 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:33 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:33 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:33 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:33 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:33 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:33 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:33 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:33 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:33 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies
DEBUG 04-23 17:43:33 p2p  peer   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Requesting 1024 BlockBodies from ##865a6325…
DEBUG 04-23 17:43:34 p2p  sync   865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 BlocksBodies (0 entries) : NoMoreBodies

I suspect that Aleth only has 1 peer (the Parity Ropsten boot node) which is why it keeps pinging the same node for block bodies (#5575 should make this more clear). I'm not sure if it should do this though, I don't see anything in the wire protocol spec which calls out good / bad behavior so I suspect this is implementation-dependent. @gumb0 / @chfast : Do you know if Aleth is expected to continuously query the same node for block bodies if it keeps getting no bodies in return?

Additionally, Aleth keeps trying to connect to the same node multiple times, despite it being on a separate network. For example:

DEBUG 04-23 17:57:42 p2p  net    Hello: Geth/v1.8.22-stable/linux-amd64/go1.10.3 V[5] ##a979fb57… (eth,63) 0
DEBUG 04-23 17:57:42 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-23 17:57:42 p2p  net    p2p.host.peer.register ##a979fb57…
DEBUG 04-23 17:57:42 p2p  ethcap a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Status: 63 / 1 / #d4e56740…, TD: 9941218370451185254834 = #6d41ee6d…
DEBUG 04-23 17:57:42 p2p  sync   a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Peer not suitable for sync: Network identifier mismatch. Host network id: 3, peer network id: 1
DEBUG 04-23 17:57:42 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Closing peer session :-(
DEBUG 04-23 17:57:45 eth  client Since 1970-01-15 22:08:09.546Z (15): 15ticks
DEBUG 04-23 17:57:51 p2p  net    865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Closing peer session :-(
DEBUG 04-23 17:57:52 p2p  net    Hello: Geth/v1.8.22-stable/linux-amd64/go1.10.3 V[5] ##a979fb57… (eth,63) 0
DEBUG 04-23 17:57:52 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-23 17:57:52 p2p  net    p2p.host.peer.register ##a979fb57…
DEBUG 04-23 17:57:52 p2p  ethcap a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Status: 63 / 1 / #d4e56740…, TD: 9941218370451185254834 = #6d41ee6d…
DEBUG 04-23 17:57:52 p2p  sync   a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Peer not suitable for sync: Network identifier mismatch. Host network id: 3, peer network id: 1
DEBUG 04-23 17:57:52 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Closing peer session :-(
DEBUG 04-23 17:57:58 p2p  net    Hello: Geth/v1.8.22-stable/linux-amd64/go1.10.3 V[5] ##a979fb57… (eth,63) 0
DEBUG 04-23 17:57:58 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-23 17:57:58 p2p  net    p2p.host.peer.register ##a979fb57…
DEBUG 04-23 17:57:58 p2p  ethcap a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Status: 63 / 1 / #d4e56740…, TD: 9941218370451185254834 = #6d41ee6d…
DEBUG 04-23 17:57:58 p2p  sync   a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Peer not suitable for sync: Network identifier mismatch. Host network id: 3, peer network id: 1
DEBUG 04-23 17:57:58 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Closing peer session :-(
DEBUG 04-23 17:58:00 eth  client Since 1970-01-15 22:08:24.561Z (15): 15ticks
DEBUG 04-23 17:58:09 eth  client Time since last block queue sync: 3466.62 seconds
DEBUG 04-23 17:58:15 eth  client Since 1970-01-15 22:08:39.576Z (15): 15ticks
DEBUG 04-23 17:58:29 p2p  net    Hello: Geth/v1.8.22-stable/linux-amd64/go1.10.3 V[5] ##a979fb57… (eth,63) 0
DEBUG 04-23 17:58:29 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-23 17:58:29 p2p  net    p2p.host.peer.register ##a979fb57…
DEBUG 04-23 17:58:29 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Disconnect (reason: Peer had too many connections.)
DEBUG 04-23 17:58:29 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Closing peer session :-(
DEBUG 04-23 17:58:30 eth  client Since 1970-01-15 22:08:54.591Z (15): 15ticks
DEBUG 04-23 17:58:40 eth  client Time since last block queue sync: 3497.62 seconds
DEBUG 04-23 17:58:45 eth  client Since 1970-01-15 22:09:09.605Z (15): 15ticks
DEBUG 04-23 17:58:55 p2p  net    Hello: Geth/v1.8.22-stable/linux-amd64/go1.10.3 V[5] ##a979fb57… (eth,63) 0
DEBUG 04-23 17:58:55 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-23 17:58:55 p2p  net    p2p.host.peer.register ##a979fb57…
DEBUG 04-23 17:58:55 p2p  ethcap a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Status: 63 / 1 / #d4e56740…, TD: 9941218370451185254834 = #6d41ee6d…
DEBUG 04-23 17:58:55 p2p  sync   a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Peer not suitable for sync: Network identifier mismatch. Host network id: 3, peer network id: 1
DEBUG 04-23 17:58:55 p2p  net    a979fb57…|Geth/v1.8.22-stable/linux-amd64/go1.10.3 Closing peer session :-(

This seems like bad behavior - @gumb0 / @chfast : Is this expected?

[gumb0]

Do you know if Aleth is expected to continuously query the same node for block bodies if it keeps getting no bodies in return?

What we do in this case is we lower peer's rating and continue with the sync

aleth/libethereum/BlockChainSync.cpp

Lines 597 to 601 in 6de1e88

	if (itemCount == 0)
	{
	LOG(m_loggerDetail) << "Peer does not have the blocks requested";
	m_host.capabilityHost().updateRating(_peerID, -1);
	}

This seems reasonable, but unfortunately the only thing this rating affects as I understand is the order of traversal of peers here

aleth/libp2p/Host.cpp

Lines 1098 to 1103 in 6de1e88

	auto sessionLess = [](shared_ptr<SessionFace> const& _left,
	shared_ptr<SessionFace> const& _right) {
	return _left->rating() == _right->rating() ?
	_left->connectionTime() < _right->connectionTime() :
	_left->rating() > _right->rating();
	};

I think what we could try to do with this is disconnect from the peer when it reaches some negative limit of rating. Then we'll send this block bodies request to a single peer a limited number of times before disconnecting.

(Yeah these peer reputation systems are implementation-specific and I don't really know how other clients implement this)

[gumb0]

But then the more interesting question is how did we get to the point where we request 1024 blocks, which the bootnode doesn't have... Maybe we ended up on some fork of Ropsten, or maybe something went very wrong before that. Do you have the earlier log?

[gumb0]

Additionally, Aleth keeps trying to connect to the same node multiple times, despite it being on a separate network.

I think this is expected, because this is a (mainnet) bootnode, and bootnodes are added as required peers, which means constantly trying to reconnect. But we could optimize this by splitting the list of bootnodes to separate lists for mainnet and Ropsten.

Also note the interconnection with what I suggested above about rating: if we disconnect from the bootnode because its rating dropped, we'll immediately reconnect because bootnode is required... I think we really shouldn't end up in the situation where bootnode's rating goes down, something went wrong there

[halfalicious]

But then the more interesting question is how did we get to the point where we request 1024 blocks, which the bootnode doesn't have... Maybe we ended up on some fork of Ropsten, or maybe something went very wrong before that. Do you have the earlier log?

Unfortunately no, the console buffer only contained the last ~15 minutes of logs. I'll look into performing a new run and capturing a greater time window of logs - I might try something like only enabling the client / sync / peer / net channels and redirecting all log output to a file, the problem is that the amount of time it takes to hit this problem is unpredictable and the network logs can be very big and I don't want the log file to fill my entire disk. I might also try moving some net messages to new loggers so I can filter things down further or perhaps only enable debug verbosity until I know what to look for, then doing a run with even more filtering but trace verbosity.