Parity Full Node Occasionally Skips Blocks

[thodges-gh]

I'm running:

• Which Parity version?: v1.11.8
• Which operating system?: Docker parity/parity:v1.11.8
• How installed?: Docker
• Are you fully synchronized?: yes
• Which network are you connected to?: ropsten
• Did you try to restart the node?: yes

We're currently running a full parity node on Ropsten and seeing some notifications for new blocks being dropped. We're connecting to a Parity node with pubsub via websocket connection and can verify that our node did not receive the skipped blocks.

Parity output (missed block 3797581):

2018-08-08 18:03:27 UTC Imported #3797579 0x981e…fc53 (75 txs, 5.65 Mgas, 725.03 ms, 21.79 KiB)
2018-08-08 18:03:46 UTC   25/25 peers      5 MiB chain   72 MiB db  0 bytes queue   90 KiB sync  RPC:  1 conn,  0 req/s,  76 µs
2018-08-08 18:03:49 UTC Imported #3797580 0x3680…e5c1 (68 txs, 3.57 Mgas, 873.04 ms, 14.52 KiB)
2018-08-08 18:03:50 UTC Imported #3797582 0xb9d8…cf6e (31 txs, 3.22 Mgas, 223.74 ms, 13.02 KiB)
2018-08-08 18:04:11 UTC Imported #3797583 0xc2ee…ba30 (4 txs, 2.18 Mgas, 28.82 ms, 8.65 KiB)
2018-08-08 18:04:21 UTC   25/25 peers      5 MiB chain   72 MiB db  0 bytes queue   90 KiB sync  RPC:  1 conn,  0 req/s,  76 µs

