peer disconnect when erigon mining

[flywukong]

System information

Erigon version: erigon version 2022.08.3-alpha-31940528

OS & Version: linux

Commit hash :
836dda9

Expected behaviour

sync stage should run well when run as erigon validator

Actual behaviour

Tested erigon as a validator on bsc private testnet, the tps of the chain is 300 , after the validators has runned 1-2 hours , I find that validator of erigon began to miss some block which should mining by it , and
eventually caused it to be slashed. Deeply look into the logs , I find it may caused by Peer disconnected , the peer exception caused the sync stage exception and affected the mining jobs. as the logs show below, the peer error caused syncing a block took 70s , another strange things is that erigon is keep on mining some block for 2-10 times during this time. I believe something is abnormal of peering . This error happened dozens of times and eventually caused the validator to be slashed.

Backtrace

the logs of erigon show the peer take 70s to recover

[TRACE] [09-09|14:59:31.605] Peer disconnected id="[249 12 139 193 153 80 134 73 129 204 166 54 54 76 253 192 206 104 244 27 82 126 68 16 232 13 163 29 153 100 217 43 85 177 168 176 12 61 200 201 8 160 97 154 133 129 116 47 110 213 155 246 211 79 237 49 97 15 145 11 27 215 118 0]" name=Geth/v1.1.12-f68965a6-20220728/linux-amd64/go1.17.10
[TRACE] [09-09|14:59:31.605] [ù^L<8b>Á<99>P<86>I<81>̦66LýÀÎhô^[R~D^Pè^M£^]<99>dÙ+U±¨°^L=ÈÉ^H a<9a><85><81>t/nÕ<9b>öÓOí1a^O<91>^K^[×v^@] Error while running peer: reading message: EOF

（...ignore some log）

[TRACE] [09-09|15:00:41.609] Failed p2p handshake id=8c8c0185c3236d53233992cd0c885f958ad4db8a073e4962015e226de533eb16 addr=10.90.43.107:30311 conn=staticdial err="already connected"
[TRACE] [09-09|15:00:41.609] Adding p2p peer peercount=2 id=5fdd754e399604f824cd10f35cde6837c586acdcc277aa2b0ccd875aea98234a conn=staticdial addr=10.90.41.73:30311 name=Geth/v1.1.12-f68965a...
[TRACE] [09-09|15:00:41.610] Starting protocol eth/66 id=5fdd754e399604f824cd10f35cde6837c586acdcc277aa2b0ccd875aea98234a conn=staticdial
[TRACE] [09-09|15:00:41.610] [x^Cìp<90>H(^\g^E w<9a>6µ^WXGêMjC»<9a>w<9e>b<<9e>^Q8&¢@<8f>-<8a><ôT´<9e>ä<8f>E^[­2Ã[^Rl¹Ã^<8a>¡ÃS<8b>&<81>&^@] Start with peer
[TRACE] [09-09|15:00:41.610] Link queue size=1
[TRACE] [09-09|15:00:41.610] headerLoop woken up by the incoming request
[DBUG] [09-09|15:00:41.610] Request skeleton anchors=1 top seen height=12367 highestInDb=12368
[TRACE] [09-09|15:00:41.610] Rejected peer id=5fdd754e399604f824cd10f35cde6837c586acdcc277aa2b0ccd875aea98234a addr=10.90.41.73:59576 conn=inbound err="already connected"
[TRACE] [09-09|15:00:41.610] Protocol eth/66 failed id=5fdd754e399604f824cd10f35cde6837c586acdcc277aa2b0ccd875aea98234a conn=staticdial err="handshake to peer x^C�p�H(^\g^E w�6�^WXG�MjC��w�b<�^Q8&�@�-�<�T����E^[�2�[^Rl��^���S�&�&^@: EOF"
[TRACE] [09-09|15:00:41.610] Removing p2p peer peercount=1 id=5fdd754e399604f824cd10f35cde6837c586acdcc277aa2b0ccd875aea98234a duration=909.528µs req=true err="disconnect requested"
[TRACE] [09-09|15:00:41.613] Link queue size=15
[TRACE] [09-09|15:00:41.613] Link queue size=15
[TRACE] [09-09|15:00:41.613] headerLoop woken up by the incoming request
[TRACE] [09-09|15:00:41.613] Empty anchor queue
[INFO] [09-09|15:00:41.615] [1/16 Headers] Processed highest inserted=12384 age=1s HighestHash=0x67ce83d3b4a910e0423a4e56d593298cb8719c8a9627ca5cd8138c4e89e7916a
[INFO] [09-09|15:00:41.615] [1/16 Headers] DONE in=1m10.198002459s

the log of other bsc validator:
2022-09-09T14:59:31+0000 lvl=dbug msg="Message handling failed in eth" id=c2dc66641c2b41b72523d9d0a8efb6f15a9a142ed829eb999ded4a845b71e45a conn=staticdial err="invalid message: message msg #6 (12 bytes): invalid message: (code 6) (size 12) rlp: too few elements for eth.BlockBody, decoding into (eth.BlockBodiesPacket66).BlockBodiesPacket[0]"
t=2022-09-09T14:59:31+0000 lvl=dbug msg="Removing Ethereum peer" peer=c2dc6664 snap=false
t=2022-09-09T14:59:31+0000 lvl=dbug msg="Removing p2p peer" peercount=2 id=c2dc66641c2b41b72523d9d0a8efb6f15a9a142ed829eb999ded4a845b71e45a duration=4m39.997s req=false err="invalid message: message msg #6 (12 bytes): invalid message: (code 6) (size 12) rlp: too few elements for eth.BlockBody, decoding into (eth.BlockBodiesPacket66).BlockBodiesPacket[0]"
t=2022-09-09T14:59:31+0000 lvl=info msg="Looking for peers" peercount=2 tried=0 static=2
t=2022-09-09T14:59:31+0000 lvl=dbug msg="Adding p2p peer" peercount=3 id=c2dc66641c2b41b72523d9d0a8efb6f15a9a142ed829eb999ded4a845b71e45a conn=staticdial addr=10.90.42.57:30311 name=erigon/v2022.08.3-al...
t=2022-09-09T14:59:31+0000 lvl=dbug msg="Ethereum handshake failed" id=c2dc66641c2b41b72523d9d0a8efb6f15a9a142ed829eb999ded4a845b71e45a conn=staticdial err="no status message: first msg has code 3 (!= 0)"
t=2022-09-09T14:59:31+0000 lvl=dbug msg="Removing p2p peer" peercount=2 id=c2dc66641c2b41b72523d9d0a8efb6f15a9a142ed829eb999ded4a845b71e45a duration=1.091ms req=false err="no status message: first msg has code 3 (!= 0)"

[AskAlexSharov]

probably fixed by #5359

[flywukong]

probably fixed by #5359

it is tested on a simple private testnet , so I think it is not related to bsc hardfork

[github-actions]

This issue is stale because it has been open for 40 days with no activity. Remove stale label or comment, or this will be closed in 7 days.

[github-actions]

This issue was closed because it has been stalled for 7 days with no activity.