New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sometimes, transactions disappear from txpool rather than being mined into the next block #14893

Closed
alanbuxton opened this Issue Aug 3, 2017 · 6 comments

Comments

Projects
None yet
4 participants
@alanbuxton

alanbuxton commented Aug 3, 2017

System information

Geth version: Version: 1.6.7-stable
OS & Version: Ubuntu 16.04.3 LTS

Expected behaviour

I submit several hundred transactions with geth. They are all visible in txpool and all have legitimate nonce values. There are too many to mine into one block, so they should be mined into consecutive blocks.

Actual behaviour

See the log below for an example where the first two blocks worked but subsequent txns were lost.

107 txns are selected for the first block (nr 104). The block is mined and I see 107 "Remove old pending transaction" log messages.
107 txns are then selected for the 2nd block (nr 105). The block is mined
The log then shows: "Transaction failed, will be removed hash=5cad23…bf7433 err="invalid nonce: have 1429, expected 1536"

The txpool is now empty and the remaining txns are left in a limbo state.

From the log below you can see that the nonces for the created txns are from 1322 to 1821.
The first block should contain 1322-1428
The second block: 1429-1535
The third block should start from 1536

It looks like:

  • 1322-1428 are mined into block 104
  • 1322-1428 are removed from txpool
  • 1429-1535 are mined into block 105
  • no txns are removed from the txpool
  • Block 106 now expects to find 1536, but instead finds 1429 again

txpool is empty, first 214 txns are mined, but the rest are in some kind of limbo.

> txpool
{
  content: {
    pending: {},
    queued: {}
  },
  inspect: {
    pending: {},
    queued: {}
  },
  status: {
    pending: 0,
    queued: 0
  },
  getContent: function(callback),
  getInspect: function(callback),
  getStatus: function(callback)
}
> eth.getTransaction(arr[106])
{
  blockHash: "0x8450e81838e6f35166e4fe86b84d7b65150795c836311bca52b827b248a6b469",
  blockNumber: 104,
  from: "0xfb37cbdd0cda6c93fac48cec9919919a0262b9be",
  gas: 90000,
  gasPrice: 18000000000,
  hash: "0x564f23e4d81febe0dab92630b9ffe0921ef3f45bd599af09229e2c66a142e402",
  input: "0x",
  nonce: 1428,
  r: "0x54ca599331176bd2629fee36b2dc4f80926158891d4b9b5a09c049a04f6246d2",
  s: "0x6728e3582df709cc2e4b14df911f08fabb33f9691bb749535212aa9e2978ffce",
  to: "0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96",
  transactionIndex: 106,
  v: "0x41",
  value: 1106000000000
}
> eth.getTransactionReceipt(arr[106])
{
  blockHash: "0x8450e81838e6f35166e4fe86b84d7b65150795c836311bca52b827b248a6b469",
  blockNumber: 104,
  contractAddress: null,
  cumulativeGasUsed: 2247000,
  from: "0xfb37cbdd0cda6c93fac48cec9919919a0262b9be",
  gasUsed: 21000,
  logs: [],
  logsBloom: "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
  root: "0x6ec3231d2f66c917fff9dc298372983322492f9b03cc15db294d208bab685e7e",
  to: "0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96",
  transactionHash: "0x564f23e4d81febe0dab92630b9ffe0921ef3f45bd599af09229e2c66a142e402",
  transactionIndex: 106
}
> eth.getTransaction(arr[213])
{
  blockHash: "0xbf8d854cb79a0d0f9acd5f1b309acc22c3cd6c0bd4d305675c0c8f83a1aedf9f",
  blockNumber: 105,
  from: "0xfb37cbdd0cda6c93fac48cec9919919a0262b9be",
  gas: 90000,
  gasPrice: 18000000000,
  hash: "0xb1e443575c88a41d490865e7110e5dfb21cf306317fd31902c6281b1162e72f0",
  input: "0x",
  nonce: 1535,
  r: "0x6d67dcbcc1eb58fd8f00954f8f5ebf08c9150401d46029f4d346923cccd7b328",
  s: "0xad0bbdca6b62c91fcb6a35d528e7102e5e2eb9cffc2834392c96a5a721c4662",
  to: "0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96",
  transactionIndex: 106,
  v: "0x42",
  value: 1213000000000
}
> eth.getTransactionReceipt(arr[213])
{
  blockHash: "0xbf8d854cb79a0d0f9acd5f1b309acc22c3cd6c0bd4d305675c0c8f83a1aedf9f",
  blockNumber: 105,
  contractAddress: null,
  cumulativeGasUsed: 2247000,
  from: "0xfb37cbdd0cda6c93fac48cec9919919a0262b9be",
  gasUsed: 21000,
  logs: [],
  logsBloom: "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
  root: "0x4973df7e54c51dba2beae194040cee07d6a9c0e1b4bf7f9cc8abf5de6d0f584d",
  to: "0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96",
  transactionHash: "0xb1e443575c88a41d490865e7110e5dfb21cf306317fd31902c6281b1162e72f0",
  transactionIndex: 106
}
> eth.getTransaction(arr[214])
{
  blockHash: "0x0000000000000000000000000000000000000000000000000000000000000000",
  blockNumber: null,
  from: "0xfb37cbdd0cda6c93fac48cec9919919a0262b9be",
  gas: 90000,
  gasPrice: 18000000000,
  hash: "0x2750ad5bfab03a7e982ac063ec6f61e5a1ec67fbc12d09f0239d7c50053e39a1",
  input: "0x",
  nonce: 1536,
  r: "0x45d7111286835caf7fa9718984c561a5a28fd73bac01e7dcb14bb7d8d86a18b4",
  s: "0x3a993ad04e326567ae9f30746481626af7239044a63b3222679cdce9953634b4",
  to: "0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96",
  transactionIndex: 0,
  v: "0x42",
  value: 1214000000000
}
> eth.getTransactionReceipt(arr[214])
null

Steps to reproduce the behaviour

Here is my genesis.json

{
    "config": {
        "chainId": 15,
        "homesteadBlock": 0,
        "eip155Block": 0,
        "eip158Block": 0
    },
    "difficulty": "0x400",
    "gasLimit": "2100000",
    "alloc": {
    }
}

I run geth with

geth --datadir . --networkid 12345 --nodiscover --maxpeers 0  console

