Parity-ethereum: Node is failing to sync with error "Error: Error(Engine(RequiresClient)"

[ArseniiPetrovich]

• Parity Ethereum version: tried 2.2.5 and 2.2.1
• Operating system: Ubuntu 16/18
• Installation: downloaded binary
• Fully synchronized: no and yes
• Network: POA xDAI
• Restarted: both
  Error log:

2018-12-19 13:31:46  Stage 3 block verification failed for #1210413 (0xc2a1…9c29)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2018-12-19 13:31:46  
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
RLP: f90249f90244a015bf167c5b4c07587408ce07860c6a8a6f4ea098c2457f86042575e4073db456a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347946dc0c0be4c8b2dfe750156dc7d59faabfb5b923da0518feb50424fef5033af4fd2d11281e7919218c2538d45db7433191e3c0347d0a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffd8312782d8398968080845c1a1e0c9fde830202018f5061726974792d457468657265756d86312e33302e31826c6984126b9f9cb8416432efb986cffdd90973796712f64819aa5daa07ecd21a40284c6a82f1dd7fe64e031a733e95c40e6dae2f9d52c0b56c4f380b189ce17409fe79066d0cf4109b00c0c0
Header: Header { parent_hash: 0x15bf167c5b4c07587408ce07860c6a8a6f4ea098c2457f86042575e4073db456, timestamp: 1545215500, number: 1210413, author: 0x6dc0c0be4c8b2dfe750156dc7d59faabfb5b923d, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 2, 1, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 48, 46, 49, 130, 108, 105], state_root: 0x518feb50424fef5033af4fd2d11281e7919218c2538d45db7433191e3c0347d0, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 10000000, difficulty: 340282366920938463463374607431768211453, seal: [[132, 18, 107, 159, 156], [184, 65, 100, 50, 239, 185, 134, 207, 253, 217, 9, 115, 121, 103, 18, 246, 72, 25, 170, 93, 170, 7, 236, 210, 26, 64, 40, 76, 106, 130, 241, 221, 127, 230, 78, 3, 26, 115, 62, 149, 196, 14, 109, 174, 47, 157, 82, 192, 181, 108, 79, 56, 11, 24, 156, 225, 116, 9, 254, 121, 6, 109, 12, 244, 16, 155, 0]], hash: Some(0xc2a1a685d2cedd5f3c69826bfb7a8210213dd58e177dd438512baaa717cb9c29) }
Uncles: 
Transactions:

We have launched a number of validator nodes at xDAI network (statistics at https://dai-netstat.poa.network) at AWS that works pretty fine. After that we have tried to launch one of the nodes via the same way, but at the local infrastructure (Protofire Validator). Node is hided behind the NAT, and 30303 port were made public. It worked fine for some time and then errors started to occur (see logs above). We've launched a full resync, and it helped, but for a short period of time only.
We've decided, that the roots of that issue might lie in a fact that Ubuntu 18 were used. So we launched an Ubuntu 16, but it didn't help.
Can you help us solving the issue?

[joshua-mir]

Is this related to https://github.com/paritytech/parity-ethereum/issues/9114 @sorpaas?

@ArseniiPetrovich this might be related to the fixes to emptyStep behaviour in 2.2.5 - but I'm not certain xDai uses emptySteps. Are you sure you're seeing this error in 2.2.1 and have you tried making the changes outlined in the changelog https://github.com/paritytech/parity-ethereum/releases/tag/v2.2.5 ?

I don't think this is related in any way to your OS.

[ArseniiPetrovich]

xDai does not uses emptySteps, so it look like that problems aren't related.

[jcortejoso]

Hi! I think I am seeing the same behavior in one node of our PoA. We are running v2.3.0-nightly (commit bf9fedc4ee2eaa4dcbc6fcb9ef73bdf6967ee071), secret store is enabled in this node. I find it strange because this node keep importing the new blocks. The other nodes (same configuration) works well. These are the logs:

Jan 14 08:27:01 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:01 UTC Public node URL: enode://204b11794d16f382bab24a7cdde5ec1273b8c6c2b23e64560d7ef1707708158a45300e920607aa413633e45c5eea472c17f474866ce5901515249abfbe9c4e1c@172.17.0.2:30303 Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:24 UTC Stage 3 block verification failed for #20576 (0x28ce…3a4b) Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:24 UTC Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: RLP: f90248f90243a0c0b6d8709608a422297d286640d11af4fabd9865b850a18198f41d9ec0d5764ea01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794a1345ed0b2d1e193aead673e33dac56515af128aa06517af1a718ec3f7e459f809438c1b96c9a394d85746b2cffd9538cfec336d2ea056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090ffffffffffffffffffffffffffffffef8250608365b9aa80845c3c44f59fde830203008f5061726974792d457468657265756d86312e33312e31826c698412727431b8413aa81df658fd004c8b0589947dc2c7debeaf950ef11690156b6324272cd2bc8671a9f867df91b9cfc3acf5e95a05056f87d72463598a71f0740866cc5f909d2000c0c0 Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Header: Header { parent_hash: 0xc0b6d8709608a422297d286640d11af4fabd9865b850a18198f41d9ec0d5764e, timestamp: 1547453685, number: 20576, author: 0xa1345ed0b2d1e193aead673e33dac56515af128a, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 3, 0, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x6517af1a718ec3f7e459f809438c1b96c9a394d85746b2cffd9538cfec336d2e, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 6666666, difficulty: 340282366920938463463374607431768211439, seal: [[132, 18, 114, 116, 49], [184, 65, 58, 168, 29, 246, 88, 253, 0, 76, 139, 5, 137, 148, 125, 194, 199, 222, 190, 175, 149, 14, 241, 22, 144, 21, 107, 99, 36, 39, 44, 210, 188, 134, 113, 169, 248, 103, 223, 145, 185, 207, 195, 172, 245, 233, 90, 5, 5, 111, 135, 215, 36, 99, 89, 138, 113, 240, 116, 8, 102, 204, 95, 144, 157, 32, 0]], hash: Some(0x28ce97bb48c7decc725eae5e994a1ab48cc56e03bff469b6e73e0552c75d3a4b) } Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Uncles: Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Transactions: Jan 14 08:27:26 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:26 UTC 0/25 peers 78 KiB chain 4 MiB db 0 bytes queue 1 MiB sync RPC: 0 conn, 0 req/s, 0 µs Jan 14 08:27:56 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:56 UTC 0/25 peers 78 KiB chain 4 MiB db 0 bytes queue 1 MiB sync RPC: 0 conn, 0 req/s, 0 µs Jan 14 08:28:26 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:28:26 UTC 0/25 peers 78 KiB chain 4 MiB db 0 bytes queue 1 MiB sync RPC: 0 conn, 0 req/s, 0 µs Jan 14 08:28:56 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:28:56 UTC 0/25 peers 78 KiB chain 4 MiB db 0 bytes queue 1 MiB sync RPC: 0 conn, 0 req/s, 0 µs Jan 14 08:29:05 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:29:05 UTC Imported #19973 0x07d5…5578 (0 txs, 0.00 Mgas, 50 ms, 0.57 KiB)

[joshua-mir]

Hey @ArseniiPetrovich, just pinging to check whether you are still seeing anything similar on recent releases or if this issue can be closed.

I should have asked about the status of the validators on the xDai network and whether you could verify that they were all online / the blocks you see in your logs matched the blocks on blockscout, but it is probably a little late for checking that now 😅

[varasev]

I caught the same error on one of our nine local nodes when test running. That error desynchronized ~the nodes~ the first node and the error seemed to appear after finalizeChange had been called but I’m not sure that was a reason (maybe coincidence). I’m attaching the logs for all 9 nodes. Please pay attention to the different blocks hashes after the error on ~all~ the first and the rest nodes and benign reports. See the logs for the first node (which was a validator along with nodes 2-6) from the First incident.zip attached.

I tried to launch our test setup once more from scratch and caught the same error Stage 3 block verification failed for #86 but at another block and only on the node #8 this time (which was not a validator). See the Second incident.zip (and node8 log file inside).

First incident.zip
Second incident.zip

[phahulin]

Hi, is there any insight on the probable cause of this? We are still seeing it on 2.3.2.

[ArseniiPetrovich]

Hi, @joshua-mir. I can confirm the issue still exists and affects validators from time to time.

[gitcoinbot]

Issue Status: 1. Open 2. Started 3. Submitted 4. Done

---

__This issue now has a funding of 500.0 DAI (500.0 USD @ $1.0/DAI) attached to it as part of the poanetwork fund.__

• If you would like to work on this issue you can 'start work' on the Gitcoin Issue Details page.
  
  
  
  • Want to chip in? Add your own contribution here.
  
  
  • Questions? Checkout Gitcoin Help or the Gitcoin Slack
  
  
  • $42,793.04 more funded OSS Work available on the Gitcoin Issue Explorer
  
  

[HCastano]

I'm not looking to take the bounty, but I can take a look at this next week.

[SurfingNerd]

i was able to reproduce the issue very frequently, running an trustnode for ARTIS tau1 testnet at home.
parity 2.2.10 with authority round engine
https://github.com/lab10-coop/tau1

When i ran the node in a serverhouse, everything was fine.
So i upgraded my 5 year old stock router at home with a new one.
That solved the problem, so i can't reproduce it anymore.

So either try to get a really bad router, or maybe the instable network can be simulated ?!

[gitcoinbot]

Issue Status: 1. Open 2. Cancelled

---

__Work has been started__.

These users each claimed they can complete the work by 9 months, 3 weeks from now.
Please review their action plans below:

1) faabsorg has started work.

Let's take a look at it.
I'll need ssh access to one of the nodes that are having the issue.
[email protected]

Learn more on the Gitcoin Issue Details page.

[HCastano]

@varasev Hey, can you share the chain spec and node config files you were using while you collected the First/Second Incident logs?

Also, in the future if you could run your node with --logging engine=debug,finality=debug it would be super helpful in debugging what's going on.

[varasev]

@HCastano For that launching, I used our posdao-test-setup repo and our a bit modified build of Parity.

To start the setup, the next commands should be performed:

$ git clone https://github.com/poanetwork/posdao-test-setup
$ cd posdao-test-setup
$ npm i
$ npm run get-all-submodules
$ npm run cleanup
$ npm run compile-posdao-contracts
$ npm run make-spec
$ npm run start-test-setup

