search

openethereum / parity-ethereum

The fast, light, and robust client for Ethereum-like networks.
Other
6.83k stars 1.69k forks source link

Race condition between jsonRPC API and worker that actually mines transaction #10672

Closed thomaseizinger closed 4 years ago

thomaseizinger commented 5 years ago

Before filing a new issue, please provide the following information.

Your issue description goes here below. Try to include actual vs. expected behavior and steps to reproduce the issue.

I think I found a race condition between the parity node returning a transaction receipt and the transaction actually being mined.

I am using the parity instant seal engine to test local signing of transactions. In a test that deploys a contract, I experienced a flaky behaviour: Directly invoking the contract after it was deployed failed sometimes. Here are the logs of the parity node where it failed:

Logs ``` 2019-05-17 02:19:17 UTC main DEBUG parity_ethereum::helpers Executed 1 upgrade scripts - ok 2019-05-17 02:19:17 UTC main INFO parity_ethereum::run Starting Parity-Ethereum/v2.5.1-beta-adabd81-20190514/x86_64-linux-gnu/rustc1.34.1 2019-05-17 02:19:17 UTC main INFO parity_ethereum::run Keys path /home/parity/.local/share/io.parity.ethereum/keys/DevelopmentChain 2019-05-17 02:19:17 UTC main INFO parity_ethereum::run DB path /home/parity/.local/share/io.parity.ethereum/chains/DevelopmentChain/db/1484bce8c021f2ca 2019-05-17 02:19:17 UTC main INFO parity_ethereum::run State DB configuration: fast +Trace 2019-05-17 02:19:17 UTC main INFO parity_ethereum::run Operating mode: active 2019-05-17 02:19:17 UTC main DEBUG ethcore_accounts Error initializing hardware wallets: Other error 2019-05-17 02:19:17 UTC fetch DEBUG fetch processing requests ... 2019-05-17 02:19:17 UTC main INFO ethcore_service::service Configured for DevelopmentChain using InstantSeal engine 2019-05-17 02:19:17 UTC main DEBUG verification Allocating 8 verifiers, 8 initially active 2019-05-17 02:19:17 UTC main DEBUG verification Verifier auto-scaling disabled 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #0 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #1 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #2 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #3 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #4 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #5 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #6 2019-05-17 02:19:17 UTC main DEBUG verification Adding verification thread #7 2019-05-17 02:19:17 UTC main DEBUG client Obtained genesis transition proof: [] 2019-05-17 02:19:17 UTC main TRACE miner minimal_gas_price: recalibrating... 2019-05-17 02:19:17 UTC main DEBUG miner minimal_gas_price: Got gas price! 0 2019-05-17 02:19:17 UTC main DEBUG pip Initializing light protocol handler 2019-05-17 02:19:17 UTC main DEBUG ethcore_network_devp2p::host Error opening key file: Os { code: 2, kind: NotFound, message: "No such file or directory" } 2019-05-17 02:19:17 UTC main DEBUG network Listening at V4(0.0.0.0:30303) 2019-05-17 02:19:17 UTC main DEBUG network Error opening node table file: Os { code: 2, kind: NotFound, message: "No such file or directory" } 2019-05-17 02:19:17 UTC main INFO parity_ws Listening for new connections on 0.0.0.0:8546. 2019-05-17 02:19:17 UTC main DEBUG jsonrpc_ws_server::server Bound to local address: 0.0.0.0:8546 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":0,"method":"personal_sendTransaction","params":[{"from":"0x00a329c0648769a73afac7f9381e08fb43dbea72","to":"0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6","value":"0x8ac7230489e80000"},""]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 WARN rpc personal_sendTransaction is deprecated and will be removed in future versions: Account management is being phased out see #9997 for alternatives. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG own_tx Imported to the pool (hash 0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991] Added to the pool. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991] Sender: 0x00a3…ea72, nonce: 0, gasPrice: 0, gas: 1600000, value: 10000000000000000000, dataLen: 0)) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: sealing enabled 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: preparing a block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner prepare_block: No existing work - making new block 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG sync Finished transaction propagation, took 0ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue Re-computing pending set for block: 0 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Attempting to push 1 transactions. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Adding tx 0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991 took 0 ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Pushed 1 transactions in 0 ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: engine indicates internal sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner seal_block_internally: attempting internal seal. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner Received a Regular seal. 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG sync Finished block propagation, took 0ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner chain_new_blocks 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner minimal_gas_price: recalibrating... 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner minimal_gas_price: Got gas price! 0 2019-05-17 02:19:18 UTC IO Worker #0 INFO own_tx Transaction mined (hash 0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991) 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG txqueue [0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991] Culled or mined. 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG txqueue Removed 1 stalled transactions. Pool: 0/8192 (0 senders; 0/4096 kB) [minGasPrice: 0 Mwei, maxGas: 8000000] 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: imported internally sealed block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0x2cc50663f4b51af3dc58dc86032552e7a9a6bc784068b38e2cee755bfc0d0991","id":0}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":1,"method":"eth_getBalance","params":["0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6","latest"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0x8ac7230489e80000","id":1}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":2,"method":"eth_getTransactionCount","params":["0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6","latest"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0x0","id":2}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":3,"method":"eth_sendRawTransaction","params":["0xf9027a8080830f42408080b9022c608060405234801561001057600080fd5b5061020c806100206000396000f3fe60806040526004361061003b576000357c010000000000000000000000000000000000000000000000000000000090048063ead710c414610040575b600080fd5b34801561004c57600080fd5b506101066004803603602081101561006357600080fd5b810190808035906020019064010000000081111561008057600080fd5b82018360208201111561009257600080fd5b803590602001918460018302840111640100000000831117156100b457600080fd5b91908080601f016020809104026020016040519081016040528093929190818152602001838380828437600081840152601f19601f820116905080830192505050505050509192919290505050610108565b005b7f8252da6cc8ba70656d63b4439295f2de59ffee7cf90c96f5aee10857159474e781604051808060200180602001838103835260058152602001807f48656c6c6f000000000000000000000000000000000000000000000000000000815250602001838103825284818151815260200191508051906020019080838360005b838110156101a2578082015181840152602081019050610187565b50505050905090810190601f1680156101cf5780820380516001836020036101000a031916815260200191505b50935050505060405180910390a15056fea165627a7a72305820a7fc90d894eccd0e714c28a89f2dff015f9e03a78a8dcca74ed34bef840c2369002926a01e50e76341d862e680b2ad3f1b5001e92d90d7c0ee9884c9a9cb4e551f91cd2ba041f9eb5f47143e0ece207588bca96e27402ee4eaed631f93d61be99302dcb7b6"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG own_tx Imported to the pool (hash 0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c] Added to the pool. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c] Sender: 0xc245…00b6, nonce: 0, gasPrice: 0, gas: 1000000, value: 0, dataLen: 556)) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: sealing enabled 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG sync Finished transaction propagation, took 0ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: preparing a block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner prepare_block: No existing work - making new block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue Re-computing pending set for block: 1 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Attempting to push 1 transactions. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Adding tx 0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c took 0 ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Pushed 1 transactions in 0 ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: engine indicates internal sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner seal_block_internally: attempting internal seal. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner Received a Regular seal. 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG sync Finished block propagation, took 0ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner chain_new_blocks 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner minimal_gas_price: recalibrating... 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner minimal_gas_price: Got gas price! 0 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: imported internally sealed block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c","id":3}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":4,"method":"eth_getTransactionReceipt","params":["0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":{"blockHash":"0x959604bf8689a15dea50307b4ef5e68c7e27ad2613e9b5d8aa8af717bad92698","blockNumber":"0x2","contractAddress":"0xda9448f6429628dbd46ecd667ef941cd9154b668","cumulativeGasUsed":"0x2e6f1","from":"0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6","gasUsed":"0x2e6f1","logs":[],"logsBloom":"0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000","root":null,"status":"0x1","to":null,"transactionHash":"0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c","transactionIndex":"0x0"},"id":4}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":5,"method":"eth_getTransactionCount","params":["0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6","latest"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0x1","id":5}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":6,"method":"eth_sendRawTransaction","params":["0xf8c5010a830f424094da9448f6429628dbd46ecd667ef941cd9154b66880b864ead710c40000000000000000000000000000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000654686f6d6173000000000000000000000000000000000000000000000000000026a0ffc0b24b4bbfcc04d331eb0b36e3b8bad44b9bb15e506c14a8a1f596a75e6669a004de6d4f7aa688fc44c66d9cb84286ad4a4b1fb0378236f1c87e41e203cfca8c"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG own_tx Imported to the pool (hash 0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac] Added to the pool. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue [0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac] Sender: 0xc245…00b6, nonce: 1, gasPrice: 10, gas: 1000000, value: 0, dataLen: 100)) 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: sealing enabled 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false 2019-05-17 02:19:18 UTC IO Worker #0 DEBUG sync Finished transaction propagation, took 0ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: preparing a block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner prepare_block: No existing work - making new block 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG txqueue Re-computing pending set for block: 2 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Attempting to push 0 transactions. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG miner Pushed 0 transactions in 0 ms 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE miner update_sealing: engine indicates internal sealing 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":"0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac","id":6}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":7,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:18 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":7}. 2019-05-17 02:19:18 UTC IO Worker #2 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:19 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":8,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:19 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":8}. 2019-05-17 02:19:19 UTC IO Worker #2 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:20 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":9,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:20 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":9}. 2019-05-17 02:19:20 UTC IO Worker #0 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:21 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":10,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:21 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":10}. 2019-05-17 02:19:21 UTC IO Worker #2 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:22 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":11,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:22 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":11}. 2019-05-17 02:19:22 UTC IO Worker #3 INFO own_tx Transaction mined (hash 0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c) 2019-05-17 02:19:22 UTC IO Worker #3 DEBUG txqueue [0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c] Culled or mined. 2019-05-17 02:19:22 UTC IO Worker #3 DEBUG txqueue Removed 1 stalled transactions. Pool: 1/8192 (1 senders; 0/4096 kB) [minGasPrice: 0 Mwei, maxGas: 8000000] 2019-05-17 02:19:22 UTC IO Worker #1 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:22 UTC DEBUG ethcore_network_devp2p::ip_utils Gateway search error: IO error: Resource temporarily unavailable (os error 11) 2019-05-17 02:19:22 UTC IO Worker #1 INFO network Public node URL: enode://32258ec82ae13f05e319d1504f7f1ecdc0e622c544f2018649a9d376f7a6b6e215fefbf9911275a321050e48bdebb1a09de94baa6cd436f967515e00f48a67ec@172.17.0.2:30303 2019-05-17 02:19:23 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":12,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:23 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":12}. 2019-05-17 02:19:23 UTC IO Worker #3 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:24 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":13,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:24 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":13}. 2019-05-17 02:19:24 UTC IO Worker #0 DEBUG network Connecting peers: 0 sessions, 0 pending + 0 started 2019-05-17 02:19:25 UTC jsonrpc-eventloop-1 TRACE rpc Request: {"jsonrpc":"2.0","id":14,"method":"eth_getTransactionReceipt","params":["0xaa3a10a8b9adcebabd0c0e17b6c7ce0c942b005e40a48cc21ba087b2711818ac"]}. 2019-05-17 02:19:25 UTC jsonrpc-eventloop-1 DEBUG rpc Response: {"jsonrpc":"2.0","result":null,"id":14}. ```