(I use those flags to minimise TRACE logs, the symptoms are the same even if I don't set nodiscover and maxpeers).

And then run this script:

personal.unlockAccount(eth.accounts[0]);
var arr = [] ;
start=eth.getTransactionCount(eth.accounts[0]);
for (i = 0; i < 500; i++) {
    arr.push(eth.sendTransaction({
        from: eth.accounts[0],
        to: eth.accounts[1],
        nonce: start + i,
        value: web3.toWei( (i/1000 + 1).toFixed(4) , 'szabo')
    }))
}
console.log("First nonce: " + eth.getTransaction(arr[0]).nonce)
console.log("Last nonce: " + eth.getTransaction(arr[499]).nonce)

debug.verbosity(5) ; miner.start(1); admin.sleepBlocks(6) ; miner.stop(); debug.verbosity(3);

Backtrace

Example console log showing a successful block and then unsuccessful ones.

....
INFO [08-03|14:06:54] Submitted transaction                    fullhash=0x00dab5fbd774ebb6886602aa070ff228be1ac52646ff664de79f8e6037e5e020 recipient=0x8a4e9bd9f20fa003c4894d1fb1d17a8cecca3c96
First nonce: 1322
Last nonce: 1821
TRACE[08-03|14:06:54]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1515,\"result\":null}"
TRACE[08-03|14:06:54]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1516,\"method\":\"miner_start\",\"params\":[1]}"
INFO [08-03|14:06:54] Updated mining threads                   threads=1
INFO [08-03|14:06:54] Transaction pool price threshold updated price=18000000000
INFO [08-03|14:06:54] Starting mining operation 
TRACE[08-03|14:06:54] Gas limit exceeded for current block     sender=0xfb37cbdd0cda6c93fac48cec9919919a0262b9be
TRACE[08-03|14:06:54]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1516,\"result\":null}"
TRACE[08-03|14:06:54]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1517,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:54]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1517,\"result\":\"0x67\"}"
TRACE[08-03|14:06:54]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1518,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:54]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1518,\"result\":\"0x67\"}"
INFO [08-03|14:06:54] Commit new mining work                   number=104 txs=107 uncles=0 elapsed=33.191ms
TRACE[08-03|14:06:54] Requiring new ethash dataset             epoch=0
TRACE[08-03|14:06:54] Requiring new future ethash dataset      epoch=1
DEBUG[08-03|14:06:54] Loaded old ethash dataset from disk      epoch=0
TRACE[08-03|14:06:54] Started ethash search for new nonces     miner=0 seed=7607668769625014234
DEBUG[08-03|14:06:54] Loaded old ethash dataset from disk      epoch=1
TRACE[08-03|14:06:55]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1519,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:55]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1519,\"result\":\"0x67\"}"
TRACE[08-03|14:06:56]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1520,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:56]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1520,\"result\":\"0x67\"}"
TRACE[08-03|14:06:56] Ethash nonce found and reported          miner=0 attempts=48070 nonce=7607668769625062304
INFO [08-03|14:06:56] Successfully sealed new block            number=104 hash=8450e8…a6b469
DEBUG[08-03|14:06:56] Trie cache stats after commit            misses=2014 unloads=0
INFO [08-03|14:06:56] 🔨 mined potential block                  number=104 hash=8450e8…a6b469
TRACE[08-03|14:06:56] Propagated block                         hash=8450e8…a6b469 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:06:56] Announced block                          hash=8450e8…a6b469 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:06:56] Announced block                          hash=8450e8…a6b469 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:06:56] Removed old pending transaction          hash=4c696b…12070e
TRACE[08-03|14:06:56] Removed old pending transaction          hash=f485dd…e6c6d6
TRACE[08-03|14:06:56] Removed old pending transaction          hash=1090e1…820e05
TRACE[08-03|14:06:56] Removed old pending transaction          hash=1311d2…920ecf
TRACE[08-03|14:06:56] Removed old pending transaction          hash=65aa17…4220a9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2a4b6a…7b2013
TRACE[08-03|14:06:56] Removed old pending transaction          hash=4ee8d3…c6b315
TRACE[08-03|14:06:56] Removed old pending transaction          hash=cb82bd…00db79
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2bcbf9…f15855
TRACE[08-03|14:06:56] Removed old pending transaction          hash=66fa8e…5169bd
TRACE[08-03|14:06:56] Removed old pending transaction          hash=bc1105…095a2d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=5517f0…59f38c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=7d1e87…55ba88
TRACE[08-03|14:06:56] Removed old pending transaction          hash=e8eb50…bac45b
TRACE[08-03|14:06:56] Removed old pending transaction          hash=4dbe97…8deb7c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=391035…bac1e4
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2b5d03…adec2d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=eb6608…61c33f
TRACE[08-03|14:06:56] Removed old pending transaction          hash=523fd8…9c457c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=0b639e…e6d10a
TRACE[08-03|14:06:56] Removed old pending transaction          hash=eee803…d7e3a4
TRACE[08-03|14:06:56] Removed old pending transaction          hash=51c70a…f34c1c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=510995…86f68c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=82c2e9…f4e58e
TRACE[08-03|14:06:56] Removed old pending transaction          hash=ca82cd…32c4ec
TRACE[08-03|14:06:56] Removed old pending transaction          hash=8c03fd…14b7fe
TRACE[08-03|14:06:56] Removed old pending transaction          hash=191604…5a15c0
TRACE[08-03|14:06:56] Removed old pending transaction          hash=3ae91e…61a8b4
TRACE[08-03|14:06:56] Removed old pending transaction          hash=7bc6c6…20ffa4
TRACE[08-03|14:06:56] Removed old pending transaction          hash=e42fb6…9495bd
TRACE[08-03|14:06:56] Removed old pending transaction          hash=748535…f7af24
TRACE[08-03|14:06:56] Removed old pending transaction          hash=94205e…fbbbe8
TRACE[08-03|14:06:56] Removed old pending transaction          hash=62e07d…927bd3
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9e05fa…437698
TRACE[08-03|14:06:56] Removed old pending transaction          hash=bbec12…9e7c6d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=a6f442…48ead0
TRACE[08-03|14:06:56] Removed old pending transaction          hash=738259…004dc1
TRACE[08-03|14:06:56] Removed old pending transaction          hash=ffb021…8a9524
TRACE[08-03|14:06:56] Removed old pending transaction          hash=226241…ed2623
TRACE[08-03|14:06:56] Removed old pending transaction          hash=92e4c4…ab1cfa
TRACE[08-03|14:06:56] Removed old pending transaction          hash=ce4373…3273a2
TRACE[08-03|14:06:56] Removed old pending transaction          hash=651da3…8adf6e
TRACE[08-03|14:06:56] Removed old pending transaction          hash=0c3246…bdb47f
TRACE[08-03|14:06:56] Removed old pending transaction          hash=b57fef…36453b
TRACE[08-03|14:06:56] Removed old pending transaction          hash=31f13a…08fd0f
TRACE[08-03|14:06:56] Removed old pending transaction          hash=c7fac7…46830b
TRACE[08-03|14:06:56] Removed old pending transaction          hash=0f4873…b463b7
TRACE[08-03|14:06:56] Removed old pending transaction          hash=83f4ce…b7baf5
TRACE[08-03|14:06:56] Removed old pending transaction          hash=005c42…ae4884
TRACE[08-03|14:06:56] Removed old pending transaction          hash=afff70…60321a
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2ae323…2123a9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=c46562…9766c9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=209ffc…b673ae
TRACE[08-03|14:06:56] Removed old pending transaction          hash=f6f88c…fcd618
TRACE[08-03|14:06:56] Removed old pending transaction          hash=6c16d6…1ad801
TRACE[08-03|14:06:56] Removed old pending transaction          hash=429a7c…c34240
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2f9454…fee04f
TRACE[08-03|14:06:56] Removed old pending transaction          hash=4821cd…8eab86
TRACE[08-03|14:06:56] Removed old pending transaction          hash=7181ad…8f2ade
TRACE[08-03|14:06:56] Removed old pending transaction          hash=19a37a…0b1dea
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9de448…344a84
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2dc9af…a2ff9c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=22df40…efc688
TRACE[08-03|14:06:56] Removed old pending transaction          hash=f0d845…627bdd
TRACE[08-03|14:06:56] Removed old pending transaction          hash=1ccb66…0e60d6
TRACE[08-03|14:06:56] Removed old pending transaction          hash=49ea31…875b39
TRACE[08-03|14:06:56] Removed old pending transaction          hash=ac1568…33dc64
TRACE[08-03|14:06:56] Removed old pending transaction          hash=81c209…e6135e
TRACE[08-03|14:06:56] Removed old pending transaction          hash=1d6aa2…436c99
TRACE[08-03|14:06:56] Removed old pending transaction          hash=e7c872…7125ed
TRACE[08-03|14:06:56] Removed old pending transaction          hash=651d0c…0a215a
TRACE[08-03|14:06:56] Removed old pending transaction          hash=980de3…0a70d1
TRACE[08-03|14:06:56] Removed old pending transaction          hash=d1e8b5…b134c8
TRACE[08-03|14:06:56] Removed old pending transaction          hash=4707cd…d0369e
TRACE[08-03|14:06:56] Removed old pending transaction          hash=a76bd7…2a1b4d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=77325a…09fe8b
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2cb840…6f4192
TRACE[08-03|14:06:56] Removed old pending transaction          hash=7f6bc6…f7b3e2
TRACE[08-03|14:06:56] Removed old pending transaction          hash=274bc1…4fda8c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=21e297…76e947
TRACE[08-03|14:06:56] Removed old pending transaction          hash=ff6ff9…6faaa9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=234ab6…47b412
TRACE[08-03|14:06:56] Removed old pending transaction          hash=73878f…ea8253
TRACE[08-03|14:06:56] Removed old pending transaction          hash=5d2960…c9969a
TRACE[08-03|14:06:56] Removed old pending transaction          hash=0f9a67…dce2ea
TRACE[08-03|14:06:56] Removed old pending transaction          hash=d12529…782b7d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=e43ea8…6a5ac9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2d1238…ccd4a9
TRACE[08-03|14:06:56] Removed old pending transaction          hash=570813…e88c5d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=d202e4…c157b7
TRACE[08-03|14:06:56] Removed old pending transaction          hash=909f9d…51d69d
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9d6ab0…3749cd
TRACE[08-03|14:06:56] Removed old pending transaction          hash=3aed6f…8ae2d0
TRACE[08-03|14:06:56] Removed old pending transaction          hash=29128e…bbf4be
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2788db…4b0417
TRACE[08-03|14:06:56] Removed old pending transaction          hash=d0fe86…e13e05
TRACE[08-03|14:06:56] Removed old pending transaction          hash=a5a10e…f1806f
TRACE[08-03|14:06:56] Removed old pending transaction          hash=43d9c8…c3cd3b
TRACE[08-03|14:06:56] Removed old pending transaction          hash=835e5a…c526cc
TRACE[08-03|14:06:56] Removed old pending transaction          hash=81b5b7…6e4473
TRACE[08-03|14:06:56] Removed old pending transaction          hash=2d96c6…889c25
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9374ad…2347cf
TRACE[08-03|14:06:56] Removed old pending transaction          hash=750b0e…ad2fc7
TRACE[08-03|14:06:56] Removed old pending transaction          hash=64b661…19abc1
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9f4fca…d1135c
TRACE[08-03|14:06:56] Removed old pending transaction          hash=9319fc…962b30
TRACE[08-03|14:06:56] Removed old pending transaction          hash=564f23…42e402
TRACE[08-03|14:06:56] Gas limit exceeded for current block     sender=0xfb37cbdd0cda6c93fac48cec9919919a0262b9be
INFO [08-03|14:06:56] Commit new mining work                   number=105 txs=107 uncles=0 elapsed=40.028ms
TRACE[08-03|14:06:56] Started ethash search for new nonces     miner=0 seed=1157945254908980731
TRACE[08-03|14:06:57]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1521,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:57]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1521,\"result\":\"0x68\"}"
TRACE[08-03|14:06:58]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1522,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:58]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1522,\"result\":\"0x68\"}"
DEBUG[08-03|14:06:58] Transaction pool status report           executable=393 queued=0 stales=107
TRACE[08-03|14:06:59]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1523,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:06:59]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1523,\"result\":\"0x68\"}"
TRACE[08-03|14:07:00]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1524,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:00]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1524,\"result\":\"0x68\"}"
TRACE[08-03|14:07:01]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1525,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:01]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1525,\"result\":\"0x68\"}"
TRACE[08-03|14:07:02] Ethash nonce found and reported          miner=0 attempts=135868 nonce=1157945254909116599
INFO [08-03|14:07:02] Successfully sealed new block            number=105 hash=bf8d85…aedf9f
DEBUG[08-03|14:07:02] Trie cache stats after commit            misses=2014 unloads=0
INFO [08-03|14:07:02] 🔨 mined potential block                  number=105 hash=bf8d85…aedf9f
TRACE[08-03|14:07:02] Transaction failed, will be removed      hash=5cad23…bf7433 err="invalid nonce: have 1429, expected 1536"
TRACE[08-03|14:07:02] Propagated block                         hash=bf8d85…aedf9f recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:07:02] Announced block                          hash=bf8d85…aedf9f recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:07:02] Announced block                          hash=bf8d85…aedf9f recipients=0 duration=2562047h47m16.854s
INFO [08-03|14:07:02] Commit new mining work                   number=106 txs=0   uncles=0 elapsed=2.223ms
TRACE[08-03|14:07:02] Started ethash search for new nonces     miner=0 seed=3611537876636299363
DEBUG[08-03|14:07:02] Recalculated downloader QoS values       rtt=20s confidence=1.000 ttl=1m0s
TRACE[08-03|14:07:02]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1526,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:02]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1526,\"result\":\"0x69\"}"
TRACE[08-03|14:07:03]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1527,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:03]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1527,\"result\":\"0x69\"}"
TRACE[08-03|14:07:04] Ethash nonce found and reported          miner=0 attempts=59183  nonce=3611537876636358546
INFO [08-03|14:07:04] Successfully sealed new block            number=106 hash=b2d54a…241924
DEBUG[08-03|14:07:04] Trie cache stats after commit            misses=2014 unloads=0
INFO [08-03|14:07:04] 🔨 mined potential block                  number=106 hash=b2d54a…241924
INFO [08-03|14:07:04] Commit new mining work                   number=107 txs=0   uncles=0 elapsed=192.286µs
TRACE[08-03|14:07:04] Propagated block                         hash=b2d54a…241924 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:07:04] Announced block                          hash=b2d54a…241924 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:07:04] Announced block                          hash=b2d54a…241924 recipients=0 duration=2562047h47m16.854s
TRACE[08-03|14:07:04] Started ethash search for new nonces     miner=0 seed=1231871270841904727
TRACE[08-03|14:07:04]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1528,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:04]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1528,\"result\":\"0x6a\"}"
TRACE[08-03|14:07:05]                                          msg="sending {\"jsonrpc\":\"2.0\",\"id\":1529,\"method\":\"eth_blockNumber\",\"params\":[]}"
TRACE[08-03|14:07:05]                                          msg="<-readResp: response {\"jsonrpc\":\"2.0\",\"id\":1529,\"result\":\"0x6a\"}"
TRACE[08-03|14:07:06] Ethash nonce found and reported          miner=0 attempts=27186  nonce=1231871270841931913
INFO [08-03|14:07:06] Successfully sealed new block            number=107 hash=d199a7…9097ee
DEBUG[08-03|14:07:06] Trie cache stats after commit            misses=2014 unloads=0
INFO [08-03|14:07:06] 🔨 mined potential block                  number=107 hash=d199a7…9097ee
INFO [08-03|14:07:06] Commit new mining work                   number=108 txs=0   uncles=0 elapsed=165.607µs

