[permission] finalizeChange is not called when maximumEmptySteps is set

[zean00]

• Parity Ethereum version: 2.7.1
• Operating system: MacOS
• Installation: docker (from parity repo)
• Fully synchronized: -
• Network: aura (private)
• Restarted: yes

Actual

2020-02-04 12:46:45 UTC IO Worker #3 INFO engine Signal for switch to contract-based validator set. 2020-02-04 12:46:45 UTC IO Worker #3 INFO engine Initial contract validators: [0x662eb278299d1f2069a52d09f308a599a99afd39, 0x59f6566306843fb7d18f782733e19223ca5f07ab, 0xade4279d444bb1183e733dcc1adffa06b53d72d2] 2020-02-04 12:46:45 UTC IO Worker #3 INFO import Imported #7 0x6d71…8993 (0 txs, 0.00 Mgas, 3 ms, 1.30 KiB) 2020-02-04 12:47:08 UTC IO Worker #1 INFO import 2/25 peers 19 KiB chain 28 KiB db 0 bytes queue 3 KiB sync RPC: 0 conn, 1 req/s, 112 µs 2020-02-04 12:47:38 UTC IO Worker #1 INFO import 2/25 peers 19 KiB chain 28 KiB db 0 bytes queue 3 KiB sync RPC: 0 conn, 5 req/s, 69 µs 2020-02-04 12:48:08 UTC IO Worker #3 INFO import 2/25 peers 19 KiB chain 28 KiB db 0 bytes queue 3 KiB sync RPC: 0 conn, 4 req/s, 108 µs 2020-02-04 12:48:38 UTC IO Worker #2 INFO import 2/25 peers 19 KiB chain 28 KiB db 0 bytes queue 3 KiB sync RPC: 0 conn, 4 req/s, 107 µs 2020-02-04 12:49:08 UTC IO Worker #2 INFO import 2/25 peers 19 KiB chain 28 KiB db 0 bytes queue 3 KiB sync RPC: 0 conn, 1 req/s, 145 µs 2020-02-04 12:49:30 UTC IO Worker #0 INFO import Imported #8 0xad09…1e07 (0 txs, 0.00 Mgas, 0 ms, 1.30 KiB)

Expected
2020-02-04 12:55:40 UTC Verifier #1 INFO engine Signal for switch to contract-based validator set. 2020-02-04 12:55:40 UTC Verifier #1 INFO engine Initial contract validators: [0x662eb278299d1f2069a52d09f308a599a99afd39, 0x59f6566306843fb7d18f782733e19223ca5f07ab, 0xade4279d444bb1183e733dcc1adffa06b53d72d2] 2020-02-04 12:55:40 UTC Verifier #1 INFO import Imported #7 0x2040…c1b6 (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB) 2020-02-04 12:55:45 UTC IO Worker #0 INFO engine Applying validator set change signalled at block 7 2020-02-04 12:55:45 UTC IO Worker #0 INFO import Imported #8 0xa4a4…609b (0 txs, 0.00 Mgas, 6 ms, 0.57 KiB)

Step to Reproduce

