--config=dev doesn't seal properly when transactions are sent in parallel

[berndbohmeier]

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

• Parity Ethereum version: v2.0.6-stable-7658d22-20180921
• Operating system: Linux
• Installation: docker image
• Fully synchronized: yes
• Network: dev config.
• Restarted: yes
• Used Options: --jsonrpc-cors "*" --jsonrpc-apis all --jsonrpc-hosts=all --base-path=/data/ --config dev --unlock 0x00a329c0648769a73afac7f9381e08fb43dbea72 --password=/pw --jsonrpc-interface "0.0.0.0"

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

I have a client sending in transactions to parity via the HTTP RPC method eth_sendRawTransaction. The pseudo code for the logs later is roughly:

logger.debug('Sending tx: {hash}'))
web3.eth.sendRawTransaction(rawTxn)
logger.debug('Sent tx: {hash}')

Also the client is listening for events using filters. I send in the transaction at nearly the same time. Because I use the instant seal engine I would expect parity to instantly produce blocks for the two transaction, either by including them in one block or by producing two blocks shortly after each other.
What happens is that the first transaction gets included, but the second transaction hangs somewhere and gets included only if another transaction comes in.
You can see that in the logs I collected.

client        | 2018-09-27 14:36:00,470[DEBUG] Sending tx: 0xc838d956c720eae34b04752a8b2bc361762512d0fdb983fde7bebabfa06b63c5
client        | 2018-09-27 14:36:00,472[DEBUG] Sending tx: 0x637e268e8da6ff7403ad2c03ce723afd619c174349077c04163229202f314036
parity       | 2018-09-27 14:36:00 UTC Imported #26 0x051e…ae52 (1 txs, 0.06 Mgas, 0 ms, 0.69 KiB) + another 1 block(s) containing 1 tx(s)
parity       | 2018-09-27 14:36:00 UTC Transaction mined (hash 0xc838d956c720eae34b04752a8b2bc361762512d0fdb983fde7bebabfa06b63c5)
client        | 2018-09-27 14:36:00,479[DEBUG] Sent tx: 0xc838d956c720eae34b04752a8b2bc361762512d0fdb983fde7bebabfa06b63c5
client        | 2018-09-27 14:36:00,481[DEBUG] Sent tx: 0x637e268e8da6ff7403ad2c03ce723afd619c174349077c04163229202f314036
client        | 2018-09-27 14:36:00,515[DEBUG] new entries for filter Filter for 0x5: ['0xc838d956c720eae34b04752a8b2bc361762512d0fdb983fde7bebabfa06b63c5']
parity       | 2018-09-27 14:36:03 UTC Imported #27 0x341b…37f8 (2 txs, 0.34 Mgas, 0 ms, 0.79 KiB) + another 1 block(s) containing 2 tx(s)
parity       | 2018-09-27 14:36:03 UTC Transaction mined (hash 0x1a757833012244c503bdd74e16b91be46ab8cde50e97a4622e3dda46373d7488)
parity       | 2018-09-27 14:36:03 UTC Transaction mined (hash 0x637e268e8da6ff7403ad2c03ce723afd619c174349077c04163229202f314036)
parity       | 2018-09-27 14:36:03 UTC Transaction mined (hash 0x2d4e9421e1d9d60c6c371c7561235200aad8f8dca582b39f66ca01b7680f4c8c)
client        | 2018-09-27 14:36:03,321[DEBUG] new entries for filter Filter for 0x2: ['0x637e268e8da6ff7403ad2c03ce723afd619c174349077c04163229202f314036']

As a comparison, this is how it looks if I send in the transaction after each other:

client        | 2018-09-27 14:44:21,384[DEBUG] Sending tx: 0x7f0e1baac164517fbabbea8cad2d47098a2d61cc5a769a87dc65164a341c814a
parity       | 2018-09-27 14:44:21 UTC Transaction mined (hash 0x7f0e1baac164517fbabbea8cad2d47098a2d61cc5a769a87dc65164a341c814a)
parity       | 2018-09-27 14:44:21 UTC Imported #26 0xa2c7…6569 (1 txs, 0.06 Mgas, 0 ms, 0.69 KiB) + another 1 block(s) containing 1 tx(s)
client        | 2018-09-27 14:44:21,391[DEBUG] Sent tx: 0x7f0e1baac164517fbabbea8cad2d47098a2d61cc5a769a87dc65164a341c814a
client        | 2018-09-27 14:44:21,392[DEBUG] Sending tx: 0x3bed1cc2f1dfa6308ab6434c80faf75016be10fafe98e2236c55a30a939c89d0
parity       | 2018-09-27 14:44:21 UTC Transaction mined (hash 0x3bed1cc2f1dfa6308ab6434c80faf75016be10fafe98e2236c55a30a939c89d0)
client        | 2018-09-27 14:44:21,400[DEBUG] Sent tx: 0x3bed1cc2f1dfa6308ab6434c80faf75016be10fafe98e2236c55a30a939c89d0
client        | 2018-09-27 14:44:21,567[DEBUG] new entries for filter Filter for 0x2: ['0x3bed1cc2f1dfa6308ab6434c80faf75016be10fafe98e2236c55a30a939c89d0']
client        | 2018-09-27 14:44:21,729[DEBUG] new entries for filter Filter for 0x5: ['0x7f0e1baac164517fbabbea8cad2d47098a2d61cc5a769a87dc65164a341c814a']

This was an issue before, see #2589, #4494, and it seems it was not fully fixed.

[ltfschoen]

i'm looking into this, waiting to get fully synchronised

[berndbohmeier]

Let me know if you need more input on this.
What do you mean by fully synchronized? This happens with dev settings, so no need to synchronize with any chain.

[ltfschoen]

@berndbohmeier i've uploaded my progress here: https://github.com/ltfschoen/parity-ethereum-issue-9660

Differences in my initial setup:

• using latest nightly version of Parity Ethereum, instead of v2.0.6-stable
• using macOS, instead of Linux with Docker
• using Kovan, instead of Dev chain
• using a Web3 1.0 beta.16 script with WebSockets to send transactions and to subscribe to pending txs and logs from the account the tx is sent from, instead of HTTP RPC

TODO:

• use my initial setup and:
  • add timestamps to Parity Ethereum logs and add timestamps to Node.js script using 'logger' NPM package
  • replicate the logs shown in issue --config=dev doesn't seal properly when transactions are sent in parallel #9660 to see if able to replicate the issue
• change to @berndbohmeier's setup to see if can replicate the issue