test node bans allegedly valid bulk extrinsics

[brenzi]

We're benchmarking by sending a large bunch of balances::transfer extrinsics using substrate-api-client

Our benchmark code

test node (based on 3bf9540) :
https://github.com/scs/substrate-test-nodes/tree/api-M1.5

Expected behaviour

• substrate includes all extrinsics into blocks sooner or later

Bug

• substrate includes the first 2 extrinsics but bans all subsequent extrinsics (although nonce is counting up)

Reproduce:

/substrate-test-nodes$ ./target/release/substrate-test-node --dev --execution native --ws-port 9979 -ltxpool=debug

and

/substrate-api-client$ ./target/release/examples/example_benchmark_bulk_xt -p 9979

node logs:

2020-02-24 11:55:24.009 tokio-runtime-worker-2 INFO substrate  Imported #118 (0x184b…dc19)
2020-02-24 11:55:24.009 tokio-runtime-worker-4 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  [0x73a14d705a86d4386cad8846fb36d0445c7a5e602eac20c6e27e910b9694f9b2] Pruned at 0x184b0a02014b716036e0b63ce6eff53e05ffbec41b7e491dfefb5637f59cdc19
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  [0x121828bf5f44286400a92a393495b9806b4c87a8a658fb76ebc39b6bb7badb65] Pruned at 0x184b0a02014b716036e0b63ce6eff53e05ffbec41b7e491dfefb5637f59cdc19
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  [0x6f875bf76ef25004172095bec6aba357fac25362d8dda2f4ff1e0291d87ad7c4] Importing to ready
2020-02-24 11:55:24.010 tokio-runtime-worker-6 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:28.024 tokio-runtime-worker-7 INFO substrate  Idle (0 peers), best: #118 (0x184b…dc19), finalized #117 (0x3697…673e), ⬇ 0 ⬆ 0
2020-02-24 11:55:30.033 tokio-runtime-worker-2 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x184b0a02014b716036e0b63ce6eff53e05ffbec41b7e491dfefb5637f59cdc19
2020-02-24 11:55:30.033 tokio-runtime-worker-2 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:30.035 tokio-runtime-worker-2 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 119 [hash: 0xd105eb5e34a6c439a820108ff9ef32147d2173b4beb1925c8ff9d770b33120b6; parent_hash: 0x184b…dc19; extrinsics: [0xc4f3…942c, 0x6f87…d7c4]]
2020-02-24 11:55:30.035 tokio-runtime-worker-2 INFO substrate_consensus_slots  Pre-sealed block for proposal at 119. Hash now 0x90df880d625da16810283a2a9e169fa6fc2b058b48d7537ef4bc5a3ad72ad05f, previously 0xd105eb5e34a6c439a820108ff9ef32147d2173b4beb1925c8ff9d770b33120b6.
2020-02-24 11:55:30.037 tokio-runtime-worker-2 DEBUG txpool  Starting pruning of block BlockId::Hash(0x90df880d625da16810283a2a9e169fa6fc2b058b48d7537ef4bc5a3ad72ad05f) (extrinsics: 2)
2020-02-24 11:55:30.037 tokio-runtime-worker-3 INFO substrate  Imported #119 (0x90df…d05f)
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  [0xc4f365a7a8eba96b83e2a5e9ed6d1a6cf3a00e84b882d381e93458a360ce942c] Pruned at 0x90df880d625da16810283a2a9e169fa6fc2b058b48d7537ef4bc5a3ad72ad05f
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  [0x6f875bf76ef25004172095bec6aba357fac25362d8dda2f4ff1e0291d87ad7c4] Pruned at 0x90df880d625da16810283a2a9e169fa6fc2b058b48d7537ef4bc5a3ad72ad05f
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:30.037 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:30.038 tokio-runtime-worker-2 DEBUG txpool  [0xfc19d50b12515dbec3ae3c8f7da70d1a007e3d262e02c8d87d9f86fd9a352fd6] Importing to ready
2020-02-24 11:55:30.038 tokio-runtime-worker-2 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:33.026 tokio-runtime-worker-10 INFO substrate  Idle (0 peers), best: #119 (0x90df…d05f), finalized #118 (0x184b…dc19), ⬇ 0 ⬆ 0
2020-02-24 11:55:36.001 tokio-runtime-worker-7 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x90df880d625da16810283a2a9e169fa6fc2b058b48d7537ef4bc5a3ad72ad05f
2020-02-24 11:55:36.002 tokio-runtime-worker-7 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:36.006 tokio-runtime-worker-7 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 120 [hash: 0xeec81267850388d78cd368c31da9e95b64d7a7a78b421ecb23effe96a3ea1ad0; parent_hash: 0x90df…d05f; extrinsics: [0x09fe…d18a, 0xfc19…2fd6]]
2020-02-24 11:55:36.006 tokio-runtime-worker-7 INFO substrate_consensus_slots  Pre-sealed block for proposal at 120. Hash now 0xf0ed9fecdb377afa427664e0b6763d3187965d0ed476320d9a09aba634e7c68e, previously 0xeec81267850388d78cd368c31da9e95b64d7a7a78b421ecb23effe96a3ea1ad0.
2020-02-24 11:55:36.008 tokio-runtime-worker-0 DEBUG txpool  Starting pruning of block BlockId::Hash(0xf0ed9fecdb377afa427664e0b6763d3187965d0ed476320d9a09aba634e7c68e) (extrinsics: 2)
2020-02-24 11:55:36.008 tokio-runtime-worker-4 INFO substrate  Imported #120 (0xf0ed…c68e)
2020-02-24 11:55:36.008 tokio-runtime-worker-4 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:36.008 tokio-runtime-worker-2 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:36.008 tokio-runtime-worker-2 DEBUG txpool  [0x09fe005af15c2755ee152aa5a186212283a6c08a1583f10657055a2ef1e6d18a] Pruned at 0xf0ed9fecdb377afa427664e0b6763d3187965d0ed476320d9a09aba634e7c68e
2020-02-24 11:55:36.008 tokio-runtime-worker-2 DEBUG txpool  [0xfc19d50b12515dbec3ae3c8f7da70d1a007e3d262e02c8d87d9f86fd9a352fd6] Pruned at 0xf0ed9fecdb377afa427664e0b6763d3187965d0ed476320d9a09aba634e7c68e
2020-02-24 11:55:36.009 tokio-runtime-worker-2 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:36.009 tokio-runtime-worker-2 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:36.009 tokio-runtime-worker-9 DEBUG txpool  [0x22370722e40fc24a388930bd3452db2eb2939a0e3830b466c29b18fa8e925be5] Importing to ready
2020-02-24 11:55:36.009 tokio-runtime-worker-9 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:38.027 tokio-runtime-worker-4 INFO substrate  Idle (0 peers), best: #120 (0xf0ed…c68e), finalized #119 (0x90df…d05f), ⬇ 0 ⬆ 0
2020-02-24 11:55:42.001 tokio-runtime-worker-2 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xf0ed9fecdb377afa427664e0b6763d3187965d0ed476320d9a09aba634e7c68e
2020-02-24 11:55:42.002 tokio-runtime-worker-2 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:42.005 tokio-runtime-worker-2 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 121 [hash: 0x26e22855db53e49153d522df568f98dbd8742caf9a31c96fdba74224c28067fc; parent_hash: 0xf0ed…c68e; extrinsics: [0x3c18…ba21, 0x2237…5be5]]
2020-02-24 11:55:42.005 tokio-runtime-worker-2 INFO substrate_consensus_slots  Pre-sealed block for proposal at 121. Hash now 0x4ee199f834952e65713dca0b5964de84302a859b2ae9d954e4b985077f2098e6, previously 0x26e22855db53e49153d522df568f98dbd8742caf9a31c96fdba74224c28067fc.
2020-02-24 11:55:42.007 tokio-runtime-worker-4 INFO substrate  Imported #121 (0x4ee1…98e6)
2020-02-24 11:55:42.007 tokio-runtime-worker-0 DEBUG txpool  Starting pruning of block BlockId::Hash(0x4ee199f834952e65713dca0b5964de84302a859b2ae9d954e4b985077f2098e6) (extrinsics: 2)
2020-02-24 11:55:42.007 tokio-runtime-worker-8 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:42.008 tokio-runtime-worker-8 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:42.008 tokio-runtime-worker-8 DEBUG txpool  [0x3c183348f7d55ec0a453124390afb2d60940e38d9a03bd189c3593bf7911ba21] Pruned at 0x4ee199f834952e65713dca0b5964de84302a859b2ae9d954e4b985077f2098e6
2020-02-24 11:55:42.008 tokio-runtime-worker-8 DEBUG txpool  [0x22370722e40fc24a388930bd3452db2eb2939a0e3830b466c29b18fa8e925be5] Pruned at 0x4ee199f834952e65713dca0b5964de84302a859b2ae9d954e4b985077f2098e6
2020-02-24 11:55:42.008 tokio-runtime-worker-8 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:42.008 tokio-runtime-worker-8 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:42.009 tokio-runtime-worker-0 DEBUG txpool  [0x7d8389407d156b76852929eed9e2772effa52f78a1a674e174428d7a681e091d] Importing to ready
2020-02-24 11:55:42.009 tokio-runtime-worker-0 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:43.029 tokio-runtime-worker-2 INFO substrate  Idle (0 peers), best: #121 (0x4ee1…98e6), finalized #119 (0x90df…d05f), ⬇ 0 ⬆ 0
2020-02-24 11:55:48.030 tokio-runtime-worker-7 INFO substrate  Idle (0 peers), best: #121 (0x4ee1…98e6), finalized #120 (0xf0ed…c68e), ⬇ 0 ⬆ 0
2020-02-24 11:55:48.032 tokio-runtime-worker-10 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x4ee199f834952e65713dca0b5964de84302a859b2ae9d954e4b985077f2098e6
2020-02-24 11:55:48.032 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:48.034 tokio-runtime-worker-10 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 122 [hash: 0xa8e75652fe4adf2d3d765814fd595c96254c831f939cf5179d22b9a59d4816b8; parent_hash: 0x4ee1…98e6; extrinsics: [0x092b…102f, 0x7d83…091d]]
2020-02-24 11:55:48.034 tokio-runtime-worker-10 INFO substrate_consensus_slots  Pre-sealed block for proposal at 122. Hash now 0x5b19346c7ed82b7a6f2f739a3a9d95435e5c9be74f96f4bc66e24f1883641ea7, previously 0xa8e75652fe4adf2d3d765814fd595c96254c831f939cf5179d22b9a59d4816b8.
2020-02-24 11:55:48.036 tokio-runtime-worker-8 INFO substrate  Imported #122 (0x5b19…1ea7)
2020-02-24 11:55:48.036 tokio-runtime-worker-7 DEBUG txpool  Starting pruning of block BlockId::Hash(0x5b19346c7ed82b7a6f2f739a3a9d95435e5c9be74f96f4bc66e24f1883641ea7) (extrinsics: 2)
2020-02-24 11:55:48.036 tokio-runtime-worker-5 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:55:48.036 tokio-runtime-worker-9 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:48.036 tokio-runtime-worker-9 DEBUG txpool  [0x092b1fa379b686610827d194a6c4b7e495f6f8bed5a56f02417d0371c257102f] Pruned at 0x5b19346c7ed82b7a6f2f739a3a9d95435e5c9be74f96f4bc66e24f1883641ea7
2020-02-24 11:55:48.036 tokio-runtime-worker-9 DEBUG txpool  [0x7d8389407d156b76852929eed9e2772effa52f78a1a674e174428d7a681e091d] Pruned at 0x5b19346c7ed82b7a6f2f739a3a9d95435e5c9be74f96f4bc66e24f1883641ea7
2020-02-24 11:55:48.036 tokio-runtime-worker-9 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:48.036 tokio-runtime-worker-9 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:53.031 tokio-runtime-worker-10 INFO substrate  Idle (0 peers), best: #122 (0x5b19…1ea7), finalized #121 (0x4ee1…98e6), ⬇ 0 ⬆ 0
2020-02-24 11:55:54.001 tokio-runtime-worker-9 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x5b19346c7ed82b7a6f2f739a3a9d95435e5c9be74f96f4bc66e24f1883641ea7
2020-02-24 11:55:54.002 tokio-runtime-worker-9 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:55:54.006 tokio-runtime-worker-9 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 123 [hash: 0xa3c2fa2b0f1f49e44d873ce54da18321f4cc01ec3abb4e5afa701cc4d9553097; parent_hash: 0x5b19…1ea7; extrinsics: [0xfb5b…7cf3]]
2020-02-24 11:55:54.006 tokio-runtime-worker-9 INFO substrate_consensus_slots  Pre-sealed block for proposal at 123. Hash now 0xfa01c61a49740b8c0d1dc449c600255badb27966794e93bb420ac9aa5e9f1ad9, previously 0xa3c2fa2b0f1f49e44d873ce54da18321f4cc01ec3abb4e5afa701cc4d9553097.
2020-02-24 11:55:54.008 tokio-runtime-worker-10 INFO substrate  Imported #123 (0xfa01…1ad9)
2020-02-24 11:55:54.008 tokio-runtime-worker-8 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:55:58.032 tokio-runtime-worker-7 INFO substrate  Idle (0 peers), best: #123 (0xfa01…1ad9), finalized #122 (0x5b19…1ea7), ⬇ 0 ⬆ 0
2020-02-24 11:56:00.000 tokio-runtime-worker-5 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xfa01c61a49740b8c0d1dc449c600255badb27966794e93bb420ac9aa5e9f1ad9
2020-02-24 11:56:00.001 tokio-runtime-worker-5 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:00.002 tokio-runtime-worker-5 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 124 [hash: 0x610a4fd22a8d3b4f416caf0d169de73da50e0ace8979dfaa8f4f70537473f14f; parent_hash: 0xfa01…1ad9; extrinsics: [0x222a…5d13]]
2020-02-24 11:56:00.003 tokio-runtime-worker-5 INFO substrate_consensus_slots  Pre-sealed block for proposal at 124. Hash now 0x3a45342e38516216fdb93cf554e4cee7a6175a55a6050bc5599e1067b6c0c18a, previously 0x610a4fd22a8d3b4f416caf0d169de73da50e0ace8979dfaa8f4f70537473f14f.
2020-02-24 11:56:00.005 tokio-runtime-worker-2 INFO substrate  Imported #124 (0x3a45…c18a)
2020-02-24 11:56:00.005 tokio-runtime-worker-5 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:56:03.033 tokio-runtime-worker-4 INFO substrate  Idle (0 peers), best: #124 (0x3a45…c18a), finalized #123 (0xfa01…1ad9), ⬇ 0 ⬆ 0
2020-02-24 11:56:06.001 tokio-runtime-worker-10 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x3a45342e38516216fdb93cf554e4cee7a6175a55a6050bc5599e1067b6c0c18a
2020-02-24 11:56:06.002 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:06.006 tokio-runtime-worker-10 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 125 [hash: 0xeb672409b3fe39e1a0a4547b0d5229fa9291bef2408b62303b08dcac712bf945; parent_hash: 0x3a45…c18a; extrinsics: [0x7109…bcf1]]
2020-02-24 11:56:06.006 tokio-runtime-worker-10 INFO substrate_consensus_slots  Pre-sealed block for proposal at 125. Hash now 0xf0d2e88334d55407ad0ca9487a922a2a5b6fd3f0f9b5b3b233544f6250327f9d, previously 0xeb672409b3fe39e1a0a4547b0d5229fa9291bef2408b62303b08dcac712bf945.
2020-02-24 11:56:06.008 tokio-runtime-worker-10 INFO substrate  Imported #125 (0xf0d2…7f9d)
2020-02-24 11:56:06.008 tokio-runtime-worker-5 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.034 tokio-runtime-worker-5 INFO substrate  Idle (0 peers), best: #125 (0xf0d2…7f9d), finalized #124 (0x3a45…c18a), ⬇ 0 ⬆ 0
2020-02-24 11:56:08.498 tokio-runtime-worker-1 DEBUG txpool  [0x06df84104e05268d27330b036f29e653ee709baabdddfcd52586b11428df9b70] Importing to ready
2020-02-24 11:56:08.498 tokio-runtime-worker-1 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.499 tokio-runtime-worker-0 DEBUG txpool  [0x415f9193191088cf046bcbd5023d173100305c88e1c19b02c991717a4432d228] Importing to ready
2020-02-24 11:56:08.499 tokio-runtime-worker-0 DEBUG txpool  Pool Status: Status { ready: 2, ready_bytes: 286, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.500 tokio-runtime-worker-4 DEBUG txpool  [0x9a4056b93b895d063f0dab9f51c5b3d4d4932ef931d28294adb9c604c68d55d8] Importing to ready
2020-02-24 11:56:08.500 tokio-runtime-worker-4 DEBUG txpool  Pool Status: Status { ready: 3, ready_bytes: 429, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.501 tokio-runtime-worker-1 DEBUG txpool  [0x1824f6314f7b7a8bbf107b1842148ec68ad80a82b4495a9af8e99340d2ad551f] Importing to ready
2020-02-24 11:56:08.501 tokio-runtime-worker-1 DEBUG txpool  Pool Status: Status { ready: 4, ready_bytes: 572, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.502 tokio-runtime-worker-5 DEBUG txpool  [0x287056952dd3e79dac3d0a835cf34617ef368cb4459fb0093967cd7cd4ccbd5c] Importing to ready
2020-02-24 11:56:08.502 tokio-runtime-worker-5 DEBUG txpool  Pool Status: Status { ready: 5, ready_bytes: 715, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.503 tokio-runtime-worker-5 DEBUG txpool  [0x9740b20841d423333b1c550943d9990fb48603105f93347f87ae2b71722f92e4] Importing to ready
2020-02-24 11:56:08.503 tokio-runtime-worker-5 DEBUG txpool  Pool Status: Status { ready: 6, ready_bytes: 858, future: 0, future_bytes: 0 }
2020-02-24 11:56:08.504 tokio-runtime-worker-4 DEBUG txpool  [0x0338455188c845ebaa58327e48cdd298404de786bf23d998683b7f93886033a5] Importing to ready
...
2020-02-24 11:56:09.107 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 87, ready_bytes: 12480, future: 0, future_bytes: 0 }
2020-02-24 11:56:09.110 tokio-runtime-worker-6 DEBUG txpool  [0x4b1f212d37e1abaf33cab82e0d07900fc984f1c364531471ed2b55067a80ff25] Importing to ready
2020-02-24 11:56:09.110 tokio-runtime-worker-6 DEBUG txpool  Pool Status: Status { ready: 88, ready_bytes: 12624, future: 0, future_bytes: 0 }
2020-02-24 11:56:12.001 tokio-runtime-worker-6 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xf0d2e88334d55407ad0ca9487a922a2a5b6fd3f0f9b5b3b233544f6250327f9d
2020-02-24 11:56:12.011 tokio-runtime-worker-6 DEBUG txpool  Banning invalid transactions: [0x9a4056b93b895d063f0dab9f51c5b3d4d4932ef931d28294adb9c604c68d55d8, 0x1824f6314f7b7a8bbf107b1842148ec68ad80a82b4495a9af8e99340d2ad551f, 0x287056952dd3e79dac3d0a835cf34617ef368cb4459fb0093967cd7cd4ccbd5c, 
....
0x0cde1bb8dc57bb73a9fafeef5b511e4d5dad841bc3e08005249bffa525224883, 0xe6e0dfa96f789e911d651b263f287246af3904812e2e11a32dc53898fa3bdc62, 0x836c9993065035850709a36f4145f4b00a3b1b36b53404f92d1a88c808cdee8d, 0x4b1f212d37e1abaf33cab82e0d07900fc984f1c364531471ed2b55067a80ff25]
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x4b1f212d37e1abaf33cab82e0d07900fc984f1c364531471ed2b55067a80ff25] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x836c9993065035850709a36f4145f4b00a3b1b36b53404f92d1a88c808cdee8d] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0xe6e0dfa96f789e911d651b263f287246af3904812e2e11a32dc53898fa3bdc62] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x0cde1bb8dc57bb73a9fafeef5b511e4d5dad841bc3e08005249bffa525224883] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x9a504b0b2d8b3f3fef10e5ac6812e4330d0736e0b177dae01286d6c5d2298865] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x0eeb301e8dec1ea136d0d90b66ea2e06af8b77ffd39d75bf89ea94a066e1a77f] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x70641da1020e94e266d81bfb1d79fb4ab91dc5bb94fd447a80dbcb808561cfc2] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x51db3a8f6fc933c67c243a7825e593d68b19aef67383669672e12d53087e2442] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x00c0e9342a0fd5561bbcf0683b8ad53d7ab3db139a2fc9f85bc24364f4028c52] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x8ba6af9b298623003b6b6528bc016d215f4e3ca5e7a9adf01beaf89e4fb3587a] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  
....
[0x0338455188c845ebaa58327e48cdd298404de786bf23d998683b7f93886033a5] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x9740b20841d423333b1c550943d9990fb48603105f93347f87ae2b71722f92e4] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x287056952dd3e79dac3d0a835cf34617ef368cb4459fb0093967cd7cd4ccbd5c] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x1824f6314f7b7a8bbf107b1842148ec68ad80a82b4495a9af8e99340d2ad551f] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 DEBUG txpool  [0x9a4056b93b895d063f0dab9f51c5b3d4d4932ef931d28294adb9c604c68d55d8] Removed as invalid:
2020-02-24 11:56:12.012 tokio-runtime-worker-6 WARN transaction-pool  Extrinsic invalid: 0x4b1f212d37e1abaf33cab82e0d07900fc984f1c364531471ed2b55067a80ff25
2020-02-24 11:56:12.012 tokio-runtime-worker-6 WARN transaction-pool  Extrinsic invalid: 0x836c9993065035850709a36f4145f4b00a3b1b36b53404f92d1a88c808cdee8d
...
2020-02-24 11:56:12.012 tokio-runtime-worker-6 WARN transaction-pool  Extrinsic invalid: 0x1824f6314f7b7a8bbf107b1842148ec68ad80a82b4495a9af8e99340d2ad551f
2020-02-24 11:56:12.012 tokio-runtime-worker-6 WARN transaction-pool  Extrinsic invalid: 0x9a4056b93b895d063f0dab9f51c5b3d4d4932ef931d28294adb9c604c68d55d8
2020-02-24 11:56:12.014 tokio-runtime-worker-6 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 126 [hash: 0x4a7c17360a7562e7285561761db99863ec12c19704e1b982b044924d0db80e61; parent_hash: 0xf0d2…7f9d; extrinsics: [0x7dec…b089, 0x06df…9b70]]
2020-02-24 11:56:12.014 tokio-runtime-worker-6 INFO substrate_consensus_slots  Pre-sealed block for proposal at 126. Hash now 0x17421d366d3b329c38ac633a1c439f9330856112740db1646413438f7750e7e1, previously 0x4a7c17360a7562e7285561761db99863ec12c19704e1b982b044924d0db80e61.
2020-02-24 11:56:12.016 tokio-runtime-worker-6 INFO substrate  Imported #126 (0x1742…e7e1)
2020-02-24 11:56:12.016 tokio-runtime-worker-0 DEBUG txpool  Starting pruning of block BlockId::Hash(0x17421d366d3b329c38ac633a1c439f9330856112740db1646413438f7750e7e1) (extrinsics: 2)
2020-02-24 11:56:12.016 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 2, ready_bytes: 286, future: 0, future_bytes: 0 }
2020-02-24 11:56:12.016 tokio-runtime-worker-6 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:56:12.016 tokio-runtime-worker-6 DEBUG txpool  [0x7dec6e7e0a4950a82486616330c90c0381ca2e20570d462055fbd17c1eedb089] Pruned at 0x17421d366d3b329c38ac633a1c439f9330856112740db1646413438f7750e7e1
2020-02-24 11:56:12.016 tokio-runtime-worker-6 DEBUG txpool  [0x06df84104e05268d27330b036f29e653ee709baabdddfcd52586b11428df9b70] Pruned at 0x17421d366d3b329c38ac633a1c439f9330856112740db1646413438f7750e7e1
2020-02-24 11:56:12.016 tokio-runtime-worker-6 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:12.016 tokio-runtime-worker-6 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:13.036 tokio-runtime-worker-10 INFO substrate  Idle (0 peers), best: #126 (0x1742…e7e1), finalized #125 (0xf0d2…7f9d), ⬇ 0 ⬆ 0
2020-02-24 11:56:18.001 tokio-runtime-worker-0 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x17421d366d3b329c38ac633a1c439f9330856112740db1646413438f7750e7e1
2020-02-24 11:56:18.003 tokio-runtime-worker-0 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:18.006 tokio-runtime-worker-0 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 127 [hash: 0x79e4d6f8fed986de519a3e87c8bdd183efd57180d35b1e31f16b6f4fd32d3810; parent_hash: 0x1742…e7e1; extrinsics: [0x21d6…dc06, 0x415f…d228]]
2020-02-24 11:56:18.006 tokio-runtime-worker-0 INFO substrate_consensus_slots  Pre-sealed block for proposal at 127. Hash now 0xfa0fe7ddadea5b046634b04b71687d5c3a286f643ae16f77064b4fa8c246e540, previously 0x79e4d6f8fed986de519a3e87c8bdd183efd57180d35b1e31f16b6f4fd32d3810.
2020-02-24 11:56:18.008 tokio-runtime-worker-4 DEBUG txpool  Starting pruning of block BlockId::Hash(0xfa0fe7ddadea5b046634b04b71687d5c3a286f643ae16f77064b4fa8c246e540) (extrinsics: 2)
2020-02-24 11:56:18.008 tokio-runtime-worker-1 INFO substrate  Imported #127 (0xfa0f…e540)
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 1, ready_bytes: 143, future: 0, future_bytes: 0 }
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  [0x21d6cb03857a415469a74bbc1a818cdc6fc955b1b788cf22eb62a2c6dd21dc06] Pruned at 0xfa0fe7ddadea5b046634b04b71687d5c3a286f643ae16f77064b4fa8c246e540
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  [0x415f9193191088cf046bcbd5023d173100305c88e1c19b02c991717a4432d228] Pruned at 0xfa0fe7ddadea5b046634b04b71687d5c3a286f643ae16f77064b4fa8c246e540
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:18.008 tokio-runtime-worker-10 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:18.038 tokio-runtime-worker-10 INFO substrate  Idle (0 peers), best: #127 (0xfa0f…e540), finalized #125 (0xf0d2…7f9d), ⬇ 0 ⬆ 0
2020-02-24 11:56:23.039 tokio-runtime-worker-1 INFO substrate  Idle (0 peers), best: #127 (0xfa0f…e540), finalized #126 (0x1742…e7e1), ⬇ 0 ⬆ 0
2020-02-24 11:56:24.001 tokio-runtime-worker-9 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xfa0fe7ddadea5b046634b04b71687d5c3a286f643ae16f77064b4fa8c246e540
2020-02-24 11:56:24.002 tokio-runtime-worker-9 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:24.006 tokio-runtime-worker-9 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 128 [hash: 0x2a55b20b037a41020d0ff3e7a57aa1ad77f143d00a8e44be75214e2486154059; parent_hash: 0xfa0f…e540; extrinsics: [0xa577…b2a8]]
2020-02-24 11:56:24.006 tokio-runtime-worker-9 INFO substrate_consensus_slots  Pre-sealed block for proposal at 128. Hash now 0xac8b9138face3fc29fc6f0b864733f080c53362256401bf50011fad6720922eb, previously 0x2a55b20b037a41020d0ff3e7a57aa1ad77f143d00a8e44be75214e2486154059.
2020-02-24 11:56:24.008 tokio-runtime-worker-9 INFO substrate  Imported #128 (0xac8b…22eb)
2020-02-24 11:56:24.008 tokio-runtime-worker-1 DEBUG txpool  Pool Status: Status { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2020-02-24 11:56:28.041 tokio-runtime-worker-10 INFO substrate  Idle (0 peers), best: #128 (0xac8b…22eb), finalized #127 (0xfa0f…e540), ⬇ 0 ⬆ 0
2020-02-24 11:56:30.001 tokio-runtime-worker-4 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xac8b9138face3fc29fc6f0b864733f080c53362256401bf50011fad6720922eb
2020-02-24 11:56:30.002 tokio-runtime-worker-4 DEBUG txpool  Banning invalid transactions: []
2020-02-24 11:56:30.006 tokio-runtime-worker-4 INFO substrate_basic_authorship::basic_authorship  Prepared block for proposing at 129 [hash: 0x71d936c059b3490e1309b602a030f6a04cd703f7226e42e58a474addca2eb1e2; parent_hash: 0xac8b…22eb; extrinsics: [0xe23e…81b0]]
2020-02-24 11:56:30.006 tokio-runtime-worker-4 INFO substrate_consensus_slots  Pre-sealed block for proposal at 129. Hash now 0xfb724aa25a39361cca034e4930361a7d689eb496ae943f1630813c74b7c87b31, previously 0x71d936c059b3490e1309b602a030f6a04cd703f7226e42e58a474addca2eb1e2.
2020-02-24 11:56:30.008 tokio-runtime-worker-0 INFO substrate  Imported #129 (0xfb72…7b31)

[brenzi]

@tomusdrw any news on this one?

[tomusdrw]

No, sorry I didn't yet have time to reproduce it. Is it possible that the account you are sending from is simply going below Existential deposit and is being pruned?
That would render all subsequent transactions Future, but since they were already in the Ready queue, we probably remove them as invalid.

I'll try to reproduce in upcoming days.

[tomusdrw]

Found a culprit, working on a fix.
The problem is that your block (weight) size is very small, so it's able to only fit couple of initial transactions.

We have a mechanism for block proposing that will try to push a bit more transactions even if the last one failed (to pack the block up to some local maximum), but this causes an issue, cause, because since all transactions are coming from a single sender, and we skip one because it doesn't fit, the rest is reported as invalid due to mismatching nonce.

The solution is to not mark them as invalid if we skipped some previous transactions. I'm currently working on a fix and test for this case.

[brenzi]

Ok, thanks for looking into this. Is there a quick fix for me? Where would I increase the block weight and what would be a reasonable number?

[tomusdrw]

You can increase the block size here:
https://github.com/scs/substrate-test-nodes/blob/api-M1.5/runtime/src/lib.rs#L143

Unfortunatelly, the issue will still persist with your current benchmarking code, you would need to:

1. Send transactions in batches that fits into a block
2. Detect failures, and restart with correct nonce from time to time

[brenzi]

I is strange though that @shawntabrizi's benchmark in js didn't run into this. (I haven't tested it, but I guess Shawn has.