The interesting part is transaction 0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c. It is the contract deployment.

At timestamp 2019-05-17 02:19:18 UTC, the parity node successfully returns the transaction receipt of the transaction:

{
  "blockHash": "0x959604bf8689a15dea50307b4ef5e68c7e27ad2613e9b5d8aa8af717bad92698",
  "blockNumber": "0x2",
  "contractAddress": "0xda9448f6429628dbd46ecd667ef941cd9154b668",
  "cumulativeGasUsed": "0x2e6f1",
  "from": "0xc2457d129c78bde6a4742b3ef38a7ba7f83d00b6",
  "gasUsed": "0x2e6f1",
  "logs": [],
  "logsBloom": "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
  "root": null,
  "status": "0x1",
  "to": null,
  "transactionHash": "0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c",
  "transactionIndex": "0x0"
}

However, and this is where it gets nasty, the transaction is actually not yet mined! Only at timestamp 2019-05-17 02:19:22 UTC, which is a full 4 seconds later, the transaction is actually mined by a worker.

You can also see in the logs, how this causes problems. As soon as the transaction receipt is returned, I am trying to invoke the contract under the given address by sending a 2nd transaction to the node. The receipt for this transaction is never returned, causing the test to fail.

In order to fix this, I am sleeping for a defined period of time after the deployment before I actually invoke the contract. It makes my test pass but I wonder, is this actually expected behaviour?

