Parity-ethereum: PoA authorities don't add TXs from all accounts in block

Created on 22 Aug 2018 · 22Comments · Source: openethereum/parity-ethereum

I'm running:

Which Parity version?: v1.11.8-stable-c754a02-20180725/x86_64-linux-gnu/rustc1.27.2

Which operating system?: Linux

How installed?: one-line installer for Mac and Ubuntu

Are you fully synchronized?: yes

Which network are you connected to?: Private PoA network

Did you try to restart the node?: yes

I have a PoA setup with 3 authorities on 3 separate (large) ec2 instances.
I'm making TXs to each authority from 2 accounts at a rate of 20 TX / sec per account. So there are a total of 6 accounts and 120 TX / sec to the network.
Additionally there are 3 ec2 instances being used to make the TXs - 2 accounts on each instance.

After some time(sometimes ~60+ mins, other times ~5 mins), 2 of the authorities stop adding TXs from one of the two accounts sending it TX. It still creates blocks and adds TXs from the other account. There are no missing nonces. I checked.
Also, the TXs are propagated to all 3 authorities.

If I stop sending TXs from the account being 'ignored', after some time it gradually starts including TXs from the ignored account in the blocks it creates - but very few each block.

Mining config for the authorities:

engine_signer = "0x3e86b3d46fe0494bdd94625cc12984ce1f7ac6ab"
reseal_on_txs = "own"
min_gas_price = 0
relay_set = "lenient"
tx_queue_mem_limit = 0
tx_queue_size = 819200

Step duration = 1 second

Nonce handling is local and is correct.
The instances and parity versions (v1.11.8-stable-c754a02-20180725/x86_64-linux-gnu/rustc1.27.2) are the same. The TXs are propagated across the network.

Why does this happen? The TX queue isn't full, and there are no missing nonces. And why does this happen on only 2/3 authorities?

Will run the authorities with -l own_tx=trace,txqueue and share the logs in a gist.

F3-annoyance 💩 M4-core ⛓ P5-sometimesoon 🌲

Source

aaroncolaco

👍1

Most helpful comment

Same issue here. Sending the exact same way with addresses I've used before results in no issues whatsoever. Fresh accounts (nonce = 0) don't appear to work for me.

Qkyrie on 5 Nov 2018

👍3

All 22 comments

Thanks for the report. Please ping me when you added the logs.

Tbaut on 22 Aug 2018

The gist is here: https://gist.github.com/aaroncolaco/cff2dfc332b5f41327ae14ca0190f3dd

The TX 0x651e71e1ffcddcb4816842a5808ed3dda5885f396377004dac38e7f489c2f039 was one of the TXs that wasn't mined for a long time.
0xa91ce60af465e38a8e441072689cb2a829ad7b6208657dbfb7ce08ccfde79c95 as well

Cc @Tbaut

aaroncolaco on 22 Aug 2018

Thanks for the details. Here are a couple other questions:

Do you sign the transactions locally and then forecast them (with sendRawTransaction) ?
What hardware do the ec2 instances have?
Do you monitor them and see if CPU/RAM/Disk could be the bottleneck?
Do you monitor the blocks (are the blocks full?) you can see that with an explorer such as Etherchain light

After some time(sometimes ~60+ mins, other times ~5 mins), 2 of the authorities stop adding TXs from one of the two accounts sending it TX

Not sure I fully grasp this. Please tell me if this is correct:

3 authorities (A1, A2, A3), receive each ~40TX/s from 2 accounts (ax).
6 accounts (a1, a2, a3.. a6), each sending 20TX/s, sending by pair their TXs to one of the 3 authorities (there are 3 pairs, so that all the authorities receive ~40TX/s).
For instance
- a1 and a2 send their TXs to A1
  - a3 and a4 send their TXs to A2
    
    ...
At some point 2 authorities stop processing the TXs of one of the account in each pair
For instance
- A1 only includes the TXs from a1 (not a2 anymore)
- A2 only includes the TXs from a3 (not a4 anymore)
- A3 includes the TXs from a5 and a6 still

