PoA one validator is behaving strange and skipping its rounds to validate (or validating a wrong round)

[gperezalba]

Before filing a new issue, please provide the following information.

If you think that your issue is an exploitable security vulnerability, please mail your bugreport to security@parity.io instead; your submission might be eligible for our Bug Bounty.
You can find mode info on the reporting process in SECURITY.md

• Parity Ethereum version: v2.5.5-stable and v2.6.1-beta
• Operating system: Linux
• Installation: built from source
• Fully synchronized: yes
• Network: custom PoA
• Restarted: yes

Your issue description goes here below. Try to include actual vs. expected behavior and steps to reproduce the issue.

ACTUAL
I'm running a PoA and I'm experiencing a very strange behaviour. I have 10 validators and for some reason every 8 blocks 9 of them are Reporting benign misbehaviour (cause: skipped step).
The validator they are reporting is working and when I check it's logs I find out this:
(i) This validator genarates its block (IO Worker #1 INFO import Imported #1015986) but
(ii) it seems to be an incorrect block number (?) but
(iii) after that this validator reports bening misbehaviour for the same block number (Verifier #0 TRACE engine Reporting benign misbehaviour (cause: skipped step) at block #1015986, epoch set number 10, step proposer=0x54e2af914baaccd6841378d52e13bd5faec2d88b. Own address: 0xde56…c176) then
(iv) two logs that make me think this validator made any error (1: Verifier #0 WARN engine Validator 0x54e2…d88b could not be reported Transaction import error: Transaction error (Already imported) 2: Verifier #0 TRACE engine Primary that skipped is self, not self-reporting. Own address: 0xde56…c176), finally
(v) Verifier imports blocks #1015986 (again) and #1015987 (that contains the other 9 validator's reports).

Here you can see the complete log for this period of time:

2020-01-09 11:02:44 UTC IO Worker #1 INFO import Imported #1015986 0x7f5e…2b83 (0 txs, 0.00 Mgas, 9 ms, 0.57 KiB)
2020-01-09 11:02:45 UTC IO Worker #3 TRACE engine step_proposer: Fetched proposer for step 315713553: 0xe576…1b8d
2020-01-09 11:02:45 UTC IO Worker #3 TRACE engine Not preparing block: not a proposer for step 315713553. (Our address: 0xde56…c176)
2020-01-09 11:02:45 UTC IO Worker #3 TRACE engine step_proposer: Fetched proposer for step 315713553: 0xe576…1b8d
2020-01-09 11:02:45 UTC IO Worker #3 TRACE engine Not preparing block: not a proposer for step 315713553. (Our address: 0xde56…c176)
2020-01-09 11:02:46 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x2e7b…2f04
2020-01-09 11:02:46 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:46 UTC Verifier #0 DEBUG engine Author 0xe576…1b8d built block with step gap. current step: 315713553, parent step: 315713550
2020-01-09 11:02:46 UTC Verifier #0 TRACE engine step_proposer: Fetched proposer for step 315713551: 0x54e2…d88b
2020-01-09 11:02:46 UTC Verifier #0 TRACE engine Reporting benign misbehaviour (cause: skipped step) at block #1015986, epoch set number 10, step proposer=0x54e2af914baaccd6841378d52e13bd5faec2d88b. Own address: 0xde56…c176
2020-01-09 11:02:46 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:46 UTC Verifier #0 TRACE engine validator set recording benign misbehaviour at block #1015986 by 0x54e2af914baaccd6841378d52e13bd5faec2d88b
2020-01-09 11:02:49 UTC Verifier #0 WARN engine Validator 0x54e2…d88b could not be reported Transaction import error: Transaction error (Already imported)
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine step_proposer: Fetched proposer for step 315713552: 0xde56…c176
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine Primary that skipped is self, not self-reporting. Own address: 0xde56…c176
2020-01-09 11:02:49 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x2e7b…2f04
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:49 UTC Verifier #0 DEBUG engine Expected topics for header 0x2fa9…8d17: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x2e7b2f568c20e75e5345a91e2c9391b75e7f2fd0b00c41e512d1277cf5ec2f04]
2020-01-09 11:02:49 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x2e7b…2f04
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:49 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:49 UTC Verifier #0 INFO import Imported #1015986 0x2fa9…8d17 (0 txs, 0.00 Mgas, 2662 ms, 0.57 KiB)
2020-01-09 11:02:50 UTC IO Worker #3 DEBUG engine Zooming to epoch after block 0x7f5e…2b83
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine step_proposer: Fetched proposer for step 315713554: 0x1746…8f20
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine Not preparing block: not a proposer for step 315713554. (Our address: 0xde56…c176)
2020-01-09 11:02:50 UTC IO Worker #3 DEBUG engine Zooming to epoch after block 0x7f5e…2b83
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine step_proposer: Fetched proposer for step 315713554: 0x1746…8f20
2020-01-09 11:02:50 UTC IO Worker #3 TRACE engine Not preparing block: not a proposer for step 315713554. (Our address: 0xde56…c176)
2020-01-09 11:02:51 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x7f5e…2b83
2020-01-09 11:02:51 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:51 UTC Verifier #0 DEBUG engine Author 0x1746…8f20 built block with step gap. current step: 315713554, parent step: 315713552
2020-01-09 11:02:51 UTC Verifier #0 TRACE engine step_proposer: Fetched proposer for step 315713553: 0xe576…1b8d
2020-01-09 11:02:51 UTC Verifier #0 TRACE engine Reporting benign misbehaviour (cause: skipped step) at block #1015987, epoch set number 10, step proposer=0xe576439f06dcaff4d29d150ad50345b91a981b8d. Own address: 0xde56…c176
2020-01-09 11:02:51 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:51 UTC Verifier #0 TRACE engine validator set recording benign misbehaviour at block #1015987 by 0xe576439f06dcaff4d29d150ad50345b91a981b8d
2020-01-09 11:02:53 UTC Verifier #0 WARN engine Reported benign validator misbehaviour 0xe576…1b8d
2020-01-09 11:02:53 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x7f5e…2b83
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:53 UTC Verifier #0 DEBUG engine Expected topics for header 0x5de9…329d: [0x55252fa6eee4741b4e24a74a70e9c11fd2c2281df8d6ea13126ff845f7825c89, 0x7f5e6a1fe2d1d4d9223e5c6a192cda5faf5219cfc91f67dec0e19d7422e72b83]
2020-01-09 11:02:53 UTC Verifier #0 DEBUG engine Zooming to epoch after block 0x7f5e…2b83
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Current validator set: SimpleList { validators: [0xdd1115ff827ef48b83fca7e1098238047daaa1ce, 0x54e2af914baaccd6841378d52e13bd5faec2d88b, 0xde563309e2b5b103a4a9e0975881552861f6c176, 0xe576439f06dcaff4d29d150ad50345b91a981b8d, 0x174684af45972e624c5d333d0361de3964118f20, 0x20580de9c6ed939c6d43e06b4e050014971b9ee0, 0x8854522fbf6ff0ce35951ea9679feeac7a4bb02d, 0x87f4afcd7be74ae20183c358ed0ae7b419068123, 0xe895b3912adb2dcab6ca1552795f92743d8373dd, 0xdd7f5b5be491df41ac0b3517100bf413d070d748] }
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Multi ValidatorSet retrieved for block 10.
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine step_proposer: Fetched proposer for step 315713554: 0x1746…8f20
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Not preparing block: not a proposer for step 315713554. (Our address: 0xde56…c176)
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine step_proposer: Fetched proposer for step 315713554: 0x1746…8f20
2020-01-09 11:02:53 UTC Verifier #0 TRACE engine Not preparing block: not a proposer for step 315713554. (Our address: 0xde56…c176)
2020-01-09 11:02:53 UTC IO Worker #1 INFO own_tx Transaction culled (hash 0xfbe76d912b3207c7e096cf86c7033f14a3a0184876b136cd9d3893b8786848d0)
2020-01-09 11:02:53 UTC Verifier #0 INFO import Imported #1015987 0x5de9…329d (9 txs, 0.28 Mgas, 2763 ms, 2.09 KiB)

EXPECTED
The expected behaviour is the 10 validators validating in their round...they have been working properly for a month and now suddenly it starting to fail...

[jam10o-new]

this sounds very much like a system clock issue - can you verify that whatever you use to keep your system clocks in sync is working as expected?

[gperezalba]

All validators use chronyd to sync and it seems to be working properly...
But maybe you are right because:
(i) Block #1015985 is imported at 11:02:30 UTC (2020-01-09 11:02:30 UTC Verifier #0 INFO import Imported #1015985)
(ii) This validator generates the block #1015986 at 11:02:44 UTC (2020-01-09 11:02:44 UTC IO Worker #1 INFO import Imported #1015986) and I have a 5s stepValidator

Any idea about how to solve?