Then you can watch the logs for all the nine local nodes in the parity-data directory during the first 100 blocks. If you don't see the error during the first launch, try to start again:

$ npm run stop-test-setup
$ npm run cleanup
$ npm run start-test-setup

The error doesn't appear every time, so it's not easy to catch it, but I think it would be enough to wait for the first 100 blocks for each test launching.

[HCastano]

@varasev Hey, I set up your fork of Parity Ethereum as well as the posdao-test-setup repo and did mange to see the Stage 3 block verification error (albeit not that often). From the logs I got it seems that there are multiple blocks being produced at the same height by the same validator. If you take a look at this Gist you can see that starting at block 101 there are multiple blocks being built at the same height. This eventually leads to an error in node6 while trying to make block 104.

Looking further, I noticed that in the node.toml files there seem to be multiple nodes with the same engine_signer. I think that this is the reason that there were multiple blocks being made at the same height. This could also explain the Stage 3 block verification error. This error happens when the current candidate block's parent block isn't in the database. So if the current validators decided to build on the wrong chain their parent wouldn't be in the database and thus this error would occur.

I've tried running four nodes using the latest master of Parity Ethereum to try and replicate this problem there. I've set up two of the nodes to have the same engine_signer. Unfortunately I haven't been able to see the issue again. I've tried using a static validator set, and using the OwnedSet.sol contract as well.

Even though I wasn't able to confirm this was the root cause, going forward I don't think you should be reusing your signer key on multiple nodes. Try running your setup without this and let me know if you see the issue again. Alternatively, try running with with the same engine_signer on multiple nodes using the "canonical" Parity Ethereum client and see if you're able to replicate the bug.

[varasev]

Yes, we have a wrong set of nodes in that test repo, so those three validators launch two nodes each with the same engine_signer. Will fix that. But as far as I know, the error also occurs in xDai network which doesn't have such duplicated nodes. @ArseniiPetrovich @phahulin am I right?

[phahulin]

Right, seen it just today on xDai chain, where we (POA Network) run a single node for our validator. Here's log

2019-03-21 06:53:15 UTC Stage 3 block verification failed for #2762467 (0x1cb6…b473)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-03-21 06:53:15 UTC 
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace:
 None } })
RLP: f90249f90244a006a14efb409ea712ff9aa1a376beb26f1ba1c6bb1a49188f604800e61762ef69a01dcc4de8dec75d7aab85b567b6ccd41a
d312451b948a7413f0a142fd40d49347949e41ba620feba8198369c26351063b26ec5b7c9ea0691d46159abb7f64319bbdd54f1209bc8166cceed
5a167eb68ae7641881aa461a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692
c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffff
ffffd832a26e38398968080845c9334d69fde830203028f5061726974792d457468657265756d86312e33312e31826c69841283d75eb841db05a9
85134a9a0f986ba526de76cd31f6bc7df9dcb14dc27fadbc741194afb0591253e5b3cf24e55345c4a804a98c3ff2d59cce4363b57b39782b4fe90
a422900c0c0
Header: Header { parent_hash: 0x06a14efb409ea712ff9aa1a376beb26f1ba1c6bb1a49188f604800e61762ef69, timestamp: 15531511
90, number: 2762467, author: 0x9e41ba620feba8198369c26351063b26ec5b7c9e, transactions_root: 0x56e81f171bcc55a6ff8345e
692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d
49347, extra_data: [222, 131, 2, 3, 2, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 13
4, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x691d46159abb7f64319bbdd54f1209bc8166cceed5a167eb68ae7641881a
a461, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 10000000, difficulty: 340282366920938463463374607431768211453, seal: [[132, 18, 131, 215, 94], [184, 65, 219, 5, 169, 133, 19, 74, 154, 15, 152, 107, 165, 38, 222, 118, 205, 49, 246, 188, 125, 249, 220, 177, 77, 194, 127, 173, 188, 116, 17, 148, 175, 176, 89, 18, 83, 229, 179, 207, 36, 229, 83, 69, 196, 168, 4, 169, 140, 63, 242, 213, 156, 206, 67, 99, 181, 123, 57, 120, 43, 79, 233, 10, 66, 41, 0]], hash: Some(0x1cb6604ae6c76ffd888fc8412a994f2a34a6776d34a44f7a2458516d0028b473) }
Uncles: 
Transactions:

After this error the validator stops accepting blocks from the rest of the network and keeps producing new blocks in his own "fork".

[igorbarinov]

Saw it again on xDai Chain today again😬

[HCastano]

I was looking at this again today and I have a few follow up questions.

1. Are you warp syncing the nodes? If so, how often after warp syncing do you see these errors?
2. How often do you change validators? Do these errors happen soon after changing validators?
3. Can you run your nodes with -lengine=trace,client=trace,blockchain=trace and include the full logs in your next update?

@varasev @phahulin @ArseniiPetrovich @igorbarinov

[VladLupashevskyi]

The same just happened to our PoA chain after validator VM rebooting.

Here is the output with logs @HCastano mentioned:

2019-04-02 21:42:32  Verifier #3 INFO import  Imported #2155448 0x51e9…01a0 (1 txs, 0.03 Mgas, 2 ms, 0.73 KiB) + another 2 block(s) containing 1 tx(s)
2019-04-02 21:42:33  jsonrpc-eventloop-0 WARN rpc  eth_accounts is deprecated and will be removed in future versions: Account management is being phased out see #9997 for alternatives.
2019-04-02 21:42:34  IO Worker #1 INFO import  Syncing #2155448 0x51e9…01a0     1.00 blk/s    0.6 tx/s    0.0 Mgas/s      0+    0 Qed  #2155055    4/25 peers   1 MiB chain 51 KiB db 0 bytes queue 502 KiB sync  RPC:  0 conn,    0 req/s,  192 µs
2019-04-02 21:42:35  Verifier #7 DEBUG engine  Zooming to epoch for block 0xd08c…b4d5
2019-04-02 21:42:35  Verifier #7 TRACE blockchain  Loading epoch transition at block 2157167, 0x4e1a…582d
2019-04-02 21:42:35  Verifier #7 DEBUG engine  No genesis transition found.
2019-04-02 21:42:35  Verifier #7 DEBUG engine  Unable to zoom to epoch.
2019-04-02 21:42:35  Verifier #7 WARN client  Stage 3 block verification failed for #2157168 (0xd08c…b4d5)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-04-02 21:42:35  Verifier #7 ERROR client
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
RLP: f90234f9022fa04e1aff48fa851a268f406b8a810b6505584114543b4e5c51a866c4083870582da01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d493479486217959f8f0bd724b309d5ddd844fd1de93aeefa09b45b0d8ef25f5447b809eeba40772e9877304037e5e3be50e3483c776e37768a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffd8320ea708405f5e10080845ca3a6f889747275737477697365841728e9beb8412c736b14e448acb5d84f4617edb87a0075f7090996b4bd1b8e0c9bc616f18da65e95105e4432d21e798bbf4423ab233e00f4082da9fbf8c9d47184de47ce3bd301c0c0
Header: Header { parent_hash: 0x4e1aff48fa851a268f406b8a810b6505584114543b4e5c51a866c4083870582d, timestamp: 1554228984, number: 2157168, author: 0x86217959f8f0bd724b309d5ddd844fd1de93aeef, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [116, 114, 117, 115, 116, 119, 105, 115, 101], state_root: 0x9b45b0d8ef25f5447b809eeba40772e9877304037e5e3be50e3483c776e37768, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 100000000, difficulty: 340282366920938463463374607431768211453, seal: [[132, 23, 40, 233, 190], [184, 65, 44, 115, 107, 20, 228, 72, 172, 181, 216, 79, 70, 23, 237, 184, 122, 0, 117, 247, 9, 9, 150, 180, 189, 27, 142, 12, 155, 198, 22, 241, 141, 166, 94, 149, 16, 94, 68, 50, 210, 30, 121, 139, 191, 68, 35, 171, 35, 62, 0, 244, 8, 45, 169, 251, 248, 201, 212, 113, 132, 222, 71, 206, 59, 211, 1]], hash: Some(0xd08c7a6ccb45d3f8499e50b1cbc4e45e13d043227a7a72a7b1f2f39ef173b4d5) }
Uncles:
Transactions:

2019-04-02 21:43:04  IO Worker #1 INFO import  Syncing #2155448 0x51e9…01a0     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #2157166    4/25 peers   6 MiB chain 51 KiB db 0 bytes queue 694 KiB sync  RPC:  0 conn,    0 req/s,   46 µs
2019-04-02 21:43:14  IO Worker #1 INFO import  Syncing #2155448 0x51e9…01a0     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #2157166    5/25 peers   6 MiB chain 51 KiB db 0 bytes queue 694 KiB sync  RPC:  0 conn,    1 req/s,   46 µs
2019-04-02 21:43:24  IO Worker #1 INFO import  Syncing #2155448 0x51e9…01a0     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #2157166    2/25 peers   6 MiB chain 51 KiB db 0 bytes queue 694 KiB sync  RPC:  0 conn,    1 req/s,   46 µs
2019-04-02 21:43:34  IO Worker #2 INFO import  Syncing #2155448 0x51e9…01a0     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #2157166    2/25 peers   6 MiB chain 51 KiB db 0 bytes queue 694 KiB sync  RPC:  0 conn,    1 req/s,   45 µs

[phahulin]

@HCastano

1. Are you warp syncing the nodes? If so, how often after warp syncing do you see these errors?

Yes, we use warp sync (by default). There doesn't seem to be any pattern. It looks more like multiple nodes are affected in succession (with short intervals between errors, maybe 3-4 errors in 2 weeks), and then error disappears for some time.
To fix the error we drop the database and resync from scratch.

1. How often do you change validators? Do these errors happen soon after changing validators?

We didn't change validators for a few months, but still got this error.

1. Can you run your nodes with -lengine=trace,client=trace,blockchain=trace and include the full logs in your next update?

Okay we'll do that and let you know as soon as we catch it again.

[HCastano]

Hey guys, I put in a preliminary patch here: #10566. Not entirely sure if it's going to fix the issue, but it'll at least give us some better logs to work with. Would you guys mind running this on your node, as well as adding -lfinality=trace to the logging settings?

@varasev @phahulin @ArseniiPetrovich @igorbarinov

[phahulin]

Hey @HCastano we've compiled patched parity version and have it running on the xDai network. Will post the logs when the error happens again.

[aahutsal]

@igorbarinov is that bounty still actual?

[igorbarinov]

@igorbarinov is that bounty still actual?

Yes it is

[phahulin]

@HCastano we caught the error today, attaching the log (please note I removed ip address)
We and @ArseniiPetrovich also noticed that error might happen when there is a network change. Today we were upgrading to a larger instance and the external ip changed. After starting up, we caught this error.
issue.log.gz

[HCastano]

@phahulin Thanks for following up. I don't have time to take a look at this this week but I'll try and spend some time on it next week.

[aahutsal]

@igorbarinov
so do you guys have the strict way to reproduce the issue or all you have are just guesses? Asking as I could probably participate if I can reproduce the issue.

[VladLupashevskyi]

Today I've got again problem with RequiresClient. The node was not configured as validator.
After flushing database and resyncing it failed with this error again, but on the block in the past when I faced this issue as well. So I was trying to reproduce it. And I think I succeeded - So I took a copy of the database where the best block was -10k blocks away from the block where the issue took place. I was stoping and staring parity every 2 seconds, so in this way, I assume, the verified queue gets reset and I can face the issue (in the normal flow without restarting I think the queue gets big enough and somehow we skip this problem).

I have some logs which I took with 2 versions: 1st - patched #10566, but without match self.block_hash(details.number) part, and 2nd - the complete patch #10566:

Logs taken with 1st version (without match part):

2019-04-25 00:06:12  Verifier #2 DEBUG engine  Zooming to epoch for block 0xdffd…eaa0
2019-04-25 00:06:12  Verifier #2 TRACE blockchain  Got hash 0xc1d0…a3ce from ancestry_iter
2019-04-25 00:06:12  Verifier #2 TRACE blockchain  Got block details for block #1410192
2019-04-25 00:06:12  Verifier #2 TRACE blockchain  Loading epoch transition at block 1410192, 0xc1d0…a3ce
2019-04-25 00:06:12  Verifier #2 DEBUG engine  No genesis transition found.
2019-04-25 00:06:12  Verifier #2 DEBUG engine  Unable to zoom to epoch.
2019-04-25 00:06:12  Verifier #2 WARN client  Stage 3 block verification failed for #1410193 (0xdffd…eaa0)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-04-25 00:06:12  Verifier #2 ERROR client
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
RLP: f9022ef90229a0c1d0a5f27d20c6255bf42c17c566d0acdee1982cec921643e5a166bbccdea3cea01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347945c93c27365f0ee8d06dd947a1294982eff3896d1a0e0342c0abf116b43eb43b8aace28150096225047ca34d558c751b213d09be485a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffe831584918405f5e10080845c76030c833f3f3f84171d80c3b8412aebd7fd80fdc0ffb1a769d3c8a84cf93b18e6612cbb2167b4abe6f32748ed861227152083c3c09ea29bb64033795bc43ffb05acff01d7f81c46f74324e9a33900c0c0
Header: Header { parent_hash: 0xc1d0a5f27d20c6255bf42c17c566d0acdee1982cec921643e5a166bbccdea3ce, timestamp: 1551237900, number: 1410193, author: 0x5c93c27365f0ee8d06dd947a1294982eff3896d1, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [63, 63, 63], state_root: 0xe0342c0abf116b43eb43b8aace28150096225047ca34d558c751b213d09be485, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 100000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 23, 29, 128, 195], [184, 65, 42, 235, 215, 253, 128, 253, 192, 255, 177, 167, 105, 211, 200, 168, 76, 249, 59, 24, 230, 97, 44, 187, 33, 103, 180, 171, 230, 243, 39, 72, 237, 134, 18, 39, 21, 32, 131, 195, 192, 158, 162, 155, 182, 64, 51, 121, 91, 196, 63, 251, 5, 172, 255, 1, 215, 248, 28, 70, 247, 67, 36, 233, 163, 57, 0]], hash: Some(0xdffddc74feab8aa6cb4a16b6cf909ccaede43dc827bb26c1e2fb273f8017eaa0) }
Uncles:
Transactions:

Then I started 2nd version and got these logs:

2019-04-25 00:14:41  Verifier #1 DEBUG engine  Zooming to epoch for block 0xdffd…eaa0
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0xc1d0…a3ce from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410192
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410192, 0xc1d0…a3ce
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0xc942…469f from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410191
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410191, 0xc942…469f
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0x28d1…c11e from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410190
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410190, 0x28d1…c11e
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0xc14e…020d from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410189
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410189, 0xc14e…020d
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0x1d58…957f from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410188
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410188, 0x1d58…957f
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0x01e5…d87a from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410187
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410187, 0x01e5…d87a
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0xea86…31c2 from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410186
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410186, 0xea86…31c2
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got hash 0x9546…4ff1 from ancestry_iter
2019-04-25 00:14:41  Verifier #1 TRACE blockchain  Got block details for block #1410185
….
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Found non-canonical block hash 0x2909…035c
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0xea13…40fa from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1406349
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406349, 0xea13…40fa
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Found non-canonical block hash 0xef57…67a0
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0xac35…0f5a from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1406348
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:14:42  Verifier #1 TRACE engine  extracting epoch set for epoch (1361021, 0xf342…db7d) signalled at #1361020
2019-04-25 00:14:42  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:42  Verifier #1 DEBUG engine  Expected topics for header 0x6f89…edb5: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x04c1c9c3b2da544a60e86a8f2c5461215903462e37cc11048e5255ae31fe975b]
2019-04-25 00:14:42  Verifier #1 DEBUG engine  Zooming to epoch for block 0xdffd…eaa0
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0xc1d0…a3ce from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1410192
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410192, 0xc1d0…a3ce
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0xc942…469f from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1410191
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410191, 0xc942…469f
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0x28d1…c11e from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1410190
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410190, 0x28d1…c11e
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0xc14e…020d from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1410189
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410189, 0xc14e…020d
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got hash 0x1d58…957f from ancestry_iter
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Got block details for block #1410188
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410188, 0x1d58…957f
2019-04-25 00:14:42  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
…
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Found non-canonical block hash 0xef57…67a0
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got hash 0xac35…0f5a from ancestry_iter
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got block details for block #1406348
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410192, 0xc1d0…a3ce
2019-04-25 00:14:44  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:44  Verifier #1 DEBUG engine  Expected topics for header 0xdffd…eaa0: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0xc1d0a5f27d20c6255bf42c17c566d0acdee1982cec921643e5a166bbccdea3ce]
2019-04-25 00:14:44  Verifier #1 DEBUG engine  Zooming to epoch for block 0xdffd…eaa0
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got hash 0xc1d0…a3ce from ancestry_iter
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got block details for block #1410192
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410192, 0xc1d0…a3ce
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got hash 0xc942…469f from ancestry_iter
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got block details for block #1410191
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410191, 0xc942…469f
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got hash 0x28d1…c11e from ancestry_iter
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Got block details for block #1410190
2019-04-25 00:14:44  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410190, 0x28d1…c11e
….
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Found non-canonical block hash 0x2909…035c
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got hash 0xea13…40fa from ancestry_iter
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got block details for block #1406349
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406349, 0xea13…40fa
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Found non-canonical block hash 0xef57…67a0
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got hash 0xac35…0f5a from ancestry_iter
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got block details for block #1406348
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410193, 0xdffd…eaa0
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 DEBUG engine  Expected topics for header 0x060e…df82: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0xdffddc74feab8aa6cb4a16b6cf909ccaede43dc827bb26c1e2fb273f8017eaa0]
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410194, 0x060e…df82
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 DEBUG engine  Expected topics for header 0xe590…900d: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x060e7af5394114d4e3df0b1714fb263f83ab44ba3bf2b9bc992e1f969159df82]
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 TRACE blockchain  Loading epoch transition at block 1410195, 0xe590…900d
2019-04-25 00:14:48  Verifier #1 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:48  Verifier #1 DEBUG engine  Expected topics for header 0xefbe…8ca1: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0xe590336b4bde32b223a9e1c9708a7d3ad174a4cf1fa96c5928da220b166d900d]
…..
2019-04-25 00:14:54  IO Worker #3 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:54  IO Worker #3 TRACE blockchain  Loading epoch transition at block 1411132, 0x28bf…dafa
2019-04-25 00:14:54  IO Worker #3 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:54  IO Worker #3 DEBUG engine  Expected topics for header 0x2883…33e3: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x28bf9b78ec139adc2496875a44684519e347f56d3a12439f4e378f1cb3f1dafa]
2019-04-25 00:14:54  IO Worker #3 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:54  IO Worker #3 TRACE blockchain  Loading epoch transition at block 1411133, 0x2883…33e3
2019-04-25 00:14:54  IO Worker #3 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:14:54  IO Worker #3 DEBUG engine  Expected topics for header 0xd35e…be46: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x28835e11da358c7fcc42f2f5d41ce599b6f8219d12a460784be95b24e45b33e3]
2019-04-25 00:14:54  IO Worker #3 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:15:54  main WARN parity_ethereum::run  Shutdown is taking longer than expected.

Here we can see that zooming happens 3 times and on the 3rd time the output changes after processing block which fails with RequiresClient (1406347).

Then if I start the 1st version, I'm getting this:

