Multi ValidatorSet not working as expected, doesn't validate new nodes but uses old contract

[S3bb1]

I'm running:

• Which Parity version?: 1.11.4
• Which operating system?: Windows / Linux
• How installed?: binaries / from source
• Are you fully synchronized?: yes
• Which network are you connected to?: private PoA network
• Did you try to restart the node?: yes

Hi there i'm currently testing the validator set multi option on AuRa ... my current workflow is

1. Deploy new OwnedSet Contract
2. Add to chain spec at a future block ( e.g.

     "multi": {
         "0": {
             "safeContract": "0x0000000000000000000000000000000000000005"
         },
         "37270": {
             "safeContract": "0x6a1c3cf62a5e5f36516f2687144445b64c9ecbdc"
         }
     }

3. restart mining nodes
4. wait until block is reached
   see the log message that a new validator contract is active
5. add new validator to contract (with initiateChange event)
   but now the new validator doesn't signs any new blocks ... instead the logs say that when emptysteps are done, the old validator set is active

signing nodes active in old contract: [0x5307…46e0, 0x4a67…a83d]
signing nodes active in new contract [0x4a67…a83d,0x00aC5...805B]

2018-06-27 10:49:27 Fetched proposer for step 510029789: 0x5307…46e0
2018-06-27 10:49:27 IO Worker TRACE engine generate_seal: 0x4a67…a83d not a proposer for step 510029789.
2018-06-27 10:49:30 IO Worker DEBUG engine Zooming to epoch for block 0x64d0…9ed4
2018-06-27 10:49:30 IO Worker TRACE engine Fetched proposer for step 510029790: 0x4a67…a83d

any ideas why for the empty steps the old validator contract is used?

[andresilva]

I haven't tested using empty steps with a validator set yet. I think what you're seeing is a bug here. I'm working on this ATM so should have a fix soon.

[S3bb1]

Cool, i will check if the problem still occurs if i setup a new chain without emtpy steps to proof that it comes from the empty step feature.

[S3bb1]

i tried it again without empty steps and the issue is the same:

at the start of the node, he tries to get the epoch set for block 0 and in the contract at block 0 the signer isn't added to the set so he turns into an endless loop

2018-06-27 20:55:33 IO Worker #3 DEBUG engine Zooming to epoch for block 0xe8e5…1e77
2018-06-27 20:55:33 IO Worker #3 TRACE engine extracting epoch set for epoch (0, 0x4cf1…99ed) signalled at #0
2018-06-27 20:55:33 IO Worker #3 TRACE engine Multi ValidatorSet retrieved for block 0.
2018-06-27 20:55:33 IO Worker #3 TRACE engine Fetched proposer for step 510041911: 0x5307…46e0
2018-06-27 20:55:33 IO Worker #3 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041911.
2018-06-27 20:55:36 IO Worker #0 DEBUG engine Zooming to epoch for block 0x6260…705d
2018-06-27 20:55:36 IO Worker #0 TRACE engine Fetched proposer for step 510041912: 0x4a67…a83d
2018-06-27 20:55:36 IO Worker #0 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041912.
2018-06-27 20:55:39 IO Worker #0 DEBUG engine Zooming to epoch for block 0x7baf…24ee
2018-06-27 20:55:39 IO Worker #0 TRACE engine Fetched proposer for step 510041913: 0x5307…46e0
2018-06-27 20:55:39 IO Worker #0 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041913.
2018-06-27 20:55:42 IO Worker #1 DEBUG engine Zooming to epoch for block 0x0aa0…d421
2018-06-27 20:55:42 IO Worker #1 TRACE engine Fetched proposer for step 510041914: 0x4a67…a83d
2018-06-27 20:55:42 IO Worker #1 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041914.
2018-06-27 20:55:45 IO Worker #2 DEBUG engine Zooming to epoch for block 0xc1c8…8615
2018-06-27 20:55:45 IO Worker #2 TRACE engine Fetched proposer for step 510041915: 0x5307…46e0
2018-06-27 20:55:45 IO Worker #2 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041915.
2018-06-27 20:55:48 IO Worker #2 DEBUG engine Zooming to epoch for block 0x7a57…3c1c
2018-06-27 20:55:48 IO Worker #2 TRACE engine Fetched proposer for step 510041916: 0x4a67…a83d
2018-06-27 20:55:48 IO Worker #2 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510041916.
2018-06-27 20:55:51 IO Worker #1 DEBUG engine Zooming to epoch for block 0x8410…b01e

[S3bb1]

Update:

when i set
"immediateTransitions": true
in the authority round params all works fine

it seems that https://github.com/paritytech/parity/blob/master/ethcore/src/engines/authority_round/mod.rs#L889
returns the wrong epoch

[andresilva]

Could you try with this branch? https://github.com/paritytech/parity/tree/andre/fix-aura-reporting

[S3bb1]

i'll give it a try, one moment please :)

[S3bb1]

doesn't seem to work. The messages appearing again:

2018-06-28 07:43:30 IO Worker #2 DEBUG engine Zooming to epoch for block 0xacaf…239d
2018-06-28 07:43:30 IO Worker #2 TRACE engine Fetched proposer for step 510054870: 0x4a67…a83d
2018-06-28 07:43:30 IO Worker #2 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510054870.
2018-06-28 07:43:33 IO Worker #2 DEBUG engine Zooming to epoch for block 0x99de…7151
2018-06-28 07:43:33 IO Worker #2 TRACE engine Fetched proposer for step 510054871: 0x5307…46e0
2018-06-28 07:43:33 IO Worker #2 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510054871.
2018-06-28 07:43:36 IO Worker #3 DEBUG engine Zooming to epoch for block 0xd6ee…945a
2018-06-28 07:43:36 IO Worker #3 TRACE engine Fetched proposer for step 510054872: 0x4a67…a83d

but not for every transaction the following lines appear:
2018-06-28 07:42:25 Verifier #2 TRACE engine Multi ValidatorSet retrieved for block 37270.
2018-06-28 07:42:25 Verifier #2 DEBUG engine Zooming to epoch for block 0x037e…4f9a
2018-06-28 07:42:25 Verifier #2 DEBUG engine inconsistent validator set within epoch
2018-06-28 07:42:25 Verifier #2 TRACE client Pruning state for ancient era 30721
2018-06-28 07:42:25 Verifier #2 INFO own_tx Transaction mined (hash 0x78985b4f4fa2b3068d5f03d4f52f1580e8dd2b1f1f86a8047f602b7919a1a3ab)

[andresilva]

What you show in the logs of the authority constantly trying to seal a new block and then issuing:

TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510054871.

It's normal, it's just the way the engine works. Could you explain to me the steps you take to replicate this? I just tried to replicate this and couldn't, here's what I did:

• Start with multiset contract pointing to a contract defined in genesis and activated at block 0.
• The contract only has one authority (A0)
• Deploy a new contract, with another authority as validator (A1)
• Update spec to set multiset contract to activate new contract at a future block
  • Important: this must be a future block, you cannot change the history, e.g. we're at block 200 and we decide to set a new contract in multiset for block 150.
• Restart all nodes
• Wait for the transition to the new contract to trigger at the configured block
• A1 is now sealing blocks

[S3bb1]

i will test it again today :) thx for the solutions

