Multiple errors on sync

[rex4539]

I have finally imported the blockchain :)

Now, when I run pzec, I see multiple errors.

2019-04-17 06:36:30  WARN sync Disconnecting from peer#1 due to misbehavior: Got 'headers' message without known blocks
2019-04-17 06:36:30  WARN sync Last peer was marked as non-useful. Moving to saturated state.
2019-04-17 06:36:39  WARN sync Last peer was marked as non-useful. Moving to saturated state.
2019-04-17 06:36:39  WARN sync Disconnecting from peer#4 due to misbehavior: Got 'headers' message without known blocks
2019-04-17 06:36:39  WARN sync Last peer was marked as non-useful. Moving to saturated state.
2019-04-17 06:36:49  WARN sync Failed to get requested block from peer#3 in 5.68 seconds.
2019-04-17 06:36:49  WARN sync Too many failures for peer#3. Excluding from synchronization.
2019-04-17 06:36:49  WARN sync Disconnecting from peer#3 due to misbehavior: Too many failures.
2019-04-17 06:36:49  WARN sync Too many header failures for peer#3. Excluding from synchronization.
2019-04-17 06:36:50  WARN sync Previous header of the first header from peer#6 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:36:50  WARN sync Disconnecting from peer#6 due to misbehavior: Too many failures.
2019-04-17 06:36:50  WARN sync Previous header of the first header from peer#7 `headers` message is unknown. First: 0004b371c02c41c61c189ce04ac147220daf796e9a60ce90cfee31e5a71dda2d. Previous: 0007104ccda289427919efc39dc9e4d499804b7bebc22df55f8b834301260602
2019-04-17 06:36:50  WARN sync Disconnecting from peer#7 due to misbehavior: Too many failures.
2019-04-17 06:37:23  WARN sync Disconnecting from peer#12 due to misbehavior: Error verifying header 001bb0d07e628cccfbf2998d27bf18bd0463a44b64bba5664ef786fa17bd5170 from `headers`: "Pow"
2019-04-17 06:37:31  WARN sync Previous header of the first header from peer#14 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:31  WARN sync Disconnecting from peer#14 due to misbehavior: Too many failures.
2019-04-17 06:37:40  WARN sync Previous header of the first header from peer#15 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:40  WARN sync Disconnecting from peer#15 due to misbehavior: Too many failures.
2019-04-17 06:37:44  INFO sync Processed 120 blocks in 61.15 seconds (1.96 blk/s).	Peers: 6 (act: 6, idl: 0, bad: 1).	Chain: [sch:84 > req:0 > vfy:1064 > db:515558]
2019-04-17 06:37:49  WARN sync Too many header failures for peer#13. Excluding from synchronization.
2019-04-17 06:37:49  WARN sync Disconnecting from peer#13 due to misbehavior: Too many header failures.
2019-04-17 06:37:50  WARN sync Previous header of the first header from peer#16 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:50  WARN sync Disconnecting from peer#16 due to misbehavior: Too many failures.
2019-04-17 06:37:51  WARN sync Previous header of the first header from peer#19 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:51  WARN sync Disconnecting from peer#19 due to misbehavior: Too many failures.
2019-04-17 06:37:51  WARN sync Previous header of the first header from peer#18 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:51  WARN sync Disconnecting from peer#18 due to misbehavior: Too many failures.
2019-04-17 06:37:51  WARN sync Previous header of the first header from peer#17 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:37:51  WARN sync Disconnecting from peer#17 due to misbehavior: Too many failures.
2019-04-17 06:38:00  WARN sync Previous header of the first header from peer#21 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:00  WARN sync Disconnecting from peer#21 due to misbehavior: Too many failures.
2019-04-17 06:38:00  WARN sync Previous header of the first header from peer#20 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:00  WARN sync Disconnecting from peer#20 due to misbehavior: Too many failures.
2019-04-17 06:38:00  WARN sync Previous header of the first header from peer#22 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:00  WARN sync Disconnecting from peer#22 due to misbehavior: Too many failures.
2019-04-17 06:38:20  WARN sync Previous header of the first header from peer#25 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:20  WARN sync Disconnecting from peer#25 due to misbehavior: Too many failures.
2019-04-17 06:38:20  WARN sync Previous header of the first header from peer#24 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:20  WARN sync Disconnecting from peer#24 due to misbehavior: Too many failures.
2019-04-17 06:38:20  WARN sync Disconnecting from peer#26 due to misbehavior: Provided after dead-end block 001bb0d07e628cccfbf2998d27bf18bd0463a44b64bba5664ef786fa17bd5170
2019-04-17 06:38:30  WARN sync Previous header of the first header from peer#28 `headers` message is unknown. First: 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5. Previous: 00052461a5006c2e3b74ce48992a08695607912d5604c3eb8da25749b0900444
2019-04-17 06:38:30  WARN sync Disconnecting from peer#28 due to misbehavior: Too many failures.
2019-04-17 06:38:44  INFO sync Switched to saturated state.	Chain: [sch:0 > req:0 > vfy:1027 > db:515679]
2019-04-17 06:39:09  WARN sync Disconnecting from peer#30 due to misbehavior: Got 'headers' message without known blocks
2019-04-17 06:39:09  WARN sync Last peer was marked as non-useful. Moving to saturated state.
2019-04-17 06:41:10  WARN sync Disconnecting from peer#32 due to misbehavior: Got 'headers' message without known blocks
2019-04-17 06:41:10  WARN sync Last peer was marked as non-useful. Moving to saturated state.

