stress testing on the 7node example causes unexpected behaviour

[guojian1234]

System information

Geth version: 1.7.2-stable
Quorum Version 2.0.2
Go Version : go1.9.2

OS & Version: Centos7

Branch, Commit Hash or Release: Release Tag:v2.0.2

Expected behaviour

I did a test with around 150 transactions per second, It should work all the time

Actual behaviour

a few hours later, Transactions cannot bt executed, and there is always an error :"nonce too high"。at this time , txpool.status is {pending:4096, queue :64}
I repeated the test several times, Sometimes after a few hours, sometimes a few days, this error will occur

Steps to reproduce the behaviour

1、start quorum-example whit raft-start.sh
2、deploy contracts ENS.sol
3、use web3js call ens.setOwner() ten times per second
ENS.sol is a very simple contracts as:
pragma solidity ^0.4.15;
contract ENS {

mapping(string =>string) records;
struct Timer {
    uint256 time;
}
Timer timer;
function ENS() public {
    timer.time = 0;
}

function setOwner(string node,string owner) public {
    records[node]= owner;
    addNumber(timer);
}

}

Backtrace

6748557 TRACE[06-19|11:36:42|core/tx_pool.go:606] add tx nonce is :=303058 tx hash=5d5860…9e8f10
6748558 INFO [06-19|11:36:42|raft/minter.go:379] TX success nonce=303056 txCount=2
6748559 TRACE[06-19|11:36:42|core/state_transition.go:207] account nonce is :=303057 tx nonce is :=303057
6748560 DEBUG[06-19|11:36:42|core/state_transition.go:277] set nonce LOG15_ERROR= LOG15_ERROR="Normalized odd number of arguments by adding nil"
6748561 INFO [06-19|11:36:42|raft/minter.go:379] TX success nonce=303057 txCount=3
6748562 TRACE[06-19|11:36:42|core/tx_pool.go:666] Pooled new future transaction hash=5d5860…9e8f10 from=0xed9d02e382b34818e88B88a309c7fe71E65f419d to=0x9d13C6D3aFE1721BEef56B55D303B09E021E27ab nonce=303058
6748563 TRACE[06-19|11:36:42|core/tx_pool.go:919] Promoting queued transaction hash=5d5860…9e8f10
6748564 TRACE[06-19|11:36:42|core/tx_pool.go:606] add tx nonce is :=303058 tx hash=5d5860…9e8f10
6748565 TRACE[06-19|11:36:42|core/tx_pool.go:608] Discarding already known transaction hash=5d5860…9e8f10
6748566 TRACE[06-19|11:36:42|core/tx_pool.go:606] add tx nonce is :=303058 tx hash=5d5860…9e8f10
6748567 TRACE[06-19|11:36:42|core/tx_pool.go:608] Discarding already known transaction hash=5d5860…9e8f10
6748568 TRACE[06-19|11:36:42|core/tx_pool.go:606] add tx nonce is :=303058 tx hash=5d5860…9e8f10
6748569 TRACE[06-19|11:36:42|core/tx_pool.go:608] Discarding already known transaction hash=5d5860…9e8f10
6748570 INFO [06-19|11:36:42|raft/minter.go:337] Generated next block block num=80045 num txes=3
6748571 TRACE[06-19|11:36:42|eth/handler.go:769] Broadcast transaction hash=5d5860…9e8f10 recipients=5
6748572 TRACE[06-19|11:36:42|core/tx_pool.go:606] add tx nonce is :=303058 tx hash=5d5860…9e8f10
6748573 TRACE[06-19|11:36:42|core/tx_pool.go:608] Discarding already known transaction hash=5d5860…9e8f10
6748574 DEBUG[06-19|11:36:42|core/state/statedb.go:605] Trie cache stats after commit misses=480225 unloads=160066
6748575 DEBUG[06-19|11:36:42|core/state/statedb.go:605] Trie cache stats after commit misses=480225 unloads=160066
6748576 INFO [06-19|11:36:42|raft/minter.go:352] 🔨 Mined block number=80045 hash=8af99bb0 elapsed=3.014995ms
4033038 INFO [06-19|11:36:44|raft/minter.go:352] 🔨 Mined block number=80043 hash=00798135 elapsed=56.821356ms
4033039 INFO [06-19|11:36:44|raft/speculative_chain.go:72] Another node minted; Clearing speculative state block=acbc00…8d2e5d；

[backtrace]

[guojian1234]

I think I found the cause of the error.
Analyze the log and found that this error always occurred after the leader exchange.during new leader minter the second block ,there are two block insert into blockchain which mintered by old leader ,Let's say these two blocks are block-a and block-b. Because the new miners have packed a block, minter.speculativeChain is not nil。 when block-a was inserted into blockchain, minter clear speculative and set speculativeChain.head = block-a, in function func (chain *speculativeChain) accept(acceptedBlock *types.Block)，and then block-b was inserted into blockchain, at this time ,because speculativeChain is nil， func accept() do not set speculativeChain.head = block-b， here error occur,speculatuve.head is block-a ,and blockchain.current = block-b. block-b.blocknumber = block-a.blocknumber + 1.then, when new leader minter a new block,there will be an error: nonce too high
at any time speculatuve.head.blocknumber should >= blockchain.current.blocknumber

[guojian1234]

My solution:
add a function at raft/minter.go like；
func (minter *minter) checkSpeculative() {
parent := minter.speculativeChain.head
parentNumber := parent.Number()
block := minter.chain.CurrentBlock()
blockNumber := block.Number()
if checkflag := parentNumber.Cmp(blockNumber) < 0; checkflag{
log.Info("Speculative.head.blockNumber < minter.chain.currenBlock.blockNumber")
minter.speculativeChain.clear(block)
}
}
this function check when speculative.head.blockNumber < minter.chain.currenBlock.blockNumer , it will clear speculative with minter.chain.currenBlock.

call minter.checkSpeculative() at function mintNewBlock() about line 326 ,as ：
func (minter *minter) mintNewBlock() {
......
if txCount == 0 {
log.Info("Not minting a new block since there are no pending transactions")
minter.checkSpeculative()
return
}

........
}

[jpmsam]

@guojian1234 can you please try running the same test on master?

[fixanoid]

@jpmsam I see this occur occasionally off the master as well.

@guojian1234 we accept pull requests, so if you submit one I'll expedite it. Otherwise, we'll add an update in a bit.

[guojian1234]

@fixanoid I will add a pull requests later

[joelburget]

@guojian1234 I opened another proposed fix in #437. It would be great if you could take a look and test that it fixes your issue