flaky timeout error on v2-periphery test

[sekisamu]

Description

I've treid with latest update of polkadot-sdk(commit version: 8ab9a68e4f1185685206d581bd018bd7d0d7f051), the good news is the test cases of v2-core run well, while v2-periphery always fail with Timeout error, but this could happen to different test cases, seems random.

Env

polkadot-sdk: 8ab9a68e4f1185685206d581bd018bd7d0d7f051
test repo: GitHub - papermoonio/v2-periphery-polkadot at revm

How to reproduce

1. clone the repo and build

git clone https://github.com/papermoonio/v2-periphery-polkadot
cd v2-periphery-polkadot
git checkout revm
npm install

2. Test

remember to start the local revive-dev-node first.

npx hardhat test --network local

the error log is

  1) ExampleComputeLiquidityValue
       #getLiquidityValue
         fee on
           correct after swap:
     Error: Timeout of 100000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/home/maggie/workspace/blockchain/paritytech/v2-periphery-polkadot/test/ExampleComputeLiquidityValue.spec.ts)
      at listOnTimeout (node:internal/timers:594:17)
      at processTimers (node:internal/timers:529:7)

And this error could also happen to other cases as well.

[sekisamu]

Investigation 1

This issue appears to encompass two distinct questions:

1. What is the root cause of the Timeout error? Specifically, why did the transaction execution fail?
2. When an on-chain transaction fails to execute, why isn't the result immediately returned to the client (Hardhat)? Instead, it causes a client-side timeout, which in turn leads to all subsequent transactions failing with Invalid transaction and temporarily banned errors.

First, we used the Polkadot.js app to quickly locate the problematic transaction:

We identified that the problematic transaction occurred in block 68, with the error reason being TxFeeOverdraw. At the same time, we located the following error log on the eth-rpc side:

2025-10-30 00:11:47.062 ERROR tokio-runtime-worker eth-rpc: Receipt data length (0) does not match extrinsics length (1)    
2025-10-30 00:11:47.062 ERROR tokio-runtime-worker eth-rpc::client: Failed to process block 68: ReceiptDataLengthMismatch

The probable cause is that the transaction receipt (tx receipt) could not be fetched or was fetched incorrectly. This caused the transaction to remain in a pending state, which consequently blocked the client until a timeout occurred.

[sekisamu]

Investigation into the Root Cause of the Timeout

As seen in the discussion at https://github.com/paritytech/contract-issues/issues/205#issuecomment-3466503451, the transaction failed with a revive.TxFeeOverdraw error. This again appeared to be an issue of insufficient transaction fees. However, I wanted to investigate the cause more deeply, especially given that the OutOfGas error related to Uniswap V2 Core has been fixed in the new version of polkadot-sdk.

I compared the dry-run logs with the actual execution logs for the failed transaction and discovered that they exhibited different behaviors for the same transaction:

As you can see, the left side of the image shows the dry-run logs, while the right side shows the actual execution logs. The behavior begins to diverge at the point marked by the red box. A closer look reveals that this divergence resulted in two additional storage write operations during the actual transaction execution compared to the dry-run. Due to the presence of storage deposits, this makes it more likely for insufficient fee errors to occur, even when the estimateGas function includes a redundancy mechanism.

Full dry run log:

2025-10-30 00:11:46.998 DEBUG tokio-runtime-worker runtime::revive: dry_run_eth_transact: GenericTransaction { access_list: None, authorization_list: [], blob_versioned_hashes: [], blobs: [], chain_id: None, from: Some(0xf24ff3a9cf04c71dbc94d0b566f7a27b94566cac), gas: None, gas_price: None, input: InputOrData { input: None, data: Some(Bytes(0x38ed1739000000000000000000000000000000000000000000000001158e460913d0000000000000000000000000000000...)) }, max_fee_per_blob_gas: None, max_fee_per_gas: None, max_priority_fee_per_gas: None, nonce: None, to: Some(0x74daa94fe6cf3d1a2481f4b9a8183b3189efb43f), type: None, value: None }    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255]) for key Fix([88, 76, 48, ca, 72, 58, f0, 5a, fe, 93, f1, b5, 7b, 62, b5, ce, 9b, 9f, 90, d2, f7, 60, 1f, 47, 47, a2, 26, 40, 57, 74, b9, 3d])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 29, 4, 82, 131, 177, 158, 112, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 27, 238, 196, 61, 168, 138, 160, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 167, 88, 193, 94, 135, 218, 100, 186, 200, 43, 173, 217, 224, 63, 48, 215, 225, 141, 118, 119]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 6])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 194, 165, 115, 75, 64, 33, 242, 221, 12, 39, 249, 73, 239, 132, 235, 93, 233, 99, 96, 229]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 7])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 177, 174, 77, 110, 46, 245, 0, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 231, 207, 62, 8, 119, 105, 234, 159, 186]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>) 