Our application output (verifies that it also didn't see block 3797581 on the Parity node):

{"level":"debug","ts":1533751407.759711,"caller":"services/head_tracker.go:221","msg":"Received header #3797579 (0x39f24b) with hash 0x2a3183b0a8f6c062f8577272a6f0ec4c699c20b5ea7a8b7721df740615ea6512","hash":"0x2a3183b0a8f6c062f8577272a6f0ec4c699c20b5ea7a8b7721df740615ea6512"}
{"level":"debug","ts":1533751429.2156775,"caller":"services/head_tracker.go:221","msg":"Received header #3797580 (0x39f24c) with hash 0x921a45c0763d6be52f4f97c8d98edc2ca3ef5b4e2712a9cf99ccb63da0a9df8d","hash":"0x921a45c0763d6be52f4f97c8d98edc2ca3ef5b4e2712a9cf99ccb63da0a9df8d"}
{"level":"debug","ts":1533751430.88954,"caller":"services/head_tracker.go:221","msg":"Received header #3797582 (0x39f24e) with hash 0xabb65b548e4462108ace90a796639511e13ce86c11802056979988ca3ce8e905","hash":"0xabb65b548e4462108ace90a796639511e13ce86c11802056979988ca3ce8e905"}
{"level":"debug","ts":1533751451.3204648,"caller":"services/head_tracker.go:221","msg":"Received header #3797583 (0x39f24f) with hash 0xf5ae32cc6aa0a96f343070ff8c8212250bf088284c461440aff6c21f82d3d4e5","hash":"0xf5ae32cc6aa0a96f343070ff8c8212250bf088284c461440aff6c21f82d3d4e5"}

Sometimes, when this happens, there's a line like + another 2 block(s) containing 137 tx(s) that "catches up" the missed blocks, but this does not happen every time. Can anything be done when Parity skips blocks and does not account for the skipped blocks?

[Tbaut]

Very interesting.

We're connecting to a Parity node with pubsub via websocket connection and can verify that our node did not receive the skipped blocks.

Can you provide the output of a call such as (for 3797581)

curl --data '{"method":"eth_getBlockByNumber","params":["0x39F24D",false],"id":1,"jsonrpc":"2.0"}' -H "Content-Type: application/json" -X POST localhost:8545

[wkarshat]

How can we quickly check our own logs for the instances of missed blocks, please?

Which logs can this be seen in, and is this a problem with the blocks being generated at all, generated in time, propagated through the network afterwards, accepted by the PoA consensus?

Anyone's quick enough with Python or similar to generate a script for us to run over the relevant logs?

[thodges-gh]

Reproduced locally for blocks 3803810 & 3803812

Parity output:

2018-08-09 13:38:02  Imported #3803808 0x2c47…0283 (2 txs, 0.06 Mgas, 27.95 ms, 0.80 KiB) + another 2 block(s) containing 51 tx(s)
2018-08-09 13:38:03  Imported #3803809 0xaa28…607b (67 txs, 7.10 Mgas, 37.66 ms, 25.30 KiB)
2018-08-09 13:38:07  Imported #3803811 0x2575…ee6d (30 txs, 5.14 Mgas, 20.18 ms, 17.21 KiB)
2018-08-09 13:38:34  Imported #3803813 0xbb02…d9cc (40 txs, 11.90 Mgas, 20.89 ms, 33.13 KiB)

Pubsub log of block headers:

2018-08-09T18:38:02Z [DEBUG] Received header #3803808 (0x3a0aa0) with hash 0xbefc187e4cfbe0be3e7b2b94837bb58cd614d2959376a15b662d374b83cb7b42 services/head_tracker.go:221     
2018-08-09T18:38:02Z [DEBUG] Received header #3803807 (0x3a0a9f) with hash 0x9d9b45c9a4efb7377f7c9c13e8e6c8e8e9764dfe80b6644b92c21c5df29d89bc services/head_tracker.go:221     
2018-08-09T18:38:03Z [DEBUG] Received header #3803809 (0x3a0aa1) with hash 0x55102a540312cbea07c84e0c30a8a41bea44edc43e03b37a273ff1f60aa099be services/head_tracker.go:221     
2018-08-09T18:38:07Z [DEBUG] Received header #3803811 (0x3a0aa3) with hash 0x7b616a5a013885a01085a411c65aee0bb3f9e95664d42bb1be978c2d2f5c1fb6 services/head_tracker.go:221     
2018-08-09T18:38:34Z [DEBUG] Received header #3803813 (0x3a0aa5) with hash 0x6f1e2131f804680ad3353d680c628b7dd4c77a89862cf4d4e7b275a2d7f321ea services/head_tracker.go:221

Get block 3803810:

curl --data '{"method":"eth_getBlockByNumber","params":["0x3a0aa2",false],"id":1,"jsonrpc":"2.0"}' -H "Content-Type: application/json" -X POST localhost:8545

Result:

{"jsonrpc":"2.0","result":{"author":"0x2b126e450158f14add6770739a2e6b4037526817","difficulty":"0x51e64b8a","extraData":"0xd88301080d846765746888676f312e31302e33856c696e7578","gasLimit":"0xb6c46c","gasUsed":"0x0","hash":"0x45919b126dbaeeff6f7669c9e54aa8226d2a8976abcbc73ec8571a245abad711","logsBloom":"0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000","miner":"0x2b126e450158f14add6770739a2e6b4037526817","mixHash":"0xc3967a9a3942eefcb71f23d05f08b75d87dafe9c6016a580ffb54d324f32cba1","nonce":"0x634a4e365627d130","number":"0x3a0aa2","parentHash":"0xaa28d10954d0a74376a79350531a2c57d6c67eac73a99ff215f11880e4d8607b","receiptsRoot":"0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421","sealFields":["0xa0c3967a9a3942eefcb71f23d05f08b75d87dafe9c6016a580ffb54d324f32cba1","0x88634a4e365627d130"],"sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","size":"0x21c","stateRoot":"0xe914dbed1e263436c37580bfb2e8168f46a6b97f627175f4e3e8c02d0985e006","timestamp":"0x5b6c8a0c","totalDifficulty":"0x20a868680d2d4f","transactions":[],"transactionsRoot":"0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421","uncles":[]},"id":1}

Get block 3803812:

curl --data '{"method":"eth_getBlockByNumber","params":["0x3a0aa4",false],"id":1,"jsonrpc":"2.0"}' -H "Content-Type: application/json" -X POST localhost:8545

Result:

{"jsonrpc":"2.0","result":{"author":"0x5699b1a504f139100b889c7280074c028eb318bb","difficulty":"0x51fac6e4","extraData":"0xd683010803846765746886676f312e3130856c696e7578","gasLimit":"0xb6c460","gasUsed":"0x1ad1fb","hash":"0x63e48887f23a3e988dbcefc23200d80bbd7fdde22cd17133191f37ff456cce72","logsBloom":"0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000","miner":"0x5699b1a504f139100b889c7280074c028eb318bb","mixHash":"0x1251b5338e7be354e9579be9b3d284df28afb4ccb8feaea0a3ba0dd354b15022","nonce":"0xb55d349a2399a25e","number":"0x3a0aa4","parentHash":"0x25751ab2c91cda5e9c7368ad00d21817d6cf3aab8469fdbf9df39491f23eee6d","receiptsRoot":"0x81143a6f642f22d187dbd20abccb98675bebaf558fbef080b44fdf2b531f2946","sealFields":["0xa01251b5338e7be354e9579be9b3d284df28afb4ccb8feaea0a3ba0dd354b15022","0x88b55d349a2399a25e"],"sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","size":"0x1c50","stateRoot":"0xb11a3f8637ad6d9c410f69e548b80c5dc9658d4b89f955e13fc1046b9a07c2db","timestamp":"0x5b6c8a0f","totalDifficulty":"0x20a8690bf87cc6","transactions":["0x59df306398b9f968fa48e37c9f40511b05d54443be74077df0047feb1a5f4b8f","0xee6413c58f29380d2d5ebaceedce2c8f9705421d25691bb2db1ab5bfcf386c2d","0xf99ea14ba799540d2dbf599b2342d893ad3961f588095b403564a962cc65de4f","0xc1a63356e94c099abd76aa0853bbf3ec5b31c5d74d0ca97de35e02062e883673","0x7915bda5697d01c18a85c2e7358ec3c88868fbac8885e105d49c1a8688db4385","0xe4cb154999eb02f78b82602a164c27866c88e70bb3cb53e45516b507f067a41a","0xe68f844a40277af9030b3af3da317969867e4fa4f56f28b9e1d5877a0c5ada24"],"transactionsRoot":"0x43bdccdf3647f519296972019fc0603f7ca7089751cdb33cfd8b7b78423746ea","uncles":[]},"id":1}

So, it looks like that at some point the Parity client is getting the block, but clients that subscribe to new block headers never see it. Additionally, the output of Parity never indicates when it received blocks 3803810 & 3803812.

[tzapu]

depending on peer count and rpc load am also experiencing this but always thought it was as good as it could get, never thought of opening an issue to see if it can be made better :P.
when peer count is really low, i have seen it skip 10s of blocks. this is most evident with reorgs, as in the example above (3803808, 3803807, 3803809) but those are usually seen in parity's log as well, maybe omitted here.
seeing this on mainnet btw

[wkarshat]

How are reorgs reflected in the parity.log, or is this something one can turn on?

Did the maximum number of peers increase from 25 to 100 in a recent release?