Substrate: Long-lived off-chain workers can't submit transactions

[enfipy]

When execution of off-chain worker took more than block time - transaction submission from off-chain results in this error: (offchain call) Error submitting a transaction to the pool: Pool(InvalidTransaction(InvalidTransaction::BadProof)). But if the time of execution less - everything works fine.

I created a repository with a delayed request in off-chain worker - to reproduce error just run cargo run --release -- --dev it will automatically insert dev key and start an off-chain worker that fails after 3s. To prove that it works without delay - change this line with time query to 1 or fewer seconds.

[bkchr]

@tomusdrw any idea?

[enfipy]

I changed era to generic::Era::immortal() in offchain::CreateTransaction and CheckEra passed without error. Now there is no error with BadProof 🥳

But I do not quite understand why this error shows BadProof instead of theEra specific error 🤔

[tomusdrw]

@enfipy I wasn't able to reproduce your issue, but it indeed sounds interesting. The steps I did to reproduce:

1. Clone the repo
2. Bring back Era:mortal by uncommenting some lines
3. Running with cargo run --release --dev after purging the chain data.

It submits the transactions fine for me, I've tried increasing the delay or lowering it, still getting no BadProof errors.

I occasionaly got LowPriority error, but it's related to duplicated nonce. Since your offchain worker does not coordinate with other instances running concurrently it may sometimes produce two transactions using the same nonce, and one of them will be rejected by the pool. I'm aware of that issue, but haven't yet put enough effort to fix it in generic fashion (i.e. also for non frame-based runtimes, that might not have nonce at all). For now I'd suggest having CreateTransaction trait storing some nonce information internally (for instance in offchain worker's local storage).

If you are able to reproduce that error, could you please send me logs when running with -l=txpool=trace,runtime=trace,offchain=trace? I'll also try to investigate the code if it's possible that we don't return the correct error about era being incorrect and return BadProof instead.

[enfipy]

Sorry for the late response @tomusdrw.

I ran my project with old commit (that faced this issue first) and got this error again. Below are the logs with -l=txpool=trace,runtime=trace,offchain=trace flag:

2019-12-24 15:35:18.007 tokio-runtime-worker-3 INFO sc_consensus_slots  Pre-sealed block for proposal at 611. Hash now 0x94b51d0474ca44ea957459428d02f9bf0ecd45672141ed1ff80bd8f81184f4b3, previously 0xede0f13acfb97b8b45875422c29116652d2e94afd07398522c53bfcf5c2a1a86.
2019-12-24 15:35:18.008 tokio-runtime-worker-3 INFO substrate  Imported #611 (0x94b5…f4b3)
2019-12-24 15:35:18.008 tokio-runtime-worker-1 TRACE txpool  [BlockId::Hash(0x94b51d0474ca44ea957459428d02f9bf0ecd45672141ed1ff80bd8f81184f4b3)] Starting pool maintainance
2019-12-24 15:35:18.009  WARN runtime::modules::myproject::offchain  Start mint submission logic
2019-12-24 15:35:18.009  WARN runtime::modules::myproject::offchain  No available mint orders
2019-12-24 15:35:18.011 tokio-runtime-worker-1 TRACE txpool  [BlockId::Hash(0x94b51d0474ca44ea957459428d02f9bf0ecd45672141ed1ff80bd8f81184f4b3)] Re-submitting retracted done. Took 3 ms
2019-12-24 15:35:18.549 tokio-runtime-worker-0 TRACE txpool  [0x36f1b277116552efb686231ee488e62053328420ba29c18f2ea3b19eb3c81160] WaitingTransaction { imported_at: Instant { t: 18150790139728 }, transaction: Transaction { hash: 0x36f1b277116552efb686231ee488e62053328420ba29c18f2ea3b19eb3c81160, priority: 30157, valid_till: 674, bytes: 157, propagate: true, requires: [], provides: [d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d2d020000], data: 84ffd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d01da090222d70ce6f15a6d58ae34b224d29340b6055d1a17f149c5d4c0bf66fb63019e6362518cf746aa620b1ab0fb9e019fd789e7eae1699c51404460a9bb640b3502b50800060804d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d0000c16ff28623000000000000000000}, missing_tags: { }}
2019-12-24 15:35:18.550 tokio-runtime-worker-0 DEBUG txpool  [0x36f1b277116552efb686231ee488e62053328420ba29c18f2ea3b19eb3c81160] Importing to ready
2019-12-24 15:35:18.550 tokio-runtime-worker-0 TRACE txpool  [0x36f1b277116552efb686231ee488e62053328420ba29c18f2ea3b19eb3c81160] Ready (replaced: None)
2019-12-24 15:35:18.550 tokio-runtime-worker-0 DEBUG txpool  Pool Status: PoolStatus { ready: 1, ready_bytes: 157, future: 0, future_bytes: 0 }
2019-12-24 15:35:20.005 tokio-runtime-worker-0 INFO sc_basic_authority::basic_authorship  Starting consensus session on top of parent 0x94b51d0474ca44ea957459428d02f9bf0ecd45672141ed1ff80bd8f81184f4b3
2019-12-24 15:35:20.016 tokio-blocking-driver INFO sc_basic_authority::basic_authorship  Prepared block for proposing at 612 [hash: 0xdaa9880bae7296a2624a6abaad4c180b92463db3b35a47566ca8ebc175b577dc; parent_hash: 0x94b5…f4b3; extrinsics: [0x2a0e…55d7, 0x36f1…1160]]
2019-12-24 15:35:20.016 tokio-runtime-worker-0 INFO sc_consensus_slots  Pre-sealed block for proposal at 612. Hash now 0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc, previously 0xdaa9880bae7296a2624a6abaad4c180b92463db3b35a47566ca8ebc175b577dc.
2019-12-24 15:35:20.018 tokio-runtime-worker-2 TRACE txpool  [BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc)] Starting pool maintainance
2019-12-24 15:35:20.018 tokio-runtime-worker-2 DEBUG txpool  Starting pruning of block BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc) (extrinsics: 2)
2019-12-24 15:35:20.018 tokio-runtime-worker-2 DEBUG txpool  Fetching ready transactions (up to: 16)
2019-12-24 15:35:20.018 tokio-runtime-worker-1 INFO substrate  Imported #612 (0x29e6…00dc)
2019-12-24 15:35:20.019 tokio-runtime-worker-2 TRACE txpool  [BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc)] Re-submitting retracted done. Took 1 ms
2019-12-24 15:35:20.020 tokio-runtime-worker-2 DEBUG txpool  Pruning at BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc)
2019-12-24 15:35:20.020 tokio-runtime-worker-2 TRACE txpool  Prunning at BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc). Resubmitting transactions.
2019-12-24 15:35:20.020 tokio-runtime-worker-2 DEBUG txpool  [0x2a0eb6009dea99b1a79aac45c837b229d05bd24a872469d497ca3fbe179b55d7] Pruned at 0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc
2019-12-24 15:35:20.020 tokio-runtime-worker-2 DEBUG txpool  [0x36f1b277116552efb686231ee488e62053328420ba29c18f2ea3b19eb3c81160] Pruned at 0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc
2019-12-24 15:35:20.020  WARN runtime::modules::myproject::offchain  Start mint submission logic
2019-12-24 15:35:20.023 tokio-runtime-worker-2 TRACE txpool  [BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc)] Pruning done. Took 5 ms
2019-12-24 15:35:20.023 tokio-runtime-worker-2 DEBUG txpool  Re-verified transactions, took 5 ms. Resubmitting.
2019-12-24 15:35:20.023 tokio-runtime-worker-2 DEBUG txpool  Resubmitted. Took 0 ms. Status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 }
2019-12-24 15:35:20.023 tokio-runtime-worker-2 DEBUG txpool  [BlockId::Hash(0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc)] Revalidation done: Took 5 ms
2019-12-24 15:35:20.107  DEBUG txpool  (offchain call) Submitting a transaction to the pool: 84ffd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d014ab50b029aa1403df0a4de739e7e10e8ef56955f2f4162d6d8123dc367b5641c44183ee750e419cb5e514ebb7ca235b16d06a38efffdfec2971fa7677216a4890700b90800060940020000000000000024009100000000000000000058ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000000000000000b0d86b9088a60000000000000000069700000000000000000058ec3548445300000000000000000798000000000000000000703b1bd2aa400300000000000000089900000000000000000060521035ac8620000000000000000080dd62b221020000000000000000000080dd62b22102000000000000000000030000000000000024009100000000000000000058ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000...58ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000000000000000b0d86b9088a60000000000000000069700000000000000000058ec354844530000000000000000078f000000000000000000703b1bd2aa400300000000000000081b00000000000000000060521035ac8620000000000000000080dd62b221020000000000000000000080dd62b22102000000000000000000110000000000000024009100000000000000602b9b32c90483370000000000000000019200000000000000602b9b32c904833700000000000000000293000000000000004004a32fb71c124d0100000000000000039400000000000000602b9b32c90483370000000000000000049500000000000000f88e540f0a8dc6020000000000000000059600000000000000c05636659209066f0000000000000000069700000000000000602b9b32c90483370000000000000000078f00000000000000c0b10ffadb2f1e2b020000000000000008120000000000000080f19cc497de2daf150000000000000016cd0555cd6b010000000000000000000080dd62b22102000000000000000000
2019-12-24 15:35:20.108  WARN txpool  (offchain call) Error submitting a transaction to the pool: Pool(InvalidTransaction(InvalidTransaction::BadProof))
2019-12-24 15:35:20.108  WARN runtime::modules::myproject::offchain  Finished mint: Err(())
2019-12-24 15:35:22.004 tokio-runtime-worker-1 INFO sc_basic_authority::basic_authorship  Starting consensus session on top of parent 0x29e66a9fc039fdec2ae549ae64cac39f2c82f712a1aef66f5b778f5fa9e200dc
2019-12-24 15:35:22.015 tokio-blocking-driver INFO sc_basic_authority::basic_authorship  Prepared block for proposing at 613 [hash: 0xade95427775b469cbfdd5601af2b9bc6ca618d808694b912afa0d66fcb884268; parent_hash: 0x29e6…00dc; extrinsics: [0x7e00…37ea]]
2019-12-24 15:35:22.016 tokio-runtime-worker-1 INFO sc_consensus_slots  Pre-sealed block for proposal at 613. Hash now 0xab224c260555fff42bd86848dd9f96f122ef49fadffc0e6eef194a333b64b9ad, previously 0xade95427775b469cbfdd5601af2b9bc6ca618d808694b912afa0d66fcb884268.
2019-12-24 15:35:22.017 tokio-runtime-worker-0 INFO substrate  Imported #613 (0xab22…b9ad)
2019-12-24 15:35:22.016 tokio-runtime-worker-3 TRACE txpool  [BlockId::Hash(0xab224c260555fff42bd86848dd9f96f122ef49fadffc0e6eef194a333b64b9ad)] Starting pool maintainance
2019-12-24 15:35:22.018  WARN runtime::modules::myproject::offchain  Start mint submission logic
2019-12-24 15:35:22.034 tokio-runtime-worker-2 TRACE txpool  [BlockId::Hash(0xab224c260555fff42bd86848dd9f96f122ef49fadffc0e6eef194a333b64b9ad)] Re-submitting retracted done. Took 17 ms
2019-12-24 15:35:22.095  DEBUG txpool  (offchain call) Submitting a transaction to the pool: 84ffd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d01d08ea5ec2a85fadba30f8950048d5dc332be96fdee5004a703b95fe50c973302f6756d51f0a3aa8652d51c314d4933e6034c51cd151fade23fc6123a9142fa800700b90800060940020000000000000024009100000000000000000058ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000000000000000b0d86b9088a60000000000000000069700000000000000000058ec3548445300000000000000000798000000000000000000703b1bd2aa400300000000000000089900000000000000000060521035ac8620000000000000000080dd62b221020000000000000000000080dd62b22102000000000000000000030000000000000024009100000000000000000058ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000...58ec354844530000000000000000019200000000000000000058ec3548445300000000000000000293000000000000000000108a43b199f30100000000000000039400000000000000000058ec35484453000000000000000004950000000000000000009e1869d0290400000000000000000596000000000000000000b0d86b9088a60000000000000000069700000000000000000058ec354844530000000000000000078f000000000000000000703b1bd2aa400300000000000000081b00000000000000000060521035ac8620000000000000000080dd62b221020000000000000000000080dd62b22102000000000000000000110000000000000024009100000000000000602b9b32c90483370000000000000000019200000000000000602b9b32c904833700000000000000000293000000000000004004a32fb71c124d0100000000000000039400000000000000602b9b32c90483370000000000000000049500000000000000f88e540f0a8dc6020000000000000000059600000000000000c05636659209066f0000000000000000069700000000000000602b9b32c90483370000000000000000078f00000000000000c0b10ffadb2f1e2b020000000000000008120000000000000080f19cc497de2daf150000000000000016cd0555cd6b010000000000000000000080dd62b22102000000000000000000
2019-12-24 15:35:22.114  WARN txpool  (offchain call) Error submitting a transaction to the pool: Pool(InvalidTransaction(InvalidTransaction::BadProof))
2019-12-24 15:35:22.114  WARN runtime::modules::myproject::offchain  Finished mint: Err(())
2019-12-24 15:35:22.386 tokio-runtime-worker-1 INFO substrate  Idle (0 peers), best: #613 (0xab22…b9ad), finalized #611 (0x94b5…f4b3), ⬇ 0 ⬆ 0