(etc)
@AlekseiSmirnov

This comment has been minimized.

AlekseiSmirnov commented Aug 3, 2017

I think I have the same problem

@alanbuxton

This comment has been minimized.

alanbuxton commented Aug 4, 2017

I've been dong some more digging and it looks like the issue depends on what order the code responds to a ChainHeadEvent.

  • If loop() in core/tx_pool.go fires first then resetState is called followed by demoteUnexecutables which removes old pending transactions. Future mining can continue as expected.
  • If update() in miner/worker.go fires first then commitNewWork is called followed by commitTransaction. It doesn't make sense to commitNewWork after the txns have been mined, so this produces the error "Transaction failed, will be removed" due to an old nonce still being in the txpool , After this error happens, the txpool is emptied and further mining won't find any transactions. Once geth is restarted then the missing txns will be put back into the pool.
  • If update() in miner/worker.go fires while demoteUnexecutables is processing then I'm struggling to follow the exact logic but it looks like the next block won't contain any transactions, but that the txpool will get cleaned up in time for the next but one block.

I've put some log.Info calls into my local copy of geth - see below the above 3 scenarios playing out:

My txpool contains 500 pending txns with nonce from 11675 to 12174 (some lines removed for brevity). In my env each block can fit about 150 txns, so 4 blocks should be sufficient.

> txpool
{
  ....
  inspect: {
    pending: {
      0xf74afb1FacD5Eb2dd69fEB589213C12Be9b38177: {
        11675: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1000000000000 wei + 90000 × 18000000000 gas",
        11676: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1001000000000 wei + 90000 × 18000000000 gas",
        11677: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1002000000000 wei + 90000 × 18000000000 gas",
		....
        12171: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1496000000000 wei + 90000 × 18000000000 gas",
        12172: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1497000000000 wei + 90000 × 18000000000 gas",
        12173: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1498000000000 wei + 90000 × 18000000000 gas",
        12174: "0xF0A3Cf66cc2806A1e9626E11e5324360EE97f968: 1499000000000 wei + 90000 × 18000000000 gas"
      }
    },
    queued: {}
  },
  status: {
    pending: 500,
    queued: 0
  },
  ...
}

Log results from mining these txns:

> miner.start(1);admin.sleepBlocks(4);miner.stop()
INFO [08-04|21:01:27] Updated mining threads                   threads=1
INFO [08-04|21:01:27] Transaction pool price threshold updated price=18000000000
INFO [08-04|21:01:27] Starting mining operation 
INFO [08-04|21:01:27] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:01:27] In commitTransaction                     nonce=11675
INFO [08-04|21:01:27] In commitTransaction                     nonce=11676
INFO [08-04|21:01:27] In commitTransaction                     nonce=11677
INFO [08-04|21:01:27] In commitTransaction                     nonce=11678
INFO [08-04|21:01:27] In commitTransaction                     nonce=11679
INFO [08-04|21:01:27] In commitTransaction                     nonce=11680
INFO [08-04|21:01:27] In commitTransaction                     nonce=11681
INFO [08-04|21:01:27] In commitTransaction                     nonce=11682
INFO [08-04|21:01:27] In commitTransaction                     nonce=11683
INFO [08-04|21:01:27] In commitTransaction                     nonce=11684
INFO [08-04|21:01:27] In commitTransaction                     nonce=11685
INFO [08-04|21:01:27] In commitTransaction                     nonce=11686
INFO [08-04|21:01:27] In commitTransaction                     nonce=11687
INFO [08-04|21:01:27] In commitTransaction                     nonce=11688
INFO [08-04|21:01:27] In commitTransaction                     nonce=11689
INFO [08-04|21:01:27] In commitTransaction                     nonce=11690
INFO [08-04|21:01:27] In commitTransaction                     nonce=11691
INFO [08-04|21:01:27] In commitTransaction                     nonce=11692
INFO [08-04|21:01:27] In commitTransaction                     nonce=11693
INFO [08-04|21:01:27] In commitTransaction                     nonce=11694
INFO [08-04|21:01:27] In commitTransaction                     nonce=11695
INFO [08-04|21:01:27] In commitTransaction                     nonce=11696
INFO [08-04|21:01:27] In commitTransaction                     nonce=11697
INFO [08-04|21:01:27] In commitTransaction                     nonce=11698
INFO [08-04|21:01:27] In commitTransaction                     nonce=11699
INFO [08-04|21:01:27] In commitTransaction                     nonce=11700
INFO [08-04|21:01:27] In commitTransaction                     nonce=11701
INFO [08-04|21:01:27] In commitTransaction                     nonce=11702
INFO [08-04|21:01:27] In commitTransaction                     nonce=11703
INFO [08-04|21:01:27] In commitTransaction                     nonce=11704
INFO [08-04|21:01:27] In commitTransaction                     nonce=11705
INFO [08-04|21:01:27] In commitTransaction                     nonce=11706
INFO [08-04|21:01:27] In commitTransaction                     nonce=11707
INFO [08-04|21:01:27] In commitTransaction                     nonce=11708
INFO [08-04|21:01:27] In commitTransaction                     nonce=11709
INFO [08-04|21:01:27] In commitTransaction                     nonce=11710
INFO [08-04|21:01:27] In commitTransaction                     nonce=11711
INFO [08-04|21:01:27] In commitTransaction                     nonce=11712
INFO [08-04|21:01:27] In commitTransaction                     nonce=11713
INFO [08-04|21:01:27] In commitTransaction                     nonce=11714
INFO [08-04|21:01:27] In commitTransaction                     nonce=11715
INFO [08-04|21:01:27] In commitTransaction                     nonce=11716
INFO [08-04|21:01:27] In commitTransaction                     nonce=11717
INFO [08-04|21:01:27] In commitTransaction                     nonce=11718
INFO [08-04|21:01:27] In commitTransaction                     nonce=11719
INFO [08-04|21:01:27] In commitTransaction                     nonce=11720
INFO [08-04|21:01:27] In commitTransaction                     nonce=11721
INFO [08-04|21:01:27] In commitTransaction                     nonce=11722
INFO [08-04|21:01:27] In commitTransaction                     nonce=11723
INFO [08-04|21:01:27] In commitTransaction                     nonce=11724
INFO [08-04|21:01:27] In commitTransaction                     nonce=11725
INFO [08-04|21:01:27] In commitTransaction                     nonce=11726
INFO [08-04|21:01:27] In commitTransaction                     nonce=11727
INFO [08-04|21:01:27] In commitTransaction                     nonce=11728
INFO [08-04|21:01:27] In commitTransaction                     nonce=11729
INFO [08-04|21:01:27] In commitTransaction                     nonce=11730
INFO [08-04|21:01:27] In commitTransaction                     nonce=11731
INFO [08-04|21:01:27] In commitTransaction                     nonce=11732
INFO [08-04|21:01:27] In commitTransaction                     nonce=11733
INFO [08-04|21:01:27] In commitTransaction                     nonce=11734
INFO [08-04|21:01:27] In commitTransaction                     nonce=11735
INFO [08-04|21:01:27] In commitTransaction                     nonce=11736
INFO [08-04|21:01:27] In commitTransaction                     nonce=11737
INFO [08-04|21:01:27] In commitTransaction                     nonce=11738
INFO [08-04|21:01:27] In commitTransaction                     nonce=11739
INFO [08-04|21:01:27] In commitTransaction                     nonce=11740
INFO [08-04|21:01:27] In commitTransaction                     nonce=11741
INFO [08-04|21:01:27] In commitTransaction                     nonce=11742
INFO [08-04|21:01:27] In commitTransaction                     nonce=11743
INFO [08-04|21:01:27] In commitTransaction                     nonce=11744
INFO [08-04|21:01:27] In commitTransaction                     nonce=11745
INFO [08-04|21:01:27] In commitTransaction                     nonce=11746
INFO [08-04|21:01:27] In commitTransaction                     nonce=11747
INFO [08-04|21:01:27] In commitTransaction                     nonce=11748
INFO [08-04|21:01:27] In commitTransaction                     nonce=11749
INFO [08-04|21:01:27] In commitTransaction                     nonce=11750
INFO [08-04|21:01:27] In commitTransaction                     nonce=11751
INFO [08-04|21:01:27] In commitTransaction                     nonce=11752
INFO [08-04|21:01:27] In commitTransaction                     nonce=11753
INFO [08-04|21:01:27] In commitTransaction                     nonce=11754
INFO [08-04|21:01:27] In commitTransaction                     nonce=11755
INFO [08-04|21:01:27] In commitTransaction                     nonce=11756
INFO [08-04|21:01:27] In commitTransaction                     nonce=11757
INFO [08-04|21:01:27] In commitTransaction                     nonce=11758
INFO [08-04|21:01:27] In commitTransaction                     nonce=11759
INFO [08-04|21:01:27] In commitTransaction                     nonce=11760
INFO [08-04|21:01:27] In commitTransaction                     nonce=11761
INFO [08-04|21:01:27] In commitTransaction                     nonce=11762
INFO [08-04|21:01:27] In commitTransaction                     nonce=11763
INFO [08-04|21:01:27] In commitTransaction                     nonce=11764
INFO [08-04|21:01:27] In commitTransaction                     nonce=11765
INFO [08-04|21:01:27] In commitTransaction                     nonce=11766
INFO [08-04|21:01:27] In commitTransaction                     nonce=11767
INFO [08-04|21:01:27] In commitTransaction                     nonce=11768
INFO [08-04|21:01:27] In commitTransaction                     nonce=11769
INFO [08-04|21:01:27] In commitTransaction                     nonce=11770
INFO [08-04|21:01:27] In commitTransaction                     nonce=11771
INFO [08-04|21:01:27] In commitTransaction                     nonce=11772
INFO [08-04|21:01:27] In commitTransaction                     nonce=11773
INFO [08-04|21:01:27] In commitTransaction                     nonce=11774
INFO [08-04|21:01:27] In commitTransaction                     nonce=11775
INFO [08-04|21:01:27] In commitTransaction                     nonce=11776
INFO [08-04|21:01:27] In commitTransaction                     nonce=11777
INFO [08-04|21:01:27] In commitTransaction                     nonce=11778
INFO [08-04|21:01:27] In commitTransaction                     nonce=11779
INFO [08-04|21:01:27] In commitTransaction                     nonce=11780
INFO [08-04|21:01:27] In commitTransaction                     nonce=11781
INFO [08-04|21:01:27] In commitTransaction                     nonce=11782
INFO [08-04|21:01:27] In commitTransaction                     nonce=11783
INFO [08-04|21:01:27] In commitTransaction                     nonce=11784
INFO [08-04|21:01:27] In commitTransaction                     nonce=11785
INFO [08-04|21:01:27] In commitTransaction                     nonce=11786
INFO [08-04|21:01:27] In commitTransaction                     nonce=11787
INFO [08-04|21:01:27] In commitTransaction                     nonce=11788
INFO [08-04|21:01:27] In commitTransaction                     nonce=11789
INFO [08-04|21:01:27] In commitTransaction                     nonce=11790
INFO [08-04|21:01:27] In commitTransaction                     nonce=11791
INFO [08-04|21:01:27] In commitTransaction                     nonce=11792
INFO [08-04|21:01:27] In commitTransaction                     nonce=11793
INFO [08-04|21:01:27] In commitTransaction                     nonce=11794
INFO [08-04|21:01:27] In commitTransaction                     nonce=11795
INFO [08-04|21:01:27] In commitTransaction                     nonce=11796
INFO [08-04|21:01:27] In commitTransaction                     nonce=11797
INFO [08-04|21:01:27] In commitTransaction                     nonce=11798
INFO [08-04|21:01:27] In commitTransaction                     nonce=11799
INFO [08-04|21:01:27] In commitTransaction                     nonce=11800
INFO [08-04|21:01:27] In commitTransaction                     nonce=11801
INFO [08-04|21:01:27] In commitTransaction                     nonce=11802
INFO [08-04|21:01:27] In commitTransaction                     nonce=11803
INFO [08-04|21:01:27] In commitTransaction                     nonce=11804
INFO [08-04|21:01:27] In commitTransaction                     nonce=11805
INFO [08-04|21:01:27] In commitTransaction                     nonce=11806
INFO [08-04|21:01:27] In commitTransaction                     nonce=11807
INFO [08-04|21:01:27] In commitTransaction                     nonce=11808
INFO [08-04|21:01:27] In commitTransaction                     nonce=11809
INFO [08-04|21:01:27] In commitTransaction                     nonce=11810
INFO [08-04|21:01:27] In commitTransaction                     nonce=11811
INFO [08-04|21:01:27] In commitTransaction                     nonce=11812
INFO [08-04|21:01:27] In commitTransaction                     nonce=11813
INFO [08-04|21:01:27] In commitTransaction                     nonce=11814
INFO [08-04|21:01:27] In commitTransaction                     nonce=11815
INFO [08-04|21:01:27] In commitTransaction                     nonce=11816
INFO [08-04|21:01:27] In commitTransaction                     nonce=11817
INFO [08-04|21:01:27] In commitTransaction                     nonce=11818
INFO [08-04|21:01:27] In commitTransaction                     nonce=11819
INFO [08-04|21:01:27] In commitTransaction                     nonce=11820
INFO [08-04|21:01:27] In commitTransaction                     nonce=11821
INFO [08-04|21:01:27] In commitTransaction                     nonce=11822
INFO [08-04|21:01:27] In commitTransaction                     nonce=11823
INFO [08-04|21:01:27] In commitTransaction                     nonce=11824
INFO [08-04|21:01:27] In commitTransaction                     nonce=11825
INFO [08-04|21:01:27] Commit new mining work                   number=444 txs=150 uncles=0 elapsed=15.618ms
INFO [08-04|21:02:03] Successfully sealed new block            number=444 hash=d73186…8033fb
INFO [08-04|21:02:03] 🔨 mined potential block                  number=444 hash=d73186…8033fb
INFO [08-04|21:02:03] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:02:03] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:02:03] In commitTransaction                     nonce=11675
INFO [08-04|21:02:03] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:02:03] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:02:03] In demoteUnexecutables                   nonce=11825
INFO [08-04|21:02:03] Removed old pending transaction          hash=a320b4…983369
INFO [08-04|21:02:03] Removed old pending transaction          hash=42178b…c1e4cd
INFO [08-04|21:02:03] Removed old pending transaction          hash=c9ad77…af748e
INFO [08-04|21:02:03] Removed old pending transaction          hash=e7fe69…5c19c8
INFO [08-04|21:02:03] Removed old pending transaction          hash=d883e9…9fd92f
INFO [08-04|21:02:03] Removed old pending transaction          hash=7ba7de…6a2d06
INFO [08-04|21:02:03] Removed old pending transaction          hash=335faf…16bcb6
INFO [08-04|21:02:03] Removed old pending transaction          hash=765d41…77fcd0
INFO [08-04|21:02:03] Removed old pending transaction          hash=098bdd…c9296f
INFO [08-04|21:02:03] Removed old pending transaction          hash=aa1844…161971
INFO [08-04|21:02:03] Removed old pending transaction          hash=7e0a32…bed61f
INFO [08-04|21:02:03] Removed old pending transaction          hash=aacc01…3f1bf7
INFO [08-04|21:02:03] Removed old pending transaction          hash=a1d491…2511a8
INFO [08-04|21:02:03] Removed old pending transaction          hash=fa43f8…fdef45
INFO [08-04|21:02:03] Removed old pending transaction          hash=c30135…07b754
INFO [08-04|21:02:03] Removed old pending transaction          hash=1d6bee…05321a
INFO [08-04|21:02:03] Removed old pending transaction          hash=4a37ba…5c4231
INFO [08-04|21:02:03] Removed old pending transaction          hash=a96c3b…fa2ada
INFO [08-04|21:02:03] Removed old pending transaction          hash=7ed216…8ac453
INFO [08-04|21:02:03] Removed old pending transaction          hash=8e82d8…3f23fa
INFO [08-04|21:02:03] Removed old pending transaction          hash=9b6b6a…740ca7
INFO [08-04|21:02:03] Removed old pending transaction          hash=97cead…61c2af
INFO [08-04|21:02:03] Removed old pending transaction          hash=71e963…c459ae
INFO [08-04|21:02:03] Removed old pending transaction          hash=88422f…df2da2
INFO [08-04|21:02:03] Removed old pending transaction          hash=456f69…170a3d
INFO [08-04|21:02:03] Removed old pending transaction          hash=39bdee…52cc24
INFO [08-04|21:02:03] Removed old pending transaction          hash=2c8aae…6e1f1b
INFO [08-04|21:02:03] Removed old pending transaction          hash=ba4ab1…160f24
INFO [08-04|21:02:03] Removed old pending transaction          hash=7f0507…782bc0
INFO [08-04|21:02:03] Removed old pending transaction          hash=d56b0c…bcd12b
INFO [08-04|21:02:03] Removed old pending transaction          hash=0f5f36…0d5143
INFO [08-04|21:02:03] Removed old pending transaction          hash=960849…6029cb
INFO [08-04|21:02:03] Removed old pending transaction          hash=6ae44e…d89104
INFO [08-04|21:02:03] Removed old pending transaction          hash=40eb75…067b9b
INFO [08-04|21:02:03] Removed old pending transaction          hash=3b8723…b70934
INFO [08-04|21:02:03] Removed old pending transaction          hash=338459…59d18d
INFO [08-04|21:02:03] Removed old pending transaction          hash=712817…565893
INFO [08-04|21:02:03] Removed old pending transaction          hash=76fc4e…7d0aa8
INFO [08-04|21:02:03] Removed old pending transaction          hash=99189f…e0a214
INFO [08-04|21:02:03] Removed old pending transaction          hash=312549…094c28
INFO [08-04|21:02:03] Removed old pending transaction          hash=7494a3…8d7e34
INFO [08-04|21:02:03] Removed old pending transaction          hash=9ea417…1ac52b
INFO [08-04|21:02:03] Removed old pending transaction          hash=736788…f2470d
INFO [08-04|21:02:03] Removed old pending transaction          hash=dbda81…8445ba
INFO [08-04|21:02:03] Removed old pending transaction          hash=3f3414…31d134
INFO [08-04|21:02:03] Removed old pending transaction          hash=ad2e0a…28bbc6
INFO [08-04|21:02:03] Removed old pending transaction          hash=e56707…947ca5
INFO [08-04|21:02:03] Removed old pending transaction          hash=4fe7b0…8560e1
INFO [08-04|21:02:03] Removed old pending transaction          hash=0ae40b…de0579
INFO [08-04|21:02:03] Removed old pending transaction          hash=86fdc9…05aaa7
INFO [08-04|21:02:03] Removed old pending transaction          hash=8a233d…898378
INFO [08-04|21:02:03] Removed old pending transaction          hash=35a6b9…52594a
INFO [08-04|21:02:03] Removed old pending transaction          hash=8d62bb…c0861b
INFO [08-04|21:02:03] Transaction failed, will be removed      hash=a320b4…983369 err="invalid nonce: have 11675, expected 11825"
INFO [08-04|21:02:03] Removed old pending transaction          hash=4a0769…89beed
INFO [08-04|21:02:03] Removed old pending transaction          hash=de28a2…c95511
INFO [08-04|21:02:03] Removed old pending transaction          hash=5475cf…b5a366
INFO [08-04|21:02:03] Removed old pending transaction          hash=aded85…91c11f
INFO [08-04|21:02:03] Removed old pending transaction          hash=ac6858…573f7d
INFO [08-04|21:02:03] Removed old pending transaction          hash=d0ac57…bc53cc
INFO [08-04|21:02:03] Removed old pending transaction          hash=2fcda9…cb5f3b
INFO [08-04|21:02:03] Removed old pending transaction          hash=950071…dc4d27
INFO [08-04|21:02:03] Removed old pending transaction          hash=47af8a…5a2f45
INFO [08-04|21:02:03] Removed old pending transaction          hash=0b62be…b85488
INFO [08-04|21:02:03] Removed old pending transaction          hash=1d1145…268cf4
INFO [08-04|21:02:03] Removed old pending transaction          hash=8548d4…a9503a
INFO [08-04|21:02:03] Removed old pending transaction          hash=377ed7…89679a
INFO [08-04|21:02:03] Removed old pending transaction          hash=5fb3c8…7e112a
INFO [08-04|21:02:03] Removed old pending transaction          hash=1cea81…d0724d
INFO [08-04|21:02:03] Removed old pending transaction          hash=22b6f2…0f0ea4
INFO [08-04|21:02:03] Removed old pending transaction          hash=54ec76…af5322
INFO [08-04|21:02:03] Removed old pending transaction          hash=65b6bd…3491ab
INFO [08-04|21:02:03] Removed old pending transaction          hash=6aab9d…6fda24
INFO [08-04|21:02:03] Removed old pending transaction          hash=4e6071…6034fd
INFO [08-04|21:02:03] Removed old pending transaction          hash=e7ab91…384d2b
INFO [08-04|21:02:03] Removed old pending transaction          hash=805a93…e9a92b
INFO [08-04|21:02:03] Removed old pending transaction          hash=c38aa4…9cb3dd
INFO [08-04|21:02:03] Removed old pending transaction          hash=b4ccbd…fb441b
INFO [08-04|21:02:03] Removed old pending transaction          hash=a89536…cce5c3
INFO [08-04|21:02:03] Removed old pending transaction          hash=bcf9ca…041ce1
INFO [08-04|21:02:03] Removed old pending transaction          hash=5da0e6…0d3f1a
INFO [08-04|21:02:03] Removed old pending transaction          hash=6898f7…8f46a3
INFO [08-04|21:02:03] Removed old pending transaction          hash=ed9620…fd40e3
INFO [08-04|21:02:03] Removed old pending transaction          hash=abca99…693076
INFO [08-04|21:02:03] Removed old pending transaction          hash=e979ae…5677f8
INFO [08-04|21:02:03] Removed old pending transaction          hash=7163f0…3d2d2b
INFO [08-04|21:02:03] Removed old pending transaction          hash=3dadff…e206d1
INFO [08-04|21:02:03] Removed old pending transaction          hash=c5ae90…626c1a
INFO [08-04|21:02:03] Removed old pending transaction          hash=99063a…de3f64
INFO [08-04|21:02:03] Removed old pending transaction          hash=fa445a…68afee
INFO [08-04|21:02:03] Removed old pending transaction          hash=0f3b31…6a5542
INFO [08-04|21:02:03] Removed old pending transaction          hash=dc6a68…76c458
INFO [08-04|21:02:03] Removed old pending transaction          hash=ea9599…972ac6
INFO [08-04|21:02:03] Removed old pending transaction          hash=dce678…3b37e6
INFO [08-04|21:02:03] Removed old pending transaction          hash=4c1dbf…d79189
INFO [08-04|21:02:03] Removed old pending transaction          hash=8435ee…114038
INFO [08-04|21:02:03] Removed old pending transaction          hash=578af3…ff80a2
INFO [08-04|21:02:03] Removed old pending transaction          hash=0856fb…276876
INFO [08-04|21:02:03] Removed old pending transaction          hash=bf504e…92579d
INFO [08-04|21:02:03] Removed old pending transaction          hash=297815…6df128
INFO [08-04|21:02:03] Removed old pending transaction          hash=48ec86…ef2064
INFO [08-04|21:02:03] Removed old pending transaction          hash=b0ddca…724329
INFO [08-04|21:02:03] Removed old pending transaction          hash=2f931b…15b536
INFO [08-04|21:02:03] Removed old pending transaction          hash=d87597…10370d
INFO [08-04|21:02:03] Removed old pending transaction          hash=5c2b9d…5d11b2
INFO [08-04|21:02:03] Removed old pending transaction          hash=0c8344…b1624e
INFO [08-04|21:02:03] Removed old pending transaction          hash=90584e…84285e
INFO [08-04|21:02:03] Removed old pending transaction          hash=1bc7f2…072fb9
INFO [08-04|21:02:03] Removed old pending transaction          hash=62644f…5943ce
INFO [08-04|21:02:03] Removed old pending transaction          hash=a677b8…469821
INFO [08-04|21:02:03] Removed old pending transaction          hash=fa3fc2…6ca331
INFO [08-04|21:02:03] Removed old pending transaction          hash=f70a04…15e9ff
INFO [08-04|21:02:03] Removed old pending transaction          hash=354bc5…6e6d75
INFO [08-04|21:02:03] Removed old pending transaction          hash=28d7bc…a72191
INFO [08-04|21:02:03] Removed old pending transaction          hash=c1af38…61f082
INFO [08-04|21:02:03] Removed old pending transaction          hash=64188d…f3741c
INFO [08-04|21:02:03] Removed old pending transaction          hash=5fa871…3a3a95
INFO [08-04|21:02:03] Removed old pending transaction          hash=20f457…972534
INFO [08-04|21:02:03] Removed old pending transaction          hash=a6743c…a55ece
INFO [08-04|21:02:03] Removed old pending transaction          hash=7d760c…ec65f9
INFO [08-04|21:02:03] Removed old pending transaction          hash=e39c06…01ef31
INFO [08-04|21:02:03] Removed old pending transaction          hash=7b973b…4d6bb6
INFO [08-04|21:02:03] Removed old pending transaction          hash=afa96b…00654a
INFO [08-04|21:02:03] Removed old pending transaction          hash=4c52ef…5cd6e6
INFO [08-04|21:02:03] Removed old pending transaction          hash=f5a7ab…c2f99f
INFO [08-04|21:02:03] Removed old pending transaction          hash=bbf730…9edca0
INFO [08-04|21:02:03] Removed old pending transaction          hash=ae92c1…b172d2
INFO [08-04|21:02:03] Removed old pending transaction          hash=7b7f38…e8bcd0
INFO [08-04|21:02:03] Removed old pending transaction          hash=fb7776…97a036
INFO [08-04|21:02:03] Removed old pending transaction          hash=749b28…4afa53
INFO [08-04|21:02:03] Removed old pending transaction          hash=170dc4…9b6e2c
INFO [08-04|21:02:03] Removed old pending transaction          hash=3b4ed0…40d22d
INFO [08-04|21:02:03] Removed old pending transaction          hash=c72804…6a3feb
INFO [08-04|21:02:03] Removed old pending transaction          hash=d78ff9…03e557
INFO [08-04|21:02:03] Removed old pending transaction          hash=f70c41…518666
INFO [08-04|21:02:03] Removed old pending transaction          hash=f95dcd…df81b4
INFO [08-04|21:02:03] Removed old pending transaction          hash=7d1b08…f3a0cb
INFO [08-04|21:02:03] Removed old pending transaction          hash=98cd51…eb3d86
INFO [08-04|21:02:03] Removed old pending transaction          hash=164770…4e16dd
INFO [08-04|21:02:03] Removed old pending transaction          hash=82e62a…19ca6c
INFO [08-04|21:02:03] Removed old pending transaction          hash=f1304b…22c4d4
INFO [08-04|21:02:03] Removed old pending transaction          hash=7b5430…c80d04
INFO [08-04|21:02:03] Removed old pending transaction          hash=66ab66…d62b92
INFO [08-04|21:02:03] Removed old pending transaction          hash=b92464…b886e7
INFO [08-04|21:02:03] Removed old pending transaction          hash=c6391e…ce19c5
INFO [08-04|21:02:03] Removed old pending transaction          hash=358340…c908d5
INFO [08-04|21:02:03] Removed old pending transaction          hash=6e9ce8…dce16c
INFO [08-04|21:02:03] Removed old pending transaction          hash=2fd24b…9febb0
INFO [08-04|21:02:03] Removed old pending transaction          hash=377a13…d0c795
INFO [08-04|21:02:03] Removed old pending transaction          hash=06c32f…3d3e52
INFO [08-04|21:02:03] Removed old pending transaction          hash=a2b6b2…0443c6
INFO [08-04|21:02:03] Commit new mining work                   number=445 txs=0   uncles=0 elapsed=25.240ms
INFO [08-04|21:02:06] Successfully sealed new block            number=445 hash=a79c6d…53ac78
INFO [08-04|21:02:06] 🔨 mined potential block                  number=445 hash=a79c6d…53ac78
INFO [08-04|21:02:06] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:02:06] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:02:06] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:02:06] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:02:06] In demoteUnexecutables                   nonce=11825
INFO [08-04|21:02:06] In commitTransaction                     nonce=11825
INFO [08-04|21:02:06] In commitTransaction                     nonce=11826
INFO [08-04|21:02:06] In commitTransaction                     nonce=11827
INFO [08-04|21:02:06] In commitTransaction                     nonce=11828
INFO [08-04|21:02:06] In commitTransaction                     nonce=11829
INFO [08-04|21:02:06] In commitTransaction                     nonce=11830
INFO [08-04|21:02:06] In commitTransaction                     nonce=11831
INFO [08-04|21:02:06] In commitTransaction                     nonce=11832
INFO [08-04|21:02:06] In commitTransaction                     nonce=11833
INFO [08-04|21:02:06] In commitTransaction                     nonce=11834
INFO [08-04|21:02:06] In commitTransaction                     nonce=11835
INFO [08-04|21:02:06] In commitTransaction                     nonce=11836
INFO [08-04|21:02:06] In commitTransaction                     nonce=11837
INFO [08-04|21:02:06] In commitTransaction                     nonce=11838
INFO [08-04|21:02:06] In commitTransaction                     nonce=11839
INFO [08-04|21:02:06] In commitTransaction                     nonce=11840
INFO [08-04|21:02:06] In commitTransaction                     nonce=11841
INFO [08-04|21:02:06] In commitTransaction                     nonce=11842
INFO [08-04|21:02:06] In commitTransaction                     nonce=11843
INFO [08-04|21:02:06] In commitTransaction                     nonce=11844
INFO [08-04|21:02:06] In commitTransaction                     nonce=11845
INFO [08-04|21:02:06] In commitTransaction                     nonce=11846
INFO [08-04|21:02:06] In commitTransaction                     nonce=11847
INFO [08-04|21:02:06] In commitTransaction                     nonce=11848
INFO [08-04|21:02:06] In commitTransaction                     nonce=11849
INFO [08-04|21:02:06] In commitTransaction                     nonce=11850
INFO [08-04|21:02:06] In commitTransaction                     nonce=11851
INFO [08-04|21:02:06] In commitTransaction                     nonce=11852
INFO [08-04|21:02:06] In commitTransaction                     nonce=11853
INFO [08-04|21:02:06] In commitTransaction                     nonce=11854
INFO [08-04|21:02:06] In commitTransaction                     nonce=11855
INFO [08-04|21:02:06] In commitTransaction                     nonce=11856
INFO [08-04|21:02:06] In commitTransaction                     nonce=11857
INFO [08-04|21:02:06] In commitTransaction                     nonce=11858
INFO [08-04|21:02:06] In commitTransaction                     nonce=11859
INFO [08-04|21:02:06] In commitTransaction                     nonce=11860
INFO [08-04|21:02:06] In commitTransaction                     nonce=11861
INFO [08-04|21:02:06] In commitTransaction                     nonce=11862
INFO [08-04|21:02:06] In commitTransaction                     nonce=11863
INFO [08-04|21:02:06] In commitTransaction                     nonce=11864
INFO [08-04|21:02:06] In commitTransaction                     nonce=11865
INFO [08-04|21:02:06] In commitTransaction                     nonce=11866
INFO [08-04|21:02:06] In commitTransaction                     nonce=11867
INFO [08-04|21:02:06] In commitTransaction                     nonce=11868
INFO [08-04|21:02:06] In commitTransaction                     nonce=11869
INFO [08-04|21:02:06] In commitTransaction                     nonce=11870
INFO [08-04|21:02:06] In commitTransaction                     nonce=11871
INFO [08-04|21:02:06] In commitTransaction                     nonce=11872
INFO [08-04|21:02:06] In commitTransaction                     nonce=11873
INFO [08-04|21:02:06] In commitTransaction                     nonce=11874
INFO [08-04|21:02:06] In commitTransaction                     nonce=11875
INFO [08-04|21:02:06] In commitTransaction                     nonce=11876
INFO [08-04|21:02:06] In commitTransaction                     nonce=11877
INFO [08-04|21:02:06] In commitTransaction                     nonce=11878
INFO [08-04|21:02:06] In commitTransaction                     nonce=11879
INFO [08-04|21:02:06] In commitTransaction                     nonce=11880
INFO [08-04|21:02:06] In commitTransaction                     nonce=11881
INFO [08-04|21:02:06] In commitTransaction                     nonce=11882
INFO [08-04|21:02:06] In commitTransaction                     nonce=11883
INFO [08-04|21:02:06] In commitTransaction                     nonce=11884
INFO [08-04|21:02:06] In commitTransaction                     nonce=11885
INFO [08-04|21:02:06] In commitTransaction                     nonce=11886
INFO [08-04|21:02:06] In commitTransaction                     nonce=11887
INFO [08-04|21:02:06] In commitTransaction                     nonce=11888
INFO [08-04|21:02:06] In commitTransaction                     nonce=11889
INFO [08-04|21:02:06] In commitTransaction                     nonce=11890
INFO [08-04|21:02:06] In commitTransaction                     nonce=11891
INFO [08-04|21:02:06] In commitTransaction                     nonce=11892
INFO [08-04|21:02:06] In commitTransaction                     nonce=11893
INFO [08-04|21:02:06] In commitTransaction                     nonce=11894
INFO [08-04|21:02:06] In commitTransaction                     nonce=11895
INFO [08-04|21:02:06] In commitTransaction                     nonce=11896
INFO [08-04|21:02:06] In commitTransaction                     nonce=11897
INFO [08-04|21:02:06] In commitTransaction                     nonce=11898
INFO [08-04|21:02:06] In commitTransaction                     nonce=11899
INFO [08-04|21:02:06] In commitTransaction                     nonce=11900
INFO [08-04|21:02:06] In commitTransaction                     nonce=11901
INFO [08-04|21:02:06] In commitTransaction                     nonce=11902
INFO [08-04|21:02:06] In commitTransaction                     nonce=11903
INFO [08-04|21:02:06] In commitTransaction                     nonce=11904
INFO [08-04|21:02:06] In commitTransaction                     nonce=11905
INFO [08-04|21:02:06] In commitTransaction                     nonce=11906
INFO [08-04|21:02:06] In commitTransaction                     nonce=11907
INFO [08-04|21:02:06] In commitTransaction                     nonce=11908
INFO [08-04|21:02:06] In commitTransaction                     nonce=11909
INFO [08-04|21:02:06] In commitTransaction                     nonce=11910
INFO [08-04|21:02:06] In commitTransaction                     nonce=11911
INFO [08-04|21:02:06] In commitTransaction                     nonce=11912
INFO [08-04|21:02:06] In commitTransaction                     nonce=11913
INFO [08-04|21:02:06] In commitTransaction                     nonce=11914
INFO [08-04|21:02:06] In commitTransaction                     nonce=11915
INFO [08-04|21:02:06] In commitTransaction                     nonce=11916
INFO [08-04|21:02:06] In commitTransaction                     nonce=11917
INFO [08-04|21:02:06] In commitTransaction                     nonce=11918
INFO [08-04|21:02:06] In commitTransaction                     nonce=11919
INFO [08-04|21:02:06] In commitTransaction                     nonce=11920
INFO [08-04|21:02:06] In commitTransaction                     nonce=11921
INFO [08-04|21:02:06] In commitTransaction                     nonce=11922
INFO [08-04|21:02:06] In commitTransaction                     nonce=11923
INFO [08-04|21:02:06] In commitTransaction                     nonce=11924
INFO [08-04|21:02:06] In commitTransaction                     nonce=11925
INFO [08-04|21:02:06] In commitTransaction                     nonce=11926
INFO [08-04|21:02:06] In commitTransaction                     nonce=11927
INFO [08-04|21:02:06] In commitTransaction                     nonce=11928
INFO [08-04|21:02:06] In commitTransaction                     nonce=11929
INFO [08-04|21:02:06] In commitTransaction                     nonce=11930
INFO [08-04|21:02:06] In commitTransaction                     nonce=11931
INFO [08-04|21:02:06] In commitTransaction                     nonce=11932
INFO [08-04|21:02:06] In commitTransaction                     nonce=11933
INFO [08-04|21:02:06] In commitTransaction                     nonce=11934
INFO [08-04|21:02:06] In commitTransaction                     nonce=11935
INFO [08-04|21:02:06] In commitTransaction                     nonce=11936
INFO [08-04|21:02:06] In commitTransaction                     nonce=11937
INFO [08-04|21:02:06] In commitTransaction                     nonce=11938
INFO [08-04|21:02:06] In commitTransaction                     nonce=11939
INFO [08-04|21:02:06] In commitTransaction                     nonce=11940
INFO [08-04|21:02:06] In commitTransaction                     nonce=11941
INFO [08-04|21:02:06] In commitTransaction                     nonce=11942
INFO [08-04|21:02:06] In commitTransaction                     nonce=11943
INFO [08-04|21:02:06] In commitTransaction                     nonce=11944
INFO [08-04|21:02:06] In commitTransaction                     nonce=11945
INFO [08-04|21:02:06] In commitTransaction                     nonce=11946
INFO [08-04|21:02:06] In commitTransaction                     nonce=11947
INFO [08-04|21:02:06] In commitTransaction                     nonce=11948
INFO [08-04|21:02:06] In commitTransaction                     nonce=11949
INFO [08-04|21:02:06] In commitTransaction                     nonce=11950
INFO [08-04|21:02:06] In commitTransaction                     nonce=11951
INFO [08-04|21:02:06] In commitTransaction                     nonce=11952
INFO [08-04|21:02:06] In commitTransaction                     nonce=11953
INFO [08-04|21:02:06] In commitTransaction                     nonce=11954
INFO [08-04|21:02:06] In commitTransaction                     nonce=11955
INFO [08-04|21:02:06] In commitTransaction                     nonce=11956
INFO [08-04|21:02:06] In commitTransaction                     nonce=11957
INFO [08-04|21:02:06] In commitTransaction                     nonce=11958
INFO [08-04|21:02:06] In commitTransaction                     nonce=11959
INFO [08-04|21:02:06] In commitTransaction                     nonce=11960
INFO [08-04|21:02:06] In commitTransaction                     nonce=11961
INFO [08-04|21:02:06] In commitTransaction                     nonce=11962
INFO [08-04|21:02:06] In commitTransaction                     nonce=11963
INFO [08-04|21:02:06] In commitTransaction                     nonce=11964
INFO [08-04|21:02:06] In commitTransaction                     nonce=11965
INFO [08-04|21:02:06] In commitTransaction                     nonce=11966
INFO [08-04|21:02:06] In commitTransaction                     nonce=11967
INFO [08-04|21:02:06] In commitTransaction                     nonce=11968
INFO [08-04|21:02:06] In commitTransaction                     nonce=11969
INFO [08-04|21:02:06] In commitTransaction                     nonce=11970
INFO [08-04|21:02:06] In commitTransaction                     nonce=11971
INFO [08-04|21:02:06] In commitTransaction                     nonce=11972
INFO [08-04|21:02:06] In commitTransaction                     nonce=11973
INFO [08-04|21:02:06] In commitTransaction                     nonce=11974
INFO [08-04|21:02:06] In commitTransaction                     nonce=11975
INFO [08-04|21:02:06] In commitTransaction                     nonce=11976
INFO [08-04|21:02:06] Commit new mining work                   number=446 txs=151 uncles=0 elapsed=45.355ms
INFO [08-04|21:02:20] Successfully sealed new block            number=446 hash=5a5562…4f0ad1
INFO [08-04|21:02:20] 🔨 mined potential block                  number=446 hash=5a5562…4f0ad1
INFO [08-04|21:02:20] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:02:20] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:02:20] In commitTransaction                     nonce=11825
INFO [08-04|21:02:20] Transaction failed, will be removed      hash=6aecb8…4b8e0c err="invalid nonce: have 11825, expected 11976"
INFO [08-04|21:02:20] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:02:20] Commit new mining work                   number=447 txs=0   uncles=0 elapsed=5.211ms
INFO [08-04|21:02:20] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:02:20] Successfully sealed new block            number=447 hash=804730…960155
INFO [08-04|21:02:20] 🔨 mined potential block                  number=447 hash=804730…960155
INFO [08-04|21:02:20] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:02:20] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:02:20] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:02:20] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:02:20] Commit new mining work                   number=448 txs=0   uncles=0 elapsed=503.44µs