2019-04-25 00:23:40  Verifier #1 DEBUG engine  Zooming to epoch for block 0x49bf…6acf
2019-04-25 00:23:40  Verifier #1 TRACE blockchain  Got hash 0xd35e…be46 from ancestry_iter
2019-04-25 00:23:40  Verifier #1 TRACE blockchain  Got block details for block #1411134
2019-04-25 00:23:40  Verifier #1 TRACE blockchain  Loading epoch transition at block 1411134, 0xd35e…be46
2019-04-25 00:23:40  Verifier #1 DEBUG engine  No genesis transition found.
2019-04-25 00:23:40  Verifier #1 DEBUG engine  Unable to zoom to epoch.
2019-04-25 00:23:40  Verifier #1 WARN client  Stage 3 block verification failed for #1411135 (0x49bf…6acf)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-04-25 00:23:40  Verifier #1 ERROR client
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
RLP: f9023bf90236a0d35ebf7e366f4125f2edb1faf18d9d95e2b6db402c63489eb692d30c80a1be46a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794776752b30017afc25494e79048424cfa8fb066d0a02605ce6314ed68b5995d47977c95505217db9ec20002e3d8465c7842c6d4e01ea056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffe8315883f8405f5e10080845c7611c4906469676974616c2d636f6e636570747384171d8471b841f36cbbcb4a4ab4da8c5c23db283b2a25cc558dc5477cbf21186574a14d924fdf3bcad594b10181ccbcf6c921148d3dc8f0c906dcb41610f79961843aa5817aee01c0c0
Header: Header { parent_hash: 0xd35ebf7e366f4125f2edb1faf18d9d95e2b6db402c63489eb692d30c80a1be46, timestamp: 1551241668, number: 1411135, author: 0x776752b30017afc25494e79048424cfa8fb066d0, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [100, 105, 103, 105, 116, 97, 108, 45, 99, 111, 110, 99, 101, 112, 116, 115], state_root: 0x2605ce6314ed68b5995d47977c95505217db9ec20002e3d8465c7842c6d4e01e, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 100000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 23, 29, 132, 113], [184, 65, 243, 108, 187, 203, 74, 74, 180, 218, 140, 92, 35, 219, 40, 59, 42, 37, 204, 85, 141, 197, 71, 124, 191, 33, 24, 101, 116, 161, 77, 146, 79, 223, 59, 202, 213, 148, 177, 1, 129, 204, 188, 246, 201, 33, 20, 141, 61, 200, 240, 201, 6, 220, 180, 22, 16, 247, 153, 97, 132, 58, 165, 129, 122, 238, 1]], hash: Some(0x49bf89d4f4db9be0943c6dff6bd5eb5bf226385a27dd59f6c35cda73060c6acf) }
Uncles:
Transactions:

We can see here that it fails on the block number which is always +2 than the block in the previous case (checked multiple times).

And again the output of the second version:

2019-04-25 00:24:45  Verifier #4 DEBUG engine  Zooming to epoch for block 0x49bf…6acf
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got hash 0xd35e…be46 from ancestry_iter
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got block details for block #1411134
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411134, 0xd35e…be46
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got hash 0x2883…33e3 from ancestry_iter
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got block details for block #1411133
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411133, 0x2883…33e3
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got hash 0x28bf…dafa from ancestry_iter
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got block details for block #1411132
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411132, 0x28bf…dafa
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got hash 0x0008…1ccf from ancestry_iter
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Got block details for block #1411131
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411131, 0x0008…1ccf
2019-04-25 00:24:45  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
…
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got hash 0xac35…0f5a from ancestry_iter
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got block details for block #1406348
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:25:22  Verifier #4 TRACE engine  extracting epoch set for epoch (1361021, 0xf342…db7d) signalled at #1361020
2019-04-25 00:25:22  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:25:22  Verifier #4 DEBUG engine  Expected topics for header 0x6f89…edb5: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x04c1c9c3b2da544a60e86a8f2c5461215903462e37cc11048e5255ae31fe975b]
2019-04-25 00:25:22  Verifier #4 DEBUG engine  Zooming to epoch for block 0x49bf…6acf
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got hash 0xd35e…be46 from ancestry_iter
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got block details for block #1411134
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411134, 0xd35e…be46
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got hash 0x2883…33e3 from ancestry_iter
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got block details for block #1411133
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411133, 0x2883…33e3
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:25:22  Verifier #4 TRACE blockchain  Got hash 0x28bf…dafa from ancestry_iter
…
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411134, 0xd35e…be46
2019-04-25 00:25:56  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:25:56  Verifier #4 DEBUG engine  Expected topics for header 0x49bf…6acf: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0xd35ebf7e366f4125f2edb1faf18d9d95e2b6db402c63489eb692d30c80a1be46]
2019-04-25 00:25:56  Verifier #4 DEBUG engine  Zooming to epoch for block 0x49bf…6acf
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got hash 0xd35e…be46 from ancestry_iter
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got block details for block #1411134
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411134, 0xd35e…be46
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got hash 0x2883…33e3 from ancestry_iter
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Got block details for block #1411133
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411133, 0x2883…33e3
2019-04-25 00:25:56  Verifier #4 TRACE blockchain  Block hash not found in cache or DB
…
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Got block details for block #1406348
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406348, 0xac35…0f5a
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Found non-canonical block hash 0x4ccc…5a54
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Got hash 0x6521…5e4f from ancestry_iter
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Got block details for block #1406347
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Loading epoch transition at block 1406347, 0x6521…5e4f
2019-04-25 00:26:29  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411135, 0x49bf…6acf
2019-04-25 00:26:29  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:26:29  Verifier #4 DEBUG engine  Expected topics for header 0x7309…53c2: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x49bf89d4f4db9be0943c6dff6bd5eb5bf226385a27dd59f6c35cda73060c6acf]
2019-04-25 00:26:29  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:26:29  Verifier #4 TRACE blockchain  Loading epoch transition at block 1411136, 0x7309…53c2
2019-04-25 00:26:29  Verifier #4 TRACE engine  Multi ValidatorSet retrieved for block 49700.
2019-04-25 00:26:29  Verifier #4 DEBUG engine  Expected topics for header 0x90ab…48aa: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x730992135c01d8f7d93456b9dadd4571b9a4f7911147ed32d4500d7001c953c2]

Also it worth mentioning that when I start 2nd version it starts to get block details of the block -1 of the block number where it fails. Then block numbers are decreasing, after some point they start to increase again - this can happen multiple times until we reach the block with Error when behavior changes.

I hope this information will be helpful to resolve this issue. I would recommend others try to reproduce (in the way I described above) this issue on their chains where this issue already took place.

[HCastano]

@VladLupashevskyi Hey, this is definitely useful info! I appreciate the effort you've put into this :)

[mirek]