Tbaut on 22 Aug 2018

@Tbaut

Do you sign the transactions locally and then forecast them (with sendRawTransaction) ?

Signed locally and then sent with sendSignedTransaction; not sendRawTransaction

What hardware do the ec2 instances have?

8 vCPU, 16 GiB Mem, 1 x 200 NVMe SSD. Instance type: c5d.2xlarge

Do you monitor them and see if CPU/RAM/Disk could be the bottleneck?

Yes, Not the bottleneck.
For the misbehaving authorities:

CPU 0.2% RAM 2.6% - 3.2% HDD 24%
CPU 0.2% RAM 3.8% - 4.0% HDD 24%
Which is the more or less the same as the the authority that is working properly.

Do you monitor the blocks (are the blocks full?)

Yes the entire gas isn't used even before the misbehaviour starts.
You can see detailed gas usage per block in the gist: https://gist.github.com/aaroncolaco/cff2dfc332b5f41327ae14ca0190f3dd#file-gasuseage-log

And yes. What you describe is exactly what happens

aaroncolaco on 23 Aug 2018

I just noticed:

Soon after the problem started, it took ~30 mins for authority to propagate a TX from the account being ignored
After letting the system run longer, misbehaving authorities stopped propagating TXs completely. Started only after I stopped sending TXs from the account being ignored.

eg.

A1 propagated TXs from a2 very slowly after problem started.
After letting this run for a long time A1 stopped propagating TXs from a2 completely until I stopped sending TXs from a2.
Then A1 started propagating TXs from a1 (still very slowly) and started including in blocks as well.

Misbehaving authority A2 is currently at step 2 from the example above. It is not including TXs from one of the accounts (say a1) and isn't propagating TXs from a1 either.

aaroncolaco on 23 Aug 2018

👍1

Thanks for the details, it looks like the queue doesn't work as expected because of the 0 gas price. We'll need to have a closer look. cc @tomusdrw

Tbaut on 23 Aug 2018

👍2

@Tbaut @tomusdrw, I think this isn't isolated to 0 gas TXs.
I started using random gas values between 1-3, both inclusive.
The problem still arises.

Furthermore, once I stop sending TXs, the authorities stop adding TXs from any account to blocks, infact they stop creating blocks every step.

From parity_allTransactions:

A1 has ~10k from a2
A2 has ~3k from a2
A3 has ~13k from a2

The nonces in the result array obtained are in order.

Eg.
eth.getTransactionCount(acc, 'pending') = 27148 (same without 'pending')
and in the result array obtained from parity_allTransactions the TXs for acc start from 27149 and continue sequentially.

To make the Auths resume creating blocks every step and adding these pending(?) TXs I need to start sending TXs from the associated accounts again. Otherwise they just stay as is. Waited for ~24 hours to this theory :)

PS. in the config file, min_gas_price = 0 is still present. Do you think that is the cause? Even though gasPrice > 0 when sending?

aaroncolaco on 31 Aug 2018

@aaroncolaco could you provide some -lminer=trace logs for us on one of the authority node (or best -lminer=trace,txqueue=trace logs)?

Randomizing between 1-3 might not help either, the problem is that if you have a chain of transactions from an account, say:

Acc1 = Tx(gp=1), Tx(gp=3), Tx(gp=2)
Acc2 = Tx(gp=1), Tx(gp=3)...
Acc3 = Tx(gp=4)

And Acc1 transaction was imported first, and you keep sending transactions from Acc2 and Acc3 the entire chain might be blocked due to this low gas price transaction in front that was imported first (since it always has the lowest priority, and no further transactions from Acc1 are actually affecting that)

That said, it doesn't fully explain the behavior you are observing, specificly:

Furthermore, once I stop sending TXs, the authorities stop adding TXs

So additional logs would be super useful.

tomusdrw on 31 Aug 2018

@tomusdrw, makes sense! Thanks for the explanation.