Scenarios highlighted in this example:

  • Block 444 has 150 txns. While old pending txns are being removed, you can see a "Transaction failed, will be removed" at 21:02:03
  • Next block 445 picks up no txns
  • Block 446 has 151 txns. commitTransactions is called before demoteUnexecutables, I get the "Transaction failed" error message and all future blocks will have no txns.
  • Block 447 has no txns
  • txpool is now empty and future mining won't work. (This is incorrect as there were 500 txns submitted of which only 301 have been mined).
> txpool
{
  content: {
    pending: {},
    queued: {}
  },
  inspect: {
    pending: {},
    queued: {}
  },
  status: {
    pending: 0,
    queued: 0
  },
  getContent: function(callback),
  getInspect: function(callback),
  getStatus: function(callback)
}
> eth.getBlock(444).transactions.length
150
> eth.getBlock(445).transactions.length
0
> eth.getBlock(446).transactions.length
151
> eth.getBlock(447).transactions.length
0

To prove that future blocks won't have any txns mined, see extract below:

> miner.start(1);admin.sleepBlocks(3);miner.stop()
INFO [08-04|21:05:08] Updated mining threads                   threads=1
INFO [08-04|21:05:08] Transaction pool price threshold updated price=18000000000
INFO [08-04|21:05:08] Starting mining operation 
INFO [08-04|21:05:08] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:05:08] Commit new mining work                   number=448 txs=0   uncles=0 elapsed=151.385µs
INFO [08-04|21:05:17] Successfully sealed new block            number=448 hash=a1d60e…c7fe3b
INFO [08-04|21:05:17] 🔨 mined potential block                  number=448 hash=a1d60e…c7fe3b
INFO [08-04|21:05:17] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:05:17] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:05:17] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:05:17] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:05:17] Commit new mining work                   number=449 txs=0   uncles=0 elapsed=280.165µs
INFO [08-04|21:05:30] Successfully sealed new block            number=449 hash=6caa18…411946
INFO [08-04|21:05:30] 🔗 block reached canonical chain          number=444 hash=d73186…8033fb
INFO [08-04|21:05:30] 🔨 mined potential block                  number=449 hash=6caa18…411946
INFO [08-04|21:05:30] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:05:30] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:05:30] Commit new mining work                   number=450 txs=0   uncles=0 elapsed=302.631µs
INFO [08-04|21:05:30] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:05:30] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:05:47] Successfully sealed new block            number=450 hash=e7138d…b3c98b
INFO [08-04|21:05:47] 🔗 block reached canonical chain          number=445 hash=a79c6d…53ac78
INFO [08-04|21:05:47] 🔨 mined potential block                  number=450 hash=e7138d…b3c98b
INFO [08-04|21:05:47] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:05:47] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:05:47] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:05:47] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:05:47] Commit new mining work                   number=451 txs=0   uncles=0 elapsed=429.941µs
INFO [08-04|21:05:48] Successfully sealed new block            number=451 hash=a23359…6f2dbf
INFO [08-04|21:05:48] 🔗 block reached canonical chain          number=446 hash=5a5562…4f0ad1
INFO [08-04|21:05:48] 🔨 mined potential block                  number=451 hash=a23359…6f2dbf
INFO [08-04|21:05:48] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:05:48] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:05:48] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:05:48] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:05:48] Commit new mining work                   number=452 txs=0   uncles=0 elapsed=351.115µs

