Command line parameter `--allowedfutureblocktime` can result in "Mining too far in the future" messages

[SatpalSandhu61]

System information

Geth version: geth version

Version: 1.9.7-stable
Git Commit: e2e782ecfda15810823a111c52ee862cb66e12f9
Git Commit Date: 20200515
Quorum Version: 2.6.0
Architecture: amd64
Protocol Versions: [64 63]
Network Id: 1337
Go Version: go1.11.13
Operating System: darwin
GOPATH=/Users/satpal/Documents/go-workspace/
GOROOT=/usr/local/go

Expected behaviour

If a node is 10’s of milliseconds out of sync, then --allowedfutureblocktime should prevent “Block in the future” messages.
No other impact should be seen.

Actual behaviour

The message “Mining too far in the future” is being sporadically logged. When this occurs a 2 second wait is also introduced.
This occurs for clique and IBFT consensus.

Steps to reproduce the behaviour

Set up an IBFT network where one node has the current time around 20 milliseconds ahead of the other nodes. All nodes must be configured with --allowedfutureblocktime 2 command line parameter.
You will see “Mining too far in the future” messages logged sporadically by nodes (you may need to wait for a hundred or so blocks to be created).

Root cause

Issue is caused by a pre-prepare message being received with a future time.
If -- allowedfutureblocktime is not used then a delay is introduced in consensus/Istanbul/core/preprepare.go::handlePreprepare() where it waits until the pre-prepare message is no longer in the future. That has the effect of delaying processing so that this issue does not occur.
Therefore the issue is only seen when using a non-zero value of -- allowedfutureblocktime.

Detail

The problem is with code in miner/worker.go::commitNewWork() where it checks that nodes aren’t “going off too far in the future”.
Here are the details by virtue of an example, where node 1 is 20 milliseconds ahead (note that log lines with “======” are additional debug logs):

• node 1 is creating a new block and its time has just ticked over the second when it sends the ‘pre-prepare’ message to other nodes
  
  INFO [05-22|14:20:21.001] ======= istanbul/core/preprepare.go::sendPreprepare()
  INFO [05-22|14:20:21.031] 🔨 mined potential block number=27 hash=59c9c7…9efc55

• node 2 receives and processes pre-prepare message for the new block, however it’s time hasn’t ticked over the second yet
  
  INFO [05-22|14:20:20.985] ======= istanbul/core/preprepare.go::handlePreprepare() time.Now()=2020-05-22T14:20:20+0000

• node 2 calls worker.go::commitNewWork() with parameter timestamp = 1590157220 (which is time.Now())
  
  INFO [05-22|14:20:20.997] ======= istanbul/backend/engine.go::verifyHeader() checking for Future Block, block number=27, AllowedFutureBlockTime=2, now().Unix()=1590157220, header.Time=1590157221
  INFO [05-22|14:20:20.998] ======= miner/worker.go::commitNewWork() parent block number=27, time.Now()=1590157220, timestamp=1590157220

• commitNewWork() performs the following:
  
  block header.time = 1590157221 this is > time.Now(), so block header.time+1 is used for future check
  code now checks: (block header.time+1) > (current time+1), i.e. 1590157222 > 1590157222
  this check fails, so ‘Mining too far in the future’ occurs.

The fix for this is to add the threshold value when comparing current time to block time. The threshold value should be set to one second. This will allow blocks to be slightly in the future, but will avoid issues caused by any node(s) being a few milliseconds out of sync.