Go-ethereum: Transactions being given the same nonce

Created on 26 Aug 2016 · 28Comments · Source: ethereum/go-ethereum

(Hi, just quickly... I'm not sure if this is geth of web3.js. But my test code works consistently in 1.4 stable... and I couldn't see where web3.js was taking care of the nonce. If this is in the wrong project, apologies!).

System information

Geth version:
Version: 1.5.0-unstable-5fc032a9
Protocol Versions: [63 62]
Network Id: 1
Go Version: go1.7
OS: darwin
GOPATH=/Users/elliot/.go
GOROOT=/usr/local/opt/go/libexec

OS & Version: OSX 10.11.5

Commit hash : 5fc032a9

Expected behaviour

Transactions are added to pending, then I can retrieve receipts.

Actual behaviour

Transactions are added to pending (and I receive their id), but not all are mined... a receipt is never available for some of them.

Steps to reproduce the behaviour

I'm calling a contract method 20 times, concurrently. I'm seeing random numbers of them actually get mined. The others have duplicated nonces. Smells like a race somewhere :)

Logging web3.eth.pendingTransactions in the console shows that there are 20 transactions in the list, but that some have the same nonce.

Here is an example of the first two in that array

{
    "blockHash": null,
    "blockNumber": null,
    "from": "0x007ccffb7916f37f7aeef05e8096ecfbe55afc2f",
    "gas": 10000000,
    "gasPrice": "20000000000",
    "hash": "0xfa0ed40399052ddb7c122b1ec7c4e8f16a948af3ff45cb1a5ecf895b937474b3",
    "input": "0x9cbf9e36",
    "nonce": 6,
    "r": "0x2a35320723a78e820762af60c5565918def6d0d382f9d2d687dfa2815f7efe99",
    "s": "0x49d122640da031bac203e14fa1c7160e5dcd0dd4e1397cd61cb5945acfa1f3c5",
    "to": "0xa7b3058152165c72a4dd7c4812c5964f1c26f00d",
    "transactionIndex": null,
    "v": "0x1c",
    "value": "0"
}, {
    "blockHash": null,
    "blockNumber": null,
    "from": "0x007ccffb7916f37f7aeef05e8096ecfbe55afc2f",
    "gas": 10000000,
    "gasPrice": "20000000000",
    "hash": "0x464bcd9e69b0dd9198bad88b46decbb03a6d2daedf1e4993f57ce8c4f29d2f49",
    "input": "0x9cbf9e36",
    "nonce": 6,
    "r": "0x2e43e4613a099a0b2e8391ce89b0cfa7add53cf64f920b7691721be4d6d079ff",
    "s": "0xc9b762646322c2fd032a38f76cd3763dd7b57b65d9b05d1b80f708985805f90",
    "to": "0xa7b3058152165c72a4dd7c4812c5964f1c26f00d",
    "transactionIndex": null,
    "v": "0x1b",
    "value": "0"
}

Backtrace

Shows the contract being created, then called 20 times.

