No Extrinsics/Transactions are validating and getting added to the block successfully

Question

Extrinsic transactions are sent to the validation pool, set to ready state and then broadcasted. After this, they are re-submitted to the validation pool until it reaches its validity period (valid_till). At this point the transaction is completely removed from the pendingExtrinsics. None of the transactions are successfully validated and are getting added to the block.

substrate version: branch = "polkadot-v0.9.25"

Can someone help debug this? Do you know in what scenarios would a transaction/extrinsic not be considered valid?

More context: The chain has been running as expected for 8 weeks and the last wasm upgrade was done 3 weeks ago. It is a 4 validator network. The validators are still producing and finalizing new blocks.

Every 24 hrs, we distribute some rewards to the stakers lazily (5 stakers per block) in an on-initialize hook via a single escrow account. We have 2500+ stakers. This reward distribution happened for around 600 blocks, however it did not consume the full block weight. Testnet worked fine before this process started. Wondering if it could be one of the culprits?

Our dev and mainnet networks are all working as expected but they have way less stakers than Testnet.

Log:

2022-10-18 15:03:38.561 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] WaitingTransaction { imported_at: Instant { tv_sec: 7255432, tv_nsec: 535242295 }, transaction: Transaction { hash: 0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a, priority: 11986, valid_till: 931887, bytes: 147, propagate: true, source: TransactionSource::External, requires: [], provides: [78a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c374156000000], data: 840078a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c37410128a86910a046cffdd5e5008297bff002b71f5e89e76e52100550c7463af18c66f45543b617928d300c7d599ba914c75d5b6a096266f34ff7d37e3f702c21d98c0503590100020000b4d1b6c9de239f4070cf74287d22d53d5854e4b975bed2771398a74bd25eab45070010a5d4e8}, missing_tags: {}}
2022-10-18 15:03:38.561 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Importing to ready
2022-10-18 15:03:38.561 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Ready (replaced with None)
2022-10-18 15:03:38.561 DEBUG tokio-runtime-worker txpool: Pool Status: PoolStatus { ready: 1, ready_bytes: 147, future: 0, future_bytes: 0 }
2022-10-18 15:03:38.562 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Broadcasted
2022-10-18 15:03:39.360  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931829 (0x88a9…e42d), finalized #931827 (0xd50e…8666), ⬇ 7.2kiB/s ⬆ 7.0kiB/s
2022-10-18 15:03:39.802  INFO tokio-runtime-worker jsonrpsee_ws_server::server: Accepting new connection, 8/1000
2022-10-18 15:03:42.028 TRACE tokio-runtime-worker txpool: Pruning transactions: [0xdb794ee3756cfc2bd7d6e8c1ced211dbdaf34a560ad580741b267487744b3d9d]
2022-10-18 15:03:42.028 DEBUG tokio-runtime-worker txpool: Starting pruning of block BlockId::Hash(0x1293b4630dcdd7ab2a0dcc2f933e08ed5c28e93a960ac1bbc391ca833e77e8e8) (extrinsics: 1)
2022-10-18 15:03:42.028  INFO tokio-runtime-worker substrate: ✨ Imported #931830 (0x1293…e8e8)
2022-10-18 15:03:42.028 DEBUG tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x1293b4630dcdd7ab2a0dcc2f933e08ed5c28e93a960ac1bbc391ca833e77e8e8)
2022-10-18 15:03:42.028 TRACE tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x1293b4630dcdd7ab2a0dcc2f933e08ed5c28e93a960ac1bbc391ca833e77e8e8). Resubmitting transactions.
2022-10-18 15:03:42.028 DEBUG tokio-runtime-worker txpool: [0xdb794ee3756cfc2bd7d6e8c1ced211dbdaf34a560ad580741b267487744b3d9d] Pruned at 0x1293b4630dcdd7ab2a0dcc2f933e08ed5c28e93a960ac1bbc391ca833e77e8e8
2022-10-18 15:03:42.028 DEBUG tokio-runtime-worker txpool: Sent 1 transactions to revalidation queue
2022-10-18 15:03:42.028 DEBUG tokio-runtime-worker txpool: Updated revalidation queue at 931830. Transactions: {0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a: 931830}
2022-10-18 15:03:42.198 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Removed as part of the subtree.
2022-10-18 15:03:42.198 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] WaitingTransaction { imported_at: Instant { tv_sec: 7255436, tv_nsec: 171786265 }, transaction: Transaction { hash: 0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a, priority: 11986, valid_till: 931887, bytes: 147, propagate: true, source: TransactionSource::External, requires: [], provides: [78a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c374156000000], data: 840078a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c37410128a86910a046cffdd5e5008297bff002b71f5e89e76e52100550c7463af18c66f45543b617928d300c7d599ba914c75d5b6a096266f34ff7d37e3f702c21d98c0503590100020000b4d1b6c9de239f4070cf74287d22d53d5854e4b975bed2771398a74bd25eab45070010a5d4e8}, missing_tags: {}}
2022-10-18 15:03:42.198 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Importing to ready
2022-10-18 15:03:42.198 DEBUG tokio-runtime-worker txpool: Resubmitted. Took 0 ms. Status: PoolStatus { ready: 1, ready_bytes: 147, future: 0, future_bytes: 0 }
2022-10-18 15:03:42.198 DEBUG tokio-runtime-worker txpool: Revalidated 1 transactions. Left in the queue for revalidation: 0.
2022-10-18 15:03:42.891 TRACE tokio-runtime-worker txpool: Attempting to notify watchers of finalization for 0x469f…5660
2022-10-18 15:03:42.891 DEBUG tokio-runtime-worker txpool: [0x007249e1fa512b1c41c02a616f1c6d1692035bb4f3baf549fe1249927eeffeab] Sent finalization event (block 0x469f2370f05adb57fd6b4022bbe51c7b439c622bb7ff24ccd335b095c13a5660)
2022-10-18 15:03:44.361  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931830 (0x1293…e8e8), finalized #931828 (0x469f…5660), ⬇ 7.4kiB/s ⬆ 6.9kiB/s
2022-10-18 15:03:48.015 TRACE tokio-runtime-worker txpool: Pruning transactions: [0x082ac78b0d0c4b181a5ce30c3448c5229cb6a34c3971c482a5fd4b65d8e2ebb8]
2022-10-18 15:03:48.015 DEBUG tokio-runtime-worker txpool: Starting pruning of block BlockId::Hash(0x646eac4219f6c338b4ef72aedf928e083fde97d11f733e8b00d2cac9ffbd1107) (extrinsics: 1)
2022-10-18 15:03:48.015  INFO tokio-runtime-worker substrate: ✨ Imported #931831 (0x646e…1107)
2022-10-18 15:03:48.019 DEBUG tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x646eac4219f6c338b4ef72aedf928e083fde97d11f733e8b00d2cac9ffbd1107)
2022-10-18 15:03:48.019 TRACE tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x646eac4219f6c338b4ef72aedf928e083fde97d11f733e8b00d2cac9ffbd1107). Resubmitting transactions.
2022-10-18 15:03:48.019 DEBUG tokio-runtime-worker txpool: [0x082ac78b0d0c4b181a5ce30c3448c5229cb6a34c3971c482a5fd4b65d8e2ebb8] Pruned at 0x646eac4219f6c338b4ef72aedf928e083fde97d11f733e8b00d2cac9ffbd1107
2022-10-18 15:03:48.019 DEBUG tokio-runtime-worker txpool: Sent 1 transactions to revalidation queue
2022-10-18 15:03:48.019 DEBUG tokio-runtime-worker txpool: Updated revalidation queue at 931831. Transactions: {0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a: 931831}
2022-10-18 15:03:48.206 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Removed as part of the subtree.
2022-10-18 15:03:48.207 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] WaitingTransaction { imported_at: Instant { tv_sec: 7255442, tv_nsec: 180733891 }, transaction: Transaction { hash: 0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a, priority: 11986, valid_till: 931887, bytes: 147, propagate: true, source: TransactionSource::External, requires: [], provides: [78a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c374156000000], data: 840078a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c37410128a86910a046cffdd5e5008297bff002b71f5e89e76e52100550c7463af18c66f45543b617928d300c7d599ba914c75d5b6a096266f34ff7d37e3f702c21d98c0503590100020000b4d1b6c9de239f4070cf74287d22d53d5854e4b975bed2771398a74bd25eab45070010a5d4e8}, missing_tags: {}}
2022-10-18 15:03:48.207 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Importing to ready
2022-10-18 15:03:48.207 DEBUG tokio-runtime-worker txpool: Resubmitted. Took 0 ms. Status: PoolStatus { ready: 1, ready_bytes: 147, future: 0, future_bytes: 0 }
2022-10-18 15:03:48.207 DEBUG tokio-runtime-worker txpool: Revalidated 1 transactions. Left in the queue for revalidation: 0.
2022-10-18 15:03:49.362  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931831 (0x646e…1107), finalized #931828 (0x469f…5660), ⬇ 6.0kiB/s ⬆ 6.0kiB/s
2022-10-18 15:03:49.594 TRACE tokio-runtime-worker txpool: Attempting to notify watchers of finalization for 0x88a9…e42d
2022-10-18 15:03:49.594 DEBUG tokio-runtime-worker txpool: [0x8520c0056df9322315ecec98acd45cfb394d8fdbe85013a0d910ad9a4c68374a] Sent finalization event (block 0x88a9da21e21049ffd13c9652de3ed41c75c518123f15428f84fa625333f5e42d)
2022-10-18 15:03:54.022 TRACE tokio-runtime-worker txpool: Pruning transactions: [0x324ddc150236de28c1aae13853deb7adba0280d77f7f6b0a6db8ae46d6a3c150]
2022-10-18 15:03:54.022 DEBUG tokio-runtime-worker txpool: Starting pruning of block BlockId::Hash(0x2dca896d347b5e8dd01491faf8eb5a4e3c76887c29fdf84b6d8cf7a51dcad137) (extrinsics: 1)
2022-10-18 15:03:54.022  INFO tokio-runtime-worker substrate: ✨ Imported #931832 (0x2dca…d137)
2022-10-18 15:03:54.027 DEBUG tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x2dca896d347b5e8dd01491faf8eb5a4e3c76887c29fdf84b6d8cf7a51dcad137)
2022-10-18 15:03:54.027 TRACE tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x2dca896d347b5e8dd01491faf8eb5a4e3c76887c29fdf84b6d8cf7a51dcad137). Resubmitting transactions.
2022-10-18 15:03:54.027 DEBUG tokio-runtime-worker txpool: [0x324ddc150236de28c1aae13853deb7adba0280d77f7f6b0a6db8ae46d6a3c150] Pruned at 0x2dca896d347b5e8dd01491faf8eb5a4e3c76887c29fdf84b6d8cf7a51dcad137
2022-10-18 15:03:54.027 DEBUG tokio-runtime-worker txpool: Sent 1 transactions to revalidation queue
2022-10-18 15:03:54.027 DEBUG tokio-runtime-worker txpool: Updated revalidation queue at 931832. Transactions: {0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a: 931832}
2022-10-18 15:03:54.216 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Removed as part of the subtree.
2022-10-18 15:03:54.216 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] WaitingTransaction { imported_at: Instant { tv_sec: 7255448, tv_nsec: 189970246 }, transaction: Transaction { hash: 0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a, priority: 11986, valid_till: 931887, bytes: 147, propagate: true, source: TransactionSource::External, requires: [], provides: [78a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c374156000000], data: 840078a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c37410128a86910a046cffdd5e5008297bff002b71f5e89e76e52100550c7463af18c66f45543b617928d300c7d599ba914c75d5b6a096266f34ff7d37e3f702c21d98c0503590100020000b4d1b6c9de239f4070cf74287d22d53d5854e4b975bed2771398a74bd25eab45070010a5d4e8}, missing_tags: {}}
2022-10-18 15:03:54.216 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Importing to ready
2022-10-18 15:03:54.216 DEBUG tokio-runtime-worker txpool: Resubmitted. Took 0 ms. Status: PoolStatus { ready: 1, ready_bytes: 147, future: 0, future_bytes: 0 }
2022-10-18 15:03:54.216 DEBUG tokio-runtime-worker txpool: Revalidated 1 transactions. Left in the queue for revalidation: 0.
2022-10-18 15:03:54.363  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931832 (0x2dca…d137), finalized #931829 (0x88a9…e42d), ⬇ 6.9kiB/s ⬆ 7.0kiB/s
2022-10-18 15:03:54.958 TRACE tokio-runtime-worker txpool: Attempting to notify watchers of finalization for 0x1293…e8e8
2022-10-18 15:03:54.958 DEBUG tokio-runtime-worker txpool: [0xdb794ee3756cfc2bd7d6e8c1ced211dbdaf34a560ad580741b267487744b3d9d] Sent finalization event (block 0x1293b4630dcdd7ab2a0dcc2f933e08ed5c28e93a960ac1bbc391ca833e77e8e8)
2022-10-18 15:03:59.364  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931832 (0x2dca…d137), finalized #931830 (0x1293…e8e8), ⬇ 6.6kiB/s ⬆ 5.9kiB/s
2022-10-18 15:04:00.001  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: 🙌 Starting consensus session on top of parent 0x2dca896d347b5e8dd01491faf8eb5a4e3c76887c29fdf84b6d8cf7a51dcad137
2022-10-18 15:04:00.002 TRACE tokio-runtime-worker txpool: Transaction pool already processed block  #931832
2022-10-18 15:04:00.002 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Reported as invalid. Will skip sub-chains while iterating.
2022-10-18 15:04:00.003  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: 🎁 Prepared block for proposing at 931833 (1 ms) [hash: 0x141d8a7c342833701ac236f3fdb4bb7237b4591481207c658d7352dbacd939d2; parent_hash: 0x2dca…d137; extrinsics (1): [0xa19a…0f44]]
2022-10-18 15:04:00.006  INFO tokio-runtime-worker aura: 🔖 Pre-sealed block for proposal at 931833. Hash now 0x93bf36a7dc5c61f076a69859cee8aa9ba0602e97b8dd6547b9591c9c4ef74453, previously 0x141d8a7c342833701ac236f3fdb4bb7237b4591481207c658d7352dbacd939d2.
...
...
...
(revalidations)
...
...
2022-10-18 15:09:24.021 TRACE tokio-runtime-worker txpool: Pruning transactions: [0x0a1f07340f857ea719b161d1c842edb555911dfcfb82c55899ec7678ce1c882d]
2022-10-18 15:09:24.021 DEBUG tokio-runtime-worker txpool: Starting pruning of block BlockId::Hash(0x4de672d4b8067e85d1f78266783688ffe195ed0564658ca5048f64275f995175) (extrinsics: 1)
2022-10-18 15:09:24.023 DEBUG tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x4de672d4b8067e85d1f78266783688ffe195ed0564658ca5048f64275f995175)
2022-10-18 15:09:24.023 TRACE tokio-runtime-worker txpool: Pruning at BlockId::Hash(0x4de672d4b8067e85d1f78266783688ffe195ed0564658ca5048f64275f995175). Resubmitting transactions.
2022-10-18 15:09:24.023 DEBUG tokio-runtime-worker txpool: [0x0a1f07340f857ea719b161d1c842edb555911dfcfb82c55899ec7678ce1c882d] Pruned at 0x4de672d4b8067e85d1f78266783688ffe195ed0564658ca5048f64275f995175
2022-10-18 15:09:24.023 DEBUG tokio-runtime-worker txpool: Removing invalid transactions: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a]
2022-10-18 15:09:24.023 TRACE tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Removed as part of the subtree.
2022-10-18 15:09:24.023 DEBUG tokio-runtime-worker txpool: Removed invalid transactions: [Transaction { hash: 0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a, priority: 11986, valid_till: 931887, bytes: 147, propagate: true, source: TransactionSource::External, requires: [], provides: [78a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c374156000000], data: 840078a64a89f33cac983967b0ebb8c7a853af69722d8493a516c97f0ef7e33c37410128a86910a046cffdd5e5008297bff002b71f5e89e76e52100550c7463af18c66f45543b617928d300c7d599ba914c75d5b6a096266f34ff7d37e3f702c21d98c0503590100020000b4d1b6c9de239f4070cf74287d22d53d5854e4b975bed2771398a74bd25eab45070010a5d4e8}]
2022-10-18 15:09:24.023 DEBUG tokio-runtime-worker txpool: [0xba6c1ea7d678160b0a81950f70e81becebe7663740c0670be44c5a85c39dd15a] Extrinsic invalid
2022-10-18 15:09:24.023  INFO tokio-runtime-worker substrate: ✨ Imported #931887 (0x4de6…5175)
2022-10-18 15:09:24.434  INFO tokio-runtime-worker substrate: 💤 Idle (7 peers), best: #931887 (0x4de6…5175), finalized #931884 (0x1eed…1a6c), ⬇ 7.1kiB/s ⬆ 7.0kiB/s
2022-10-18 15:09:24.902 TRACE tokio-runtime-worker txpool: Attempting to notify watchers of finalization for 0x7727…fd97
2022-10-18 15:09:24.902 DEBUG tokio-runtime-worker txpool: [0x117ccd88df4751c4c5e6e282b7633207915597befcc01e9af21e95a1944fd764] Sent finalization event (block 0x77273c2754b1fa43c8ad7b8f1022b886b93750f794192358e6ed7dcd3086fd97)

Answer 1

Just a reminder, if we're using the on_initialize hook, we should ensure that we don't do any heavy computation in that and also the weights are properly calculated with benchmarks. Recently, we faced this exact issue because of heavy computations on the on_initialize hook.

The on_initialize hook is part of the block initialisation process which will be executed before executing the transactions to be included in a block. One way to check if our on_intialize (which falls under mandatory class) is causing this issue is to check the BlockWeights in system storage as below

The mandatory class of the Blockweights should be as limited as possible if our on_initilize is heavier, then the mandatory class value would be very high and could potentially cause the extrinsic (which falls under normal or operational class) to not to be included in the block. More info on BlockWeights is available here