We can see this problem after upgrading from v1.11.11 to v2.2.7 on PoA with 4 authority nodes, the problem with nodes forking and not resolving after this error happens during no activity (there are empty blocks all around, we're not using empty steps, engine signers are correct/unique on each validator).

Is there v2x version that is known not to have this issue as a temporary downgrade-workaround?

[VladLupashevskyi]

@mirek I was checking the version 2.0.0 and the issue still was there. However I've done testing when it was already "broken" (I mean RequiresClient error was popping up on startup). I haven't tried to do a fresh sync on 2.0.0.

[HCastano]

Hey guys, I'm heading back to school next week so I'm going to be passing this off to @ngotchac to investigate.

@VladLupashevskyi @phahulin @igorbarinov @ArseniiPetrovich

[debragail]

Have you tried this instance on a different OS? Say windows kernel to see if it’s OS math?

[gitcoinbot]

Issue Status: 1. Open 2. Cancelled

---

__The funding of 500.0 DAI (500.0 USD @ $1.0/DAI) attached to this issue has been cancelled by the bounty submitter__

• Questions? Checkout Gitcoin Help or the Gitcoin Slack
• $92,631.31 more funded OSS Work available on the Gitcoin Issue Explorer

[gitcoinbot]

Issue Status: 1. Open 2. Started 3. Submitted 4. Done

---

__This issue now has a funding of 2500.0 DAI (2500.0 USD @ $1.0/DAI) attached to it as part of the poanetwork fund.__

• If you would like to work on this issue you can 'start work' on the Gitcoin Issue Details page.
  
  
  
  • Want to chip in? Add your own contribution here.
  
  
  • Questions? Checkout Gitcoin Help or the Gitcoin Slack
  
  
  • $90,517.75 more funded OSS Work available on the Gitcoin Issue Explorer
  
  

[igorbarinov]

Here is the 2,500 Dai reward for solving the f-issue.
If you can solve it but can't apply for it by any reason, please contact me @igorbarinov on telegram or [email protected]

[brown2rl]

@joshua-mir I'm referencing this issue in gitter

[MarkusTeufelberger]

I ran into this issue as well today, things that I find interesting from the log:

• Parity was busy writing a snapshot at the time this happened
• Parity was busy syncing blocks (maybe because the disk was saturated?), but block 11045146 was loaded after 11045151 - and then 11045152 caused this error
• Block 11045147 was again(?!) imported with a different hash and the server also seems to have silently forked off the network at this point in time

The last validated block (by this validator) at this point was 11045141 (times are at UTC+2), it should have signed every third block at this point (so ...44, ...47 etc), so that second (wrong) ...47 block is likely the start of the lonely fork.

Log:

2019-05-20 08:56:00  Imported #11045130 0xe8b0…b4bf (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2019-05-20 08:56:04  Imported #11045131 0x4bba…3a72 (0 txs, 0.00 Mgas, 4 ms, 0.57 KiB)
2019-05-20 08:56:06  Snapshot: 117089 accounts 0 blocks 89548546 bytes
2019-05-20 08:56:12  Imported #11045132 0xff8c…bba7 (1 txs, 0.09 Mgas, 12 ms, 0.78 KiB)
2019-05-20 08:56:16  Imported #11045133 0x2310…ed1d (0 txs, 0.00 Mgas, 2 ms, 0.57 KiB)
2019-05-20 08:56:16  Snapshot: 131462 accounts 0 blocks 97877828 bytes
2019-05-20 08:56:20  Imported #11045134 0xe45a…2051 (1 txs, 0.09 Mgas, 3 ms, 0.78 KiB)
2019-05-20 08:56:21    99/100 peers    264 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    3 req/s,   80 µs
2019-05-20 08:56:26  Snapshot: 138663 accounts 0 blocks 102021079 bytes
2019-05-20 08:56:28  Imported #11045135 0x510c…eb0e (0 txs, 0.00 Mgas, 5 ms, 0.57 KiB)
2019-05-20 08:56:32  Imported #11045136 0xdeae…72db (0 txs, 0.00 Mgas, 2 ms, 0.57 KiB)
2019-05-20 08:56:36  Imported #11045137 0xb407…f4bf (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2019-05-20 08:56:36  Snapshot: 149060 accounts 0 blocks 108515934 bytes
2019-05-20 08:56:44  Imported #11045138 0x91cc…7ff2 (2 txs, 2.90 Mgas, 57 ms, 11.90 KiB)
2019-05-20 08:56:46  Snapshot: 159128 accounts 0 blocks 115193530 bytes
2019-05-20 08:56:48  Imported #11045139 0xc956…17d7 (1 txs, 0.19 Mgas, 10 ms, 0.87 KiB)
2019-05-20 08:56:51    99/100 peers    284 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    3 req/s,   73 µs
2019-05-20 08:56:52  Imported #11045140 0x5f31…9871 (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2019-05-20 08:56:56  Snapshot: 162247 accounts 0 blocks 117337467 bytes
2019-05-20 08:57:00  Imported #11045141 0xb375…5e2e (2 txs, 0.07 Mgas, 15 ms, 0.86 KiB)
2019-05-20 08:57:06  Snapshot: 162247 accounts 0 blocks 117337467 bytes
2019-05-20 08:57:16  Imported #11045142 0x516a…378f (0 txs, 0.00 Mgas, 13 ms, 0.57 KiB)
2019-05-20 08:57:16  Snapshot: 164362 accounts 0 blocks 120180370 bytes
2019-05-20 08:57:21    99/100 peers    291 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    3 req/s,   75 µs
2019-05-20 08:57:26  Snapshot: 170721 accounts 0 blocks 124855477 bytes
2019-05-20 08:57:32  Imported #11045143 0x5833…a2a3 (0 txs, 0.00 Mgas, 10 ms, 0.57 KiB)
2019-05-20 08:57:36  Snapshot: 174380 accounts 0 blocks 126958730 bytes
2019-05-20 08:57:47  Snapshot: 181109 accounts 0 blocks 131241459 bytes
2019-05-20 08:57:48  Imported #11045144 0x9bcb…f878 (0 txs, 0.00 Mgas, 7 ms, 0.57 KiB)
2019-05-20 08:57:51    99/100 peers    291 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    3 req/s,   77 µs
2019-05-20 08:57:57  Snapshot: 181109 accounts 0 blocks 131241459 bytes
2019-05-20 08:58:04  Imported #11045145 0xd18c…eae2 (0 txs, 0.00 Mgas, 9 ms, 0.57 KiB)
2019-05-20 08:58:05  Imported #11045147 0x8e23…cf14 (2 txs, 0.40 Mgas, 19 ms, 0.98 KiB) + another 5 block(s) containing 3 tx(s)
2019-05-20 08:58:07  Snapshot: 182570 accounts 0 blocks 134297817 bytes
2019-05-20 08:58:08  Imported #11045150 0x05a0…0ec2 (3 txs, 0.19 Mgas, 9 ms, 2.20 KiB) + another 2 block(s) containing 1 tx(s)
2019-05-20 08:58:12  Imported #11045151 0x20cb…3c0a (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2019-05-20 08:58:17  Snapshot: 182570 accounts 0 blocks 134297817 bytes
2019-05-20 08:58:20  Imported #11045146 0x71d1…955d (9 txs, 0.81 Mgas, 26 ms, 4.06 KiB)
2019-05-20 08:58:21    89/100 peers    291 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    3 req/s,   67 µs
2019-05-20 08:58:24  Stage 3 block verification failed for #11045152 (0x7d54…6f3f)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-05-20 08:58:24  
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
RLP: f903dbf90247a020cb5a2cdd36d228d4a0ab5167342833e026661afacebc3cb77d69e3c8543c0aa01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794faadface3fbd81ce37b0e19c0b65ff423414813
2a0cfedb543d8e327b1bffe35750b34b8ff249364a15c4cb1dfc8dcb770e241431da0423e2cf7a0dfc66c503783141ed67760ffcab74a22ae9f0ae5633bb4d6c6fbf6a0423b61a818df2bf8a8cf0bf08959c70c9008814619f5cdc84b0f190
a6da7bc9ab901000000000000000000000000004000000000000000000000040000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000000000000000000000000000000000000000000000000000000000000000000000100000000000000000000000000000000000000000000000000000800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000040000000000000000000000090fffffffffffffffffffffffffffffffc83a88920837a12008307fce2845ce250109fde830204058f5061726974792d457468657265756d86312e33332e30826c698417389404b84166b6925093f915de0df13c13511dbc79d0f4512302be04d9da8ecf45dd18eabd2f8a48f07e548e0f822f4e6144457ed8a77cf2bd20c8d5612cf29be70f1c741c01f9018df9018a37843b9aca0083080e0594be4ff6ab316ff8288409c6ee5b405b3dadad940280b90124dd12931326f05e476e2dd0e3f94fa17420591b68665570ef070a67484b91f6f819e8e4842154d71df0b83756681f4fc289c3e27c528b8c411f1c687cb3ef068d2346b15c2daeab7154cbd231aaeae009eb48ba262c2bbfdb25d44af762fd496c1843d55b16181c1356eeee804759c5a24b477337c09659963b0e677c6da0f1097d72a5930668c70ebe9092e5c252e15e73daad984f6e4b1eb75ea4358252e130f0a086d3244562f185d25aa1428a9cb21e12a228cba27f8230578d00b96b8c81ad66b43b05d34bb704721a88a711b4f62674354c032346f01cd078b028e429b1363d2a760a7757173768d3329c650b3e7c238cf1c8c555a32530b58e4bbf5b682324b0ee000000000000000000000000000000000000000000000000000000000000000178a0c3797b86541816289d092a8aac0352701bb78ab73aecf54444ec3b04f7fa5d31a073e54b554558001645def11e5397dcaadbfd0a58e1726d733897485ad52b5521c0
Header: Header { parent_hash: 0x20cb5a2cdd36d228d4a0ab5167342833e026661afacebc3cb77d69e3c8543c0a, timestamp: 1558335504, number: 11045152, author: 0xfaadface3fbd81ce37b0e19c0b65ff4234148132, transactions_root: 0x423e2cf7a0dfc66c503783141ed67760ffcab74a22ae9f0ae5633bb4d6c6fbf6, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 4, 5, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 51, 46, 48, 130, 108, 105], state_root: 0xcfedb543d8e327b1bffe35750b34b8ff249364a15c4cb1dfc8dcb770e241431d, receipts_root: 0x423b61a818df2bf8a8cf0bf08959c70c9008814619f5cdc84b0f190a6da7bc9a, log_bloom: 0x00000000000000000000000040000000000000000000000400000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000000000000000000000000000000000000000000008000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000400000000000000000000000, gas_used: 523490, gas_limit: 8000000, difficulty: 340282366920938463463374607431768211452, seal: [[132, 23, 56, 148, 4], [184, 65, 102, 182, 146, 80, 147, 249, 21, 222, 13, 241, 60, 19, 81, 29, 188, 121, 208, 244, 81, 35, 2, 190, 4, 217, 218, 142, 207, 69, 221, 24, 234, 189, 47, 138, 72, 240, 126, 84, 142, 15, 130, 47, 78, 97, 68, 69, 126, 216, 167, 124, 242, 189, 32, 200, 213, 97, 44, 242, 155, 231, 15, 28, 116, 28, 1]], hash: Some(0x7d54789aec5992eaf97ab5185ddee04f01ea2d08eeeb281a29764d8e02846f3f) }
Uncles: 
Transactions:[Tx 0] UnverifiedTransaction { unsigned: Transaction { nonce: 55, gas_price: 1000000000, gas: 527877, action: Call(0xbe4ff6ab316ff8288409c6ee5b405b3dadad9402), value: 0, data: [221, 18, 147, 19, 38, 240, 94, 71, 110, 45, 208, 227, 249, 79, 161, 116, 32, 89, 27, 104, 102, 85, 112, 239, 7, 10, 103, 72, 75, 145, 246, 248, 25, 232, 228, 132, 33, 84, 215, 29, 240, 184, 55, 86, 104, 31, 79, 194, 137, 195, 226, 124, 82, 139, 140, 65, 31, 28, 104, 124, 179, 239, 6, 141, 35, 70, 177, 92, 45, 174, 171, 113, 84, 203, 210, 49, 170, 234, 224, 9, 235, 72, 186, 38, 44, 43, 191, 219, 37, 212, 74, 247, 98, 253, 73, 108, 24, 67, 213, 91, 22, 24, 28, 19, 86, 238, 238, 128, 71, 89, 197, 162, 75, 71, 115, 55, 192, 150, 89, 150, 59, 14, 103, 124, 109, 160, 241, 9, 125, 114, 165, 147, 6, 104, 199, 14, 190, 144, 146, 229, 194, 82, 225, 94, 115, 218, 173, 152, 79, 110, 75, 30, 183, 94, 164, 53, 130, 82, 225, 48, 240, 160, 134, 211, 36, 69, 98, 241, 133, 210, 90, 161, 66, 138, 156, 178, 30, 18, 162, 40, 203, 162, 127, 130, 48, 87, 141, 0, 185, 107, 140, 129, 173, 102, 180, 59, 5, 211, 75, 183, 4, 114, 26, 136, 167, 17, 180, 246, 38, 116, 53, 76, 3, 35, 70, 240, 28, 208, 120, 176, 40, 228, 41, 177, 54, 61, 42, 118, 10, 119, 87, 23, 55, 104, 211, 50, 156, 101, 11, 62, 124, 35, 140, 241, 200, 197, 85, 163, 37, 48, 181, 142, 75, 191, 91, 104, 35, 36, 176, 238, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1] }, v: 120, r: 88415646504864780009283657971290504706790535478790629947795745841255510859057, s: 52421105494784110039696272962391086920437594864508183181599881694256716010785, hash: 0x3475f250c0dfbb8266ba2ce934e8aabc271d6c2abad54de2fcc1ff7b9b7bc5dc }

2019-05-20 08:58:27  Snapshot: 182570 accounts 0 blocks 134297817 bytes
2019-05-20 08:58:36  Imported #11045147 0xb1df…6a45 (1 txs, 0.52 Mgas, 13 ms, 0.97 KiB)
2019-05-20 08:58:37  Snapshot: 183893 accounts 0 blocks 137703332 bytes
2019-05-20 08:58:46  Snapshot: 190393 accounts 0 blocks 142128504 bytes
2019-05-20 08:58:52  Imported #11045148 0x3bc0…6a42 (4 txs, 0.29 Mgas, 14 ms, 2.17 KiB)
2019-05-20 08:58:56    29/100 peers    292 MiB chain   14 MiB db  0 bytes queue   92 KiB sync  RPC:  0 conn,    1 req/s,   79 µs
2019-05-20 08:58:56  Snapshot: 193720 accounts 0 blocks 144559864 bytes
2019-05-20 08:59:06  Snapshot: 197715 accounts 0 blocks 146603233 bytes

[d10r]

A pattern I've observed is that Parity Aura validator nodes tend to drop a lot of peer connections (sometimes all) after encountering an invalid block. This can e.g. be seen in the log of the previous comment, where the peer count drops from 89 to 29.
Intuitively I'd guess that causes them to be unable to reorg to the right chain, because they simply have no peers left who could tell them about it.