I0826 12:13:54.771679 internal/ethapi/api.go:950] Tx(0x3a97352ffc165ad6339221cd7a7e17c7a370b45f7728b3559f5c8096b4106fa2) created: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:57.538333 miner/worker.go:339] 🔨  Mined block (#1 / 0b069762). Wait 5 blocks for confirmation
I0826 12:13:57.540536 miner/worker.go:573] commit new work on block 2 with 1 txs & 0 uncles. Took 2.168224ms
I0826 12:13:57.541556 miner/worker.go:573] commit new work on block 2 with 1 txs & 0 uncles. Took 972.512µs
I0826 12:13:58.935372 miner/worker.go:339] 🔨  Mined block (#2 / 68e3798f). Wait 5 blocks for confirmation
I0826 12:13:58.935526 miner/worker.go:573] commit new work on block 3 with 0 txs & 0 uncles. Took 128.169µs
I0826 12:13:58.935648 miner/worker.go:573] commit new work on block 3 with 0 txs & 0 uncles. Took 96.216µs
I0826 12:13:59.374472 internal/ethapi/api.go:952] Tx(0x3379fb531e864c7e6a195184419cdb3a9fb1ac7e19299710152ed4c0f834d186) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.375223 internal/ethapi/api.go:952] Tx(0x302eff801a1699f8147d417ea67fe3bad20912e18cb3f0e4f9815884d9921d4e) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.376272 internal/ethapi/api.go:952] Tx(0x1e8ecde880cc118855b1f8ee4f7ff41d4a2e22fdd7c3c7d788e8badc1e306bad) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.377251 internal/ethapi/api.go:952] Tx(0xfa92f9bc4c6970b1ff718dfb1cc0acbc42afbd069fd8446ad6fba132dbab6889) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.378663 internal/ethapi/api.go:952] Tx(0x560c1f825d905e3f1634f9ab1a46ba378e3839435949c6d90bbd9648ac414075) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.379475 internal/ethapi/api.go:952] Tx(0x4c0cf1e74cf69e362a791a7f1762196f6f21a9e15f04b10bf084476bad80c64e) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.380702 internal/ethapi/api.go:952] Tx(0xe9c99ce80cf8764154b5cc549dc6c4084ec37b86385b176e05a9ec74703118cf) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.382205 internal/ethapi/api.go:952] Tx(0x5b2e96d5061463cd20370b8acc6e975e97235f76ee4dc21516e15960e102c2ff) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.383315 internal/ethapi/api.go:952] Tx(0x761dc70915eb7fd96ff29ef5279524093248518eece9e2cf616dda3f8c2b5af1) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.384007 internal/ethapi/api.go:952] Tx(0xb2a88c4cd84856327fc4a3561321006f3912db61549d380059b8b0bb331b2d55) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.384949 internal/ethapi/api.go:952] Tx(0xf211ee03087616ea0c3c6cfd0d3798d01e4952a8c8bec46b35642883d0fb7aab) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.386053 internal/ethapi/api.go:952] Tx(0xdcdc05d2bbbbe31c85bf4c8289bb109e70e516b8074013a6ab36aec436f7cab1) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.387071 internal/ethapi/api.go:952] Tx(0x907d6e362d25366505490e8aa90834888bf08ea51184810b474a5e5b5d0c3cff) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.387698 internal/ethapi/api.go:952] Tx(0xfa3892fb6d4b51a166ed5fe9a4be4fcc3b2587f5f6446d4f681925bafb81ce41) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.388689 internal/ethapi/api.go:952] Tx(0xdabd7676a98ce530bfe1a48416a29795df195fb766a890508017eb190c44dd4a) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.389226 internal/ethapi/api.go:952] Tx(0x310c15dc3922b5e8a18d8e5b7fb1cbf562e1f9e11afabe143af4428fa9031200) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.466840 internal/ethapi/api.go:952] Tx(0xac821bb3c6d121173f91e81d9043edc05558fd284bbc1190bbf5aee9ffa93522) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.467598 internal/ethapi/api.go:952] Tx(0x61af9988b7dfa793b54fdd4490c2ec86ac1b4973b6f20066413ead5056f03769) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.468421 internal/ethapi/api.go:952] Tx(0x11ddfec62709611e3367666f04caa39b5b16acf620d4d0645646fb4107b6a040) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.469260 internal/ethapi/api.go:952] Tx(0x6a040baf67ef0faf55dc084d26ce10550fb6f0d13e4371d5b31640d994c940c4) to: 0xdb571079af66edbb1a56d22809584d39c20001d9
I0826 12:13:59.844582 miner/worker.go:339] 🔨  Mined block (#3 / 346586ff). Wait 5 blocks for confirmation
I0826 12:13:59.848443 miner/worker.go:573] commit new work on block 4 with 8 txs & 0 uncles. Took 3.924684ms
I0826 12:13:59.851582 miner/worker.go:573] commit new work on block 4 with 8 txs & 0 uncles. Took 3.09675ms
I0826 12:14:04.349075 miner/worker.go:339] 🔨  Mined block (#4 / c32990d6). Wait 5 blocks for confirmation
I0826 12:14:04.349764 miner/worker.go:573] commit new work on block 5 with 0 txs & 0 uncles. Took 715.784µs
I0826 12:14:04.350015 miner/worker.go:573] commit new work on block 5 with 0 txs & 0 uncles. Took 209.043µs
I0826 12:14:04.357191 miner/worker.go:339] 🔨  Mined block (#5 / fcd40238). Wait 5 blocks for confirmation
I0826 12:14:04.357492 miner/worker.go:573] commit new work on block 6 with 0 txs & 0 uncles. Took 282.708µs
I0826 12:14:04.357668 miner/worker.go:573] commit new work on block 6 with 0 txs & 0 uncles. Took 125.868µs

