BABE: vrf verification fails

[ordian]

The collating_using_undying_collator started to fail spuriously on master:

2022-11-21 13:27:12 [//Bob] Evicting failed runtime instance error=Runtime panicked: assertion failed: pubkey.vrf_verify(transcript.clone(), vrf_output, vrf_proof).is_ok()
2022-11-21 13:27:12 [//Bob] Proposing failed: Import failed: Error at calling runtime api: Execution failed: Runtime panicked: assertion failed: pubkey.vrf_verify(transcript.clone(), vrf_output, vrf_proof).is_ok() 
thread 'tokio-runtime-worker' panicked at 'assertion failed: pubkey.vrf_verify(transcript.clone(), vrf_output, vrf_proof).is_ok()', /usr/local/cargo/git/checkouts/substrate-7e08433d4c370a21/a73a35e/frame/babe/src/lib.rs:378:29

Example job: https://gitlab.parity.io/parity/mirrors/polkadot/-/jobs/2068264

Looks like after paritytech/polkadot#6127 (comment) more often than before.

This could be a legitimate issue and needs further investigation.

[bkchr]

This is going into Substrate. We also have seen this in Cumulus and I also have reports of this failing on normal Substrate nodes. Something is going on that isn't good here.

[bkchr]

In Cumulus this can be reproduced by running the following command:

while RUSTFLAGS="-Cdebug-assertions=y" cargo test --release -p cumulus-test-service -- --ignored test_migrate_solo_to_para; do true; done

(as the while already indicates, it takes some runs to happen)

[michalkucharczyk]

VRF verification sometimes fails with this substrate warp sync zombienet network:
#12751 (at 4850ad2).

2022-11-21 14:24:33 💔 Verification failed for block 0x4fcee0198698a2ef2c28719ee35b3262704e1ac8bef3aedc85ffaba6055c94ea received from peer: 12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, "VRF verification failed: EquationFalse"   

Command to run (should be run from substrate dir, zombienet 1.3.18+ is needed):

cd substrate/
zombienet-linux test --provider podman zombienet/0001-basic-warp-sync/0001-test-warp-sync.zndsl

Interestingly changing charlie's config from db_snapshot to --sync full "hides" the problem.

[bkchr]

BTW, as far as I have seen, there was no update of any direct dependencies related to schnorrkel recently. (Looked into Cargo.lock for this)

[koute]

Using the reproduction invocation posted by @bkchr I've whipped up a crappy script to launch a bunch of invocations in parallel and check if any of them fail.

It looks like the chance for this to reproduce is roughly ~10%, and every time it takes roughly ~90 seconds for the problem to appear (based on 160 total test runs, 5 serial runs of 32 parallel runs).

Here's the script in case anyone wants to try themselves:

#!/usr/bin/ruby

$running = true
$children = {}
$counter = 0

trap("SIGINT") do
    $running = false
end

def logs_for nth
    "/tmp/r_%02i.txt" % [ nth ]
end

def launch
    nth = $counter
    $counter += 1

    pid = fork do
        logs = logs_for nth
        exec "RUSTFLAGS='-Cdebug-assertions=y' cargo test --release -p cumulus-test-service -- --ignored test_migrate_solo_to_para &> #{logs}"
        # exec "/local/cpp/cumulus/target/release/deps/migrate_solo_to_para-6b0b8c9fbc7bb58c --ignored &> #{logs}"
    end
    puts "#{Time.now}: Launched child \##{nth}: #{pid}"
    $children[nth] = pid
end

COUNT = 32
# COUNT = 1
COUNT.times { |nth| launch }

while $running && !$children.empty?
    sleep 0.2
    $children.each do |nth, pid|
        begin
            Process.kill 0, pid
            rescue Errno::ESRCH
                puts "#{Time.now}: Child finished: \##{nth} (PID #{pid})"
                $children.delete nth

                if $?.exitstatus != 0
                    puts "#{Time.now}: REPRODUCED! (exit status, Job \##{nth}, PID #{pid})"
                    $running = false
                end
                next
        end

        path = logs_for nth
        data = File.read( path )
        if data.include? "assertion failed: pubkey.vrf_verify"
            puts "#{Time.now}: REPRODUCED! (assert failed, Job \##{nth}, PID #{pid})"
            $running = false
            next
        elsif data.include? "test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out"
            puts "#{Time.now}: Finished OK (Job \##{nth}, PID #{pid})"
            $children.delete nth
        end
    end
end

$children.each do |_, pid|
    Process.kill "INT", pid
end

Copy to the root of cumulus; modify the COUNT = 32 line to change how many reproductions are launched in parallel. The logs are saved to /tmp.

[burdges]

It's 10% of runs fail after 90 sec? The other runs do not fail? 90 sec is 15 blocks? Or much much more?

15 is considerably larger than the gap between primary and secondary slots, unless the primary slots were slowed down to make it more like aura? Trying a ! predigest.is_primary() check in https://github.com/paritytech/substrate/blob/master/frame/babe/src/lib.rs#L380 would tell you that its only primary VRFs failing.

[koute]

It's 10% of runs fail after 90 sec? The other runs do not fail? 90 sec is 15 blocks? Or much much more?

It seems to fail right after 10th block is imported.

Yes, other runs do not fail.

I printed out all of the arguments to the vrf_verify from a failing test; here they are:

2022-11-22 00:45:00 [//Alice] Evicting failed runtime instance error=Runtime panicked: XXX: assertion failed: pubkey.vrf_verify:
key=#PublicKey( RistrettoPoint( CompressedRistretto: [212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125] ) )
randomness=[2, 232, 2, 244, 166, 226, 138, 102, 132, 237, 9, 130, 42, 88, 216, 122, 74, 210, 211, 143, 83, 217, 31, 210, 129, 101, 20, 125, 168, 0, 36, 78]
slot=Slot(278174250)
epoch_index=#2
vrf_output=#VRFOutput(VRFOutput([156, 34, 168, 123, 10, 12, 27, 135, 196, 209, 164, 241, 244, 244, 41, 150, 104, 157, 3, 251, 173, 204, 214, 251, 166, 62, 134, 38, 32, 151, 184, 27]))
vrf_proof=#VRFProof(VRFProof { c: Scalar{bytes: [148, 32, 50, 76, 180, 35, 209, 103, 127, 47, 5, 207, 165, 127, 123, 207, 211, 3, 72, 158, 169, 54, 64, 111, 215, 22, 12, 115, 34, 46, 78, 11],}, s: Scalar{bytes: [42, 49, 167, 228, 80, 197, 54, 112, 39, 241, 239, 90, 86, 217, 53, 154, 77, 127, 140, 52, 107, 109, 230, 36, 137, 170, 71, 204, 98, 62, 12, 14],} })
-> out=#Err(EquationFalse)

2022-11-22 00:45:00 [//Bob] Evicting failed runtime instance error=Runtime panicked: XXX: assertion failed: pubkey.vrf_verify:
key=#PublicKey( RistrettoPoint( CompressedRistretto: [142, 175, 4, 21, 22, 135, 115, 99, 38, 201, 254, 161, 126, 37, 252, 82, 135, 97, 54, 147, 201, 18, 144, 156, 178, 38, 170, 71, 148, 242, 106, 72] ) )
randomness=[2, 232, 2, 244, 166, 226, 138, 102, 132, 237, 9, 130, 42, 88, 216, 122, 74, 210, 211, 143, 83, 217, 31, 210, 129, 101, 20, 125, 168, 0, 36, 78]
slot=Slot(278174250)
epoch_index=#2
vrf_output=#VRFOutput(VRFOutput([94, 177, 179, 20, 198, 243, 118, 222, 39, 243, 135, 227, 104, 94, 214, 113, 133, 10, 247, 152, 171, 182, 41, 85, 38, 158, 129, 29, 69, 8, 235, 26]))
vrf_proof=#VRFProof(VRFProof { c: Scalar{bytes: [167, 116, 132, 118, 94, 166, 126, 66, 252, 255, 177, 52, 0, 86, 116, 49, 97, 137, 125, 151, 121, 166, 235, 249, 165, 14, 244, 51, 11, 81, 141, 3],}, s: Scalar{bytes: [143, 225, 86, 22, 151, 17, 93, 156, 112, 43, 99, 114, 11, 143, 156, 231, 28, 110, 182, 102, 236, 6, 236, 149, 155, 85, 157, 185, 77, 173, 63, 0],} })
-> out=#Err(EquationFalse)

[koute]

So it looks like it's basically failing at the first block of a new epoch:

2022-11-22 00:44:30 [//Bob] 👶 Next epoch starts at slot 278174250

(Same slot as was passed to the failing vrf_verify.)

[koute]

Looks like there's something wrong on the block producer here; this isn't an issue where an imported block fails verification, this fails on the block producer itself. (Although when compiled without debug assertions it'll most likely fail when that block is imported on another node, which is most likely what @michalkucharczyk seen in his reproduction.)

[koute]

We already figured out the problem, but for posterity's sake let me just summarize the issue and paste most of the relevant info I wrote in the Element chat just so that it doesn't get lost forever.

This fails on the block producer right at the epoch boundary. When claiming a slot on the client (primary or secondary, doesn't matter) to build a block in BABE it picks the wrong epoch, which means the randomness is wrong, which means the VRF's wrong, which results in the debug assertion failing inside of FRAME where the correct epoch index was picked (hence there the randomness is correct). This only fails in FRAME when debug assertions are enabled; without them AFAIK the bad block would just get built and then later fail when another node would try to import it and verify the VRF on import.

The reason why it picks the wrong epoch is due to a bug in the pruning of the fork tree. (See the PR which fixes the issue to see exactly where and why.)

---

Looks like when it fails the node which fails picks the epoch descriptor for the previous epoch:

2022-11-22 13:56:01 [//Alice] 👶 New epoch 1 launching at block 0x42c0…7fc6 (block slot 278182160 >= start slot 278182160, src = NetworkBroadcast).
2022-11-22 13:56:01 [//Alice] 👶 Next epoch starts at slot 278182165
2022-11-22 13:56:01 [//Bob] 👶 New epoch 1 launching at block 0xccb7…d57e (block slot 278182160 >= start slot 278182160, src = NetworkBroadcast).
2022-11-22 13:56:01 [//Bob] 👶 Next epoch starts at slot 278182165

2022-11-22 13:56:30 [//Bob] 👶 New epoch 2 launching at block 0xc2f8…112f (block slot 278182165 >= start slot 278182165, src = Own).
2022-11-22 13:56:30 [//Bob] 👶 Next epoch starts at slot 278182170
2022-11-22 13:56:30 [//Bob] XXX: Attempting to claim slot 278182165 with: epoch_descriptor=Signaled(EpochIdentifier { position: Regular, hash: 0xccb772b6ffb23ca137a18ee3ceb75c120cab426be6e0db225721ef6fb8abd57e, number: 6 }, EpochHeader { start_slot: Slot(278182165), end_slot: Slot(278182170) })
2022-11-22 13:56:30 [//Alice] XXX: Attempting to claim slot 278182165 with: epoch_descriptor=Signaled(EpochIdentifier { position: Genesis1, hash: 0x46cbfa68979cd3c45cc3997cef55bffe2526aeb1c382b156b11201176ed691d6, number: 1 }, EpochHeader { start_slot: Slot(278182160), end_slot: Slot(278182165) })
2022-11-22 13:56:30 [//Alice] Evicting failed runtime instance error=Runtime panicked: XXX: assertion failed: pubkey.vrf_verify

Here's a different reproduction where within the same reproduction Alice produced a block and Bob failed:

Fork tree of Alice:

inner: ForkTree {
    roots: [
        Node {
            hash: 0x4b5fbe4c2f20b796096a0396c29b3669d9d10f79e0cc2634b922165e644de4ba,
            number: 1,
            data: Genesis(
                EpochHeader {
                    start_slot: Slot(
                        278183811,
                    ),
                    end_slot: Slot(
                        278183816,
                    ),
                },
                EpochHeader {
                    start_slot: Slot(
                        278183816,
                    ),
                    end_slot: Slot(
                        278183821,
                    ),
                },
            ),
            children: [
                Node {
                    hash: 0x9862372020c3a0f7a974a16cdabb28c6f5a9f5931505a63fbca52bfc4936b3ab,
                    number: 6,
                    data: Regular(
                        EpochHeader {
                            start_slot: Slot(
                                278183821,
                            ),
                            end_slot: Slot(
                                278183826,
                            ),
                        },
                    ),
                    children: [],
                },
            ],
        },
    ],
    best_finalized_number: None,
},

Fork tree of Bob:

inner: ForkTree {
    roots: [
        Node {
            hash: 0x4b5fbe4c2f20b796096a0396c29b3669d9d10f79e0cc2634b922165e644de4ba,
            number: 1,
            data: Genesis(
                EpochHeader {
                    start_slot: Slot(
                        278183811,
                    ),
                    end_slot: Slot(
                        278183816,
                    ),
                },
                EpochHeader {
                    start_slot: Slot(
                        278183816,
                    ),
                    end_slot: Slot(
                        278183821,
                    ),
                },
            ),
            children: [
                Node {
                    hash: 0x85e1a8f436aabef4f4aebac1f71b8d6b2ef64879d4ec9ee9061fb9a3fa5edb3c,
                    number: 6,
                    data: Regular(
                        EpochHeader {
                            start_slot: Slot(
                                278183821,
                            ),
                            end_slot: Slot(
                                278183826,
                            ),
                        },
                    ),
                    children: [],
                },
            ],
        },
    ],
    best_finalized_number: None,
},

Notice the hash of the node in children. On Alice it's 0x9862... and on Bob it's 0x85e1.

Here's Alice searching for the epoch: (hashes simplified for readability)

2022-11-22 16:42:06 [//Alice] XXX: aux_data: parent=Header { parent_hash: 0xd072..., number: 10
2022-11-22 16:42:06 [//Alice] XXX: is_descendent_of: current=Some((FAKE_HEAD, 0xd4d0...)) base=0x9862... hash=FAKE_HEAD
2022-11-22 16:42:06 [//Alice] XXX: is_descendent_of: true ancestor=HashAndNumber { number: 6, hash: 0x9862... }
2022-11-22 16:42:06 [//Alice] XXX: aux_data: result=Ok(Signaled(EpochIdentifier { position: Regular, hash: 0x9862..., number: 6 }, EpochHeader { start_slot: Slot(278183821), end_slot: Slot(278183826) }))

And here's the same for Bob:

2022-11-22 16:42:06 [//Bob] XXX: aux_data: parent=Header { parent_hash: 0xd072..., number: 10
2022-11-22 16:42:06 [//Bob] XXX: is_descendent_of: current=Some((FAKE_HEAD, 0xd4d0...)) base=0x85e1... hash=FAKE_HEAD
2022-11-22 16:42:06 [//Bob] XXX: is_descendent_of: false ancestor=HashAndNumber { number: 5, hash: 0xe0cc... }
2022-11-22 16:42:06 [//Bob] XXX: is_descendent_of: current=Some((FAKE_HEAD, 0xd4d0...)) base=0x4b5f... hash=FAKE_HEAD
2022-11-22 16:42:06 [//Bob] XXX: is_descendent_of: true ancestor=HashAndNumber { number: 1, hash: 0x4b5f... }
2022-11-22 16:42:06 [//Bob] XXX: aux_data: result=Ok(Signaled(EpochIdentifier { position: Genesis1, hash: 0x4b5f...., number: 1 }, EpochHeader { start_slot: Slot(278183816), end_slot: Slot(278183821) }))

So is_descendent_of is first called with base equal to the hash of the node in children from the fork tree. That calls sp_blockchain::lowest_common_ancestor with one hash being the fake head and the other hash being the base.

On Alice this returns block 6 (0x9862) which is equal to the base hash (0x9862), so is_descendent_of returns true, so epoch from that block (epoch 2) is picked.

On Bob this returns block 5 (0xe0cc) which is not equal to the base hash (0x85e1), so is_descendent_of return false, so it tries to go deeper into the tree and only picks epoch 1 for block production.

2022-11-22 16:41:36 [//Bob] 🔖 Pre-sealed block for proposal at 6. Hash now 0x9862
2022-11-22 16:41:36 [//Bob] 👶 New epoch 1 launching at block 0x9862…b3ab
2022-11-22 16:41:37 [//Bob] ✨ Imported #6 (0x9862…b3ab)
2022-11-22 16:41:37 [//Bob] 👶 New epoch 1 launching at block 0x85e1…db3c
2022-11-22 16:41:39 [//Bob] ✨ Imported #6 (0x85e1…db3c)
2022-11-22 16:41:40 [//Bob] 💤 Idle (3 peers), best: #6 (0x9862…b3ab), finalized #3 (0xe44e…8d1b), ⬇ 1.0kiB/s ⬆ 1.6kiB/s
2022-11-22 16:41:42 [//Bob] 🙌 Starting consensus session on top of parent 0x9862

2022-11-22 16:41:36 [//Alice] 🔖 Pre-sealed block for proposal at 6. Hash now 0x85e1
2022-11-22 16:41:36 [//Alice] 👶 New epoch 1 launching at block 0x85e1…db3c
2022-11-22 16:41:37 [//Alice] ✨ Imported #6 (0x85e1…db3c)
2022-11-22 16:41:37 [//Alice] 👶 New epoch 1 launching at block 0x9862…b3ab
2022-11-22 16:41:39 [//Alice] ♻️  Reorg on #6,0x85e1…db3c to #6,0x9862…b3ab, common ancestor #5,0xe0cc…57e8
2022-11-22 16:41:39 [//Alice] ✨ Imported #6 (0x9862…b3ab)
2022-11-22 16:41:53 [//Alice] 💤 Idle (3 peers), best: #8 (0x9313…c66a), finalized #6 (0x9862…b3ab), ⬇ 1.4kiB/s ⬆ 1.2kiB/s

So it looks like 0x85e1 was built by Alice while 0x9862 was built by Bob, and they both imported both of these blocks, but 0x9862 got finalized.

Here's how the full tree of blocks looks like with block numbers and block hashes:

0 5e8f (genesis)
└ 1 4b5f (epoch 0)
  └ 2 315c (epoch 0)
     └ 3 e44e (epoch 0)
       └ 4 ffaa (epoch 0)
         └ 5 e0cc (epoch 0)
           ├ 6 9862 (epoch 1)
           | └ 7 9efe (epoch 1)
           |   └ 8 9313 (epoch 1)
           |     └ 9 d072 (epoch 1)
           |       └ 10 d4d0 (epoch 1)
           |         └ 11 ae3c (epoch 2)
           └ 6 85e1 (epoch 1)

And finally here's the sequence of calls that gets called on the fork tree which results in the wrong thing being pruned (different reproduction so the hashes are different):

2022-11-22 20:38:52 [//Bob] XXX: epoch_changes: rebalance    
2022-11-22 20:38:52 [//Bob] XXX: epoch_changes: prune_finalized: hash=0x5e8f0b6d60b48da41007e493f4b78e1a549bdca634131b7c39baa6c5c60bcb0e number=0 slot=Slot(0)    
2022-11-22 20:38:55 [//Bob] XXX: epoch_changes: prune_finalized: hash=0x5e8f0b6d60b48da41007e493f4b78e1a549bdca634131b7c39baa6c5c60bcb0e number=0 slot=Slot(0)    
2022-11-22 20:38:56 [//Bob] XXX: epoch_changes: import: hash=0xebc98b3226f50a4bbed366bd7d66a116eb933b1d0a5c40dbd33f4b83dd9598be number=1 parent_hash=0x5e8f0b6d60b48da41007e493f4b78e1a549bdca634131b7c39baa6c5c60bcb0e epoch=IncrementedEpoch(Genesis(Epoch { epoch_index: 0, start_slot: Slot(278186189), duration: 5, authorities: [(Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1), (Public(8eaf04151687736326c9fea17e25fc5287613693c912909cb226aa4794f26a48 (5FHneW46...)), 1)], randomness: [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, 0], config: BabeEpochConfiguration { c: (1, 4), allowed_slots: AllowedSlots::PrimaryAndSecondaryVRFSlots } }, Epoch { epoch_index: 1, start_slot: Slot(278186194), duration: 5, authorities: [(Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1), (Public(8eaf04151687736326c9fea17e25fc5287613693c912909cb226aa4794f26a48 (5FHneW46...)), 1)], randomness: [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, 0], config: BabeEpochConfiguration { c: (1, 4), allowed_slots: AllowedSlots::PrimaryAndSecondaryVRFSlots } }))    
2022-11-22 20:39:24 [//Bob] XXX: epoch_changes: prune_finalized: hash=0x5c53e2839e55131ec24a6b447546a9674591a58a8ddaa076293eec9d045564cb number=3 slot=Slot(278186191)    
2022-11-22 20:39:25 [//Bob] XXX: epoch_changes: import: hash=0x3160db38092ed5d82940b7f15a26f1c73770f14dfd63f619120ca7b585f294a1 number=6 parent_hash=0x40991791639b090113ea9d7e893043e0a6cb7e55f362c6b877b1a6a0907457ed epoch=IncrementedEpoch(Regular(Epoch { epoch_index: 2, start_slot: Slot(278186199), duration: 5, authorities: [(Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1), (Public(8eaf04151687736326c9fea17e25fc5287613693c912909cb226aa4794f26a48 (5FHneW46...)), 1)], randomness: [2, 232, 2, 244, 166, 226, 138, 102, 132, 237, 9, 130, 42, 88, 216, 122, 74, 210, 211, 143, 83, 217, 31, 210, 129, 101, 20, 125, 168, 0, 36, 78], config: BabeEpochConfiguration { c: (1, 4), allowed_slots: AllowedSlots::PrimaryAndSecondaryVRFSlots } }))    
2022-11-22 20:39:26 [//Bob] XXX: epoch_changes: prune_finalized: hash=0x5c53e2839e55131ec24a6b447546a9674591a58a8ddaa076293eec9d045564cb number=3 slot=Slot(278186191)    
2022-11-22 20:39:26 [//Bob] XXX: epoch_changes: import: hash=0x46b9293899d277b7331d396470003ec12e9de064c5087f6460ab57cb79bd59f1 number=6 parent_hash=0x40991791639b090113ea9d7e893043e0a6cb7e55f362c6b877b1a6a0907457ed epoch=IncrementedEpoch(Regular(Epoch { epoch_index: 2, start_slot: Slot(278186199), duration: 5, authorities: [(Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1), (Public(8eaf04151687736326c9fea17e25fc5287613693c912909cb226aa4794f26a48 (5FHneW46...)), 1)], randomness: [2, 232, 2, 244, 166, 226, 138, 102, 132, 237, 9, 130, 42, 88, 216, 122, 74, 210, 211, 143, 83, 217, 31, 210, 129, 101, 20, 125, 168, 0, 36, 78], config: BabeEpochConfiguration { c: (1, 4), allowed_slots: AllowedSlots::PrimaryAndSecondaryVRFSlots } }))