genesis

    "name":"parity",
    "engine": {
       "authorityRound": {
          "params": {
            "stepDuration": "5",
            "validators" : {
                "multi": {
                    "0": {
                        "list": [ "0x662eb278299d1f2069a52d09f308a599a99afd39", "0x59f6566306843fb7d18f782733e19223ca5f07ab", "0xade4279d444bb1183e733dcc1adffa06b53d72d2" ]
                    },
                    "7": {
                        "contract" : "0x289631594ec63a592aed277Ef6Dce46937959A7e"
                    }
                }
            },
            "blockReward": "10",
            "emptyStepsTransition" : "5",
            "maximumEmptySteps": "10"
        }
    }

If maximumEmptySteps parameter is removed, message Applying validator set change signalled at block 7 will be appeared on log output.

If I set emptyStepsTransition higher than block number of validator contract supposed to activate, then finalizeChange is successfully called and message Applying validator set change signalled at block 7 will be present. But once block number reach emptyStepsTransition, any method that should trigger finalizeChange called (i.e. addValidator) will not trigger finalizeChange properly

[dvdplm]

@zean00 Is this a recent problem? Do you see the same issue with 2.6.8 for example?

[zean00]

Actually I have tested on 2.5.7 , 2.6.6, and 2.7.1 , same issue

[afck]

To clarify, does this really depend on maximumEmptySteps (seems to have default value 0), or only on emptyStepsTransition?
Are you using the POA contracts? I don't think they've ever been tested with empty steps. (Although that should work, of course.)

I'm not familiar with all the relevant code, but maximum_empty_steps seems to be used in exactly one place.
If I understand correctly, the Applying validator set message is sent later, when the block in which the event was logged (i.e. the block containing the transaction that called finalizeChange) is finalized.
So maybe finalizeChange was called, but somehow the event was not detected or something went wrong with finalization…?

[zean00]

It works fine when I remove maximumEmptySteps or set to 0, and I'm using permission contract from parity

Not sure related or not, Is it normal when maximumEmptySteps is set more than 0 that each node will have different block hash on same block number ?

** Node 1 **
2020-02-04 20:23:15 UTC IO Worker #3 INFO import Imported #7 0x4526…8b8b (0 txs, 0.00 Mgas, 3 ms, 0.65 KiB)

Node 2
2020-02-04 20:22:50 UTC Imported #7 0xa53b…8c21 (0 txs, 0.00 Mgas, 5 ms, 0.65 KiB)

Node 3
2020-02-04 20:23:25 UTC Imported #7 0xabc7…1bd7 (0 txs, 0.00 Mgas, 1 ms, 0.65 KiB)

[afck]

That's very weird… this line looks like setting maximumEmptySteps to 0 should have the same effect as not specifying it at all.

each node will have different block hash on same block number ?

That's definitely not normal; it means the nodes went out of sync… either they're rejecting each other's blocks, or disagreeing on the fork choice. Do you see any "block verification failed" messages?

[zean00]

That's very weird… this line looks like setting maximumEmptySteps to 0 should have the same effect as not specifying it at all.

Yes, that's what I meant, setting to 0 or not specifying it resulting finalizeChange called as expected.

Do you see any "block verification failed" messages?

Yes, I see block verification failed message, perhaps it's related to this issue ?

Note that this log always appear same as emptyStepsTransition block number, in this case I set emptyStepsTransition value 5 hence the verification failed at block number 5. If I set emptyStepsTransition to 0, this message will appear on block number 1, but some other nodes on block number 2

2020-02-04 22:42:40 UTC Verifier #2 WARN client Stage 5 block verification failed for #5 (0xabeb…be2c) Error: Error(Block(InvalidStateRoot(Mismatch { expected: 0xe0fecad5f5ea478d61254c121e776241039df2ac30f71d5e33aedee0537646e1, found: 0xc20fe3785f270a6738813606b3f35624021811de464873a179d5fc752f57c9b0 })), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace: 0: 0x5573732762ad - <no info> 1: 0x557373049ebc - <no info> 2: 0x557372b8dda0 - <no info> 3: 0x557372d55c26 - <no info> 4: 0x5573725f4021 - <no info> 5: 0x557372b181e9 - <no info> 6: 0x557372b0c53b - <no info> 7: 0x557372b1d9c7 - <no info> 8: 0x557372bb5ba4 - <no info> 9: 0x5573732d389e - <no info> 10: 0x5573732d63eb - <no info> 11: 0x7fb5262666b9 - <no info> 12: 0x7fb525d8641c - <no info> 13: 0x0 - <no info>) } }) 2020-02-04 22:42:40 UTC Verifier #2 ERROR client Bad block detected: Error(Block(InvalidStateRoot(Mismatch { expected: 0xe0fecad5f5ea478d61254c121e776241039df2ac30f71d5e33aedee0537646e1, found: 0xc20fe3785f270a6738813606b3f35624021811de464873a179d5fc752f57c9b0 })), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace: 0: 0x5573732762ad - <no info> 1: 0x557373049ebc - <no info> 2: 0x557372b8dda0 - <no info> 3: 0x557372d55c26 - <no info> 4: 0x5573725f4021 - <no info> 5: 0x557372b181e9 - <no info> 6: 0x557372b0c53b - <no info> 7: 0x557372b1d9c7 - <no info> 8: 0x557372bb5ba4 - <no info> 9: 0x5573732d389e - <no info> 10: 0x5573732d63eb - <no info> 11: 0x7fb5262666b9 - <no info> 12: 0x7fb525d8641c - <no info> 13: 0x0 - <no info>) } }) RLP: f90293f9028ea02a3ea2ef4e69112f8558c006bc42c5dc46c1673f3404dbeb1ad128d90513cccea01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794ade4279d444bb1183e733dcc1adffa06b53d72d2a0e0fecad5f5ea478d61254c121e776241039df2ac30f71d5e33aedee0537646e1a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffe058402625a0080845e39f35f9fde830205078f5061726974792d457468657265756d86312e33362e30826c698412d863e0b8414971e66f711f2e859e061cf43e9b11ae878f0bd5847b8db33f8ae1e2788172dd0b981869b35c294bec4f0a5cff99341f1b750217b55e2b3bcce2ce8d5ec4c5aa01f84af848b841119b51181d19fc5fbac3353a7a0a7b6b6091cf04350c94755f24bea7f502d25571e5959730793632e75db4996ef5efc4724fbe536760c2ffb1b73648866a87d6018412d863dfc0c0 2020-02-04T22:42:40.055543600Z Header: Header { parent_hash: 0x2a3ea2ef4e69112f8558c006bc42c5dc46c1673f3404dbeb1ad128d90513ccce, timestamp: 1580856159, number: 5, author: 0xade4279d444bb1183e733dcc1adffa06b53d72d2, 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: 0xe0fecad5f5ea478d61254c121e776241039df2ac30f71d5e33aedee0537646e1, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 40000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 18, 216, 99, 224], [184, 65, 73, 113, 230, 111, 113, 31, 46, 133, 158, 6, 28, 244, 62, 155, 17, 174, 135, 143, 11, 213, 132, 123, 141, 179, 63, 138, 225, 226, 120, 129, 114, 221, 11, 152, 24, 105, 179, 92, 41, 75, 236, 79, 10, 92, 255, 153, 52, 31, 27, 117, 2, 23, 181, 94, 43, 59, 204, 226, 206, 141, 94, 196, 197, 170, 1], [248, 74, 248, 72, 184, 65, 17, 155, 81, 24, 29, 25, 252, 95, 186, 195, 53, 58, 122, 10, 123, 107, 96, 145, 207, 4, 53, 12, 148, 117, 95, 36, 190, 167, 245, 2, 210, 85, 113, 229, 149, 151, 48, 121, 54, 50, 231, 93, 180, 153, 110, 245, 239, 196, 114, 79, 190, 83, 103, 96, 194, 255, 177, 183, 54, 72, 134, 106, 135, 214, 1, 132, 18, 216, 99, 223]], hash: Some(0xabeb5dad965420be2a04791d5159fe4e46c1165fdb823ca1a9deb113f495be2c) } Uncles: Transactions: 2020-02-04T22:42:40.055670500Z 2020-02-04 22:42:41 UTC IO Worker #3 INFO import 2/25 peers 13 KiB chain 5 KiB db 0 bytes queue 2 KiB sync RPC: 0 conn, 3 req/s, 147 µs 2020-02-04 22:42:50 UTC Verifier #1 WARN client Stage 5 block verification failed for #5 (0x0736…b35c) Error: Error(Block(InvalidStateRoot(Mismatch { expected: 0xab55c89b1f080c140c1d2fdb0cfb5378f18e9cf5886f2613d20976328aca1360, found: 0x508671a1b3e9fb99b3957639523485be2dc840777596b1f64197bb406d45f8d7 })), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace: 0: 0x5573732762ad - <no info> 1: 0x557373049ebc - <no info> 2: 0x557372b8dda0 - <no info> 3: 0x557372d55c26 - <no info> 4: 0x5573725f4021 - <no info> 5: 0x557372b181e9 - <no info> 6: 0x557372b0c53b - <no info> 7: 0x557372b1d9c7 - <no info> 8: 0x557372bb5ba4 - <no info> 9: 0x5573732d389e - <no info> 10: 0x5573732d63eb - <no info> 11: 0x7fb5262666b9 - <no info> 12: 0x7fb525d8641c - <no info> 13: 0x0 - <no info>) } }) 2020-02-04 22:42:50 UTC Verifier #1 ERROR client Bad block detected: Error(Block(InvalidStateRoot(Mismatch { expected: 0xab55c89b1f080c140c1d2fdb0cfb5378f18e9cf5886f2613d20976328aca1360, found: 0x508671a1b3e9fb99b3957639523485be2dc840777596b1f64197bb406d45f8d7 })), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace: 0: 0x5573732762ad - <no info> 1: 0x557373049ebc - <no info> 2: 0x557372b8dda0 - <no info> 3: 0x557372d55c26 - <no info> 4: 0x5573725f4021 - <no info> 5: 0x557372b181e9 - <no info> 6: 0x557372b0c53b - <no info> 7: 0x557372b1d9c7 - <no info> 8: 0x557372bb5ba4 - <no info> 9: 0x5573732d389e - <no info> 10: 0x5573732d63eb - <no info> 11: 0x7fb5262666b9 - <no info> 12: 0x7fb525d8641c - <no info> 13: 0x0 - <no info>) } }) RLP: f90293f9028ea02a3ea2ef4e69112f8558c006bc42c5dc46c1673f3404dbeb1ad128d90513cccea01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d493479459f6566306843fb7d18f782733e19223ca5f07aba0ab55c89b1f080c140c1d2fdb0cfb5378f18e9cf5886f2613d20976328aca1360a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffc058402625a0080845e39f36a9fde830205078f5061726974792d457468657265756d86312e33362e30826c698412d863e2b8415c42c84b36f552941dd5179cbc48a3196868ac44f5bec30a7045506663a935c467570b2004be9e139b929853e8b98dad4683b0072e408025bb5253d7f12e475000f84af848b841a62f7610b69e1133fbd38687c8e0eb0414ca88ba66f367a3d022c0cca249bf8216ccf9a2c1ccbb310e03f038005610d34231709861f4382190a7f1515d4bfdc7018412d863e1c0c0 Header: Header { parent_hash: 0x2a3ea2ef4e69112f8558c006bc42c5dc46c1673f3404dbeb1ad128d90513ccce, timestamp: 1580856170, number: 5, author: 0x59f6566306843fb7d18f782733e19223ca5f07ab, 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: 0xab55c89b1f080c140c1d2fdb0cfb5378f18e9cf5886f2613d20976328aca1360, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 40000000, difficulty: 340282366920938463463374607431768211452, seal: [[132, 18, 216, 99, 226], [184, 65, 92, 66, 200, 75, 54, 245, 82, 148, 29, 213, 23, 156, 188, 72, 163, 25, 104, 104, 172, 68, 245, 190, 195, 10, 112, 69, 80, 102, 99, 169, 53, 196, 103, 87, 11, 32, 4, 190, 158, 19, 155, 146, 152, 83, 232, 185, 141, 173, 70, 131, 176, 7, 46, 64, 128, 37, 187, 82, 83, 215, 241, 46, 71, 80, 0], [248, 74, 248, 72, 184, 65, 166, 47, 118, 16, 182, 158, 17, 51, 251, 211, 134, 135, 200, 224, 235, 4, 20, 202, 136, 186, 102, 243, 103, 163, 208, 34, 192, 204, 162, 73, 191, 130, 22, 204, 249, 162, 193, 204, 187, 49, 14, 3, 240, 56, 0, 86, 16, 211, 66, 49, 112, 152, 97, 244, 56, 33, 144, 167, 241, 81, 93, 75, 253, 199, 1, 132, 18, 216, 99, 225]], hash: Some(0x0736d148cd98bc8b9847f5dae50f78f87745928ef5b76635708331f58f26b35c) } Uncles: Transactions: 2020-02-04T22:42:50.151656200Z 2020-02-04 22:43:11 UTC IO Worker #0 INFO import 2/25 peers 13 KiB chain 5 KiB db 0 bytes queue 2 KiB sync RPC: 0 conn, 2 req/s, 194 µs 2020-02-04 22:43:15 UTC IO Worker #0 INFO import Imported #5 0x86de…7b04 (0 txs, 0.00 Mgas, 9 ms, 0.65 KiB)

[afck]

I agree, it's probably a duplicate of that issue.
Empty steps seem to be pretty broken. (I won't be able to work on this anytime soon, sorry!)

@dvdplm: I wonder whether the feature should be removed entirely? I don't know if anyone is using it in production. It's set in evantestcore.json, but I have no idea whether that's still up to date.

[dvdplm]

I wonder whether the feature should be removed entirely?

You mean removing the maximumEmptySteps setting? Or…?

[afck]

I mean removing empty steps altogether… 😬
(Just a thought; I'm just wondering whether this is currently working for anyone.)

[zean00]

Personally I wish the empty steps feature is still remain, as for private network, this is useful when the user count and transaction count is still low at very beginning to reduce block number.

[dvdplm]

@zean00 yeah, I don't think it should be removed either. :)

I started work on setting things up to repeat the problem locally but got side tracked, but then I thought I could just ask if you perhaps have a setup already you can share? A repo somewhere?

[zean00]

You could use my setup