dev chain compatibility break in dev chain between v2.5.8-stable and v2.5.7-stable

[jimy74]

• Parity Ethereum version: v2.5.8-stable
• Operating system: Linux
• Installation: docker
• Fully synchronized: yes (dev chain)
• Network: dev chain
• Restarted: no

I'm using the dev chain for tests with the version v2.5.7-stable and it work well to send a tx from the default coinbase (nonce 0, chainId 11, ...).

The exact same test by starting parity in the exact same way do the error "Transaction marked invalid". (the sender have funds as it is asserted before) in my script.

Way to start parity :

parity --chain dev --jsonrpc-cors all --jsonrpc-interface all --jsonrpc-apis all --jsonrpc-hosts all
--tracing on --pruning archive -l rpc=trace,own_tx=trace

It's the proof that the compatibility is broken between the two releases for this feature.

Any guess how to fix that?

[dvdplm]

Can you provide a step-by-step description of how to repeat this? I don't understand exactly what commands you are running and what the expected output is.

[jimy74]

I run my service with a docker-compose file like that :

version: '2.4'

services:

  #1- My service well connected to Parity
 
  #2- Parity
  parity:
    image: parity/parity:v2.5.8-stable
    container_name: parity
    hostname: parity
    ports:
      - ${P_PORT:-8545:8545}
    command: >
      --chain dev --jsonrpc-cors all --jsonrpc-interface all --jsonrpc-apis all --jsonrpc-hosts all --min-gas-price 1000000000
      --tracing on --pruning archive -l rpc=trace,own_tx=trace

Then using web3j I send a first transaction :

> docker-compose logs -f parity | grep -F RawT -C 5
parity         | 2019-11-25 12:29:19 UTC jsonrpc-eventloop-1 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_gasPrice","params":[],"id":1}.
parity         | 2019-11-25 12:29:19 UTC jsonrpc-eventloop-1 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x4190ab00","id":1}.
parity         | 2019-11-25 12:29:19 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_getTransactionCount","params":["0x00a329c0648769a73afac7f9381e08fb43dbea72","pending"],"id":2}.
parity         | 2019-11-25 12:29:19 UTC jsonrpc-eventloop-0 WARN parity_rpc::v1::impls::eth  Fallback to `BlockId::Latest`
parity         | 2019-11-25 12:29:19 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x0","id":2}.
parity         | 2019-11-25 12:29:20 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_sendRawTransaction","params":["0xf86380844190ab00825208949b7b82c44bd549bb74426d97f527cc10dbd586a52a8039a0ce6c2240c34e06958f56285abedc464b34243498744e5df4ea37e633c5b967f5a07461a641adfacb93337a1061e2a67b1946b6199605f14c6f81dfee32e32d580f"],"id":3}.
parity         | 2019-11-25 12:29:20 UTC jsonrpc-eventloop-0 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 0, gas_price: 1100000000, gas: 21000, action: Call(0x9b7b82c44bd549bb74426d97f527cc10dbd586a5), value: 42, data: [] }, v: 57, r: 93367502696529313883976933879555035421805512230597068617378244464984756676597, s: 52640822061554702555567599384921379250662631745803293641737261576892797769743, hash: 0xad88cb4984ba2e63003a80fd5afe59bad9a7db2bdbd17a934b2c56bb61b9dc36 }, sender: 0x00a329c0648769a73afac7f9381e08fb43dbea72, public: Some(0x3fa8c08c65a83f6b4ea3e04e1cc70cbe3cd391499e3e05ab7dedf28aff9afc538200ff93e3f2b2cb5029f03c7ebee820d63a4c5a9541c83acebe293f54cacf0e) }, condition: None }
parity         | 2019-11-25 12:29:20 UTC jsonrpc-eventloop-0 DEBUG own_tx  Imported to the pool (hash 0xad88cb4984ba2e63003a80fd5afe59bad9a7db2bdbd17a934b2c56bb61b9dc36)
parity         | 2019-11-25 12:29:20 UTC jsonrpc-eventloop-0 WARN own_tx  Transaction marked invalid (hash 0xad88cb4984ba2e63003a80fd5afe59bad9a7db2bdbd17a934b2c56bb61b9dc36)

The transaction fo the test fail and it's not the case if I run the exact same docker-compose on the version 2.5.7-stable :

> docker-compose logs -f parity | grep -F RawT -C 5
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_gasPrice","params":[],"id":1}.
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x4190ab00","id":1}.
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_getTransactionCount","params":["0x00a329c0648769a73afac7f9381e08fb43dbea72","pending"],"id":2}.
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 WARN parity_rpc::v1::impls::eth  Fallback to `BlockId::Latest`
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x0","id":2}.
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_sendRawTransaction","params":["0xf86380844190ab0082520894373352ea752db0dec750ff61f36a6c15970f5a8b2a803aa0f85b97cd97bb116b560c33fcd3f174726659c7446483ef7318203716e587c015a00c222d1e259a71e640deffaa522c37fb75c1fefbf7d3f83eb8962c0f93abdb0c"],"id":3}.
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 0, gas_price: 1100000000, gas: 21000, action: Call(0x373352ea752db0dec750ff61f36a6c15970f5a8b), value: 42, data: [] }, v: 58, r: 112335417238011440803302954704434089682558007460611480258943380025210388856853, s: 5488138374545757064091867651842876307870794716938000639086376516304782482188, hash: 0x9bf3d1414f8dd0afc96cc14d4ee83c16b6b0df3051351a7c7af7d436ee34fb58 }, sender: 0x00a329c0648769a73afac7f9381e08fb43dbea72, public: Some(0x3fa8c08c65a83f6b4ea3e04e1cc70cbe3cd391499e3e05ab7dedf28aff9afc538200ff93e3f2b2cb5029f03c7ebee820d63a4c5a9541c83acebe293f54cacf0e) }, condition: None }
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 DEBUG own_tx  Imported to the pool (hash 0x9bf3d1414f8dd0afc96cc14d4ee83c16b6b0df3051351a7c7af7d436ee34fb58)
parity         | 2019-11-25 12:58:45 UTC IO Worker #3 INFO own_tx  Transaction mined (hash 0x9bf3d1414f8dd0afc96cc14d4ee83c16b6b0df3051351a7c7af7d436ee34fb58)
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 INFO import  Imported #1 0xeb29…e1ad (1 txs, 0.02 Mgas, 1 ms, 0.59 KiB)
parity         | 2019-11-25 12:58:45 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x9bf3d1414f8dd0afc96cc14d4ee83c16b6b0df3051351a7c7af7d436ee34fb58","id":3}.
--
parity         | 2019-11-25 12:58:55 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_gasPrice","params":[],"id":6}.
parity         | 2019-11-25 12:58:55 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x4190ab00","id":6}.
parity         | 2019-11-25 12:58:55 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_getTransactionCount","params":["0x00a329c0648769a73afac7f9381e08fb43dbea72","pending"],"id":7}.
parity         | 2019-11-25 12:58:55 UTC jsonrpc-eventloop-0 WARN parity_rpc::v1::impls::eth  Fallback to `BlockId::Latest`
parity         | 2019-11-25 12:58:55 UTC jsonrpc-eventloop-0 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0x1","id":7}.

The environment is well clean up between both run.

I sign in both time using parity dev chain default privateKey (public 0x00a329c0648769A73afAc7F9381E08FB43dBEA72)

By decoding the transaction I see that they have a identical chain ID:

// chainId, nonce, gasPrice, gasLimit, from, to, value, data
buggy2.5.8tx = DecodedRawTransaction(11,0,1100000000,21000,0x00a329c0648769a73afac7f9381e08fb43dbea72,S0x9b7b82c44bd549bb74426d97f527cc10dbd586a5,42,0x)
passing2.5.7tx = 
DecodedRawTransaction = DecodedRawTransaction(11,0,1100000000,21000,0x00a329c0648769a73afac7f9381e08fb43dbea72,0x373352ea752db0dec750ff61f36a6c15970f5a8b,42,0x)

The destination is different as it is generated by the test but don't matter in this case.

All the rest is the same as well as I use docker-compose for the test and do a "docker-compose down -v; docker-compose up" between both tests.

According to the list of changes I did not found the reason yet but it prevent me form upgrading for the dev chain, blocked on that since days.

If any one can reproduce that bug it should be quick with the docker-compose I provide and see if it fail for you so if it's the case we can fix this together.

[jimy74]

Both tx are exactly the same, signature included, it work on 2.5.7 not on 2.5.8!

bad :

parity         | 2019-11-27 18:36:17 UTC jsonrpc-eventloop-1 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_sendRawTransaction","params":["0xf86380844190ab0082520894c1d98b86fab376fca9d8291c3097a872472a6eee2a803aa0ec08c77b50e84cf111799109a113fccc0787b9f4389817e777b511b4f6deb550a0506c4747fea7f74eca8c955e3f19df91c1b3ae99fef5654dc4292e5fa5874d99"],"id":4}.
parity         | 2019-11-27 18:36:17 UTC jsonrpc-eventloop-1 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 0, gas_price: 1100000000, gas: 21000, action: Call(0xc1d98b86fab376fca9d8291c3097a872472a6eee), value: 42, data: [] }, v: 58, r: 106761343814286092350774131792736198695710060052800679130080626691587008542032, s: 36376339334622631382544306147930787679530227303871264105909102260383209967001, hash: 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec }, sender: 0x00a329c0648769a73afac7f9381e08fb43dbea72, public: Some(0x3fa8c08c65a83f6b4ea3e04e1cc70cbe3cd391499e3e05ab7dedf28aff9afc538200ff93e3f2b2cb5029f03c7ebee820d63a4c5a9541c83acebe293f54cacf0e) }, condition: None }

good :

parity         | 2019-11-27 18:47:25 UTC jsonrpc-eventloop-1 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_sendRawTransaction","params":["0xf86380844190ab0082520894c1d98b86fab376fca9d8291c3097a872472a6eee2a803aa0ec08c77b50e84cf111799109a113fccc0787b9f4389817e777b511b4f6deb550a0506c4747fea7f74eca8c955e3f19df91c1b3ae99fef5654dc4292e5fa5874d99"],"id":4}.
parity         | 2019-11-27 18:47:25 UTC jsonrpc-eventloop-1 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 0, gas_price: 1100000000, gas: 21000, action: Call(0xc1d98b86fab376fca9d8291c3097a872472a6eee), value: 42, data: [] }, v: 58, r: 106761343814286092350774131792736198695710060052800679130080626691587008542032, s: 36376339334622631382544306147930787679530227303871264105909102260383209967001, hash: 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec }, sender: 0x00a329c0648769a73afac7f9381e08fb43dbea72, public: Some(0x3fa8c08c65a83f6b4ea3e04e1cc70cbe3cd391499e3e05ab7dedf28aff9afc538200ff93e3f2b2cb5029f03c7ebee820d63a4c5a9541c83acebe293f54cacf0e) }, condition: None }

It happen at the exact same moment after reproducing it in a clean environment...
Please tell me how do you run the dev chain and make it working, what do break between both version?

[seunlanlege]

Hey @tomusdrw

this is a weird one, the transaction is successfully imported into the queue only to be marked as invalid immediately after. Under what conditions can this happen?

[tomusdrw]

@jimy74 It seems that you use getTransactionCount(<hash>, 'pending') to get a transaction nonce, is that correct?
Do you produce/submit multiple transactions in a loop or is it just this one?
Can you check if you don't submit the same transaction twice?
Do you mind providing more logs with -lminer=trace?

@seunlanlege I believe it might be related to the changes we did to InstantSeal, but I'm not exactly sure what's a reproduction case. Pretty much we consider the transaction valid when verified against latest state, but right after that when we attempt to create a new pending block we detect that it's invalid (it might be some other transactions already in the block spending the same funds for instance, or having the same nonce).

[jimy74]

It is the first transaction I sent on the node... the transaction count is 0 and no pending txs

(I though it was fixed on master but it is not)

No solution found yet, coming back with more logs soon

[jimy74]

@tomusdrw Yes I use getTransactionCount to get the nonce, but anyway it bug at the first transaction ever broadcasted and then it wait that is is included in a block (or fail in this case).
So the issue is obviously not related to the nonce, I tried with the nonce 1 for fun but same error message "transaction marked as invalid".

More logs with miner=debug :

y         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE rpc  Request: {"jsonrpc":"2.0","method":"eth_sendRawTransaction","params":["0xf86380844190ab0082520894c1d98b86fab376fca9d8291c3097a872472a6eee2a803aa0ec08c77b50e84cf111799109a113fccc0787b9f4389817e777b511b4f6deb550a0506c4747fea7f74eca8c955e3f19df91c1b3ae99fef5654dc4292e5fa5874d99"],"id":4}.
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 0, gas_price: 1100000000, gas: 21000, action: Call(0xc1d98b86fab376fca9d8291c3097a872472a6eee), value: 42, data: [] }, v: 58, r: 106761343814286092350774131792736198695710060052800679130080626691587008542032, s: 36376339334622631382544306147930787679530227303871264105909102260383209967001, hash: 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec }, sender: 0x00a329c0648769a73afac7f9381e08fb43dbea72, public: Some(0x3fa8c08c65a83f6b4ea3e04e1cc70cbe3cd391499e3e05ab7dedf28aff9afc538200ff93e3f2b2cb5029f03c7ebee820d63a4c5a9541c83acebe293f54cacf0e) }, condition: None }
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 DEBUG own_tx  Imported to the pool (hash 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec)
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE miner  update_sealing
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE miner  requires_reseal: sealing enabled
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE miner  requires_reseal: should_disable_sealing=false; forced=false, has_local=true, internal=Some(true), had_requests=false
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE miner  update_sealing: preparing a block
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 TRACE miner  prepare_block: No existing work - making new block
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 DEBUG miner  Attempting to push 1 transactions.
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 DEBUG miner  Adding tx 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec took 0 ms
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 DEBUG miner  Error adding transaction to block: number=1. transaction_hash=0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec, Error: Error(Transaction(InvalidChainId), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
parity         |    0:     0x5564443db70d - <no info>
parity         |    1:     0x5564441af6ec - <no info>
parity         |    2:     0x5564444b009b - <no info>
parity         |    3:     0x5564444b5dfe - <no info>
parity         |    4:     0x5564444b5a8e - <no info>
parity         |    5:     0x5564444b79fb - <no info>
parity         |    6:     0x5564447d1a61 - <no info>
parity         |    7:     0x55644341885c - <no info>
parity         |    8:     0x5564434737ae - <no info>
parity         |    9:     0x5564445ecbe0 - <no info>
parity         |   10:     0x5564445f3ba2 - <no info>
parity         |   11:     0x556444609e8b - <no info>
parity         |   12:     0x556444669cce - <no info>
parity         |   13:     0x55644466b3d5 - <no info>
parity         |   14:     0x55644466b3d5 - <no info>
parity         |   15:     0x5564444aa716 - <no info>
parity         |   16:     0x556444797556 - <no info>
parity         |   17:     0x5564445c5256 - <no info>
parity         |   18:     0x5564442d058d - <no info>
parity         |   19:     0x5564442cd3a2 - <no info>
parity         |   20:     0x5564442cb3e2 - <no info>
parity         |   21:     0x5564442b12fe - <no info>
parity         |   22:     0x5564442cdfcb - <no info>
parity         |   23:     0x5564442ceadf - <no info>
parity         |   24:     0x55644443938e - <no info>
parity         |   25:     0x55644443bf1b - <no info>
parity         |   26:     0x7f160bf166b9 - <no info>
parity         |   27:     0x7f160ba3641c - <no info>
parity         |   28:                0x0 - <no info>) } })
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 DEBUG miner  Pushed 0 transactions in 12 ms
parity         | 2019-12-02 16:37:44 UTC jsonrpc-eventloop-0 WARN own_tx  Transaction marked invalid (hash 0x65f0c7a4764e524c8196d87ee31a8e75de686630de4467eb8516c088f0b2b5ec)

WOW! What is the chainId now?! Why does the chainId 11 work fine with the 2.5.7 but not with the 2.5.8?!

I retry by running parity with --network-id 11 and the issue is still the same!

[ordian]

could be related to #10954

[jimy74]

Wow it is because of that it was working with whatever chainId I was putting before.

• I was setting chainID 11 but it should be 17 as it is set in hex...

So it is fixed and it we using the wrong chainID so I get rejected after your fix.

A big thanks to you all, sorry for disturging, this change of behavior was look like strange but it is not buggy but just better! Good job guys and thanks a lot!

[tomusdrw]

Transactions with invalid chainId should not be imported to the pool at all. You should get this error much earlier.
chainId is not really even a runtime parameter, it's known and stays constant at all times.