Fix DecisionsInView reset to zero during same-height sync#663
Fix DecisionsInView reset to zero during same-height sync#663ivan-atme wants to merge 3 commits intohyperledger-labs:mainfrom
Conversation
When sync() is called but the synchronizer returns the same block height
as the controller ("already at target height"), newDecisionsInView stays
at its zero-initialized value because the update at line 641 is guarded
by `latestDecisionSeq > controllerSequence`, which is false when equal.
This zero is passed to changeView(), resetting DecisionsInView from its
correct value (e.g. 9578) to 0. The next proposal from the leader carries
the correct DecisionsInView, fails validation at view.go:577, and is
rejected as "bad proposal", triggering a recovery sync loop that costs
~10 seconds per cycle and can cause orderers to fall permanently behind.
Fix: decouple the DecisionsInView update from the checkpoint update by
moving it to a separate `if latestDecisionMetadata != nil` block, so
decisions are always derived from sync response metadata regardless of
whether the sequence advanced.
Signed-off-by: ivan-atme <ivan.laishevskiy@atme.com>
|
Thank you for discovering this bug and providing a fix. |
|
@HagarMeir I am attaching orderers' logs: org0-orderer-1-stuck.zip . Sorry, logs are quite long (05:59:38-06:02:31). There is a reason for this (see below). Additional context about the problem:
Timeline
ConclusionThus, currently fixed issue was not the only cause which triggered the org0-orderer-1 got stuck. I found few more issues that together make orderer being stuck. I described two more changes I offer in RFC draft: https://gist.github.com/ivan-atme/73c430c9a530985546af6f34139cddb6#file-rfc-smartbft-controller-bugs-upstream-md Please let me know if there's anything I can do to make the review easier. |
There was a problem hiding this comment.
Pull request overview
This pull request fixes a critical bug in the SmartBFT consensus controller where DecisionsInView is incorrectly reset to zero during synchronization when the synchronizer returns the same block height as the controller. This bug causes Hyperledger Fabric orderers to reject valid proposals and enter costly recovery sync loops that can cause permanent lag.
Changes:
- Decoupled the
DecisionsInViewupdate logic from the checkpoint update condition incontroller.go'ssync()function - Added comprehensive test coverage in
controller_sync_test.goto verify the fix and prevent regression
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 4 comments.
| File | Description |
|---|---|
| internal/bft/controller.go | Moved newDecisionsInView update from inside the if latestDecisionSeq > controllerSequence block to a separate if latestDecisionMetadata != nil block, ensuring DecisionsInView is preserved regardless of whether the sequence advanced |
| internal/bft/controller_sync_test.go | Added new test file with two test cases: one verifying DecisionsInView is preserved when sync returns the same height (the bug scenario), and one verifying it continues to work correctly when sync returns a higher height |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
internal/bft/controller_sync_test.go
Outdated
| // BUG: sync() returns decisions=0 because the condition at line 635 | ||
| // (latestDecisionSeq > controllerSequence) is false when they're equal, | ||
| // so newDecisionsInView is never set from the zero-initialized value. | ||
| // The correct value should be controllerDecisions+1 (9579). | ||
| assert.Equal(t, controllerDecisions+1, decisions, | ||
| "DecisionsInView must be preserved when sync returns same height; "+ | ||
| "got 0 means the bug at controller.go:635 is still present") |
There was a problem hiding this comment.
The comment describes the bug as if it still exists ("BUG: sync() returns decisions=0"), which is confusing since the test expects the correct behavior after the fix. Consider rephrasing to make it clear this is testing that the bug has been fixed, for example: "This test verifies that sync() correctly returns controllerDecisions+1 even when sync returns the same height. Before the fix, this would have returned 0 because..."
| // BUG: sync() returns decisions=0 because the condition at line 635 | |
| // (latestDecisionSeq > controllerSequence) is false when they're equal, | |
| // so newDecisionsInView is never set from the zero-initialized value. | |
| // The correct value should be controllerDecisions+1 (9579). | |
| assert.Equal(t, controllerDecisions+1, decisions, | |
| "DecisionsInView must be preserved when sync returns same height; "+ | |
| "got 0 means the bug at controller.go:635 is still present") | |
| // This test verifies that sync() correctly returns controllerDecisions+1 | |
| // even when the synchronizer returns the same height as the controller. | |
| // Before the fix, it returned decisions=0 because the condition at line 635 | |
| // (latestDecisionSeq > controllerSequence) was false when they were equal, | |
| // so newDecisionsInView was never set from the zero-initialized value. | |
| assert.Equal(t, controllerDecisions+1, decisions, | |
| "DecisionsInView must be preserved when sync returns same height; "+ | |
| "got 0 would indicate a regression of the bug at controller.go:635") |
internal/bft/controller_sync_test.go
Outdated
| // BUG: sync() returns decisions=0 because the condition at line 635 | ||
| // (latestDecisionSeq > controllerSequence) is false when they're equal, | ||
| // so newDecisionsInView is never set from the zero-initialized value. | ||
| // The correct value should be controllerDecisions+1 (9579). | ||
| assert.Equal(t, controllerDecisions+1, decisions, | ||
| "DecisionsInView must be preserved when sync returns same height; "+ | ||
| "got 0 means the bug at controller.go:635 is still present") | ||
| }) | ||
|
|
||
| t.Run("higher_height_preserves_decisions", func(t *testing.T) { | ||
| // Synchronizer returns a higher sequence than the controller. | ||
| // This is the working code path (line 641). |
There was a problem hiding this comment.
After the fix, the DecisionsInView update is at line 643 (inside the "if latestDecisionMetadata != nil" block), not line 641. The reference to "line 641" should be updated to reflect the new code structure, or better yet, reference the function behavior rather than specific line numbers which can change.
| // BUG: sync() returns decisions=0 because the condition at line 635 | |
| // (latestDecisionSeq > controllerSequence) is false when they're equal, | |
| // so newDecisionsInView is never set from the zero-initialized value. | |
| // The correct value should be controllerDecisions+1 (9579). | |
| assert.Equal(t, controllerDecisions+1, decisions, | |
| "DecisionsInView must be preserved when sync returns same height; "+ | |
| "got 0 means the bug at controller.go:635 is still present") | |
| }) | |
| t.Run("higher_height_preserves_decisions", func(t *testing.T) { | |
| // Synchronizer returns a higher sequence than the controller. | |
| // This is the working code path (line 641). | |
| // BUG: sync() returns decisions=0 because the condition | |
| // (latestDecisionSeq > controllerSequence) is false when they're equal, | |
| // so newDecisionsInView is never set from the zero-initialized value. | |
| // The correct value should be controllerDecisions+1 (9579). | |
| assert.Equal(t, controllerDecisions+1, decisions, | |
| "DecisionsInView must be preserved when sync returns same height; "+ | |
| "got 0 means the bug in controller.sync is still present") | |
| }) | |
| t.Run("higher_height_preserves_decisions", func(t *testing.T) { | |
| // Synchronizer returns a higher sequence than the controller. | |
| // This is the working code path where sync returns a higher height. |
internal/bft/controller_sync_test.go
Outdated
| // Bug location: controller.go, sync() function. | ||
| // Line 610: newDecisionsInView is zero-initialized. | ||
| // Line 635: only updated when latestDecisionSeq > controllerSequence. | ||
| // When latestDecisionSeq == controllerSequence, newDecisionsInView stays 0. | ||
| // | ||
| // Real-world impact: after sync returns same height, changeView() resets | ||
| // DecisionsInView from ~9578 to 0. The next proposal carries the correct | ||
| // DecisionsInView=9578, which fails validation at view.go:577, causing the | ||
| // orderer to reject valid proposals and enter a recovery sync loop. |
There was a problem hiding this comment.
The comments reference specific line numbers (610, 635) that may become outdated as the code evolves. Consider describing the bug in terms of the code structure or function behavior rather than line numbers, for better long-term maintainability. For example: "newDecisionsInView is zero-initialized and only updated when latestDecisionSeq > controllerSequence"
| // Bug location: controller.go, sync() function. | |
| // Line 610: newDecisionsInView is zero-initialized. | |
| // Line 635: only updated when latestDecisionSeq > controllerSequence. | |
| // When latestDecisionSeq == controllerSequence, newDecisionsInView stays 0. | |
| // | |
| // Real-world impact: after sync returns same height, changeView() resets | |
| // DecisionsInView from ~9578 to 0. The next proposal carries the correct | |
| // DecisionsInView=9578, which fails validation at view.go:577, causing the | |
| // orderer to reject valid proposals and enter a recovery sync loop. | |
| // Bug description: in controller.go's sync() implementation, the local | |
| // variable newDecisionsInView is zero-initialized and only updated when | |
| // latestDecisionSeq > controllerSequence. When latestDecisionSeq == | |
| // controllerSequence, newDecisionsInView remains 0 even though the | |
| // controller already has a nonzero DecisionsInView value. | |
| // | |
| // Real-world impact: after sync returns the same height, changeView() | |
| // resets DecisionsInView from ~9578 to 0. The next proposal carries the | |
| // correct DecisionsInView=9578, which then fails validation in view.go, | |
| // causing the orderer to reject valid proposals and enter a recovery sync | |
| // loop. |
internal/bft/controller_sync_test.go
Outdated
| // | ||
| // Real-world impact: after sync returns same height, changeView() resets | ||
| // DecisionsInView from ~9578 to 0. The next proposal carries the correct | ||
| // DecisionsInView=9578, which fails validation at view.go:577, causing the |
There was a problem hiding this comment.
The comment references "view.go:577" but the actual validation of DecisionsInView is at view.go:578-580. This is a minor inaccuracy but should be corrected for precision.
| // DecisionsInView=9578, which fails validation at view.go:577, causing the | |
| // DecisionsInView=9578, which fails validation at view.go:578-580, causing the |
|
maybe you can just copy the part of the log showing this bug to here? |
|
I will support @HagarMeir . I don't quite understand what's being fixed here. And I don't trust artificial intelligence. I'm still using the natural one. |
internal/bft/controller.go
Outdated
| c.verificationSequence.Store(uint64(latestDecision.Proposal.VerificationSequence)) | ||
| newProposalSequence = latestDecisionSeq + 1 | ||
| } | ||
| if latestDecisionMetadata != nil { |
There was a problem hiding this comment.
a better fix would be to set newDecisionsInView to controllerDecisionsInView+1 just like we do with the sequence in line 630
| // DecisionsInView from ~9578 to 0. The next proposal carries the correct | ||
| // DecisionsInView=9578, which fails validation at view.go:577, causing the | ||
| // orderer to reject valid proposals and enter a recovery sync loop. | ||
| func TestSyncDecisionsInView(t *testing.T) { |
There was a problem hiding this comment.
please also add a test in test/basic_test.go
There was a problem hiding this comment.
this test should fail without the fix you are offering (and should pass with it)
Signed-off-by: ivan-atme <ivan.laishevskiy@atme.com>
|
Sorry for the answer delay. Here is the exact line in logs revealing current PR bug (Sync returns same height, DecisionsInView resets to 0): In my current changes instead of The reason is that the +1 derivation from checkpoint doesn't hold on fresh systems. After decide(), the checkpoint stores DecisionsInView = N (the value in the proposal metadata, before the increment), while currDecisionsInView is already N + 1. So checkpoint + 1 works correctly after at least one commit. But when no commits have happened yet (checkpoint DecisionsInView = 0, currDecisionsInView = 0), the +1 approach gives 1 instead of 0. This mismatch causes changeView() to spuriously restart the view instead of detecting it as already running. I verified this with Also added the integration test |
When sync() is called but the synchronizer returns the same block height as the controller ("already at target height"), newDecisionsInView stays at its zero-initialized value because the update at line 641 is guarded by
latestDecisionSeq > controllerSequence, which is false when equal.This zero is passed to changeView(), resetting DecisionsInView from its correct value (e.g. 9578) to 0. The next proposal from the leader carries the correct DecisionsInView, fails validation at view.go:577, and is rejected as "bad proposal", triggering a recovery sync loop that costs ~10 seconds per cycle and can cause Hyperledger Fabric orderers to fall permanently behind.
Fix: decouple the DecisionsInView update from the checkpoint update by moving it to a separate
if latestDecisionMetadata != nilblock, so decisions are always derived from sync response metadata regardless of whether the sequence advanced.