Now if I exit geth and restart it, the txpool will be recreated.

INFO [08-04|21:06:06] Starting P2P networking 
INFO [08-04|21:06:06] UDP listener up                          self=enode://08993401988acce4cd85ef46a8af10d1cacad39652c98a9df4d5785248d1910e51d7f3d330f0a96053001264700c7e94c4ac39d30ed5a5f79758774208adaa1f@[::]:30303
INFO [08-04|21:06:06] RLPx listener up                         self=enode://08993401988acce4cd85ef46a8af10d1cacad39652c98a9df4d5785248d1910e51d7f3d330f0a96053001264700c7e94c4ac39d30ed5a5f79758774208adaa1f@[::]:30303
INFO [08-04|21:06:06] IPC endpoint opened: /home/ethuser/node1/geth.ipc 
Welcome to the Geth JavaScript console!

instance: Geth/v1.7.0-unstable/linux-amd64/go1.8.1
coinbase: 0xf74afb1facd5eb2dd69feb589213c12be9b38177
at block: 451 (Fri, 04 Aug 2017 21:05:47 BST)
 datadir: /home/ethuser/node1
 modules: admin:1.0 debug:1.0 eth:1.0 miner:1.0 net:1.0 personal:1.0 rpc:1.0 txpool:1.0 web3:1.0

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