[brown2rl]

@igorbarinov I successfully built parity release from master branch on Windows 10. Parity is currently syncing snapshot 480/3144 with 25/25 peers after about 1 hour. I'm planning on adding a patch that will catch the BadBlock error, drop the DB, and syncronize. Do you think there would be an issue with down time on a node during syncronization?

[joshua-mir]

@brown2rl that probably doesn't solve the real source of the issue at hand. That said, it would certainly be a significant UX improvement if you did what you are describing, only using the BlockChainReset feature instead of dropping the entire database.

[brown2rl]

@joshua-mir Ok, thanks for the info. The idea is to improve the UX in that way as a quick patch while investigating and fixing the real source of the issue.

[brown2rl]

@joshua-mir i couldn't find any call to BlockChainReset. Is there a consensus on which num: u32 is an acceptable parameter?

[joshua-mir]

(the feature is accessible via cli with parity db reset so you'll find a call in that part of the codebase) num refers to the number of blocks you are resetting/rewinding - so according to the discussion in this issue, we want to reset 2 or 3 blocks @brown2rl

I should note that the current sync logic already resets a single block when hitting a bad block error, which you can see in the logs above.

[brown2rl]

@joshua-mir Great to know, thanks! I'll set it for 3

[xiaods]

so how to stable get the context for that bug.

[brown2rl]

@joshua-mir Am I correct in thinking that there is a perpetual sync until all snapshots are downloaded? If this is the case, we can reset/rewind 3 blocks back on BadBlock error and synchronization will continue until all snapshots are validated. Otherwise, I would assume there should be another call to restart the sync. The only function I've found so far is included in the ethcore sync tests.

[joshua-mir]

@brown2rl answering your question:

The reset function is only ever called via the cli, while the node is offline, so I am not aware if we have a call to restart sync from the block you've reset to, or if sync just continues automatically after we've reset our blocks.

Some clarification on snapshots:

sync only begins after warp-sync completes - a (state) "snapshot" has been downloaded and imported - you only download a single state snapshot over the process of warp sync. Markus' logs above have a snapshot being created for other peers simultaneously to an ongoing sync, which might be throwing you off 😅

After warp-sync is complete, along with ordinary sync (getting blocks from peers and importing them), we grab blocks from genesis until the block of our state snapshot and verify their headers/difficulty (this is "ancient block sync") which is what I believe you're referring to as "verifying snapshots"?

[brown2rl]

@joshua-mir Thanks. According to the wiki, warp-sync begins by default upon starting pairty.exe. After I built and started $ parity, it began downloading/syncing 3,144 snapshots. Is that what is supposed to happen? Maybe I was creating for other peers?

I mean to say block validation, not verifying snapshots.

[joshua-mir]

3144 chunks of one snapshot - yes, that's the correct behavior.

[brown2rl]

oh, wow. ok, thanks.

[phahulin]

@lazaridiscom unfortunately there doesn’t seem to be a certain sequence of steps to 100% reproduce the issue. Rarely it happens when node is simply running. But most frequently - after parity is restarted. On Kovan network we faced it several times after restarts.

[phahulin]

Had it today on Kovan again after restart. During shutdown noticed the following messages in logs:

2019-05-28 15:25:08 UTC IO Worker #1 WARN miner  Error queueing cull: Mio(Custom { kind: ConnectionAborted, error: StringError("Network IO notification error") })
...
2019-05-28 15:25:10 UTC main WARN parity_ethereum::run  Shutdown is taking longer than expected.
...

Could it be that the root cause is that during the shutdown some error happens and state is not correctly saved to the database? I also noticed messages about creating snapshots as @MarkusTeufelberger did.

[phahulin]

@lazaridiscom we use systemd to run parity as a service. TOML configuration file looks like this:

[parity]
chain = "spec.json"
base_path = "parity_data"
auto_update = "none"

[network]
reserved_peers="bootnodes.txt"
nat="extip:..." # real IP here
port = 30303
max_peers = 100

[rpc]
apis = ["web3", "eth", "parity", "parity_set", "net", "traces", "rpc"]

[account]
password = ["node.pwd"]
unlock = ["0x..."] # real address here

[mining]
usd_per_tx = "0"
min_gas_price = 1000000000
force_sealing = true
engine_signer = "0x..." # real address here
gas_floor_target = "8000000"
reseal_on_txs = "none"

[misc]
log_file = "logs/parity.log"
logging = "engine=trace"

So the start command is

parity --config node.toml

By default, I suppose systemd sends SIGTERM to stop the process. Maybe we could try to increase the timeout here.

[phahulin]

Today I also added the following option to the config to disable creating new snapshots

[snapshots]
disable_periodic = true

and restarted a node like 30 times - error hasn't reproduced yet.

[phahulin]

Is "disable_periodic=true" viable in production setups?

it would be better to NOT disable snapshots in production, because it's difficult to manage a network without proper snapshots, sync would take days

if you enable periodic again and restart, the error comes up again?

yes. But you have to wait until messages about creating snapshots appear in logs again, e.g.

Snapshot: 274343 accounts 0 blocks 1094979710 bytes

after that the second restart caused the issue.

If yes: at the same block?

not sure what you mean here. If an issue has happened and you restart the node, it will happen again on the same block as originally.
If you resync and try again later it will happen on a different block

[aahutsal]

@igorbarinov is it still actual, Igor?

[aahutsal]

@lazaridiscom could be vacation time, no? ;)

[igorbarinov]

Sorry guys, here I am a manager, not a developer.

I put the bounty for the solution.
When the solution will be found and fix will be merged into the codebase I will distribute the bounty.

[aahutsal]

@igorbarinov looks like @lazaridiscom should speak to some techies.

[dvdplm]

Please let's keep the conversation here focused on the issue and let's refrain from personal comment and meta-discussions.

[igorbarinov]

@dvdplm I agree. Although your message is a meta-discussion and personal comment per se.
do any ideas on how to resolve the fissue?

[MarkusTeufelberger]

So is this bug fixed now/will it be fixed or not? It seems like over the past few days you have documented your approach to potentially recreate the issue, then deleted your notes again but didn't create an actual pull request with code beyond #10700. What's the actual source/cause of this error anyways? #10712 sounds again like "No idea what the actual problem is, let's just reset something automatically and hope it works next time" similar to #10693.

[dvdplm]

is this bug fixed now

@MarkusTeufelberger We suspect there might be more than one bug involved, but no, it is not fixed as far as I know.

will it be fixed

We will obviously do our very best. One problem is we don't have a way to reliably reproduce the error with the main parity client and rebasing the poa fork is non-trivial. If anyone has any pointers of how to go about either reproducing the problem reliably with the main parity client or easily sync the poa fork of parity (so we can use @lazaridiscom repro), that would be a great help.

We believe the core issue here is that multiple blocks are produced at the same height, as has been said before in this thread. The problem seems to be more common in a single-authority scenario whereas in the multiple authority case it is often less visible. So the first order of business is to fix that.

As others have correctly pointed out the RequiresClient error is not correct and the true issue comes before it. We will improve our logging in the hope that we or others will be able to spot the problem and help drive the solution.

[phahulin]

One more note to readers:

Unfortunately, it looks like @lazaridiscom has closed/deleted his repos dedicated to this issue.
You can try to replicate it on kovan network by restarting a fully synced node. The error doesn't reproduce every restart, but quite often.

[dvdplm]

You can try to replicate it on kovan network by restarting a fully synced node. The error doesn't reproduce every restart, but quite often.

@phahulin Hmm. Have done that quite a few times here but no error. Do you see this behaviour on a particular kovan node or on several? Even locally? Running a recent parity nightly build?

[phahulin]

I haven't tried the newest parity build. This error reproduced on several nodes. The problem occured when node was stop while creating snapshots in the background (see logs for messages about it like Snapshot: 98509 accounts 0 blocks 63684258 bytes)

[dvdplm]

The problem occured when node was stop while creating snapshots in the background

Oh that is interesting. I spent some time yesterday on a fix for that, see https://github.com/paritytech/parity-ethereum/pull/10744

Would be super interesting to see if you still see the error with that patch applied.

[phahulin]

@dvdplm
I compiled that branch but wasn't able to run a node for more than few minutes because it stops with the following error

$ ./parity --config node.toml
Loading config file from node.toml
2019-06-17 08:46:10 UTC main INFO parity_ethereum::run  Starting Parity-Ethereum/v2.6.0-nightly-902ab9f-20190617/x86_64-linux-gnu/rustc1.35.0
2019-06-17 08:46:10 UTC main INFO parity_ethereum::run  Keys path parity_data/keys/kovan
2019-06-17 08:46:10 UTC main INFO parity_ethereum::run  DB path parity_data/chains/kovan/db/9bf388941c25ea98
2019-06-17 08:46:10 UTC main INFO parity_ethereum::run  State DB configuration: fast
2019-06-17 08:46:10 UTC main INFO parity_ethereum::run  Operating mode: active
2019-06-17 08:46:11 UTC main WARN engine  Not preparing block; cannot sign.
2019-06-17 08:46:11 UTC main INFO ethcore_service::service  Configured for Kovan Testnet using AuthorityRound engine
2019-06-17 08:46:11 UTC main WARN privatetx  Cannot read logs: Io(Os { code: 2, kind: NotFound, message: "No such file or directory" })
2019-06-17 08:46:11 UTC IO Worker #2 INFO network  Public node URL: enode://...


====================