I started the scripts to make TXs so the auths would start including the TXs again in blocks.
After stopping the scripts the auths went back to the previous state. A1 immediately and A3 in ~15sec

Snippet of logs from A1 for different cases:

when script was running

2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0x6aa88431dcf16b823349e763e233e0cf04c5897de64e5f98a1626a2ad23b058f] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0xe6aae751f2bb4e573730a99d322ed394cb223481f606463220a619292724cd20] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0x47e35fa21a21cc46f2a0b95c88cfa7f8f3c5e364d709e210e203e7ac78669ae7] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0x6439c080cd4d098a5d6c73a253bd5165c312a6f8c23b35da47e8a94fbfeb46c2] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0x984780df686285de00b9022288832167d5d18f8fd70332dffb99fd01999e1082] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0x48e52cdecb2b307866fb731bfef5fc31b0db92702b5b86655973c313819fbaaf] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0xce6376961fa0fe689abc8a6128487670668851a8f8b4ee8d83df0bcc396565a6] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  [0xd8e4996fcb80f8b005b46dd940e652dee56358d3ded9cf8d506ab4250de6eeeb] Mined.
2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  Removed 159 stalled transactions. Pool: 7613/819200 (2 senders; 356/18014398509481983 kB) [minGasPrice: 0 Mwei, maxGas: 4700000]

2018-08-31 07:22:31 UTC IO Worker #1 DEBUG txqueue  Re-computing pending set for block: 13379
2018-08-31 07:22:32 UTC IO Worker #2 TRACE miner  update_sealing
2018-08-31 07:22:32 UTC IO Worker #2 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:33 UTC IO Worker #0 TRACE miner  update_sealing
2018-08-31 07:22:33 UTC IO Worker #0 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  chain_new_blocks
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  minimal_gas_price: recalibrating...
2018-08-31 07:22:34 UTC Verifier #5 DEBUG miner  minimal_gas_price: Got gas price! 0
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  update_sealing
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  requires_reseal: sealing enabled
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  update_sealing: preparing a block
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 07:22:34 UTC Verifier #5 DEBUG txqueue  Re-computing pending set for block: 13380
2018-08-31 07:22:34 UTC Verifier #5 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 07:22:34 UTC Verifier #5 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 07:22:34 UTC Verifier #5 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0x3d60407281a974cabf3aa0b64c6fb455966061ec121a3dbfecb82cdd57d484ae] Mined.2018-08-31 07:22:34 UTC Verifier #5 INFO import  Imported #13380 0x33c4…b5f3 (150 txs, 4.02 Mgas, 3 ms, 20.93 KiB)

2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0x2ecf765f760ca6ef8de7b4d548dd8f79cd54ecd7cfea76c503871a076eb50639] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0x45f06fb0c18319dfeb0ad44f28c796ff4d2ca14c9279a77e80827649763e40c6] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xb761b554f3c9bd65f41008365bd17b3083227f332a5749e38f72e14184237a68] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xb5b6ffd81d58d4fa196bad03f68fd32d2ee1adb4bde5a783fd6db6f85a2710f6] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0x26a139bd6157b9fb69721b87c572f31d8d6a7bee2e578ec64b1017f7ad5dba3b] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xe7b3e57f90b10f71b6d26c28be8cf15f1d02e76c01366aa8f85d99325ca78c9d] Mined.

after stopping script:

2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xe20499a50500657e5c62e2528ff7f2191ac82d6681b8f5df39456c99e3d691b2] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xe0eb299d418146a5effdef4a5b9036989d40e1cc74d3a28036d8d552b37ddc01] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xb82dd538b9397a677c90f89f27d3b6c0a8b5eae12807d6deae1024118c92f4fb] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  [0xb9cb71c9880f5a40b6e8287a20f26a2e21774682990c80e1c40fee971a9bd4a3] Mined.
2018-08-31 07:22:34 UTC IO Worker #3 DEBUG txqueue  Removed 150 stalled transactions. Pool: 7463/819200 (1 senders; 349/18014398509481983 kB) [minGasPrice: 0 Mwei, maxGas: 4700000]

