search

hyperledger / besu

An enterprise-grade Java-based, Apache 2.0 licensed Ethereum client https://wiki.hyperledger.org/display/besu
https://www.hyperledger.org/projects/besu
Apache License 2.0
1.51k stars 831 forks source link

Qbft proposal round change is failing to decode in Quorum #2109

Closed jframe closed 3 years ago

jframe commented 3 years ago

Quorum qbft is failing to decode round change messages from Besu. Need to investigate the cause.

We are getting messages like this in the Quorum logs quorum-node-0_1 | INFO [04-07|04:41:21.636|consensus/qibft/message/roundchange.go:134] QBFT: Correctly decoded SignedRoundChangePayload p="RoundChange {seq=1, round=1, pr=<nil>, pv=0x0000000000000000000000000000000000000000000000000000000000000000}" quorum-node-0_1 | INFO [04-07|04:41:21.636|consensus/qibft/message/roundchange.go:134] QBFT: Correctly decoded SignedRoundChangePayload p="RoundChange {seq=1, round=1, pr=<nil>, pv=0x0000000000000000000000000000000000000000000000000000000000000000}" quorum-node-0_1 | ERROR[04-07|04:41:21.636|consensus/qibft/message/roundchange.go:71] QBFT: Error List() Signed Payload err="rlp: end of list"

jframe commented 3 years ago

Added some additional logging in quorum to consensus/istanbul/backend to log when message is sent and to consensus/qibft/core/handler when the encoded message is received. Added similar logging Besu as well when the message is received by the QbftController and sent by ValidatorPeers.

Looks like what is happening is that Quorum creates a preprepare message and that is sent to the Besu node which then gossips it to the Quorum. Quorum then tries to decode it and it fails decoding the round changes in the preprepare.

quorum logs besu logs

jframe commented 3 years ago

Added some additional logging in Besu for decipher the invalid proposal log message

2021-04-09 15:06:49.304+10:00 | pool-8-thread-1 | INFO  | ProposalPayloadValidator | Invalid Proposal Payload: Proposal round contains a different round to that in the supplied block

Besu is receiving a block with round of 0 in the extra

2021-04-09 15:23:34.886+10:00 | pool-8-thread-1 | DEBUG | BaseBftController | Received a message code=18 data=0xf90331f90297f902510102f9024cf90247a08ee232c1ae4221395ad3b645de0982546ff4f7d584b6676fcb2b74b96b4e5ab9a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d493479464d9be4177f418bcf4e56adad85f33e3a64efe22a0ef29d59f5304257e847b94993cce1b327ca864cbbae95a3e9556e69eca6d0d0ca056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001018429b927008084606fe4ccb851f84fa0d983010914846765746888676f312e31352e358664617277696e000000000000ea9464d9be4177f418bcf4e56adad85f33e3a64efe22949f66f8a0f0a6537e4a36aa1799673ea7ae97a166c080c0a063746963616c2062797a616e74696e65206661756c7420746f6c6572616e6365880000000000000000c0c0b8415f210579824fb1f234fc7ecdb33a5e00a2a8ce2b5b0e2bf836544225856583d2302481893558787a826aa3c806ebc31a8825b3017d32d0333c48c33c2a7d782200f895f892f847c30102c0b841ea81be12b9557d9d203e8d9be9cabb4af8cab9e6f43a65f745d389b3dc3973fd39632d5c23de2d8f38555018a678c80183fd8851a2bdce99d87d53b3256eb00601f847c30102c0b841ac2b583746390a72aedc8306a9d5ac2abf56624fd060d8e6bf371360e1d57f9a04da2c573d78aba18dbc1c6320f6b860ad860898c0d3571918a8c65216b2845301c0
2021-04-09 15:23:34.891+10:00 | pool-8-thread-1 | TRACE | BaseBftController | Received BFT Proposal message
2021-04-09 15:23:34.893+10:00 | pool-8-thread-1 | INFO  | ValidatorPeers | Sending message to peers messageCode=18 recipients=[0x9f66f8a0f0a6537e4a36aa1799673ea7ae97a166] messageData=0xf90331f90297f902510102f9024cf90247a08ee232c1ae4221395ad3b645de0982546ff4f7d584b6676fcb2b74b96b4e5ab9a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d493479464d9be4177f418bcf4e56adad85f33e3a64efe22a0ef29d59f5304257e847b94993cce1b327ca864cbbae95a3e9556e69eca6d0d0ca056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001018429b927008084606fe4ccb851f84fa0d983010914846765746888676f312e31352e358664617277696e000000000000ea9464d9be4177f418bcf4e56adad85f33e3a64efe22949f66f8a0f0a6537e4a36aa1799673ea7ae97a166c080c0a063746963616c2062797a616e74696e65206661756c7420746f6c6572616e6365880000000000000000c0c0b8415f210579824fb1f234fc7ecdb33a5e00a2a8ce2b5b0e2bf836544225856583d2302481893558787a826aa3c806ebc31a8825b3017d32d0333c48c33c2a7d782200f895f892f847c30102c0b841ea81be12b9557d9d203e8d9be9cabb4af8cab9e6f43a65f745d389b3dc3973fd39632d5c23de2d8f38555018a678c80183fd8851a2bdce99d87d53b3256eb00601f847c30102c0b841ac2b583746390a72aedc8306a9d5ac2abf56624fd060d8e6bf371360e1d57f9a04da2c573d78aba18dbc1c6320f6b860ad860898c0d3571918a8c65216b2845301c0
2021-04-09 15:23:34.894+10:00 | pool-8-thread-1 | TRACE | QbftBlockHeightManager | Received a Proposal Payload.
2021-04-09 15:23:34.895+10:00 | pool-8-thread-1 | DEBUG | QbftRound | Received a proposal message. round=ConsensusRoundIdentifier{Sequence=1, Round=2} msg=Proposal{roundChanges=[SignedData[sender=0x64d9be4177f418bcf4e56adad85f33e3a64efe22, signature=Signature{r=106070441676443619457782516886098443558957937801673203950547763663207864562685, s=25957063291337272061687174896174531028181426700182797440342874196426707873798, recId=1}, unsignedPayload=RoundChangePayload{roundChangeIdentifier=ConsensusRoundIdentifier{Sequence=1, Round=2}, preparedRoundMetadata=Optional.empty}], SignedData[sender=0x9f66f8a0f0a6537e4a36aa1799673ea7ae97a166, signature=Signature{r=77874393223978199235280779411500220898498780104441289617527540028113776115610, s=2194730083283062893250664399360534665503236325760281311903702498918958007379, recId=1}, unsignedPayload=RoundChangePayload{roundChangeIdentifier=ConsensusRoundIdentifier{Sequence=1, Round=2}, preparedRoundMetadata=Optional.empty}]], prepares=[]}
2021-04-09 15:23:34.924+10:00 | pool-8-thread-1 | INFO  | ProposalPayloadValidator | Invalid Proposal Payload: Proposal round contains a different round to that in the supplied block proposalRound=2 extraDataRound=0
2021-04-09 15:23:34.924+10:00 | pool-8-thread-1 | INFO  | ProposalValidator | Invalid Proposal Payload: invalid proposal payload in proposal message
jframe commented 3 years ago

The change in #2095 fixes this issue in Besu