Is this normal?

[svyatonik]

Cool, thanks for reporting! :)

This isn't normal, but I don't see how we could avoid this. I have also noted this recently (#58) - there are too many peers from other blockchains (here: zel.cash with its 0003eb875fc001da4a57de8465f68a2730c24ca086f37c6f14780ac9ee3ea3d5 and some other blockchain with 001bb0d07e628cccfbf2998d27bf18bd0463a44b64bba5664ef786fa17bd5170) which use the same network magic, the same client app id, the same handshaking procedure && it is impossible to distinguish between zcash peer && zel.cash/... peer until we will receive headers. And when we getting wrong headers from untrusted peer, we're disconnecting immediately (#61). So eventually you'll disconnect from all 'bad' peers and will stay connected to proper zcash peers only.

Logging the peer disconnect reason is a good option, imo. Otherwise you'll never see why your client stays unsynced && it is even more weirder (getting multiple Last peer was marked as non-useful. Moving to saturated state. without knowing the reason is annoying).

I'll leave this issue open for a bit - probably someone will have an idea of how to improve peer selection strategy.

[wkarshat]

While a Zel node, misconfigured via an explicit 'addnode' could be reaching to a Zcash one, it is unlikely, as the default port numbers are very different (16125). Though possible, we have no indication that the Zcash node would then accept lists of more Zel peers, and worse yet pass them onto other Zcash nodes. Definitely would not be able to validate and pass on a Zel transaction or block.

Looks like after a while you start erroring out and disconnecting just about every peer#. Likely you get yourself into a state where you reject valid peers and then run out of peers (you call this state saturated, though likely you mean exhausted). Does feel like more than just some annoying messages in the log file, but perhaps a stateful bug. Wonder if your peer list somehow getting polluted or filled-up.

Would help to see some peer info details, to understand what those peers are and whether you are cycling through a small set of peers, e.g. Zcash:
receive version message: /MagicBean:2.0.4/: version 170007, blocks=517363

After a quick look at the code, do wonder about the implementation of remove(), misbehaving(), dos() in synchronization_peers.rs, PeersContainer for PeersImpl:
remove() does not call connection.close()
misbehaving() and dos() reference through a peer for connection.close() after a remove().

BTW, where in the code are you disconnecting during sync peers with fewer blocks than you have already?
What about the code setting the policy for the likes of max outbound, inbound, addnode, total connections?

[svyatonik]

While a Zel node, misconfigured via an explicit 'addnode' could be reaching to a Zcash one, it is unlikely, as the default port numbers are very different (16125). Though possible, we have no indication that the Zcash node would then accept lists of more Zel peers, and worse yet pass them onto other Zcash nodes. Definitely would not be able to validate and pass on a Zel transaction or block.

When started with empty database, parity-zcash connects to hardcoded set of seed nodes. The seednodes are the same as in original zcash client. That's the only way to get set of peers. So zel.cash peers are the peers we receive from seednodes (or from nodes that seednodes have provided us with).

Looks like after a while you start erroring out and disconnecting just about every peer#. Likely you get yourself into a state where you reject valid peers and then run out of peers (you call this state saturated, though likely you mean exhausted). Does feel like more than just some annoying messages in the log file, but perhaps a stateful bug. Wonder if your peer list somehow getting polluted or filled-up.

I haven't seen any case where we disconnect from valid peers. Could you, please, file a separate issue with detailed logs (RUST_LOG=sync=trace,p2p=trace,verification=trace,db=trace) where you believe we disconnect from valid peer?

Would help to see some peer info details, to understand what those peers are and whether you are cycling through a small set of peers, e.g. Zcash:
receive version message: /MagicBean:2.0.4/: version 170007, blocks=517363

I could confirm that last time I've checked this, zel.cash peers were responding with /MagicBean:2.* user agent id.

After a quick look at the code, do wonder about the implementation of remove(), misbehaving(), dos() in synchronization_peers.rs, PeersContainer for PeersImpl:
remove() does not call connection.close()
misbehaving() and dos() reference through a peer for connection.close() after a remove().

misbehaving() and dos() are scheduling disconnect at network level. remove() is called once network level confirms that we have disconnected (and probably penalized) the peer.

BTW, where in the code are you disconnecting during sync peers with fewer blocks than you have already?

There's no such code atm.

What about the code setting the policy for the likes of max outbound, inbound, addnode, total connections?

Limits are currently hardcoded to 10 inbound and 10 outbound connections.