2018-08-31 07:22:35 UTC IO Worker #1 TRACE miner  update_sealing
2018-08-31 07:22:35 UTC IO Worker #1 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:35 UTC IO Worker #1 DEBUG txqueue  Re-computing pending set for block: 13380
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  update_sealing
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  requires_reseal: sealing enabled
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  update_sealing: preparing a block
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 07:22:36 UTC IO Worker #3 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 07:22:36 UTC IO Worker #3 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 07:22:36 UTC IO Worker #3 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 07:22:37 UTC IO Worker #0 TRACE miner  update_sealing
2018-08-31 07:22:37 UTC IO Worker #0 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  update_sealing
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  requires_reseal: sealing enabled
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  update_sealing: preparing a block
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 07:22:38 UTC IO Worker #2 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 07:22:38 UTC IO Worker #2 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 07:22:38 UTC IO Worker #2 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 07:22:39 UTC IO Worker #1 TRACE miner  update_sealing
2018-08-31 07:22:39 UTC IO Worker #1 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  update_sealing
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  requires_reseal: sealing enabled
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  update_sealing: preparing a block
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 07:22:40 UTC IO Worker #3 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 07:22:40 UTC IO Worker #3 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 07:22:40 UTC IO Worker #3 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 07:22:41 UTC IO Worker #0 TRACE miner  update_sealing
2018-08-31 07:22:41 UTC IO Worker #0 TRACE miner  requires_reseal: reseal too early
2018-08-31 07:22:41 UTC IO Worker #0 INFO import     2/25 peers   2 MiB chain 67 MiB db 0 bytes queue 333 KiB sync  RPC:  1 conn,  6 req/s,  29 µs
2018-08-31 07:22:42 UTC IO Worker #2 TRACE miner  update_sealing
2018-08-31 07:22:42 UTC IO Worker #2 TRACE miner  requires_reseal: sealing enabled
2018-08-31 07:22:42 UTC IO Worker #2 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 07:22:42 UTC IO Worker #2 TRACE miner  update_sealing: preparing a block
2018-08-31 07:22:42 UTC IO Worker #2 TRACE miner  prepare_block: No existing work - making n

aaroncolaco on 31 Aug 2018

So it seems, for some reason we consider the transactions in the pool as not ready for inclusion ( see Attempting to push 0 transactions. messages).

Could you run additionally with transaction_pool=trace?

tomusdrw on 31 Aug 2018

Sure. Here you go:

when script was running:

2018-08-31 09:48:53 UTC IO Worker #0 TRACE miner  update_sealing
2018-08-31 09:48:53 UTC IO Worker #0 TRACE miner  requires_reseal: reseal too early
2018-08-31 09:48:53 UTC IO Worker #0 INFO import     2/25 peers   148 KiB chain 67 MiB db 0 bytes queue 21 KiB sync  RPC:  1 conn, 52 req/s,  26 µs
2018-08-31 09:48:53 UTC IO Worker #3 DEBUG txqueue  Re-computing pending set for block: 13388
2018-08-31 09:48:53 UTC IO Worker #3 TRACE transaction_pool::pool  [0x58ff7da11d5099c80d71a53d819cc848a3836f319a6c659516f7d0ff4cc3100e] Ignoring Future transaction.
2018-08-31 09:48:53 UTC IO Worker #3 TRACE transaction_pool::pool  [0x3f2a53be3ba0cb476e41f374174303515be7a211c8166bc48246d4908ca4a364] Ignoring Future transaction.
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  update_sealing
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  requires_reseal: sealing enabled
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  update_sealing: preparing a block
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Attempting to push 63 transactions.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Adding tx 0x00c69d0c7be2659b87d4e7031647090772d328525943fb42850631cec8657ee8 took 0 ms
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Adding tx 0x87e18ccaf0375068e4777691fd842144d6d6137a1328b8f64fe1c83427ec5afa took 0 ms
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Adding tx 0xd938cf1175b7da9de92444bf8c60cc8958fb0c2776d45eb5d6144ca465130e9f took 0 ms
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Adding tx 0xce27f3163974bd859ca70719f6d155a24e6aaf97f9889d33115b43d2f4d1e457 took 0 ms
.
.
.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Adding tx 0x3f8ec4d9498610b53c26c1cd0e9a5875ade287fc0e1bebee27b49f5d8b4a4f80 took 0 ms
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  Pushed 63 transactions in 2 ms
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  seal_block_internally: attempting internal seal.
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  Received a Regular seal.
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  chain_new_blocks
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  minimal_gas_price: recalibrating...
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG miner  minimal_gas_price: Got gas price! 0
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x3f8ec4d9498610b53c26c1cd0e9a5875ade287fc0e1bebee27b49f5d8b4a4f80] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x5c720e3b9874633ead11c614db449e9bfee60808514c188448438559a4347d0c] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0xa1c3077b7a218973dbca7ebd50d4d1d5b65b13920f48182c8f9e14f3e9f56769] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x3f14030aec916a17918cfb4654798e42c832d9e886cb26ce331aee56eff2ecd3] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x3a814a4d867f6d14477b027917f64c78d780d2008990bed20243485482b3a66c] Mined.
.
.
.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x70c09f6fb6da9e6c80db83b55dac229354dfcc9c8d6b0d70202cfe6e3dc2eab5] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x564d0b533cf2ca1aba2ccfbcacce3f7f1bf98cdfb6c9eeddc21d48a53081f266] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x62e99c6c4d0ccbf121be7eec5c6ea23f2ea8b9b6ac31a3c116814a6804da90c7] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x503ef913926c7e059a743fbe27ee39e128acbb286c128beb79317c7cbce6701c] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0xce27f3163974bd859ca70719f6d155a24e6aaf97f9889d33115b43d2f4d1e457] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0xd938cf1175b7da9de92444bf8c60cc8958fb0c2776d45eb5d6144ca465130e9f] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x87e18ccaf0375068e4777691fd842144d6d6137a1328b8f64fe1c83427ec5afa] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  [0x00c69d0c7be2659b87d4e7031647090772d328525943fb42850631cec8657ee8] Mined.
2018-08-31 09:48:54 UTC IO Worker #3 DEBUG txqueue  Removed 63 stalled transactions. Pool: 7367/819200 (2 senders; 345/18014398509481983 kB) [minGasPrice: 0 Mwei, maxGas: 4700000]