[S3bb1]

Hi, tried it again ... fresh chain

Spec: https://gist.github.com/S3bb1/e4d2e4689edd18b314b13ee64fc120f4
ValidatorContract: https://gist.github.com/S3bb1/cbfbc206b5a1d218a88b80ab144d7fd3

First now with a list (to exclude issues with the contract at block 0) ...

• Deploy the validatorset contract with initial accounts [0x4a6723fc5a926fa150baeaf04bfd673b056ba83d, 0x00ac5b6bd71f7bae99d40a5f1b1ad0b12296805b]
• add it to the spec at block 20
• Now make transactions with account 0x4a6723fc5a926fa150baeaf04bfd673b056ba83d until block 20
• account 0x4a6723fc5a926fa150baeaf04bfd673b056ba83d signs all the transactions

Got the following log messages:

2018-07-02 20:03:36 IO Worker #0 TRACE engine Multi ValidatorSet retrieved for block 20.
2018-07-02 20:03:36 IO Worker #0 DEBUG engine signalling transition to fresh contract.
2018-07-02 20:03:36 IO Worker #0 TRACE engine obtained proof for initial set: 2 validators, 6505 bytes
2018-07-02 20:03:36 IO Worker #0 INFO engine Signal for switch to contract-based validator set.
2018-07-02 20:03:36 IO Worker #0 INFO engine Initial contract validators: [0x4a6723fc5a926fa150baeaf04bfd673b056ba83d, 0x00ac5b6bd71f7bae99d40a5f1b1ad0b12296805b]
2018-07-02 20:03:36 IO Worker #0 TRACE engine Multi ValidatorSet retrieved for block 20.
2018-07-02 20:03:36 IO Worker #0 INFO own_tx Transaction mined (hash 0x16519b4613ee75092124c9c1ab30538899f35f7deaaed88c27e83d9beab2549f)
2018-07-02 20:03:36 IO Worker #0 INFO own_tx Transaction mined (hash 0xc69ccc11e4c0946910165c523afa32f5a93d06c017a12332ef615f6398c25ce5)
2018-07-02 20:03:36 IO Worker #0 INFO import Imported #20 0x05ed…76d9 (2 txs, 0.04 Mgas, 28 ms, 0.79 KiB)
2018-07-02 20:03:38 TRACE engine Aborting seal generation. Can't propose.

