debug_setHead causes Clique to hang when period is 0

[albrow]

See #16713 and #19308 for some background.

My PR was closed in favor of a different solution. While I agree that the solution that was merged is cleaner, unfortunately it does not fully address the problem. On the latest commit (at least at the time I opened this issue) debug_setHead causes Clique to stop mining new blocks if it has a period of 0.

I decided to open a new issue because what's happening now is not the same thing as what I originally reported in #16713.

System information

Geth version:

Geth
Version: 1.9.0-unstable
Git Commit: 67fc0377e13416d9a1f8ea32e7d1b0ca89374bf3

OS & Version: MacOS version 10.14.3
Commit hash : 67fc037

Expected behaviour

debug_setHead should work when using Clique with a period of 0.

Actual behaviour

debug_setHead causes Clique to stop mining new blocks.

Steps to reproduce the behaviour

1. Run build/bin/geth --dev --dev.period 0.
2. In a separate terminal session, run build/bin/geth attach /tmp/geth.ipc.
3. Run the following commands in the console (output included here for convenience):

> eth.blockNumber
0
> eth.sendTransaction({from: eth.accounts[0], to: eth.accounts[0], value: "0x0"});
"0x88a1168223a1153ec1cda3fdbb0adeb7e8c3110a6c5d7d937a55460be5768500"
> eth.blockNumber // Sending the transaction resulted in a new block being mined.
1
> eth.sendTransaction({from: eth.accounts[0], to: eth.accounts[0], value: "0x0"});
"0x106ccc6c088f29e3a40dc1b4d90d4570d25eb3f1eb680c190a00774b7f5756c6"
> eth.blockNumber // A second block is mined if we send another transaction
2
> debug.setHead(web3.toHex(1)); // Use debug.setHead to reset to block number 1.
null
> eth.sendTransaction({from: eth.accounts[0], to: eth.accounts[0], value: "0x0"});
"0xb67c83f11784d517080926a05c33b0c991945ec5d835f434ee80dbdee3061a7c"
> eth.blockNumber // Now when we send a transaction it is not mined :/
1
> eth.sendTransaction({from: eth.accounts[0], to: eth.accounts[0], value: "0x0"});
"0x244c753974a1bc8fbd4281aea77a3d2e668d4d1f827c58cf354002258c546b07"
> eth.blockNumber
1

Log output

Here's the full log output during the commands above:

INFO [03-27|17:19:16.079] Maximum peer count                       ETH=25 LES=0 total=25
INFO [03-27|17:19:17.957] Using developer account                  address=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:19:17.973] Starting peer-to-peer node               instance=Geth/v1.9.0-unstable-67fc0377/darwin-amd64/go1.12
INFO [03-27|17:19:17.973] Allocated trie memory caches             clean=256.00MiB dirty=256.00MiB
INFO [03-27|17:19:17.973] Allocated cache and file handles         database=/tmp/geth/geth/chaindata cache=512.00MiB handles=5120
INFO [03-27|17:19:18.008] Writing custom genesis block
INFO [03-27|17:19:18.009] Persisted trie from memory database      nodes=13 size=1.81KiB time=205.941µs gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
INFO [03-27|17:19:18.009] Initialised chain configuration          config="{ChainID: 1337 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0  ConstantinopleFix: 0 Engine: clique}"
INFO [03-27|17:19:18.009] Initialising Ethereum protocol           versions="[63 62]" network=1337 dbversion=<nil>
WARN [03-27|17:19:18.009] Upgrade blockchain database version      from=<nil> to=4
INFO [03-27|17:19:18.069] Loaded most recent local header          number=0 hash=603369…c4ffb5 td=1 age=49y11mo1w
INFO [03-27|17:19:18.069] Loaded most recent local full block      number=0 hash=603369…c4ffb5 td=1 age=49y11mo1w
INFO [03-27|17:19:18.069] Loaded most recent local fast block      number=0 hash=603369…c4ffb5 td=1 age=49y11mo1w
INFO [03-27|17:19:18.069] Regenerated local transaction journal    transactions=0 accounts=0
INFO [03-27|17:19:18.070] Stored checkpoint snapshot to disk       number=0 hash=603369…c4ffb5
INFO [03-27|17:19:18.091] started whisper v.6.0
INFO [03-27|17:19:18.091] New local node record                    seq=1 id=c604ffb45fdc7e84 ip=127.0.0.1 udp=0 tcp=58546
INFO [03-27|17:19:18.091] Started P2P networking                   self="enode://6e68cf3051635c565dd22856ef5c87f8e78127555995243163cac9ef6104b8a09c1612e705ea48d89edd0c72d0400b93250e201ecc512f4b0995f04174217f08@127.0.0.1:58546?discport=0"
INFO [03-27|17:19:18.092] IPC endpoint opened                      url=/tmp/geth/geth.ipc
INFO [03-27|17:19:18.092] Transaction pool price threshold updated price=1000000000
INFO [03-27|17:19:18.092] Transaction pool price threshold updated price=1
INFO [03-27|17:19:18.092] Etherbase automatically configured       address=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:19:18.092] Commit new mining work                   number=1 sealhash=ae4acc…d2f826 uncles=0 txs=0 gas=0 fees=0 elapsed=104.384µs
INFO [03-27|17:19:18.092] Sealing paused, waiting for transactions
INFO [03-27|17:19:33.074] Setting new local account                address=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:19:33.074] Submitted transaction                    fullhash=0x88a1168223a1153ec1cda3fdbb0adeb7e8c3110a6c5d7d937a55460be5768500 recipient=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:19:33.074] Commit new mining work                   number=1 sealhash=98ba2f…1b80a5 uncles=0 txs=0 gas=0 fees=0 elapsed=102.27µs
INFO [03-27|17:19:33.074] Sealing paused, waiting for transactions
INFO [03-27|17:19:33.075] Commit new mining work                   number=1 sealhash=f90415…c9200d uncles=0 txs=1 gas=21000 fees=2.1e-14 elapsed=382.561µs
INFO [03-27|17:19:33.075] Successfully sealed new block            number=1 sealhash=f90415…c9200d hash=dce724…4061f8 elapsed=502.166µs
INFO [03-27|17:19:33.075] 🔨 mined potential block                  number=1 hash=dce724…4061f8
INFO [03-27|17:19:33.076] Commit new mining work                   number=2 sealhash=9673da…0fbcb4 uncles=0 txs=0 gas=0     fees=0       elapsed=316.474µs
INFO [03-27|17:19:33.076] Sealing paused, waiting for transactions
INFO [03-27|17:19:38.101] Submitted transaction                    fullhash=0x106ccc6c088f29e3a40dc1b4d90d4570d25eb3f1eb680c190a00774b7f5756c6 recipient=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:19:38.101] Commit new mining work                   number=2 sealhash=1fac9e…ba2095 uncles=0 txs=0 gas=0     fees=0       elapsed=70.478µs
INFO [03-27|17:19:38.101] Sealing paused, waiting for transactions
INFO [03-27|17:19:38.101] Commit new mining work                   number=2 sealhash=b9d636…cf1949 uncles=0 txs=1 gas=21000 fees=2.1e-14 elapsed=325.822µs
INFO [03-27|17:19:38.102] Successfully sealed new block            number=2 sealhash=b9d636…cf1949 hash=5447ef…0e7f36 elapsed=527.485µs
INFO [03-27|17:19:38.102] 🔨 mined potential block                  number=2 hash=5447ef…0e7f36
INFO [03-27|17:19:38.102] Commit new mining work                   number=3 sealhash=fe3260…93db86 uncles=0 txs=0 gas=0     fees=0       elapsed=383.433µs
INFO [03-27|17:19:38.102] Sealing paused, waiting for transactions
WARN [03-27|17:19:59.167] Rewinding blockchain                     target=1
INFO [03-27|17:19:59.168] Loaded most recent local header          number=1 hash=dce724…4061f8 td=3 age=26s
INFO [03-27|17:19:59.168] Loaded most recent local full block      number=1 hash=dce724…4061f8 td=3 age=26s
INFO [03-27|17:19:59.168] Loaded most recent local fast block      number=1 hash=dce724…4061f8 td=3 age=26s
INFO [03-27|17:20:03.086] Submitted transaction                    fullhash=0xb67c83f11784d517080926a05c33b0c991945ec5d835f434ee80dbdee3061a7c recipient=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:20:03.086] Commit new mining work                   number=2 sealhash=a9cd51…d4c212 uncles=0 txs=0 gas=0     fees=0       elapsed=141.281µs
INFO [03-27|17:20:03.086] Sealing paused, waiting for transactions
INFO [03-27|17:20:03.086] Commit new mining work                   number=2 sealhash=a9cd51…d4c212 uncles=0 txs=0 gas=0     fees=0       elapsed=332.186µs
INFO [03-27|17:20:09.455] Submitted transaction                    fullhash=0x244c753974a1bc8fbd4281aea77a3d2e668d4d1f827c58cf354002258c546b07 recipient=0x38c884Aa8CC82596087714E23D046Fe08b2B32b0
INFO [03-27|17:20:09.455] Commit new mining work                   number=2 sealhash=014960…be5f24 uncles=0 txs=0 gas=0     fees=0       elapsed=81.396µs
INFO [03-27|17:20:09.455] Sealing paused, waiting for transactions
INFO [03-27|17:20:09.455] Commit new mining work                   number=2 sealhash=014960…be5f24 uncles=0 txs=0 gas=0     fees=0       elapsed=279.504µs

Note that for the first two transactions, we see the message 🔨 mined potential block. However, for the last two transactions (after we called debug.setHead) that message no longer appears.

[LogvinovLeon]

@holiman ^

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[MariusVanDerWijden]

Yep, I can still repro this. Calling debug_setHead forks the second transaction away. If we try to resend the same transaction an error already known is thrown.

> eth.sendTransaction({from: eth.accounts[0], to: eth.accounts[0], value: "0x1", Nonce: "0x2"});
Error: already known
	at web3.js:6347:37(47)
	at web3.js:5081:62(37)
	at <eval>:1:20(18)

>txpool.status
{
  pending: 0,
  queued: 0
}

The suggested workaround allows anyone to skip nonces which would be fatal for the network. Since the transactions are not in the txpool anymore they should be commited to the miner on resubmission but aren't as resubmission produces a nonce too low error even though it isn't in the canonical chain nor in the txpool. This was due to the txpool not properly reseting the statedb when a sethead occured.

I think there are two ways to solve it: resubmit all transactions that have been invalidated by debug_setHead or better allow the user to resubmit transactions that are not part of the canonical chain anymore.

I created a fix here: #22247