stack backtrace:
   0:     0x55d0214408ed - backtrace::backtrace::trace::h56c8efbab259809f
   1:     0x55d02143f782 - <backtrace::capture::Backtrace as core::default::Default>::default::h99b341993d0da47f
   2:     0x55d02143e986 - panic_hook::gen_panic_msg::h54dce1596a42fbb1
   3:     0x55d02143e7bf - panic_hook::set_with::{{closure}}::h9478b73d5573da85
   4:     0x55d0214b2078 - rust_panic_with_hook
                        at src/libstd/panicking.rs:478
   5:     0x55d0214b1b11 - continue_panic_fmt
                        at src/libstd/panicking.rs:381
   6:     0x55d0214b1a5e - begin_panic_fmt
                        at src/libstd/panicking.rs:336
   7:     0x55d02148594f - primitive_types::H256::from_slice::h3442f4757348343f
   8:     0x55d020695d98 - std::sync::once::Once::call_once::{{closure}}::h0b6005ee9fbd3b94
   9:     0x55d0214acb25 - call_inner
                        at src/libstd/sync/once.rs:387
  10:     0x55d02067a71e - <parity_updater::updater::OperationsContractClient as parity_updater::updater::OperationsClient>::latest::h9de45882ec191147
  11:     0x55d0206822d2 - parity_updater::updater::Updater<O,F,T,R>::poll::h5d4d7a959abc8b48
  12:     0x55d02067caa3 - parity_updater::updater::Updater::new::hba3869a7e80175f7
  13:     0x55d01fd6b3fd - parity_ethereum::run::execute_impl::h95ab651d84151c93
  14:     0x55d01fd838f5 - parity_ethereum::run::execute::hd8fa5f3ec6468550
  15:     0x55d020101467 - parity_ethereum::start::hfd316b1e5afa47f3
  16:     0x55d02007e689 - parity::main_direct::hf69b9b7a4698d2ef
  17:     0x55d0200819e1 - parity::main::h4090e4e4047ea2cf
  18:     0x55d02004ebd2 - std::rt::lang_start::{{closure}}::hde08f7fbb76fdab4
  19:     0x55d0214b1992 - {{closure}}
                        at src/libstd/rt.rs:49
                         - do_call<closure,i32>
                        at src/libstd/panicking.rs:293
  20:     0x55d0214bd339 - __rust_maybe_catch_panic
                        at src/libpanic_unwind/lib.rs:87
  21:     0x55d0214b255c - try<i32,closure>
                        at src/libstd/panicking.rs:272
                         - catch_unwind<closure,i32>
                        at src/libstd/panic.rs:388
                         - lang_start_internal
                        at src/libstd/rt.rs:48
  22:     0x55d020082311 - main
  23:     0x7fc5ba51282f - __libc_start_main
  24:     0x55d01fc55938 - _start
  25:                0x0 - <unknown>

Thread 'main' panicked at 'assertion failed: `(left == right)`
  left: `6`,
 right: `32`', /home/ubuntu/.cargo/registry/src/github.com-1ecc6299db9ec823/primitive-types-0.3.0/src/lib.rs:64

This is a bug. Please report it at:

    https://github.com/paritytech/parity-ethereum/issues/new


Aborted (core dumped)

Sometimes it happens right at the start (like in the log above), othertimes it would import a few blocks and then crash.

[dvdplm]

@phahulin thank you, that looks nasty. Working on a fix for that asap.

[dvdplm]

@phahulin The panic is fixed and branch updated. Can you try again please? Again, thank you for the help here.

[phahulin]

@dvdplm this time I can't compile it, because compilation process is killed as out of memory

Jun 18 12:17:58 ip-172-31-81-106 kernel: [ 9388.589854] Out of memory: Kill process 15900 (rustc) score 936 or sacrifice child
Jun 18 12:17:58 ip-172-31-81-106 kernel: [ 9388.606881] Killed process 15900 (rustc) total-vm:6038744kB, anon-rss:3778608kB, file-rss:1328kB
 ```

I'm running this command to compile

$ cargo build --release --features final
Compiling parity-ethereum v2.6.0 (/home/ubuntu/parity-ethereum)
error: Could not compile parity-ethereum.
Caused by:
process didn't exit successfully: `rustc --crate-name parity parity/main.rs ...
...
(signal: 9, SIGKILL: kill)
```
Full log here: https://gist.github.com/phahulin/ef2f0f909d166d3a2aaadf911d4da677

I'll try on a larger server, but this error didn't happen previously

[phahulin]

The build server I'm currently using has about 4Gb of free memory

$ free -m
              total        used        free      shared  buff/cache   available
Mem:           3950          83        3775           5          91        3690
Swap:             0           0           0

Rust and cargo versions:

$ rustc --version
rustc 1.35.0 (3c235d560 2019-05-20)

$ cargo --version
cargo 1.35.0 (6f3e9c367 2019-04-04)

[dvdplm]

@phahulin the problem is most likely that we're switching to lto = true in upcoming releases. This increases build times in exchange for smaller&faster binaries. You can disable it by commenting out this line.

So sorry for the hassle!

[phahulin]

@dvdplm it compiled without lto, thanks. Now have to wait a few hours for snapshots to start working in the background, then I'll test and let you know if error reproduces.

[phahulin]

@dvdplm We had our kovan node restarted multiple times today and the issue didn't reproduce :+1:

[dvdplm]

@phahulin that's good news. I do think there is an actual bug in play here, possibly several, and the search continues. Having clean shutdowns is ofc good for data integrity but I don't think it's the root problem.
The root problem is that conflicting blocks (same height, same parent) are sent around on the network and (probably) one of them is accepted locally and others are accepted by other nodes, causing a irreparable fork. Or at least that's our current best hypothesis.

[dvdplm]

The bug described in this issue is hard to reproduce. The repro code that was submitted uses a setup where 2 nodes use the same engine_signer. This is an invalid setup and will undoubtedly create problems.
At this point I think it's fair to stop for a moment and ask everyone that has reported this bug to double check their setups and ensure that they were not running with duplicate engine_signer when the problem appeared. If you did, please fix your configurations and re-run your networks and let us know.

If you are positive the setup was/is valid and still see the bug the next step here will be to provide a repro that use the latest parity master so that we can exclude that the problem lies here rather than in the POA fork (the two code bases have diverged somewhat and it's non-trivial to merge upstream).

[dvdplm]

From here on out any comment that is not in its entirety technical in content and polite in tone will be deleted immediately; the same holds for any personal comments, discussion regarding bounties and/or the completeness of any suggested fixes, payment or any other details regarding the handling this matter outside the purely technical.
Work performed on the POA fork of parity code is best discussed at the POA fork github.

[mirek]

I can confirm we've experienced this issue on: v2.2.7, no duplicate signers, 4 authority nodes, 1s block time, no activity (no transactions) on chain, empty blocks enabled. I wonder if introducing delays to disk io and/or network and/or cpu could amplify this likely race condition.

[mirek]

What about things like ntpd, can't they interfere with block creation, small clock adjustments that create activity in the "future", then in the "past"? Or is parity protected against it by using monotonic clock?

[dvdplm]

@mirek Running with 1s block time is border line and you can easily get into trouble by network latency alone. We are even considering forbidding such configs (i.e. require a sane block time) simply because of how unreliable a setup it is. And yes, clock drift becomes a worse problem the shorter the block time.

Do you have a way to try your setup using a recent master build? We'd be very keen to see the logs too (use sync=trace,miner=trace,engine=trace,blockchain=trace,finality=trace,client=trace).

[mirek]

@dvdplm Yes, we're aware of 1s being tight but we have sub 1 ms latency and we require faster finality on transactions.

In the context of this issue 1s should amplify error rate so it is probably good to use it.

Other than that I don't think there's anything special about the config.

I think I can run this config with trace. I'll probably play a bit with pumba's delays as well.

[ghost]

Root-Cause Reproduction, Fix and Deep-Fix-Suggestions are available now (parity master and poanet-posdao)

[phahulin]

@lazaridiscom we've tested parity's solution on kovan and couldn't reproduce the issue anymore, so in that respect it looks resolved now.
Do you have any other scenarios (could you open your repos?) that would show that this solution is incomplete?

[gitcoinbot]

Issue Status: 1. Open 2. Cancelled

---

__The funding of 2500.0 DAI (2500.0 USD @ $1.0/DAI) attached to this issue has been cancelled by the bounty submitter__

• Questions? Checkout Gitcoin Help or the Gitcoin Slack
• $93,924.59 more funded OSS Work available on the Gitcoin Issue Explorer

[gitcoinbot]

⚡️ A tip worth 500.00000 DAI (500.0 USD @ $1.0/DAI) has been granted to @dvdplm for this issue from @igorbarinov. ⚡️

Nice work @dvdplm! To redeem your tip, login to Gitcoin at https://gitcoin.co/explorer and select 'Claim Tip' from dropdown menu in the top right, or check your email for a link to the tip redemption page.

• $93950.91 in Funded OSS Work Available at: https://gitcoin.co/explorer
• Incentivize contributions to your repo: Send a Tip or Fund a PR
• No Email? Get help on the Gitcoin Slack

[gitcoinbot]

⚡️ A tip worth 100.00000 DAI (100.0 USD @ $1.0/DAI) has been granted to @VladLupashevskyi for this issue from @igorbarinov. ⚡️

Nice work @VladLupashevskyi! To redeem your tip, login to Gitcoin at https://gitcoin.co/explorer and select 'Claim Tip' from dropdown menu in the top right, or check your email for a link to the tip redemption page.

• $93957.95 in Funded OSS Work Available at: https://gitcoin.co/explorer
• Incentivize contributions to your repo: Send a Tip or Fund a PR
• No Email? Get help on the Gitcoin Slack

[gitcoinbot]

⚡️ A tip worth 500.00000 DAI (500.0 USD @ $1.0/DAI) has been granted to @sorpaas for this issue from @igorbarinov. ⚡️

Nice work @sorpaas! To redeem your tip, login to Gitcoin at https://gitcoin.co/explorer and select 'Claim Tip' from dropdown menu in the top right, or check your email for a link to the tip redemption page.

• $93957.95 in Funded OSS Work Available at: https://gitcoin.co/explorer
• Incentivize contributions to your repo: Send a Tip or Fund a PR
• No Email? Get help on the Gitcoin Slack

[gitcoinbot]

⚡️ A tip worth 100.00000 DAI (100.0 USD @ $1.0/DAI) has been granted to @lazaridiscom for this issue from @igorbarinov. ⚡️

Nice work @lazaridiscom! To redeem your tip, login to Gitcoin at https://gitcoin.co/explorer and select 'Claim Tip' from dropdown menu in the top right, or check your email for a link to the tip redemption page.

• $93957.95 in Funded OSS Work Available at: https://gitcoin.co/explorer
• Incentivize contributions to your repo: Send a Tip or Fund a PR
• No Email? Get help on the Gitcoin Slack

[ghost]

@igorbarinov , I do not accept this tip, ask the gitcoin clowns for a refund.

[ghost]

@debris, this is not solved by #10837.

[SidhMj]

Hi! I think I am seeing the same behavior in one node of our PoA. We are running v2.3.0-nightly (commit bf9fedc4ee2eaa4dcbc6fcb9ef73bdf6967ee071), secret store is enabled in this node. I find it strange because this node keep importing the new blocks. The other nodes (same configuration) works well. These are the logs:

Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:24 UTC Stage 3 block verification failed for #20576 (0x28ce…3a4b)
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:24 UTC
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: RLP: f90248f90243a0c0b6d8709608a422297d286640d11af4fabd9865b850a18198f41d9ec0d5764ea01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794a1345ed0b2d1e193aead673e33dac56515af128aa06517af1a718ec3f7e459f809438c1b96c9a394d85746b2cffd9538cfec336d2ea056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090ffffffffffffffffffffffffffffffef8250608365b9aa80845c3c44f59fde830203008f5061726974792d457468657265756d86312e33312e31826c698412727431b8413aa81df658fd004c8b0589947dc2c7debeaf950ef11690156b6324272cd2bc8671a9f867df91b9cfc3acf5e95a05056f87d72463598a71f0740866cc5f909d2000c0c0
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Header: Header { parent_hash: 0xc0b6d8709608a422297d286640d11af4fabd9865b850a18198f41d9ec0d5764e, timestamp: 1547453685, number: 20576, author: 0xa1345ed0b2d1e193aead673e33dac56515af128a, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 3, 0, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x6517af1a718ec3f7e459f809438c1b96c9a394d85746b2cffd9538cfec336d2e, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 6666666, difficulty: 340282366920938463463374607431768211439, seal: [[132, 18, 114, 116, 49], [184, 65, 58, 168, 29, 246, 88, 253, 0, 76, 139, 5, 137, 148, 125, 194, 199, 222, 190, 175, 149, 14, 241, 22, 144, 21, 107, 99, 36, 39, 44, 210, 188, 134, 113, 169, 248, 103, 223, 145, 185, 207, 195, 172, 245, 233, 90, 5, 5, 111, 135, 215, 36, 99, 89, 138, 113, 240, 116, 8, 102, 204, 95, 144, 157, 32, 0]], hash: Some(0x28ce97bb48c7decc725eae5e994a1ab48cc56e03bff469b6e73e0552c75d3a4b) }
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Uncles:
Jan 14 08:27:24 ip-172-31-0-123.ec2.internal docker[23873]: Transactions:
Jan 14 08:27:26 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:26 UTC    0/25 peers     78 KiB chain    4 MiB db  0 bytes queue    1 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
Jan 14 08:27:56 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:27:56 UTC    0/25 peers     78 KiB chain    4 MiB db  0 bytes queue    1 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
Jan 14 08:28:26 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:28:26 UTC    0/25 peers     78 KiB chain    4 MiB db  0 bytes queue    1 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
Jan 14 08:28:56 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:28:56 UTC    0/25 peers     78 KiB chain    4 MiB db  0 bytes queue    1 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
Jan 14 08:29:05 ip-172-31-0-123.ec2.internal docker[23873]: 2019-01-14 08:29:05 UTC Imported #19973 0x07d5…5578 (0 txs, 0.00 Mgas, 50 ms, 0.57 KiB)```