And future mining can work as expected (assuming that ChainHeadEvent leads to demoteUnexecutables being completed before commitNewWork is called).

> miner.start(1);admin.sleepBlocks(2);miner.stop()
INFO [08-04|21:07:21] Updated mining threads                   threads=1
INFO [08-04|21:07:21] Transaction pool price threshold updated price=18000000000
INFO [08-04|21:07:21] Starting mining operation 
INFO [08-04|21:07:21] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:07:21] In commitTransaction                     nonce=11976
INFO [08-04|21:07:21] In commitTransaction                     nonce=11977
INFO [08-04|21:07:21] In commitTransaction                     nonce=11978
INFO [08-04|21:07:21] In commitTransaction                     nonce=11979
INFO [08-04|21:07:21] In commitTransaction                     nonce=11980
INFO [08-04|21:07:21] In commitTransaction                     nonce=11981
INFO [08-04|21:07:21] In commitTransaction                     nonce=11982
INFO [08-04|21:07:21] In commitTransaction                     nonce=11983
INFO [08-04|21:07:21] In commitTransaction                     nonce=11984
INFO [08-04|21:07:21] In commitTransaction                     nonce=11985
INFO [08-04|21:07:21] In commitTransaction                     nonce=11986
INFO [08-04|21:07:21] In commitTransaction                     nonce=11987
INFO [08-04|21:07:21] In commitTransaction                     nonce=11988
INFO [08-04|21:07:21] In commitTransaction                     nonce=11989
INFO [08-04|21:07:21] In commitTransaction                     nonce=11990
INFO [08-04|21:07:21] In commitTransaction                     nonce=11991
INFO [08-04|21:07:21] In commitTransaction                     nonce=11992
INFO [08-04|21:07:21] In commitTransaction                     nonce=11993
INFO [08-04|21:07:21] In commitTransaction                     nonce=11994
INFO [08-04|21:07:21] In commitTransaction                     nonce=11995
INFO [08-04|21:07:21] In commitTransaction                     nonce=11996
INFO [08-04|21:07:21] In commitTransaction                     nonce=11997
INFO [08-04|21:07:21] In commitTransaction                     nonce=11998
INFO [08-04|21:07:21] In commitTransaction                     nonce=11999
INFO [08-04|21:07:21] In commitTransaction                     nonce=12000
INFO [08-04|21:07:21] In commitTransaction                     nonce=12001
INFO [08-04|21:07:21] In commitTransaction                     nonce=12002
INFO [08-04|21:07:21] In commitTransaction                     nonce=12003
INFO [08-04|21:07:21] In commitTransaction                     nonce=12004
INFO [08-04|21:07:21] In commitTransaction                     nonce=12005
INFO [08-04|21:07:21] In commitTransaction                     nonce=12006
INFO [08-04|21:07:21] In commitTransaction                     nonce=12007
INFO [08-04|21:07:21] In commitTransaction                     nonce=12008
INFO [08-04|21:07:21] In commitTransaction                     nonce=12009
INFO [08-04|21:07:21] In commitTransaction                     nonce=12010
INFO [08-04|21:07:21] In commitTransaction                     nonce=12011
INFO [08-04|21:07:21] In commitTransaction                     nonce=12012
INFO [08-04|21:07:21] In commitTransaction                     nonce=12013
INFO [08-04|21:07:21] In commitTransaction                     nonce=12014
INFO [08-04|21:07:21] In commitTransaction                     nonce=12015
INFO [08-04|21:07:21] In commitTransaction                     nonce=12016
INFO [08-04|21:07:21] In commitTransaction                     nonce=12017
INFO [08-04|21:07:21] In commitTransaction                     nonce=12018
INFO [08-04|21:07:21] In commitTransaction                     nonce=12019
INFO [08-04|21:07:21] In commitTransaction                     nonce=12020
INFO [08-04|21:07:21] In commitTransaction                     nonce=12021
INFO [08-04|21:07:21] In commitTransaction                     nonce=12022
INFO [08-04|21:07:21] In commitTransaction                     nonce=12023
INFO [08-04|21:07:21] In commitTransaction                     nonce=12024
INFO [08-04|21:07:21] In commitTransaction                     nonce=12025
INFO [08-04|21:07:21] In commitTransaction                     nonce=12026
INFO [08-04|21:07:21] In commitTransaction                     nonce=12027
INFO [08-04|21:07:21] In commitTransaction                     nonce=12028
INFO [08-04|21:07:21] In commitTransaction                     nonce=12029
INFO [08-04|21:07:21] In commitTransaction                     nonce=12030
INFO [08-04|21:07:21] In commitTransaction                     nonce=12031
INFO [08-04|21:07:21] In commitTransaction                     nonce=12032
INFO [08-04|21:07:21] In commitTransaction                     nonce=12033
INFO [08-04|21:07:21] In commitTransaction                     nonce=12034
INFO [08-04|21:07:21] In commitTransaction                     nonce=12035
INFO [08-04|21:07:21] In commitTransaction                     nonce=12036
INFO [08-04|21:07:21] In commitTransaction                     nonce=12037
INFO [08-04|21:07:21] In commitTransaction                     nonce=12038
INFO [08-04|21:07:21] In commitTransaction                     nonce=12039
INFO [08-04|21:07:21] In commitTransaction                     nonce=12040
INFO [08-04|21:07:21] In commitTransaction                     nonce=12041
INFO [08-04|21:07:21] In commitTransaction                     nonce=12042
INFO [08-04|21:07:21] In commitTransaction                     nonce=12043
INFO [08-04|21:07:21] In commitTransaction                     nonce=12044
INFO [08-04|21:07:21] In commitTransaction                     nonce=12045
INFO [08-04|21:07:21] In commitTransaction                     nonce=12046
INFO [08-04|21:07:21] In commitTransaction                     nonce=12047
INFO [08-04|21:07:21] In commitTransaction                     nonce=12048
INFO [08-04|21:07:21] In commitTransaction                     nonce=12049
INFO [08-04|21:07:21] In commitTransaction                     nonce=12050
INFO [08-04|21:07:21] In commitTransaction                     nonce=12051
INFO [08-04|21:07:21] In commitTransaction                     nonce=12052
INFO [08-04|21:07:21] In commitTransaction                     nonce=12053
INFO [08-04|21:07:21] In commitTransaction                     nonce=12054
INFO [08-04|21:07:21] In commitTransaction                     nonce=12055
INFO [08-04|21:07:21] In commitTransaction                     nonce=12056
INFO [08-04|21:07:21] In commitTransaction                     nonce=12057
INFO [08-04|21:07:21] In commitTransaction                     nonce=12058
INFO [08-04|21:07:21] In commitTransaction                     nonce=12059
INFO [08-04|21:07:21] In commitTransaction                     nonce=12060
INFO [08-04|21:07:21] In commitTransaction                     nonce=12061
INFO [08-04|21:07:21] In commitTransaction                     nonce=12062
INFO [08-04|21:07:21] In commitTransaction                     nonce=12063
INFO [08-04|21:07:21] In commitTransaction                     nonce=12064
INFO [08-04|21:07:21] In commitTransaction                     nonce=12065
INFO [08-04|21:07:21] In commitTransaction                     nonce=12066
INFO [08-04|21:07:21] In commitTransaction                     nonce=12067
INFO [08-04|21:07:21] In commitTransaction                     nonce=12068
INFO [08-04|21:07:21] In commitTransaction                     nonce=12069
INFO [08-04|21:07:21] In commitTransaction                     nonce=12070
INFO [08-04|21:07:21] In commitTransaction                     nonce=12071
INFO [08-04|21:07:21] In commitTransaction                     nonce=12072
INFO [08-04|21:07:21] In commitTransaction                     nonce=12073
INFO [08-04|21:07:21] In commitTransaction                     nonce=12074
INFO [08-04|21:07:21] In commitTransaction                     nonce=12075
INFO [08-04|21:07:21] In commitTransaction                     nonce=12076
INFO [08-04|21:07:21] In commitTransaction                     nonce=12077
INFO [08-04|21:07:21] In commitTransaction                     nonce=12078
INFO [08-04|21:07:21] In commitTransaction                     nonce=12079
INFO [08-04|21:07:21] In commitTransaction                     nonce=12080
INFO [08-04|21:07:21] In commitTransaction                     nonce=12081
INFO [08-04|21:07:21] In commitTransaction                     nonce=12082
INFO [08-04|21:07:21] In commitTransaction                     nonce=12083
INFO [08-04|21:07:21] In commitTransaction                     nonce=12084
INFO [08-04|21:07:21] In commitTransaction                     nonce=12085
INFO [08-04|21:07:21] In commitTransaction                     nonce=12086
INFO [08-04|21:07:21] In commitTransaction                     nonce=12087
INFO [08-04|21:07:21] In commitTransaction                     nonce=12088
INFO [08-04|21:07:21] In commitTransaction                     nonce=12089
INFO [08-04|21:07:21] In commitTransaction                     nonce=12090
INFO [08-04|21:07:21] In commitTransaction                     nonce=12091
INFO [08-04|21:07:21] In commitTransaction                     nonce=12092
INFO [08-04|21:07:21] In commitTransaction                     nonce=12093
INFO [08-04|21:07:21] In commitTransaction                     nonce=12094
INFO [08-04|21:07:21] In commitTransaction                     nonce=12095
INFO [08-04|21:07:21] In commitTransaction                     nonce=12096
INFO [08-04|21:07:21] In commitTransaction                     nonce=12097
INFO [08-04|21:07:21] In commitTransaction                     nonce=12098
INFO [08-04|21:07:21] In commitTransaction                     nonce=12099
INFO [08-04|21:07:21] In commitTransaction                     nonce=12100
INFO [08-04|21:07:21] In commitTransaction                     nonce=12101
INFO [08-04|21:07:21] In commitTransaction                     nonce=12102
INFO [08-04|21:07:21] In commitTransaction                     nonce=12103
INFO [08-04|21:07:21] In commitTransaction                     nonce=12104
INFO [08-04|21:07:21] In commitTransaction                     nonce=12105
INFO [08-04|21:07:21] In commitTransaction                     nonce=12106
INFO [08-04|21:07:21] In commitTransaction                     nonce=12107
INFO [08-04|21:07:21] In commitTransaction                     nonce=12108
INFO [08-04|21:07:21] In commitTransaction                     nonce=12109
INFO [08-04|21:07:21] In commitTransaction                     nonce=12110
INFO [08-04|21:07:21] In commitTransaction                     nonce=12111
INFO [08-04|21:07:21] In commitTransaction                     nonce=12112
INFO [08-04|21:07:21] In commitTransaction                     nonce=12113
INFO [08-04|21:07:21] In commitTransaction                     nonce=12114
INFO [08-04|21:07:21] In commitTransaction                     nonce=12115
INFO [08-04|21:07:21] In commitTransaction                     nonce=12116
INFO [08-04|21:07:21] In commitTransaction                     nonce=12117
INFO [08-04|21:07:21] In commitTransaction                     nonce=12118
INFO [08-04|21:07:21] In commitTransaction                     nonce=12119
INFO [08-04|21:07:21] In commitTransaction                     nonce=12120
INFO [08-04|21:07:21] In commitTransaction                     nonce=12121
INFO [08-04|21:07:21] In commitTransaction                     nonce=12122
INFO [08-04|21:07:21] In commitTransaction                     nonce=12123
INFO [08-04|21:07:21] In commitTransaction                     nonce=12124
INFO [08-04|21:07:21] In commitTransaction                     nonce=12125
INFO [08-04|21:07:21] In commitTransaction                     nonce=12126
INFO [08-04|21:07:21] In commitTransaction                     nonce=12127
INFO [08-04|21:07:21] In commitTransaction                     nonce=12128
INFO [08-04|21:07:21] Commit new mining work                   number=452 txs=152 uncles=0 elapsed=71.006ms
INFO [08-04|21:07:23] Successfully sealed new block            number=452 hash=691c64…86eea4
INFO [08-04|21:07:23] 🔨 mined potential block                  number=452 hash=691c64…86eea4
INFO [08-04|21:07:23] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:07:23] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:07:23] In commitTransaction                     nonce=11976
INFO [08-04|21:07:23] Transaction failed, will be removed      hash=a3425b…d3affd err="invalid nonce: have 11976, expected 12128"
INFO [08-04|21:07:23] Commit new mining work                   number=453 txs=0   uncles=0 elapsed=3.072ms
INFO [08-04|21:07:23] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:07:23] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:07:33] Successfully sealed new block            number=453 hash=f58295…81f98f
INFO [08-04|21:07:33] 🔨 mined potential block                  number=453 hash=f58295…81f98f
INFO [08-04|21:07:33] Worker update() got ChainHeadEvent, going to commitNewWork 
INFO [08-04|21:07:33] In commitNewWork: will shortly commitTransactions 
INFO [08-04|21:07:33] TxPool loop() Got ChainHeadEvent, going to resetState 
INFO [08-04|21:07:33] In resetState: will shortly demoteUnexecutables 
INFO [08-04|21:07:33] Commit new mining work                   number=454 txs=0   uncles=0 elapsed=384.935µs