So as you can see by logs (from this timestamp 2019-12-24 15:35:18.009) - the first transaction succeeds and was sent (I requested a small amount and computation took less time than block time). It's strange but if off-chain took less time than block time - no events submitted and logged (here 2019-12-24 15:35:18.009) to console like it didn't submit any transactions (but he did as we see tx from it here 2019-12-24 15:35:18.549).

P.S: I tried to reproduce this error again in the repo I specified in issue but it just disappeared 😨. I'm not really sure that only logs will help you to determine the root of the problem so I will try to reproduce this issue in the repository again as soon as possible and will notify you.

[jiayaoqijia]

Hi @bkchr @tomusdrw, I was building a project using off-chain worker and encountered this issue, too. I'm using @tomusdrw 's workshop branch. The "BadProof" error always occurred after block 255, so my guess is that the issue is with this line of code let period = 1 << 8;(https://github.com/tomusdrw/sub0-offchain-workshop/blob/0a03f4ac68e1d33f07dd7ecdd3074043dc8e4ce4/bin/node-template/runtime/src/lib.rs#L255. ).
Once changing to generic::Era::immortal(), the error is gone.

The logs are below.
2019-12-30 04:26:00.159 DEBUG offchain Creating signed transaction from account: 728fd9cf17e62a608aa008e06826de52abd906b399f4762025709fdec4e3012a (5Eev3mrw...) (nonce: 245) 2019-12-30 04:26:00.161 DEBUG txpool (offchain call) Submitting a transaction to the pool: 84ff728fd9cf17e62a608aa008e06826de52abd906b399f4762025709fdec4e3012a01028cc8c14d0e56b9efea7c55bc3e6c5550c1b8c55dea2d0f87d564a13a5b9219a3120f33ee090ce0cf2225cdd7b6a239f13da988db872b3eec56f1ea20d86e860700d503000606c279095e00000000184c6f6e646f6e1048617a651068617a650c35306ec2390400486b01001c0c0000983a0000f7af095e00000000ce1e0a5e00000000d08f7eaef804625cd1839eab92262be4a6dbd72734b1571bbb1099e5e328eda3 2019-12-30 04:26:00.163 DEBUG txpool Pool Status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 } 2019-12-30 04:26:00.163 WARN txpool (offchain call) Error submitting a transaction to the pool: Pool(InvalidTransaction(InvalidTransaction::BadProof)) 2019-12-30 04:26:00.163 DEBUG offchain Creating signed transaction from account: ba5477eaaa1dae39bbbc87bed27ea9599e9c5a536ff63630d7846ced9559131e (5GH1rc6t...) (nonce: 0) 2019-12-30 04:26:00.165 DEBUG txpool (offchain call) Submitting a transaction to the pool: 84ffba5477eaaa1dae39bbbc87bed27ea9599e9c5a536ff63630d7846ced9559131e01c40b1e531f212aa778ad2fd4c727fb759dd193c5ee30defec012ace2de4ffc0e26e3d32a5fc46b1dcea7635772f0ce801b74427c36e722861f969329338bb981070000000606c279095e00000000184c6f6e646f6e1048617a651068617a650c35306ec2390400486b01001c0c0000983a0000f7af095e00000000ce1e0a5e00000000d08f7eaef804625cd1839eab92262be4a6dbd72734b1571bbb1099e5e328eda3 2019-12-30 04:26:00.166 DEBUG txpool Pool Status: PoolStatus { ready: 0, ready_bytes: 0, future: 0, future_bytes: 0 } 2019-12-30 04:26:00.166 WARN txpool (offchain call) Error submitting a transaction to the pool: Pool(InvalidTransaction(InvalidTransaction::BadProof)) 2019-12-30 04:26:00.166 INFO weather_forecast_runtime::weather Sent transactions from: [(728fd9cf17e62a608aa008e06826de52abd906b399f4762025709fdec4e3012a (5Eev3mrw...), Err(())), (ba5477eaaa1dae39bbbc87bed27ea9599e9c5a536ff63630d7846ced9559131e (5GH1rc6t...), Err(()))]

[tomusdrw]

@jiayaoqijia thanks for the hint, resolved in #4521