jam10o-new commented 5 years ago

Nope, this is certainly not expected behavior - my first thought was you were getting a receipt of the transaction before it was confirmed (null blocknumber, etc) but you seem to have not fallen for that trap.

thomaseizinger commented 5 years ago

my first thought was you were getting a receipt of the transaction before it was confirmed (null blocknumber, etc) but you seem to have not fallen for that trap.

Yes correct. I did some research in the other issues and came across several where that was the case so I already checked. It really seems that one subsystem of the node thinks the transaction is already confirmed/included when it is actually not.

tomusdrw commented 5 years ago

eth_getTransactionReceipt includes pending block, you can filter out the pending receipts by comparing blockNumber with latest block number.

thomaseizinger commented 5 years ago

eth_getTransactionReceipt includes pending block, you can filter out the pending receipts by comparing blockNumber with latest block number.

That seems to be pretty counter-intuitive though. Having a receipt suggests that the transaction was executed. Especially in combination with the instantSeal engine, this causes problems. web3js has a feature to wait for a certain number of confirmations for a transaction receipt is returned, however, with instantSeal, no other block is mined after the transaction is executed.

It seems to me that this is an actual race condition. The transaction receipt should not be returned until it is actually included in the latest block.

tomusdrw commented 5 years ago

Having a receipt suggests that the transaction was executed.

Well it was executed in a pending block. You can't rely on receipts in latest block either, since they are subject to change due to re-organisations. So if you query receipts you should always check the block number and compare it with the latest one anyway, to make sure you have enough confidence that it won't change.

Especially in combination with the instantSeal engine, this causes problems.

How so? In such chain you don't really have re-orgs at all. If block is sealed it should be imported right away. If that's not the case then I think it's rather an issue with InstantSeal engine. The log line:

2019-05-17 02:19:22 UTC IO Worker #3 DEBUG txqueue  [0xb2e5be963f0c73888bc71bf56ffddaa91ddb334ae70f5b8075742aa916a2807c] Culled or mined.

Also can't be relied for regarding timestamps, cause the transaction pool may be cleared asynchronously.

web3js has a feature to wait for a certain number of confirmations for a transaction receipt is returned, however, with instantSeal, no other block is mined after the transaction is executed.

This assumption doesn't work in some other engines that we support (like AuRa + Empty Steps), so I'd say it's more a feature request to web3js to support such scenarios .

adria0 commented 4 years ago

Closing issue due to its stale state.