Context:
A parachain in Rococo is missing more block slots than I would expect it to at fairly random times.
Version: Polkadot v0.9.42 Number of Collators: 3
Logging: (Perhaps I am missing the correct trace log to see the issue?)
-lcumulus-collator=trace \
-laura=trace \
-laura::cumulus=trace \
-lcumulus-consensus-relay-chain=trace \
-lsc_basic_authorship::basic_authorship=trace \
Perhaps most useful part of the log:
cumulus-collator: [Parachain] Producing candidate relay_parent=0x04baa2159d77d3557a3d6ac6088f37874b714b2a2c3df609dbbe9b36c1b437d6
cumulus-collator: [Parachain] Starting collation. relay_parent=0x04baa2159d77d3557a3d6ac6088f37874b714b2a2c3df609dbbe9b36c1b437d6 at=0x1e9acf648cfd7d37aecd93b7bca2a09e6ad56e9f28a1d762c223b2228897650a
aura: [Parachain] Checking log DigestItem::PreRuntime(...)
aura: [Parachain] Checking log DigestItem::Seal(...)
aura: [Parachain] Ignoring digest not meant for us
aura: [Parachain] No block for 2 slots. Applying exponential lenience, total proposing duration: 750ms
aura: [Parachain] Starting authorship at slot: 140922534
sc_basic_authorship::basic_authorship: [Parachain] 🙌 Starting consensus session on top of parent 0x1e9acf648cfd7d37aecd93b7bca2a09e6ad56e9f28a1d762c223b2228897650a
sc_basic_authorship::basic_authorship: [Parachain] Attempting to push transactions from the pool.
sc_basic_authorship::basic_authorship: [Parachain] Pool status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 1680005 (0 ms) [hash: 0x53252500318ec20bc6d8ad20269819d623c83b804063bcdde94d5e3ce0cd5967; parent_hash: 0x1e9a…650a; extrinsics (2): [0xb875…d7bb, 0xc288…4d21]]
aura: [Parachain] 🔖 Pre-sealed block for proposal at 1680005. Hash now 0x88fb38e98a275c9b78a04902c48d6d59fea3949731c43855406f62fccb5809cb, previously 0x53252500318ec20bc6d8ad20269819d623c83b804063bcdde94d5e3ce0cd5967.
substrate: [Parachain] ✨ Imported #1680005 (0x88fb…09cb)
Full Log in Gist: https://gist.github.com/wilwade/f4ec02bc60a6863c0a1fed66957f8aae
Appearance: Looks like the collators are forming the candidate blocks, but the candidate blocks are not getting included in the relay chain.
Things I don't think it is:
- Appears that the collator is forming the blocks at the right time and on top of the correct relay parent (Not a relay chain sync issue)
- No failing transactions on the Relay chain blocks (that I can see)
- Not a sync issue between the collators
- No invalid transactions as these are "empty" blocks
- Rococo Relay appears to be happy
- Lots of debug logs that would indicate specific errors are not showing up. Too many to list.
- Not a block finalization issue
So actual questions:
aura: [Parachain] No block for n slots
This appears to just be telling me what I already know, that no blocks were formed when we expected them to be. Is that a correct interpretation of the log? (Log is inside of https://paritytech.github.io/substrate/master/sc_consensus_slots/fn.proposing_remaining_duration.html)- There are some Relay chain Reorgs, but I don't think those are causing the issue.
- Other ideas of things to log?
- Other ideas?
🎁 Prepared block for proposing at 1683906
13 times across two collators (logs on the third are harder to get). They keep trying and eventually it gets through. Always gettingPool status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
so no tx failing as far as I can tell. All the collators appear happy from a load perspective as well.