I have same issue. @jcortejoso let me know if you able to solve this

[joshua-mir]

@sidharthaa could you share more information like the version you are running and any logs showing the issue?

[SidhMj]

```Loading config file from /home/parity/authority.toml
2019-09-06 13:59:51 UTC Starting Parity-Ethereum/v2.5.7-stable-6bd7db9-20190829/x86_64-linux-gnu/rustc1.36.0
2019-09-06 13:59:51 UTC Keys path /home/parity/data/keys/nitchain
2019-09-06 13:59:51 UTC DB path /home/parity/data/chains/nitchain/db/652780e9e78ae1c2
2019-09-06 13:59:51 UTC State DB configuration: fast
2019-09-06 13:59:51 UTC Operating mode: active
2019-09-06 13:59:51 UTC Configured for nitchain using AuthorityRound engine
2019-09-06 13:59:52 UTC Listening for new connections on 0.0.0.0:8546.
2019-09-06 13:59:57 UTC Public node URL: enode://7936e78db2ac455a9b829a08794d8bc371b54d900bc989d7d83af6e922f237e885555cca4139ba1af38d22351f45d9fea88c23a1407a72804dcac7f493096036@172.24.0.2:30303
2019-09-06 14:00:04 UTC Stage 3 block verification failed for #199 (0xef43…4d1b)
Error: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
0: 0x56351f6492ad -
1: 0x56351f41cebc -
2: 0x56351f0931dc -
3: 0x56351f09a050 -
4: 0x56351ef5f8b3 -
5: 0x56351f125c2b -
6: 0x56351e9c7021 -
7: 0x56351eeeb1e9 -
8: 0x56351eedf53b -
9: 0x56351eef09c7 -
10: 0x56351ef88ba4 -
11: 0x56351f6a689e -
12: 0x56351f6a93eb -
13: 0x7fa88f2036b9 -
14: 0x7fa88ed2341c -
15: 0x0 - ) } })
2019-09-06 14:00:04 UTC
Bad block detected: Error(Engine(RequiresClient), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
0: 0x56351f6492ad -
1: 0x56351f41cebc -
2: 0x56351f0931dc -
3: 0x56351f09a050 -
4: 0x56351ef5f8b3 -
5: 0x56351f125c2b -
6: 0x56351e9c7021 -
7: 0x56351eeeb1e9 -
8: 0x56351eedf53b -
9: 0x56351eef09c7 -
10: 0x56351ef88ba4 -
11: 0x56351f6a689e -
12: 0x56351f6a93eb -
13: 0x7fa88f2036b9 -
14: 0x7fa88ed2341c -
15: 0x0 - ) } })
RLP: f90248f90243a0b06b6154c6125da6956b8eb7a785209aa83ee30c910179852739bfaf24d09eaca01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794314a298054f660d8128b78ced1087d5921fda422a030fbb39f739745effd387faa16c8b6c2ae3cd9875e5a589753e13450433ab0c0a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffb81c78401f6822580845d72568e9fde830205078f5061726974792d457468657265756d86312e33362e30826c698409583bdbb84190f798c546a9234e5900af266d6f9c27bb646fe760d7808abe52c9abc49b0124679115ee0d65a50bf3ddac80b909f3dd6c47e764160c7c9459a4b5756d015d8101c0c0
Header: Header { parent_hash: 0xb06b6154c6125da6956b8eb7a785209aa83ee30c910179852739bfaf24d09eac, timestamp: 1567774350, number: 199, author: 0x314a298054f660d8128b78ced1087d5921fda422, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 5, 7, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 54, 46, 48, 130, 108, 105], state_root: 0x30fbb39f739745effd387faa16c8b6c2ae3cd9875e5a589753e13450433ab0c0, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 32932389, difficulty: 340282366920938463463374607431768211451, seal: [[132, 9, 88, 59, 219], [184, 65, 144, 247, 152, 197, 70, 169, 35, 78, 89, 0, 175, 38, 109, 111, 156, 39, 187, 100, 111, 231, 96, 215, 128, 138, 190, 82, 201, 171, 196, 155, 1, 36, 103, 145, 21, 238, 13, 101, 165, 11, 243, 221, 172, 128, 185, 9, 243, 221, 108, 71, 231, 100, 22, 12, 124, 148, 89, 164, 181, 117, 109, 1, 93, 129, 1]], hash: Some(0xef438e2c7509a27ce0bf9001c3e28b8dc173c0f7c9dc04e88057c19da3af4d1b) }
Uncles:
Transactions:

2019-09-06 14:00:22 UTC 2/25 peers 22 KiB chain 32 KiB db 0 bytes queue 221 KiB sync RPC: 0 conn, 0 req/s, 0 µs
2019-09-06 14:00:52 UTC 2/25 peers 22 KiB chain 32 KiB db 0 bytes queue 221 KiB sync RPC: 0 conn, 0 req/s, 0 µs
2019-09-06 14:01:10 UTC Imported #97 0x8179…9d8b (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
```
@joshua-mir
Running in docker
I kept this node offline for few hours when it came back it started synching but in block #199 i got this error and the node created a fork and started mining from #97 but at that time current block is #357

[joshua-mir]

It'd be useful to know if there are any transitions activated around that block in your chain specification as well, I'll reopen this for now

[SidhMj]

No chain specs updated. I was observing Block generation timing of 3 nodes.
force_sealing = false
reseal_max_period = 60000
in TOML
and
{ "engine": { "authorityRound": { "params": { "stepDuration": "10", "validators": { "multi": { "0": { "list": [ "0x314a298054f660d8128b78ced1087d5921fda422", "0x643bb732810421056de703cff8c321b247fda642", "0xa89cae778b61f88926ba0198f20a5410f27cf47f" ] } } } } } } }

Interestingly observed that blocks are not generated in 60 sec gap. But at a strange frequency when 3 nodes are running but when a single node is running it showing a freq. of
60 60 60 90 60 90 sec.

[MarkusTeufelberger]

Has this been fixed finally? If yes, in which commit?

[adria0]

Hi @MarkusTeufelberger, this issue is related to versions that are not supported at this moment. In the developers call we decided to close all issues related to old and unsupported versions. If this issue is still pending is that nobody had time to work on it, I suppose.

[MarkusTeufelberger]

If it hasn't been fixed since, I would expect it to be valid for the current version though, which I assume to be supported? Just seems weird to close a "P2 - ASAP" bug as "Stale"...

[adria0]

@MarkusTeufelberger, happens that a lot of errors in old versions are just fixed in later versions, so keeping a 2.2.5 bug as open adds a lot of noise when you try to figure out what are the current issues (we had like 300 issues opened with old versions).

If this bug persists in the current version I expect that someone will fill a new issue.

[igorbarinov]

This one is fixed now. We don't have it on our chains.

On Tue, Jul 28, 2020, 10:15 AM adria0.eth [e-mail] wrote:

@MarkusTeufelberger https://github.com/MarkusTeufelberger, happens that
a lot of errors in old versions are just fixed in later versions, so
keeping a 2.2.5 bug as open adds a lot of noise when you try to figure
out what are the current issues (we had like 300 issues opened with old
versions).

If this bug persists in the current version I expect that someone will
fill a new issue.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/openethereum/openethereum/issues/10085#issuecomment-664850580,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AADHVNDCHQAGIGW2PQ6WFGLR52CKNANCNFSM4GLIHSVQ
.