2018-08-31 09:48:54 UTC IO Worker #3 INFO import  Imported #13389 0x3b00…824a (63 txs, 1.69 Mgas, 2 ms, 9.12 KiB)
2018-08-31 09:48:54 UTC IO Worker #3 TRACE miner  update_sealing: imported internally sealed block
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0xd86df3296cbf1072a10989b59ff566716a6890fc311af377c09ae01f8ad9c20d] Added to the pool.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0xd86df3296cbf1072a10989b59ff566716a6890fc311af377c09ae01f8ad9c20d] Sender: 0xa22d…9a6d, nonce: 190495, gasPrice: 2, gas: 450000, value: 0, dataLen: 36))
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0xe8066058625a98e3b4fa3e39d94a7d75d5e0aae0fdc2cb9cbc31286b06cdda7d] Added to the pool.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0xe8066058625a98e3b4fa3e39d94a7d75d5e0aae0fdc2cb9cbc31286b06cdda7d] Sender: 0xa22d…9a6d, nonce: 190496, gasPrice: 1, gas: 450000, value: 0, dataLen: 36))
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x3ed33eff24cae4e94a5f4c888923bc34ab35747238c33aef427be51b143761a0] Added to the pool.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x3ed33eff24cae4e94a5f4c888923bc34ab35747238c33aef427be51b143761a0] Sender: 0xa22d…9a6d, nonce: 190497, gasPrice: 1, gas: 450000, value: 0, dataLen: 36))
.
.
.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x086e7e4493647864923858c48d673e53b65edd31e34dc2e876f68bf8f12ae2af] Added to the pool.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x086e7e4493647864923858c48d673e53b65edd31e34dc2e876f68bf8f12ae2af] Sender: 0xa22d…9a6d, nonce: 190518, gasPrice: 2, gas: 450000, value: 0, dataLen: 36))
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x1795be8cf37a1c09cdf6477aaaba74e14ff18df1486e15bb0b98a7b49cff03ab] Added to the pool.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  [0x1795be8cf37a1c09cdf6477aaaba74e14ff18df1486e15bb0b98a7b49cff03ab] Sender: 0xa22d…9a6d, nonce: 190519, gasPrice: 2, gas: 450000, value: 0, dataLen: 36))
2018-08-31 09:48:54 UTC IO Worker #2 TRACE miner  update_sealing
2018-08-31 09:48:54 UTC IO Worker #2 TRACE miner  requires_reseal: sealing enabled
2018-08-31 09:48:54 UTC IO Worker #2 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 09:48:54 UTC IO Worker #2 TRACE miner  update_sealing: preparing a block
2018-08-31 09:48:54 UTC IO Worker #2 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG txqueue  Re-computing pending set for block: 13389
2018-08-31 09:48:54 UTC IO Worker #2 TRACE transaction_pool::pool  [0x58ff7da11d5099c80d71a53d819cc848a3836f319a6c659516f7d0ff4cc3100e] Ignoring Future transaction.
2018-08-31 09:48:54 UTC IO Worker #2 TRACE transaction_pool::pool  [0x3f2a53be3ba0cb476e41f374174303515be7a211c8166bc48246d4908ca4a364] Ignoring Future transaction.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Attempting to push 25 transactions.
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0xd86df3296cbf1072a10989b59ff566716a6890fc311af377c09ae01f8ad9c20d took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0xe8066058625a98e3b4fa3e39d94a7d75d5e0aae0fdc2cb9cbc31286b06cdda7d took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0x3ed33eff24cae4e94a5f4c888923bc34ab35747238c33aef427be51b143761a0 took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0xf365552a64797c22d4ca402ddfb668fb8be3ec12544bc2a3ead52e5b6a651a6e took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0x60a270af3ff6002056e622c2b41d0295014de2aceeba10033cf4bef5f0f6ffea took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0x7c3458a2a48be49ef943d4062238a63883f45d503960ab6368afce51d62ee35b took 0 ms
2018-08-31 09:48:54 UTC IO Worker #2 DEBUG miner  Adding tx 0x69ec21f7aba5a2df37f5866cb9144559ea41a5cbaef70c873d694b5fe9bbd258 took 0 ms

after stopping script:

2018-08-31 09:51:33 UTC IO Worker #3 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 09:51:33 UTC IO Worker #3 TRACE miner  update_sealing: preparing a block
2018-08-31 09:51:33 UTC IO Worker #3 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 09:51:33 UTC IO Worker #3 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 09:51:33 UTC IO Worker #3 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 09:51:33 UTC IO Worker #3 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 09:51:34 UTC IO Worker #2 TRACE miner  update_sealing
2018-08-31 09:51:34 UTC IO Worker #2 TRACE miner  requires_reseal: reseal too early
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  update_sealing
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  requires_reseal: sealing enabled
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  update_sealing: preparing a block
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 09:51:35 UTC IO Worker #1 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 09:51:35 UTC IO Worker #1 DEBUG miner  Pushed 0 transactions in 0 ms
2018-08-31 09:51:35 UTC IO Worker #1 TRACE miner  update_sealing: engine indicates internal sealing
2018-08-31 09:51:36 UTC IO Worker #0 TRACE miner  update_sealing
2018-08-31 09:51:36 UTC IO Worker #0 TRACE miner  requires_reseal: reseal too early
2018-08-31 09:51:37 UTC IO Worker #3 TRACE miner  update_sealing
2018-08-31 09:51:37 UTC IO Worker #3 TRACE miner  requires_reseal: sealing enabled
2018-08-31 09:51:37 UTC IO Worker #3 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
2018-08-31 09:51:37 UTC IO Worker #3 TRACE miner  update_sealing: preparing a block
2018-08-31 09:51:37 UTC IO Worker #3 TRACE miner  prepare_block: No existing work - making new block
2018-08-31 09:51:37 UTC IO Worker #3 DEBUG miner  Attempting to push 0 transactions.
2018-08-31 09:51:37 UTC IO Worker #3 DEBUG miner  Pushed 0 transactions in 0 ms

aaroncolaco on 31 Aug 2018

@tomusdrw, was that any help at all?

Also, PR #42 fixes the main issue right? When will it be available? I have v1.11.10 and it doesn't seem to be available.
@Tbaut

aaroncolaco on 6 Sep 2018

https://github.com/paritytech/parity-common/pull/42 was not back-ported to 1.11.10 or 2.0.3 as it is part of a bigger re-factoring (it will most probably get included in 2.1).
Could you build the master branch of Parity Ethereum and test with it?

Tbaut on 6 Sep 2018

👍1

@Tbaut @tomusdrw, I built from source - v2.1.0-nightly-6888a96-20180906. The problem seems to still be present:

Following the earlier terminology, accounts a1 and a2 on A2 get ignored.

I checked the block author signatures and A2 doesn't seem to be creating blocks as frequently as A1 & A3. A1 is 0x3e86b3d46fe0494bdd94625cc12984ce1f7ac6ab.

> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26110
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"
> n--
26109
> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26108
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"
> n--
26107
> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26106
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"
> n--
26105
> eth.getBlock(n).author
"0x3e86b3d46fe0494bdd94625cc12984ce1f7ac6ab"
> n--
26104
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"
> n--
26103
> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26102
> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26101
> eth.getBlock(n).author
"0x3e86b3d46fe0494bdd94625cc12984ce1f7ac6ab"
> n--
26100
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"
> n--
26099
> eth.getBlock(n).author
"0xbbef5f52b81188b11e1782dc5ebab9a48cc3123a"
> n--
26098
> eth.getBlock(n).author
"0x4dde05871b373f8ab2210f2b4e49b795946e3dc3"

aaroncolaco on 7 Sep 2018

And after stopping the scripts, the other problem is present still.
Nonces are in correct order in queue but no TXs are being mined.

aaroncolaco on 7 Sep 2018

@tomusdrw @5chdn @andresilva @Tbaut any idea when this might be solved?
I'm building a product using parity for the blockchain layer and this is the only thing holding us back from launching.

aaroncolaco on 18 Sep 2018

I'm having a similar problem, all Txs signed locally are sitting pending in the Tx pool indefinitely.

Has anybody found any approach for this?

dmihal on 2 Nov 2018

👍3

Same issue here. Sending the exact same way with addresses I've used before results in no issues whatsoever. Fresh accounts (nonce = 0) don't appear to work for me.

Qkyrie on 5 Nov 2018

👍3

Can you guys run with --tx-queue-per-sender 1024 and provide some logs when running with -ltxqueue=debug,miner=trace

tomusdrw on 6 Nov 2018

@tomusdrw I'm still seeing this issue. I've run the node as you described, the logs are here:

https://pastebin.com/JUMjALii

dmihal on 12 Dec 2018

👍2

@dmihal It seems that you have one transaction in the pool that is future (i.e. has nonce that doesn't match the state). Such transactions can't be included in a block. Restarting with --no-persistent-txqueue will remove that transaction.
The question is how did you end up with situation like this, I'd need logs from earlier when transactions are imported.
If you manage the nonce manually then you need to make sure that it's consecutive.

tomusdrw on 17 Dec 2018

Closing issue due to its stale state.