In this example, the ChainHeadEvent led to commitNewWork being called before resetState, so there were still some txns left in limbo.

To recap my understanding of what is happening here: ChainHeadEvent fires and this triggers code in both core/tx_pool.go miner/worker.go. If the code in core/tx_pool.go happens to be executed first then all is well. If, however, the code in miner/worker.go is executed before core/tx_pool.go has finished processing then you can end up with an inconsistent txpool that will cause future mining to not work as expected.

@snatalenko

This comment has been minimized.

snatalenko commented Sep 13, 2017

I have the same issue.
Easy to reproduce even on a small number of transactions:

  • stop miner
  • send 1st transaction
  • start miner
  • geth log output: "Commit new mining work number=N txs=1 uncles=0"
  • send 2nd transaction
  • at this moment txpool contains 2 pending transactions from same account with different nonce
  • once block N is being mined with 1st transaction, txpool becomes empty; 2nd transaction does not show up in the subsequent blocks
@karalabe

This comment has been minimized.

Member

karalabe commented Sep 13, 2017

Please use master branch, this issue should be fixed on it.

@alanbuxton

This comment has been minimized.

alanbuxton commented Sep 14, 2017

Yes looks good on master, thanks:

> admin.nodeInfo.name
"Geth/v1.7.1-unstable-5705ad00/linux-amd64/go1.8.1"
> eth.pendingTransactions.length
403
> miner.start(1);admin.sleepBlocks(3);miner.stop()
INFO [09-14|14:49:27] Updated mining threads                   threads=1
INFO [09-14|14:49:27] Transaction pool price threshold updated price=18000000000
INFO [09-14|14:49:27] Starting mining operation 
INFO [09-14|14:49:27] Commit new mining work                   number=17 txs=98 uncles=0 elapsed=9.379ms
INFO [09-14|14:49:30] Successfully sealed new block            number=17 hash=907612…64cd4f
INFO [09-14|14:49:30] 🔨 mined potential block                  number=17 hash=907612…64cd4f
INFO [09-14|14:49:30] Commit new mining work                   number=18 txs=98 uncles=0 elapsed=14.578ms
INFO [09-14|14:49:47] Successfully sealed new block            number=18 hash=58a010…6c8ee9
INFO [09-14|14:49:47] 🔨 mined potential block                  number=18 hash=58a010…6c8ee9
INFO [09-14|14:49:47] Commit new mining work                   number=19 txs=98 uncles=0 elapsed=8.234ms
INFO [09-14|14:49:49] Successfully sealed new block            number=19 hash=700acb…a08091
INFO [09-14|14:49:49] 🔨 mined potential block                  number=19 hash=700acb…a08091
INFO [09-14|14:49:49] Commit new mining work                   number=20 txs=98 uncles=0 elapsed=33.886ms
true
> eth.pendingTransactions.length
109

@alanbuxton alanbuxton closed this Sep 14, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment