Semux version: 1.2.0
OS & Version: Ubuntu 16.04 / 18.04, macOS 10.13.4
Java: 8 or 10
My validator started getting "invalid block header" warnings (errors, really) during a block proposal, resulting in failures to forge blocks. I added some debug messages and found that the cause was the proposed block's timestamp check failure, resulting from an incorrect timestamp of the block forged by the validator before mine.
In SemuxBft.validateBlock(), right before if (!Block.validateHeader()), I added:
logger.info("Time check: prev {}, current {} (delta: {})", latest.getHeader().getTimestamp(), header.getTimestamp(), header.getTimestamp() - latest.getHeader().getTimestamp());
Normally, I would see deltas of about 30 sec, but the validator before me consistently had 60 sec deltas. However, the actual time between his block and the block previous to his was still at the regular 30 sec interval. So for my validator, this resulted in the delta for my block's timestamp to be a small negative value, causing the block validation failure.
There are currently several validators with block timestamp deltas over 30 (+/-) seconds. semux666 is the validator that reports about 60 seconds, and that causes consistent failures to forge for whoever comes after him. Additionally, there are deltas in the range of 40-50 seconds for some other validators. As long as a delta is less than 60 seconds, a validator that follows is still able to forge blocks successfully.
Here's an example log, with bolded lines for the culprit and the victim:
2018-06-10T14:08:47-0400 INFO SemuxBft Entered new_height: height = 390863, # validators = 100
2018-06-10T14:08:50-0400 INFO SemuxBft Entered propose: height = 390863, view = 0, primary = false, # connected validators = 1 + 78
2018-06-10T14:09:02-0400 INFO SemuxBft Entered validate: proposal = true, votes = [4, 0] [0, 0] [0, 0]
2018-06-10T14:09:02-0400 INFO SemuxBft Time check: prev 1528654101516, current 1528654130198 (delta: 28682)
2018-06-10T14:09:08-0400 INFO SemuxBft Entered pre_commit: proposal = true, votes = [98, 0] [3, 0] [0, 0]
2018-06-10T14:09:14-0400 INFO SemuxBft Entered commit: proposal = true, votes = [98, 0] [98, 0] [4, 0]
2018-06-10T14:09:14-0400 INFO SemuxBft Entered finalize: proposal = true, votes = [98, 0] [98, 0] [67, 0]
2018-06-10T14:09:14-0400 INFO SemuxBft Block [number = 390863, view = 0, hash = 6aec8cfa86057310b2a43f8f5fe0925376cf1843759a863734d97c1cec476280, # txs = 0, # votes = 98]
2018-06-10T14:09:17-0400 INFO SemuxBft Entered new_height: height = 390864, # validators = 100
2018-06-10T14:09:20-0400 INFO SemuxBft Entered propose: height = 390864, view = 0, primary = false, # connected validators = 1 + 79
2018-06-10T14:09:32-0400 INFO SemuxBft Entered validate: proposal = true, votes = [3, 0] [0, 0] [0, 0]
2018-06-10T14:09:32-0400 INFO SemuxBft Time check: prev 1528654130198, current 1528654191065 (delta: 60867)
2018-06-10T14:09:38-0400 INFO SemuxBft Entered pre_commit: proposal = true, votes = [98, 0] [2, 0] [0, 0]
2018-06-10T14:09:44-0400 INFO SemuxBft Entered commit: proposal = true, votes = [98, 0] [98, 0] [3, 0]
2018-06-10T14:09:44-0400 INFO SemuxBft Entered finalize: proposal = true, votes = [98, 0] [98, 0] [67, 0]
2018-06-10T14:09:44-0400 INFO SemuxBft Block [number = 390864, view = 0, hash = d4d06b61b845e049f80ece7437135be50341aceb4cac0788fc4c1db9b308da69, # txs = 0, # votes = 98]
2018-06-10T14:09:47-0400 INFO SemuxBft Entered new_height: height = 390865, # validators = 100
2018-06-10T14:09:50-0400 INFO SemuxBft Entered propose: height = 390865, view = 0, primary = true, # connected validators = 1 + 80
2018-06-10T14:10:02-0400 INFO SemuxBft Entered validate: proposal = true, votes = [0, 2] [0, 0] [0, 0]
2018-06-10T14:10:02-0400 INFO SemuxBft Time check: prev 1528654191065, current 1528654190505 (delta: -560)
2018-06-10T14:10:02-0400 WARN SemuxBft Invalid block header
2018-06-10T14:10:08-0400 INFO SemuxBft Entered pre_commit: proposal = true, votes = [0, 98] [0, 4] [0, 0]
2018-06-10T14:10:14-0400 INFO SemuxBft Entered propose: height = 390865, view = 1, primary = false, # connected validators = 1 + 81
2018-06-10T14:10:26-0400 INFO SemuxBft Entered validate: proposal = true, votes = [2, 0] [0, 0] [0, 0]
2018-06-10T14:10:26-0400 INFO SemuxBft Time check: prev 1528654191065, current 1528654214503 (delta: 23438)
2018-06-10T14:10:32-0400 INFO SemuxBft Entered pre_commit: proposal = true, votes = [98, 0] [4, 0] [0, 0]
2018-06-10T14:10:38-0400 INFO SemuxBft Entered commit: proposal = true, votes = [98, 0] [98, 0] [4, 0]
2018-06-10T14:10:38-0400 INFO SemuxBft Entered finalize: proposal = true, votes = [98, 0] [98, 0] [67, 0]
2018-06-10T14:10:38-0400 INFO SemuxBft Block [number = 390865, view = 1, hash = 78e48571d5ffdf4ecba0231a2c2dc7f9e1f12a5fc794f9417f715b5bf11bfc4c, # txs = 0, # votes = 98]
2018-06-10T14:10:41-0400 INFO SemuxBft Entered new_height: height = 390866, # validators = 100