Full tx execution log:

2025-10-30 00:11:47.020 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255]) for key Fix([88, 76, 48, ca, 72, 58, f0, 5a, fe, 93, f1, b5, 7b, 62, b5, ce, 9b, 9f, 90, d2, f7, 60, 1f, 47, 47, a2, 26, 40, 57, 74, b9, 3d])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 29, 4, 82, 131, 177, 158, 112, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 27, 238, 196, 61, 168, 138, 160, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.022 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 167, 88, 193, 94, 135, 218, 100, 186, 200, 43, 173, 217, 224, 63, 48, 215, 225, 141, 118, 119]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 6])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 194, 165, 115, 75, 64, 33, 242, 221, 12, 39, 249, 73, 239, 132, 235, 93, 233, 99, 96, 229]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 7])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 177, 174, 77, 110, 46, 245, 0, 0, 0]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 231, 207, 62, 8, 119, 105, 234, 159, 186]) for key Fix([2a, 18, ba, ad, 4b, 7a, f0, 5f, 65, 53, 3a, 14, f7, d7, 98, 6e, 49, ec, f, 78, 87, e, 57, f8, 60, 7f, 31, 18, 5f, 1e, 70, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70]) for key Fix([fb, d6, 11, 49, 10, a0, 2f, 4a, c7, 45, e6, 5b, 67, 8a, c4, f, 6c, d4, e1, d2, bc, 7f, 49, 70, 5e, 21, 7f, ef, f8, 11, 50, b9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value None for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 100, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 9])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value None for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, a])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2, 143, 92, 40, 245, 194, 143, 92, 40, 245, 194, 143, 92, 40]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, a])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([105, 2, 60, 195, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, c])    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)    
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: frame finished with: Ok(<wasm:stripped>)   

[sekisamu]

Investigation into the Root Cause of the Timeout - Update

Through further analysis of the logs, I discovered that the failing transaction was executing the swapExactTokensForTokens method. Then, by cross-referencing this with the call stack information in the logs, I was able to pinpoint the problematic execution logic to the private function _update within the UniswapV2Pair contract.

Here is the code for the _update method:

// update reserves and, on the first call per block, price accumulators
function _update(
    uint balance0,
    uint balance1,
    uint112 _reserve0,
    uint112 _reserve1
) private {
    require(
        balance0 <= type(uint112).max && balance1 <= type(uint112).max,
        "UniswapV2: OVERFLOW"
    );
    uint32 blockTimestamp = uint32(block.timestamp % 2 ** 32);
    uint32 timeElapsed = blockTimestamp - blockTimestampLast; // overflow is desired
    if (timeElapsed > 0 && _reserve0 != 0 && _reserve1 != 0) {
        // * never overflows, and + overflow is desired
        price0CumulativeLast +=
            uint(UQ112x112.encode(_reserve1).uqdiv(_reserve0)) *
            timeElapsed;
        price1CumulativeLast +=
            uint(UQ112x112.encode(_reserve0).uqdiv(_reserve1)) *
            timeElapsed;
    }
    reserve0 = uint112(balance0);
    reserve1 = uint112(balance1);
    blockTimestampLast = blockTimestamp;
    emit Sync(reserve0, reserve1);
}

Based on the logs mentioned earlier, the actual transaction execution performed two additional storage write operations—to slot #9 and slot #10—compared to the dry-run. According to Solidity's storage layout rules, we can determine the following variables correspond to these slots:

    ...
    uint112 private reserve0;                             // Slot 8 (packed)
    uint112 private reserve1;                             // Slot 8 (packed)
    uint32 private blockTimestampLast;                    // Slot 8 (packed)

    uint public price0CumulativeLast;                     // Slot 9  ⚠️
    uint public price1CumulativeLast;                     // Slot 10 (0x0a) ⚠️

So the comparison of the logs shows:

Dry-run Logs (at block 67):

contract storage: read value Some([...]) for key Fix([...0, 8])    # Read reserve0/reserve1
contract storage: read value Some([...]) for key Fix([...0, 8])    # Read again
contract storage: writing value Some([...]) for key Fix([...0, 8]) # Write reserve0/reserve1
contract storage: writing value Some([...]) for key Fix([...0, c]) # Write unlocked

Actual Execution Logs (in block 68, based on block 67):