• Now start the signer with the account 0x00ac5b6bd71f7bae99d40a5f1b1ad0b12296805b as engine_signer
• create a new transaction

Now the following logmessages appear:

2018-07-02 20:04:54 IO Worker #1 DEBUG engine Zooming to epoch for block 0x9b50…7781
2018-07-02 20:04:54 IO Worker #1 TRACE engine extracting epoch set for epoch (0, 0xe619…e340) signalled at #0
2018-07-02 20:04:54 IO Worker #1 TRACE engine Multi ValidatorSet retrieved for block 0.
2018-07-02 20:04:54 IO Worker #1 TRACE engine Fetched proposer for step 510184898: 0x4a67…a83d
2018-07-02 20:04:54 IO Worker #1 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184898.
2018-07-02 20:04:57 IO Worker #1 DEBUG engine Zooming to epoch for block 0xd889…8c88
2018-07-02 20:04:57 IO Worker #1 TRACE engine Fetched proposer for step 510184899: 0x5307…46e0
2018-07-02 20:04:57 IO Worker #1 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184899.
2018-07-02 20:05:00 IO Worker #1 DEBUG engine Zooming to epoch for block 0xae88…7326
2018-07-02 20:05:00 IO Worker #1 TRACE engine Fetched proposer for step 510184900: 0x4a67…a83d
2018-07-02 20:05:00 IO Worker #1 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184900.
2018-07-02 20:05:03 IO Worker #0 DEBUG engine Zooming to epoch for block 0xab57…75ec
2018-07-02 20:05:03 IO Worker #0 TRACE engine Fetched proposer for step 510184901: 0x5307…46e0
2018-07-02 20:05:03 IO Worker #0 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184901.
2018-07-02 20:05:06 IO Worker #0 DEBUG engine Zooming to epoch for block 0x5bbf…b92b
2018-07-02 20:05:06 IO Worker #0 TRACE engine Fetched proposer for step 510184902: 0x4a67…a83d
2018-07-02 20:05:06 IO Worker #0 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184902.
2018-07-02 20:05:09 IO Worker #3 DEBUG engine Zooming to epoch for block 0x63a9…f48c
2018-07-02 20:05:09 IO Worker #3 TRACE engine Fetched proposer for step 510184903: 0x5307…46e0
2018-07-02 20:05:09 IO Worker #3 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184903.
2018-07-02 20:05:12 IO Worker #0 DEBUG engine Zooming to epoch for block 0xac3f…dacf
2018-07-02 20:05:12 IO Worker #0 TRACE engine Fetched proposer for step 510184904: 0x4a67…a83d
2018-07-02 20:05:12 IO Worker #0 TRACE engine generate_seal: 0x00ac…805b not a proposer for step 510184904.

What am i doing wrong O_o

[andresilva]

The contract you're using is an older version and it's deprecated. Could you test this one instead: https://github.com/parity-contracts/kovan-validator-set
You want to use the OwnedSet from there.

[S3bb1]

Same result with this contract. The Contract isn't finalized when created so i can't add new validators too

[andresilva]

Are both validators online and sealing blocks? You need signatures from >50% validators to finalize a block, which when using 2 validators means that both validators need to sign.

[S3bb1]

This was the trick!

Now it works like a charm!

I get this log message now which never appears before and after 1 additional block the validatorset is finalized.

2018-07-02 21:25:27 Applying validator set change signalled at block 18

many thanks and kudos to your patience!

[andresilva]

Cheers 👍