Any further blocks have 0 txs.

I found this while testing #2949 but this is happening when I am _not_ running mine.js.

Source

elliots

Most helpful comment

Any updates about this issue?

markya0616 on 20 Jan 2017

👍4

All 28 comments

This is also happening with #2742 merged in.

elliots on 26 Aug 2016

@bas-vk Didn't we have this issue a while back and you fixed it? Did we break it again? :(

karalabe on 26 Aug 2016

I don't recall looking at this. Can look at it but it will be next week.

bas-vk on 26 Aug 2016

Not at this issue in particular, rather one half a year ago. It seems that on stable this issue doesn't happen, only on develop.

karalabe on 26 Aug 2016

We are doing something similar - sending 10000 transactions serially in quick succession through the RPC layer. I'd raised #3384, but after investigation realised it was a duplicate nonce problem. We have experienced this on both 1.4.11 and 1.5.4.

We have worked around the problem by assigning our own nonces to each transaction from our client code.

mrhornsby on 1 Dec 2016

func (s *PrivateAccountAPI) SendTransaction(ctx context.Context, args SendTxArgs, passwd string) (common.Hash, error) {
    var err error
    args, err = prepareSendTxArgs(ctx, args, s.b)
    if err != nil {
        return common.Hash{}, err
    }

    if args.Nonce == nil {
        nonce, err := s.b.GetPoolNonce(ctx, args.From)
        if err != nil {
            return common.Hash{}, err
        }
        args.Nonce = rpc.NewHexNumber(nonce)

At line 267, the GetPoolNonce is used. It's incremented by one and used as Nonce.

The GetPoolNonce internally uses GetNonce(addr):

func (b *EthApiBackend) GetPoolNonce(ctx context.Context, addr common.Address) (uint64, error) {
    b.eth.txMu.Lock()
    defer b.eth.txMu.Unlock()

    return b.eth.txPool.State().GetNonce(addr), nil
}

That is defined in ManagedState:

// GetNonce returns the canonical nonce for the managed or unmanaged account
func (ms *ManagedState) GetNonce(addr common.Address) uint64 {
    ms.mu.RLock()
    defer ms.mu.RUnlock()

    if ms.hasAccount(addr) {
        account := ms.getAccount(addr)
        return uint64(len(account.nonces)) + account.nstart
    } else {
        return ms.StateDB.GetNonce(addr)
    }
}

It uses only RLock, a read-only lock which is non-exclusive to readers. So if there are several requests to SendTransaction, they will get the same nonce, and use nonce+1 for the tx.

Possible fix: Use NewNonce(addr) instead, which uses a rw-lock and returns an _already incremented_ nonce.

func (ms *ManagedState) NewNonce(addr common.Address) uint64 {
    ms.mu.Lock()
    defer ms.mu.Unlock()

N.B: I'm not 100% sure this is actually the problem, because @mrhornsby said:

10000 transactions serially

Which indicates that they are sent one at a time. The possible issue I've described above should only occur if there are paralell submissions of transactions.

holiman on 8 Dec 2016

Which indicates that they are sent one at a time. The possible issue I've described above should only occur if there are paralell submissions of transactions.

I'm using 1.5.4-stable-b70acf3c.

I have multiple NodeJS workers working in parallel and calling the JSON-RPC to push 1000 transactions. And it looks like some of them are just "dropped". It doesn't happen with 10 or 100 transactions.

Since those workers are parallelized and use the same account, there is simply no easy way to set the nonce ourselves.

promethe42 on 13 Dec 2016

@promethe42 Could you try again with 1.5.5 (unreleased master branch)? There was a fix included (https://github.com/ethereum/go-ethereum/pull/3412) that may help with this case. Possibly there's a deeper issue but would be nice to get a confirm whether it solves or not the issue for you.

karalabe on 13 Dec 2016

@karalabe sure. So I need to build master?

promethe42 on 13 Dec 2016

You can also download a pre-built binary from https://geth.ethereum.org/downloads/, just scroll down to the Develop builds section.

karalabe on 13 Dec 2016

@karalabe Thanks! Test for 1000 txs is running. It takes ~20 minutes. I'll keep you posted.

promethe42 on 13 Dec 2016

@karalabe no change. I got as much as 18% of missing events for those 1000 txs. 100 txs works. I'm testing 500 txs and I'll try to see where exactly the bottleneck is.

promethe42 on 13 Dec 2016

Update: 500 parallel txs work. Trying 750...
Update 2: 750 parallel txs dosn't work, I have ~1% of "dropped" txs.

promethe42 on 13 Dec 2016

Any updates about this issue?

markya0616 on 20 Jan 2017

👍4

I seem to have this problem when using abigen (which uses ethclient). It should have a mutex that is used when assigning nonces.

stevenroose on 4 May 2017

saved the keyfiles appart. deleted everything including the node. reinstalled the latest wallet. voila.

jaderayub on 23 May 2017

did it in programs, and also manually in win explorer.

jaderayub on 23 May 2017

guys, have any plan for fix this problem ?

LuoZijun on 19 Jun 2017

@LuoZijun I fixed it by having a mutex for accessing ethclient. That way it never fucks up nonce-generation.

stevenroose on 19 Jun 2017

@stevenroose can you show me commit hash (link) ?

LuoZijun on 19 Jun 2017

@LuoZijun @stevenroose As far as I know all know transaction nonce issues have been fixed. Are you using the latest release of Geth?

karalabe on 19 Jun 2017

@karalabe I'm use Quorum client .

LuoZijun on 19 Jun 2017

The go-ethereum repo was fixed to handle nonces correctly in Geth 1.6.3 I believe. If you have issues with Quorum, ask them to pull in the fixes.

karalabe on 19 Jun 2017

@karalabe thank you.

LuoZijun on 19 Jun 2017

@LuoZijon, I'm also using Quorum. I was aware of the fix here, but Quorum is still on v1.5. (They're working on a 1.6 rebase, though.) Just have a mutex that you lock in order to make transactions that require nonces. (Those that require TransactOpts instead of CallOpts.

stevenroose on 19 Jun 2017

@stevenroose thank you. i found that commit https://github.com/ethereum/go-ethereum/commit/ea11f7dd7aa77856a04d83d0db8f303d02e0ce14 .

LuoZijun on 20 Jun 2017

@karalabe Facing similar issue with geth Version: 1.8.11-stable on linux server. Many of the transactions are sent with same nonce. Since we are not maintaining nonce by ourselves, it took time to figure out why some of the transactions were lost.
Finally I could verify that when we do bulk transactions (in a loop, processing payments), some the transactions are sent with same nonce resulting in Transaction not found. I can provide ref transactions if required.