Parachain nodes stall syncing after async backing uprgade

[seunlanlege]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

We upgraded Hyperbridge on Paseo to async-backing with 6s block times. The upgrade was enacted by the relay chain at block 50991. We did experience our collator stalling, but luckily it continued with block production after a restart. Unfortunately this isn't working for new nodes which join the network. They all stall at the async backing block (telemetry). I've attached logs from syncing a new node from scratch with sync=trace. Polkadot-sdk version is v1.6.0

2024-05-15 10:23:00.228 TRACE tokio-runtime-worker sync: Too many blocks in the queue.
2024-05-15 10:23:00.228 TRACE tokio-runtime-worker sync: Block announcement validated successfully: from 12D3KooWLzDAxCxXBKqq6YAfdK7yYyAbETymkFt5y153ETJ62xxs: AnnouncementSummary { block_hash: 0xc34bb2bda1dd260279f74ac61ab6fd9588754dc196d6b09a5d1061f9675cec19, number: 120641, parent_hash: 0xc3256d1f75a5b94b1ea420d21bbeed023e2a3132dce82ab1542359fadc6eddd9, state: Some(Best) }. Local best: true.
2024-05-15 10:23:00.228 TRACE tokio-runtime-worker sync: Too many blocks in the queue.
2024-05-15 10:23:00.261 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50979) (0xc259…8b97)
2024-05-15 10:23:00.261 TRACE tokio-runtime-worker sync::import-queue: Header 0x4125…1287 has 4 logs
2024-05-15 10:23:00.263 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50980) (0x4125…1287)
2024-05-15 10:23:00.263 TRACE tokio-runtime-worker sync::import-queue: Header 0x3c4b…3169 has 4 logs
2024-05-15 10:23:00.264 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50981) (0x3c4b…3169)
2024-05-15 10:23:00.264 TRACE tokio-runtime-worker sync::import-queue: Header 0x2c4d…6054 has 4 logs
2024-05-15 10:23:00.266 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50982) (0x2c4d…6054)
2024-05-15 10:23:00.266 TRACE tokio-runtime-worker sync::import-queue: Header 0xc1dc…d2eb has 4 logs
2024-05-15 10:23:00.267 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50983) (0xc1dc…d2eb)
2024-05-15 10:23:00.267 TRACE tokio-runtime-worker sync::import-queue: Header 0xd401…b034 has 4 logs
2024-05-15 10:23:00.268 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50984) (0xd401…b034)
2024-05-15 10:23:00.268 TRACE tokio-runtime-worker sync::import-queue: Header 0x7292…668f has 4 logs
2024-05-15 10:23:00.270 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50985) (0x7292…668f)
2024-05-15 10:23:00.270 TRACE tokio-runtime-worker sync::import-queue: Header 0xf7b5…5aa6 has 4 logs
2024-05-15 10:23:00.429 DEBUG tokio-runtime-worker sync: Pre-validating received block announcement 0xc34bb2bda1dd260279f74ac61ab6fd9588754dc196d6b09a5d1061f9675cec19 with number 120641 from 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V
2024-05-15 10:23:00.429 TRACE tokio-runtime-worker sync: Too many blocks in the queue.
2024-05-15 10:23:00.429 TRACE tokio-runtime-worker sync: Block announcement validated successfully: from 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V: AnnouncementSummary { block_hash: 0xc34bb2bda1dd260279f74ac61ab6fd9588754dc196d6b09a5d1061f9675cec19, number: 120641, parent_hash: 0xc3256d1f75a5b94b1ea420d21bbeed023e2a3132dce82ab1542359fadc6eddd9, state: Some(Best) }. Local best: true.
2024-05-15 10:23:00.429 TRACE tokio-runtime-worker sync: Too many blocks in the queue.
2024-05-15 10:23:00.450 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50986) (0xf7b5…5aa6)
2024-05-15 10:23:00.450 TRACE tokio-runtime-worker sync::import-queue: Header 0x328c…96bc has 4 logs
2024-05-15 10:23:00.452 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50987) (0x328c…96bc)
2024-05-15 10:23:00.452 TRACE tokio-runtime-worker sync::import-queue: Header 0xc3e3…95cb has 4 logs
2024-05-15 10:23:00.454 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50988) (0xc3e3…95cb)
2024-05-15 10:23:00.454 TRACE tokio-runtime-worker sync::import-queue: Header 0x0855…7f3d has 4 logs
2024-05-15 10:23:00.505 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50989) (0x0855…7f3d)
2024-05-15 10:23:00.505 TRACE tokio-runtime-worker sync::import-queue: Header 0xbfd9…5cad has 4 logs
2024-05-15 10:23:00.506 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50990) (0xbfd9…5cad)
2024-05-15 10:23:00.506 TRACE tokio-runtime-worker sync::import-queue: Header 0xf203…0779 has 5 logs
2024-05-15 10:23:00.516 TRACE tokio-runtime-worker sync::import-queue: Block imported successfully Some(50991) (0xf203…0779)
2024-05-15 10:23:00.516 TRACE tokio-runtime-worker sync::import-queue: Header 0xbaef…155b has 4 logs
2024-05-15 10:23:00.962 TRACE tokio-runtime-worker sync: Too many blocks in the queue.
2024-05-15 10:23:01.267 TRACE tokio-runtime-worker sync::import-queue: Verifying 50992(0xbaef…155b) from 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V failed: Rejecting block (0xbaef56c1bcdf55d941cb5055b19117ff42a0c4d1d83775ac7f8ff599539a155b) from future slot Slot(285891336)
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync::import-queue: Starting import of 64 blocks  (52037..52100)
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync::import-queue: Header 0xad15…8fb9 has 4 logs
2024-05-15 10:23:01.278 DEBUG tokio-runtime-worker sync::import-queue: Block with unknown parent 52037: 0xad15455506f62893ff46dc74e81c837580135805efa644b5e194de1580288fb9, parent: 0x08ef067141f898eb9db0ca172c792b23a3569e4ff00ee39500fbed0dee9819e9
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Imported 811 of 1856
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50181 to 50245
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50245 to 50309
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50309 to 50373
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50373 to 50437
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50437 to 50501
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50501 to 50565
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50565 to 50629
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50629 to 50693
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50693 to 50757
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50757 to 50821
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50821 to 50885
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50885 to 50949
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 50949 to 51013
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51013 to 51077
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51077 to 51141
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51141 to 51205
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51205 to 51269
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51269 to 51333
2024-05-15 10:23:01.278 TRACE tokio-runtime-worker sync: Cleared blocks from 51333 to 51397
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51397 to 51461
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51461 to 51525
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51525 to 51589
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51589 to 51653
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51653 to 51717
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51717 to 51781
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51781 to 51845
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51845 to 51909
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51909 to 51973
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 51973 to 52037
2024-05-15 10:23:01.279  WARN tokio-runtime-worker sync: 💔 Verification failed for block 0xbaef56c1bcdf55d941cb5055b19117ff42a0c4d1d83775ac7f8ff599539a155b received from (12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V): "Rejecting block (0xbaef56c1bcdf55d941cb5055b19117ff42a0c4d1d83775ac7f8ff599539a155b) from future slot Slot(285891336)"
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync::import-queue: Starting import of 64 blocks  (52101..52164)
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync::import-queue: Header 0x4e7a…250a has 4 logs
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync::import-queue: Block with unknown parent 52101: 0x4e7a8865fb0f745242a7848c74dae87ef586bbf29f6625b52f42f426b367250a, parent: 0x7a7a288c30f5ce5e270858a2cc290fc4d0ab3d56eeba7c105b7a604ab7db7d11
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Restarted sync at #50991 (0xf2035c71b45575da1062bb949c8009ed122f6a75e1394f4cedb574e23ec60779)
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: Restarted with 50991 (0xf203…0779)
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: New peer 12D3KooWN7QkT3GfSuavu3HeZ6Cm7eMrM3g8FjNLx1RvC8bCigHX with unknown best hash 0xf203…0779 (50991), assuming common block.
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: New peer 12D3KooWKxT34BZth3ZT8v9yD7fXBFQFvMAELcUgUzcy7doa2WbB with known best hash 0x5771…752a (0).
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: New peer 12D3KooWLzDAxCxXBKqq6YAfdK7yYyAbETymkFt5y153ETJ62xxs with unknown best hash 0xf203…0779 (50991), assuming common block.
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: New peer 12D3KooWGLiXft3qGjz9xyzj1JbvRC2kxamz8VZPAwHoTNZyYMYK with unknown best hash 0xf203…0779 (50991), assuming common block.
2024-05-15 10:23:01.279 DEBUG tokio-runtime-worker sync: New peer 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V with unknown best hash 0xf203…0779 (50991), assuming common block.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: New block request for 12D3KooWGLiXft3qGjz9xyzj1JbvRC2kxamz8VZPAwHoTNZyYMYK, (best:120641, common:50991) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51055), direction: Descending, max: Some(64) }
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: New block request for 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V, (best:120641, common:50991) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51119), direction: Descending, max: Some(64) }
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: New block request for 12D3KooWLzDAxCxXBKqq6YAfdK7yYyAbETymkFt5y153ETJ62xxs, (best:120641, common:50991) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51183), direction: Descending, max: Some(64) }
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: New block request for 12D3KooWN7QkT3GfSuavu3HeZ6Cm7eMrM3g8FjNLx1RvC8bCigHX, (best:120641, common:50991) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51247), direction: Descending, max: Some(64) }
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed DropPeer(BadPeer(PeerId("12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V"), ReputationChange { value: -536870912, reason: "Block verification failed" })).
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed CancelBlockRequest { peer_id: PeerId("12D3KooWN7QkT3GfSuavu3HeZ6Cm7eMrM3g8FjNLx1RvC8bCigHX") }, response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed CancelBlockRequest { peer_id: PeerId("12D3KooWKxT34BZth3ZT8v9yD7fXBFQFvMAELcUgUzcy7doa2WbB") }, response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed CancelBlockRequest { peer_id: PeerId("12D3KooWLzDAxCxXBKqq6YAfdK7yYyAbETymkFt5y153ETJ62xxs") }, response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed CancelBlockRequest { peer_id: PeerId("12D3KooWGLiXft3qGjz9xyzj1JbvRC2kxamz8VZPAwHoTNZyYMYK") }, response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed CancelBlockRequest { peer_id: PeerId("12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V") }, response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed `ChainSyncAction::SendBlockRequest` to 12D3KooWGLiXft3qGjz9xyzj1JbvRC2kxamz8VZPAwHoTNZyYMYK with BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51055), direction: Descending, max: Some(64) }, stale response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed `ChainSyncAction::SendBlockRequest` to 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V with BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51119), direction: Descending, max: Some(64) }, stale response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed `ChainSyncAction::SendBlockRequest` to 12D3KooWLzDAxCxXBKqq6YAfdK7yYyAbETymkFt5y153ETJ62xxs with BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51183), direction: Descending, max: Some(64) }, stale response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Processed `ChainSyncAction::SendBlockRequest` to 12D3KooWN7QkT3GfSuavu3HeZ6Cm7eMrM3g8FjNLx1RvC8bCigHX with BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(51247), direction: Descending, max: Some(64) }, stale response removed: false.
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Imported 0 of 64
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Cleared blocks from 52037 to 52101
2024-05-15 10:23:01.279  WARN tokio-runtime-worker sync: 💔 Error importing block 0xad15455506f62893ff46dc74e81c837580135805efa644b5e194de1580288fb9: block has an unknown parent
2024-05-15 10:23:01.279 TRACE tokio-runtime-worker sync: Restarted sync at #50991 

This line stands out

2024-05-15 10:23:01.267 TRACE tokio-runtime-worker sync::import-queue: Verifying 50992(0xbaef…155b) from 12D3KooWNEsyV8dFXdDugt1SVsbUQhzowicP21TZEXmbLTe9CN3V failed: Rejecting block (0xbaef56c1bcdf55d941cb5055b19117ff42a0c4d1d83775ac7f8ff599539a155b) from future slot Slot(285891336)

It seems the client is unable to tell that the runtime is now using a different slot duration?

Steps to reproduce

No response

[alexggh]

Polkadot-sdk version is v1.6.0

Can you update the new nodes to a newer version ? 1.6.0 it is already quite old.

[seunlanlege]

Polkadot-sdk version is v1.6.0

Can you update the new nodes to a newer version ? 1.6.0 it is already quite old.

For sure, can you confirm the version the fix for this behaviour is in?

[alexggh]

This is the fix #3510 for your issue, so 1.9 is the first version including the fix.

[bkchr]

This is a fix that you can apply locally without upgrading. You basically just need to move the fetching of the slot duration into the create_inherent_data closure.

Basically your nodes should also work after restarting.

[seunlanlege]

Confirmed this is fixed after upgrading to polkadot-sdk-v1.9.0