contract storage: read value Some([...]) for key Fix([...0, 8])    # Read reserve0/reserve1
contract storage: read value None for key Fix([...0, 9])           # ⚠️ Read price0CumulativeLast (empty)
contract storage: writing value Some([0x64...]) for key Fix([...0, 9])  # ⚠️ Write price0CumulativeLast
contract storage: read value None for key Fix([...0, a])           # ⚠️ Read price1CumulativeLast (empty)
contract storage: writing value Some([...]) for key Fix([...0, a]) # ⚠️ Write price1CumulativeLast
contract storage: read value Some([...]) for key Fix([...0, 8])    # Read reserve0/reserve1
contract storage: writing value Some([...195...]) for key Fix([...0, 8]) # Write new reserve0/reserve1
contract storage: writing value Some([...0, 1]) for key Fix([...0, c])   # Write unlocked

here, the issue became clear: the dry-run skipped the execution of the following code block:

if (timeElapsed > 0 && _reserve0 != 0 && _reserve1 != 0) {
    // * never overflows, and + overflow is desired
    price0CumulativeLast +=
        uint(UQ112x112.encode(_reserve1).uqdiv(_reserve0)) *
        timeElapsed;
    price1CumulativeLast +=
        uint(UQ112x112.encode(_reserve0).uqdiv(_reserve1)) *
        timeElapsed;
}

[sekisamu]

Investigation into the Root Cause of the Timeout - Update 2

Further analysis combining the node execution logs and the contract's code logic revealed the following (only key logs are shown below):

During the dry-run:

2025-10-30 00:11:46.999 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
...
2025-10-30 00:11:47.000 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])
Based on the encoding scheme for Solidity slot data, we can see that the blockTimestampLast value remained unchanged before and after the execution.

In the actual transaction execution logs, however:

2025-10-30 00:11:47.020 TRACE tokio-runtime-worker runtime::revive: contract storage: read value Some([105, 2, 60, 194, 0, 0, 0, 0, 0, 108, 107, 147, 91, 139, 189, 64, 0, 0, 0, 0, 0, 0, 0, 1, 21, 142, 70, 9, 19, 208, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])    
...
2025-10-30 00:11:47.023 TRACE tokio-runtime-worker runtime::revive: contract storage: writing value Some([105, 2, 60, 195, 0, 0, 0, 0, 0, 54, 74, 162, 193, 67, 72, 85, 96, 70, 0, 0, 0, 0, 0, 2, 43, 28, 140, 18, 39, 160, 0, 0]) for key Fix([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 8])

The values for blockTimestampLast are different.

[sekisamu]

Root Cause of the Timeout - Conclusion

During the dry-run, the timestamp of the previous block was used. However, during the actual transaction, the on-chain timestamp was updated for the new block. This discrepancy caused a different execution path. The issue is exacerbated on revm because its gas calculation logic is more complex and includes more fee components than standard Ethereum. This makes estimateGas failures more likely, even when a buffer is added.

Current Approach Research:

After investigating the behavior of Geth and Hardhat:

1. Geth's Handling of eth_estimateGas

Geth uses the timestamp of the "pending" block when executing eth_estimateGas:

// Geth's implementation
header.Time = uint64(time.Now().Unix())        // Uses the current time, not the previous block's time
header.Number.Add(header.Number, big.NewInt(1)) // Next block number

2. Hardhat's Testnet Approach

Hardhat provides fully controllable time:

// Hardhat's strategy
async function estimateGas(tx) {
  // Execute in the context of a "pending" block
  const pendingBlock = {
    number: currentBlock + 1,
    timestamp: currentTimestamp + 1  // Predicts the next block's timestamp
  };
  return executeInContext(pendingBlock, tx);
}

Hope this would help.

[athei]

Yes I traced it back to the exact same code in UniswapV2Pair. This specific case should be fixed by paritytech/polkadot-sdk#10160.

Yes the dry run also needs to be fixed.

[athei]

I verified the behavior on geth. We should emulate their behavior.

@mokita-j

1. During eth_estimateGas

block.timestamp = max(unix_time(), latest_block.timestamp + 1);
block.number = latest_block.number + 1;

2. During eth_call

block.timestamp = latest_block.timestamp;
block.number = latest_block.number;

So far we use 2) for both calls. We need to change our eth_gasEstimate implementation:

• the block argument should default to pending instead of latest.
• If pending is used we need to apply the logic from 1).

For that we need to pass additional information into the runtime. We need to add a new version of ReviveApi::eth_transact in order to pass the current timestamp from the RPC into the runtime in case pending is used.

[mokita-j]

@sekisamu I tested this with the latest polkadot-sdk master and all the tests are passing now