Full sync requests headers too early

[gumb0]

Sometimes I see log like this during sync:

DEBUG 04-10 19:07:16 p2p  net    Hello: Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 V[5] ##12627e3f… (eth,63) 0
DEBUG 04-10 19:07:16 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-10 19:07:16 p2p  net    p2p.host.peer.register ##12627e3f…
DEBUG 04-10 19:07:16 p2p  net    Hello: Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 V[5] ##41216694… (eth,63) 0
DEBUG 04-10 19:07:16 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-10 19:07:16 p2p  net    p2p.host.peer.register ##41216694…
DEBUG 04-10 19:07:16 p2p  net    Hello: Parity/v1.11.7-stable-085035f-20180717/x86_64-linux-gnu/rustc1.27.1 V[5] ##a3171567… (eth,63) 30303
DEBUG 04-10 19:07:16 p2p  net    New session for capability eth; idOffset: 16
DEBUG 04-10 19:07:16 p2p  net    p2p.host.peer.register ##a3171567…
DEBUG 04-10 19:07:16 p2p  net    a3171567…|Parity/v1.11.7-stable-085035f-20180717/x86_64-linux-gnu/rustc1.27.1 Disconnect (reason: Peer had too many connections.)
DEBUG 04-10 19:07:16 p2p  net    a3171567…|Parity/v1.11.7-stable-085035f-20180717/x86_64-linux-gnu/rustc1.27.1 Closing peer session :-(
DEBUG 04-10 19:07:16 p2p  peer   a3171567…|Parity/v1.11.7-stable-085035f-20180717/x86_64-linux-gnu/rustc1.27.1 Requesting 1 block headers starting from 792972 from ##12627e3f…
DEBUG 04-10 19:07:16 p2p  peer   a3171567…|Parity/v1.11.7-stable-085035f-20180717/x86_64-linux-gnu/rustc1.27.1 Requesting 1 block headers starting from 792972 from ##41216694…
DEBUG 04-10 19:07:16 p2p  ethcap 12627e3f…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Status: 63 / 3125659152 / #29a742ba…, TD: 20930637977425940388 = #59d6fc3a…
DEBUG 04-10 19:07:16 p2p  sync   12627e3f…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Peer not suitable for sync: Invalid genesis hash.
DEBUG 04-10 19:07:16 p2p  net    12627e3f…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Closing peer session :-(
DEBUG 04-10 19:07:16 p2p  ethcap 41216694…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Status: 63 / 3125659152 / #29a742ba…, TD: 20930637977425940388 = #59d6fc3a…
DEBUG 04-10 19:07:16 p2p  sync   41216694…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Peer not suitable for sync: Invalid genesis hash.
DEBUG 04-10 19:07:16 p2p  net    41216694…|Pirl/v1.8.2-v5-masternode-premium-hulk-fd4b5d67/linux-amd64/go1.10 Closing peer session :-(

It looks like after RLPx handshake some peers are added to current peer list, and then I think right after that we get into BlockChainSync::continueSync() which calls syncPeer for each currently connected peer.

As a result we send header requests before we had a chance to send and receive Status messages (See Requesting 1 block headers messages). This is a violation of the protocol.

Peers that haven't sent us Status yet shouldn't be part of the "for each peer" loop in continuesSync somehow.

[gumb0]

It could be that it was like this always, I'm not sure.

Also it doesn't happen for each connected peer, so I don't consider it super-critical.

[gumb0]

I reproduced this also on the commit 21c3492 (Dec 7 2018), so this is not a new issue.