diff --git a/agreement/actions.go b/agreement/actions.go index 91276e22fc..0e0d5f19c4 100644 --- a/agreement/actions.go +++ b/agreement/actions.go @@ -66,6 +66,7 @@ type action interface { do(context.Context, *Service) String() string + ComparableStr() string } type nonpersistent struct{} @@ -88,6 +89,8 @@ func (a noopAction) String() string { return a.t().String() } +func (a noopAction) ComparableStr() string { return a.String() } + type networkAction struct { nonpersistent @@ -120,6 +123,13 @@ func (a networkAction) String() string { return fmt.Sprintf("%s: %2v", a.t().String(), a.Tag) } +func (a networkAction) ComparableStr() string { + if a.Tag == protocol.AgreementVoteTag { + return fmt.Sprintf("%s: %2v: %3v-%2v-%2v", a.t().String(), a.Tag, a.UnauthenticatedVote.R.Round, a.UnauthenticatedVote.R.Period, a.UnauthenticatedVote.R.Step) + } + return a.String() +} + func (a networkAction) do(ctx context.Context, s *Service) { if a.T == broadcastVotes { tag := protocol.AgreementVoteTag @@ -192,6 +202,18 @@ func (a cryptoAction) String() string { return a.t().String() } +func (a cryptoAction) ComparableStr() (s string) { + switch a.T { + case verifyVote: + s = fmt.Sprintf("%s: %3v-%2v TaskIndex %d", a.t().String(), a.Round, a.Period, a.TaskIndex) + case verifyPayload: + s = fmt.Sprintf("%s: %3v-%2v Pinned %v", a.t().String(), a.Round, a.Period, a.Pinned) + case verifyBundle: + s = fmt.Sprintf("%s: %3v-%2v-%2v", a.t().String(), a.Round, a.Period, a.Step) + } + return +} + func (a cryptoAction) do(ctx context.Context, s *Service) { switch a.T { case verifyVote: @@ -225,6 +247,8 @@ func (a ensureAction) String() string { return fmt.Sprintf("%s: %.5s: %v, %v, %.5s", a.t().String(), a.Payload.Digest().String(), a.Certificate.Round, a.Certificate.Period, a.Certificate.Proposal.BlockDigest.String()) } +func (a ensureAction) ComparableStr() string { return a.String() } + func (a ensureAction) do(ctx context.Context, s *Service) { logEvent := logspec.AgreementEvent{ Hash: a.Certificate.Proposal.BlockDigest.String(), @@ -288,6 +312,8 @@ func (a stageDigestAction) String() string { return fmt.Sprintf("%s: %.5s. %v. %v", a.t().String(), a.Certificate.Proposal.BlockDigest.String(), a.Certificate.Round, a.Certificate.Period) } +func (a stageDigestAction) ComparableStr() string { return a.String() } + func (a stageDigestAction) do(ctx context.Context, service *Service) { logEvent := logspec.AgreementEvent{ Hash: a.Certificate.Proposal.BlockDigest.String(), @@ -314,8 +340,25 @@ func (a rezeroAction) String() string { return a.t().String() } +func (a rezeroAction) ComparableStr() string { + return fmt.Sprintf("%s: %d", a.t().String(), a.Round) +} + func (a rezeroAction) do(ctx context.Context, s *Service) { s.Clock = s.Clock.Zero() + // Preserve the zero time of the new round a.Round (for + // period 0) for future use if a late proposal-vote arrives, + // for late credential tracking. + if _, ok := s.historicalClocks[a.Round]; !ok { + s.historicalClocks[a.Round] = s.Clock + } + + // Garbage collect clocks that are too old + for rnd := range s.historicalClocks { + if a.Round > rnd+credentialRoundLag { + delete(s.historicalClocks, rnd) + } + } } type pseudonodeAction struct { @@ -336,6 +379,8 @@ func (a pseudonodeAction) String() string { return fmt.Sprintf("%v %3v-%2v-%2v: %.5v", a.t().String(), a.Round, a.Period, a.Step, a.Proposal.BlockDigest.String()) } +func (a pseudonodeAction) ComparableStr() string { return a.String() } + func (a pseudonodeAction) persistent() bool { return a.T == attest } @@ -528,3 +573,5 @@ func (c checkpointAction) do(ctx context.Context, s *Service) { func (c checkpointAction) String() string { return c.t().String() } + +func (c checkpointAction) ComparableStr() string { return c.String() } diff --git a/agreement/demux.go b/agreement/demux.go index 60ea2a8dd5..7f888dc97f 100644 --- a/agreement/demux.go +++ b/agreement/demux.go @@ -199,13 +199,13 @@ func (d *demux) next(s *Service, deadline Deadline, fastDeadline Deadline, curre switch e.t() { case payloadVerified: - e = e.(messageEvent).AttachValidatedAt(s.Clock.Since(), currentRound) + e = e.(messageEvent).AttachValidatedAt(clockForRound(currentRound, s.Clock, s.historicalClocks)) case payloadPresent, votePresent: - e = e.(messageEvent).AttachReceivedAt(s.Clock.Since(), currentRound) + e = e.(messageEvent).AttachReceivedAt(clockForRound(currentRound, s.Clock, s.historicalClocks)) case voteVerified: // if this is a proposal vote (step 0), record the validatedAt time on the vote if e.(messageEvent).Input.Vote.R.Step == 0 { - e = e.(messageEvent).AttachValidatedAt(s.Clock.Since(), currentRound) + e = e.(messageEvent).AttachValidatedAt(clockForRound(currentRound, s.Clock, s.historicalClocks)) } } }() diff --git a/agreement/events.go b/agreement/events.go index faa4badebe..afcfa3052d 100644 --- a/agreement/events.go +++ b/agreement/events.go @@ -296,7 +296,7 @@ func (e messageEvent) String() string { } func (e messageEvent) ComparableStr() string { - return e.T.String() + return fmt.Sprintf("{T:%s %d Err:%v}", e.t().String(), e.ConsensusRound(), e.Err) } func (e messageEvent) ConsensusRound() round { @@ -424,9 +424,14 @@ type readLowestEvent struct { // Vote holds the lowest-credential vote. Vote vote + // LowestIncludingLate holds the lowest-credential vote that was received, including + // after Vote has been frozen. + LowestIncludingLate vote - // Filled indicates whether the Vote field is filled - Filled bool + // Filled and HasLowestIncludingLate indicates whether the Vote or LowestIncludingLate + // fields are filled, respectively. + Filled bool + HasLowestIncludingLate bool } func (e readLowestEvent) t() eventType { @@ -591,10 +596,36 @@ func (e payloadProcessedEvent) ComparableStr() string { return fmt.Sprintf("%v: %.5v", e.t().String(), e.Proposal.BlockDigest.String()) } +// LateCredentialTrackingEffect indicates the impact of a vote that was filtered (due to age) +// on the credential tracking system (in credentialArrivalHistory), for the purpose of tracking +// the time it took the best credential to arrive, even if it was late. +type LateCredentialTrackingEffect uint8 + +const ( + // NoLateCredentialTrackingImpact indicates the filtered event would have no impact on + // the credential tracking mechanism. + NoLateCredentialTrackingImpact LateCredentialTrackingEffect = iota + + // UnverifiedLateCredentialForTracking indicates the filtered event could impact + // the credential tracking mechanism and more processing (validation) may be required. + // It may be set by proposalManager when handling votePresent events. + UnverifiedLateCredentialForTracking + + // VerifiedBetterLateCredentialForTracking indicates that the filtered event provides a new best + // credential for its round. + // It may be set by proposalManager when handling voteVerified events. + VerifiedBetterLateCredentialForTracking +) + type filteredEvent struct { // {proposal,vote,bundle}{Filtered,Malformed} T eventType + // LateCredentialTrackingNote indicates the impact of the filtered event on the + // credential tracking machinery used for dynamically setting the filter + // timeout. + LateCredentialTrackingNote LateCredentialTrackingEffect + // Err is the reason cryptographic verification failed and is set for // events {proposal,vote,bundle}Malformed. Err *serializableError @@ -975,23 +1006,40 @@ func (e checkpointEvent) AttachConsensusVersion(v ConsensusVersionView) external return e } +// This timestamp is assigned to messages that arrive for round R+1 while the current player +// is still waiting for quorum on R. +const pipelinedMessageTimestamp = time.Nanosecond + +//msgp:ignore constantRoundStartTimer +type constantRoundStartTimer time.Duration + +func (c constantRoundStartTimer) Since() time.Duration { return time.Duration(c) } + +// clockForRound retrieves the roundStartTimer used for AttachValidatedAt and AttachReceivedAt. +func clockForRound(currentRound round, currentClock roundStartTimer, historicalClocks map[round]roundStartTimer) func(round) roundStartTimer { + return func(eventRound round) roundStartTimer { + if eventRound > currentRound { + return constantRoundStartTimer(pipelinedMessageTimestamp) + } + if eventRound == currentRound { + return currentClock + } + if clock, ok := historicalClocks[eventRound]; ok { + return clock + } + return constantRoundStartTimer(0) + } +} + // AttachValidatedAt looks for a validated proposal or vote inside a // payloadVerified or voteVerified messageEvent, and attaches the given time to // the proposal's validatedAt field. -func (e messageEvent) AttachValidatedAt(d time.Duration, currentRound round) messageEvent { +func (e messageEvent) AttachValidatedAt(getClock func(eventRound round) roundStartTimer) messageEvent { switch e.T { case payloadVerified: - if e.Input.Proposal.Round() > currentRound { - e.Input.Proposal.validatedAt = 1 - } else { - e.Input.Proposal.validatedAt = d - } + e.Input.Proposal.validatedAt = getClock(e.Input.Proposal.Round()).Since() case voteVerified: - if e.Input.Vote.R.Round > currentRound { - e.Input.Vote.validatedAt = 1 - } else { - e.Input.Vote.validatedAt = d - } + e.Input.Vote.validatedAt = getClock(e.Input.Vote.R.Round).Since() } return e } @@ -999,14 +1047,11 @@ func (e messageEvent) AttachValidatedAt(d time.Duration, currentRound round) mes // AttachReceivedAt looks for an unauthenticatedProposal inside a // payloadPresent or votePresent messageEvent, and attaches the given // time to the proposal's receivedAt field. -func (e messageEvent) AttachReceivedAt(d time.Duration, currentRound round) messageEvent { - if e.T == payloadPresent { - if e.Input.UnauthenticatedProposal.Round() > currentRound { - e.Input.UnauthenticatedProposal.receivedAt = 1 - } else { - e.Input.UnauthenticatedProposal.receivedAt = d - } - } else if e.T == votePresent { +func (e messageEvent) AttachReceivedAt(getClock func(eventRound round) roundStartTimer) messageEvent { + switch e.T { + case payloadPresent: + e.Input.UnauthenticatedProposal.receivedAt = getClock(e.Input.UnauthenticatedProposal.Round()).Since() + case votePresent: // Check for non-nil Tail, indicating this votePresent event // contains a synthetic payloadPresent event that was attached // to it by setupCompoundMessage. @@ -1014,11 +1059,7 @@ func (e messageEvent) AttachReceivedAt(d time.Duration, currentRound round) mess // The tail event is payloadPresent, serialized together // with the proposal vote as a single CompoundMessage // using a protocol.ProposalPayloadTag network message. - if e.Tail.Input.UnauthenticatedProposal.Round() > currentRound { - e.Tail.Input.UnauthenticatedProposal.receivedAt = 1 - } else { - e.Tail.Input.UnauthenticatedProposal.receivedAt = d - } + e.Tail.Input.UnauthenticatedProposal.receivedAt = getClock(e.Tail.Input.UnauthenticatedProposal.Round()).Since() } } return e diff --git a/agreement/msgp_gen.go b/agreement/msgp_gen.go index 794a9f1bc5..16679ce797 100644 --- a/agreement/msgp_gen.go +++ b/agreement/msgp_gen.go @@ -46,6 +46,16 @@ import ( // |-----> (*) MsgIsZero // |-----> DeadlineMaxSize() // +// LateCredentialTrackingEffect +// |-----> MarshalMsg +// |-----> CanMarshalMsg +// |-----> (*) UnmarshalMsg +// |-----> (*) UnmarshalMsgWithState +// |-----> (*) CanUnmarshalMsg +// |-----> Msgsize +// |-----> MsgIsZero +// |-----> LateCredentialTrackingEffectMaxSize() +// // TimeoutType // |-----> MarshalMsg // |-----> CanMarshalMsg @@ -1178,6 +1188,66 @@ func DeadlineMaxSize() (s int) { return } +// MarshalMsg implements msgp.Marshaler +func (z LateCredentialTrackingEffect) MarshalMsg(b []byte) (o []byte) { + o = msgp.Require(b, z.Msgsize()) + o = msgp.AppendUint8(o, uint8(z)) + return +} + +func (_ LateCredentialTrackingEffect) CanMarshalMsg(z interface{}) bool { + _, ok := (z).(LateCredentialTrackingEffect) + if !ok { + _, ok = (z).(*LateCredentialTrackingEffect) + } + return ok +} + +// UnmarshalMsg implements msgp.Unmarshaler +func (z *LateCredentialTrackingEffect) UnmarshalMsgWithState(bts []byte, st msgp.UnmarshalState) (o []byte, err error) { + if st.AllowableDepth == 0 { + err = msgp.ErrMaxDepthExceeded{} + return + } + st.AllowableDepth-- + { + var zb0001 uint8 + zb0001, bts, err = msgp.ReadUint8Bytes(bts) + if err != nil { + err = msgp.WrapError(err) + return + } + (*z) = LateCredentialTrackingEffect(zb0001) + } + o = bts + return +} + +func (z *LateCredentialTrackingEffect) UnmarshalMsg(bts []byte) (o []byte, err error) { + return z.UnmarshalMsgWithState(bts, msgp.DefaultUnmarshalState) +} +func (_ *LateCredentialTrackingEffect) CanUnmarshalMsg(z interface{}) bool { + _, ok := (z).(*LateCredentialTrackingEffect) + return ok +} + +// Msgsize returns an upper bound estimate of the number of bytes occupied by the serialized message +func (z LateCredentialTrackingEffect) Msgsize() (s int) { + s = msgp.Uint8Size + return +} + +// MsgIsZero returns whether this is a zero value +func (z LateCredentialTrackingEffect) MsgIsZero() bool { + return z == 0 +} + +// MaxSize returns a maximum valid message size for this message type +func LateCredentialTrackingEffectMaxSize() (s int) { + s = msgp.Uint8Size + return +} + // MarshalMsg implements msgp.Marshaler func (z TimeoutType) MarshalMsg(b []byte) (o []byte) { o = msgp.Require(b, z.Msgsize()) diff --git a/agreement/persistence.go b/agreement/persistence.go index 819806b69a..b8510e446c 100644 --- a/agreement/persistence.go +++ b/agreement/persistence.go @@ -55,6 +55,21 @@ func persistent(as []action) bool { // encode serializes the current state into a byte array. func encode(t timers.Clock[TimeoutType], rr rootRouter, p player, a []action, reflect bool) (raw []byte) { var s diskState + + // Don't persist state for old rounds + // rootRouter.update() may preserve roundRouters from credentialRoundLag rounds ago + children := make(map[round]*roundRouter) + for rnd, rndRouter := range rr.Children { + if rnd >= p.Round { + children[rnd] = rndRouter + } + } + if len(children) == 0 { + rr.Children = nil + } else { + rr.Children = children + } + if reflect { s.Router = protocol.EncodeReflect(rr) s.Player = protocol.EncodeReflect(p) diff --git a/agreement/player.go b/agreement/player.go index 72fe2f4556..21d65ecf88 100644 --- a/agreement/player.go +++ b/agreement/player.go @@ -278,22 +278,31 @@ func (p *player) handleCheckpointEvent(r routerHandle, e checkpointEvent) []acti // updateCredentialArrivalHistory is called at the end of a successful // uninterrupted round (just after ensureAction is generated) to collect // credential arrival times to dynamically set the filter timeout. -// It returns the time of the lowest credential's arrival, if one was -// collected and added to lowestCredentialArrivals, or zero otherwise. +// It returns the time of the lowest credential's arrival from +// credentialRoundLag rounds ago, if one was collected and added to +// lowestCredentialArrivals, or zero otherwise. func (p *player) updateCredentialArrivalHistory(r routerHandle, ver protocol.ConsensusVersion) time.Duration { - // only append to lowestCredentialArrivals if this was a successful round completing in period 0. if p.Period != 0 { + // only append to lowestCredentialArrivals if this was a successful round completing in period 0. return 0 } - // look up the validatedAt time of the winning proposal-vote - re := readLowestEvent{T: readLowestVote, Round: p.Round, Period: p.Period} - re = r.dispatch(*p, re, proposalMachineRound, p.Round, p.Period, 0).(readLowestEvent) - if !re.Filled { + + if p.Round <= credentialRoundLag { + // not sufficiently many rounds had passed to collect any measurement + return 0 + } + + // look up the validatedAt time of the winning proposal-vote from credentialRoundLag ago, + // by now we should have seen the lowest credential for that round. + credHistoryRound := p.Round - credentialRoundLag + re := readLowestEvent{T: readLowestVote, Round: credHistoryRound, Period: 0} + re = r.dispatch(*p, re, proposalMachineRound, credHistoryRound, 0, 0).(readLowestEvent) + if !re.HasLowestIncludingLate { return 0 } - p.lowestCredentialArrivals.store(re.Vote.validatedAt) - return re.Vote.validatedAt + p.lowestCredentialArrivals.store(re.LowestIncludingLate.validatedAt) + return re.LowestIncludingLate.validatedAt } // calculateFilterTimeout chooses the appropriate filter timeout. @@ -603,8 +612,31 @@ func (p *player) handleMessageEvent(r routerHandle, e messageEvent) (actions []a err := ef.(filteredEvent).Err return append(actions, disconnectAction(e, err)) case voteFiltered: - err := ef.(filteredEvent).Err - return append(actions, ignoreAction(e, err)) + ver := e.Proto.Version + proto := config.Consensus[ver] + if !proto.DynamicFilterTimeout { + // Dynamic filter timeout feature disabled, so we filter the + // message as usual (keeping earlier behavior) + err := ef.(filteredEvent).Err + return append(actions, ignoreAction(e, err)) + } + switch ef.(filteredEvent).LateCredentialTrackingNote { + case VerifiedBetterLateCredentialForTracking: + // Dynamic filter timeout feature enabled, and current message + // updated the best credential arrival time + v := e.Input.Vote + return append(actions, relayAction(e, protocol.AgreementVoteTag, v.u())) + case NoLateCredentialTrackingImpact: + // Dynamic filter timeout feature enabled, but current message + // may not update the best credential arrival time, so we should + // ignore it. + err := ef.(filteredEvent).Err + return append(actions, ignoreAction(e, err)) + case UnverifiedLateCredentialForTracking: + // In this case, the vote may impact credential tracking, but needs to + // be validated. So we do not return here, and continue processing, so that + // the votePresent check below will make a verifyVoteAction for this vote. + } } if e.t() == votePresent { diff --git a/agreement/player_permutation_test.go b/agreement/player_permutation_test.go index 0335093933..bd2c2c84da 100644 --- a/agreement/player_permutation_test.go +++ b/agreement/player_permutation_test.go @@ -264,6 +264,7 @@ func getMessageEventPermutation(t *testing.T, n int, helper *voteMakerHelper) (e bun := unauthenticatedBundle{ Round: r, Period: p, + Step: cert, Proposal: pV, } e = messageEvent{ @@ -339,6 +340,24 @@ func expectIgnore(t *testing.T, trace ioTrace, errMsg string, playerN int, event }), errMsg, playerN, eventN) } +func expectRelay(t *testing.T, trace ioTrace, errMsg string, playerN int, eventN int) { + require.Truef(t, trace.ContainsFn(func(b event) bool { + if b.t() != wrappedAction { + return false + } + + wrapper := b.(wrappedActionEvent) + if wrapper.action.t() != relay { + return false + } + act := wrapper.action.(networkAction) + if act.T == relay && act.Err == nil { + return true + } + return false + }), errMsg, playerN, eventN) +} + func expectDisconnect(t *testing.T, trace ioTrace, errMsg string, playerN int, eventN int) { require.Truef(t, trace.ContainsFn(func(b event) bool { if b.t() != wrappedAction { @@ -356,15 +375,37 @@ func expectDisconnect(t *testing.T, trace ioTrace, errMsg string, playerN int, e }), errMsg, playerN, eventN) } +func expectVerify(t *testing.T, trace ioTrace, errMsg string, playerN int, eventN int) { + require.Truef(t, trace.ContainsFn(func(b event) bool { + if b.t() != wrappedAction { + return false + } + + wrapper := b.(wrappedActionEvent) + if wrapper.action.t() != verifyVote { + return false + } + act := wrapper.action.(cryptoAction) + if act.T == verifyVote { + return true + } + return false + }), errMsg, playerN, eventN) +} + func requireActionCount(t *testing.T, trace ioTrace, expectedCount, playerN, eventN int) { require.Equalf(t, trace.countAction(), expectedCount, "Player should not emit extra actions, player: %v, event: %v", playerN, eventN) } func requireTraceContains(t *testing.T, trace ioTrace, expected event, playerN, eventN int) { + if !trace.Contains(expected) { + t.Log("expected:", expected.ComparableStr()) + t.Log("trace:", trace.String()) + } require.Truef(t, trace.Contains(expected), "Player should emit action, player: %v, event: %v", playerN, eventN) } -func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, helper *voteMakerHelper, trace ioTrace) { +func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, helper *voteMakerHelper, trace ioTrace, dynamicFilterTimeoutEnabled bool) { const r = round(209) const p = period(0) var payload = makeRandomProposalPayload(r) @@ -380,7 +421,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -395,7 +436,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case proposeVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, propose, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 1) requireTraceContains(t, trace, ev(a), playerN, eventN) case payloadPresentEvent, payloadVerifiedEvent, payloadVerifiedEventNoMessageHandle: requireActionCount(t, trace, 1, playerN, eventN) @@ -417,8 +458,8 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel for i := 0; i < int(cert.threshold(config.Consensus[protocol.ConsensusCurrentVersion])); i++ { votes[i] = helper.MakeVerifiedVote(t, i, r, p, cert, pV) } - bun := unauthenticatedBundle{Round: r, Period: p, Proposal: pV} - ca := cryptoAction{T: verifyBundle, M: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}, TaskIndex: 0} + bun := unauthenticatedBundle{Round: r, Period: p, Step: cert, Proposal: pV} + ca := verifyBundleAction(messageEvent{Input: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}}, r, p, cert) requireTraceContains(t, trace, ev(ca), playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: requireActionCount(t, trace, 1, playerN, eventN) @@ -431,7 +472,25 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel } case playerNextRound: switch eventN { - case softVoteVerifiedEventSamePeriod, softVotePresentEventSamePeriod, proposeVoteVerifiedEventNextPeriod, proposeVoteVerifiedEventSamePeriod, proposeVotePresentEventSamePeriod, payloadPresentEvent, payloadVerifiedEvent, payloadVerifiedEventNoMessageHandle, bundleVerifiedEventSamePeriod, bundlePresentEventSamePeriod: + case proposeVoteVerifiedEventSamePeriod: + requireActionCount(t, trace, 1, playerN, eventN) + // This case should never happen -- player is on R+1 and the voteVerified event is for R. + // Player will not queue up a verifyVoteAction for this vote (without DynamicFilterTimeout enabled). + // We are asserting the relay behavior player currently implements, but it is not possible given current + // code -- you would have filtered the votePresent for this vote. + if dynamicFilterTimeoutEnabled && p == 0 { + expectRelay(t, trace, "Player should relay period 0 msg from past rounds, player: %v, event: %v", playerN, eventN) + } else { + expectIgnore(t, trace, "Player should ignore msg from past rounds, player: %v, event: %v", playerN, eventN) + } + case proposeVotePresentEventSamePeriod: + requireActionCount(t, trace, 1, playerN, eventN) + if dynamicFilterTimeoutEnabled && p == 0 { + expectVerify(t, trace, "Player should verify period 0 msg from past rounds, player: %v, event: %v", playerN, eventN) + } else { + expectIgnore(t, trace, "Player should ignore msg from past rounds, player: %v, event: %v", playerN, eventN) + } + case softVoteVerifiedEventSamePeriod, softVotePresentEventSamePeriod, proposeVoteVerifiedEventNextPeriod, payloadPresentEvent, payloadVerifiedEvent, payloadVerifiedEventNoMessageHandle, bundleVerifiedEventSamePeriod, bundlePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) expectIgnore(t, trace, "Player should ignore msg from past rounds, player: %v, event: %v", playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: @@ -453,7 +512,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -468,7 +527,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case proposeVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, propose, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0}, r, p, 2) requireTraceContains(t, trace, ev(a), playerN, eventN) case payloadPresentEvent, payloadVerifiedEvent, payloadVerifiedEventNoMessageHandle: requireActionCount(t, trace, 1, playerN, eventN) @@ -495,7 +554,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -507,7 +566,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel expectIgnore(t, trace, "Player should ignore proposalvvote already received: %v, event: %v", playerN, eventN) case payloadPresentEvent: requireActionCount(t, trace, 2, playerN, eventN) - ca := cryptoAction{T: verifyPayload, M: message{UnauthenticatedProposal: payload.u()}, TaskIndex: 0} + ca := verifyPayloadAction(messageEvent{Input: message{UnauthenticatedProposal: payload.u()}}, r, p, false) requireTraceContains(t, trace, ev(ca), playerN, eventN) na := networkAction{T: relay, Tag: protocol.ProposalPayloadTag, CompoundMessage: compoundMessage{Proposal: payload.u()}} requireTraceContains(t, trace, ev(na), playerN, eventN) @@ -534,8 +593,8 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel for i := 0; i < int(cert.threshold(config.Consensus[protocol.ConsensusCurrentVersion])); i++ { votes[i] = helper.MakeVerifiedVote(t, i, r, p, cert, pV) } - bun := unauthenticatedBundle{Round: r, Period: p, Proposal: pV} - ca := cryptoAction{T: verifyBundle, M: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}, TaskIndex: 0} + bun := unauthenticatedBundle{Round: r, Period: p, Step: cert, Proposal: pV} + ca := verifyBundleAction(messageEvent{Input: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}}, r, p, cert) requireTraceContains(t, trace, ev(ca), playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: requireActionCount(t, trace, 1, playerN, eventN) @@ -557,7 +616,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -569,7 +628,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel expectIgnore(t, trace, "Player should ignore proposalvvote already received: %v, event: %v", playerN, eventN) case payloadPresentEvent: requireActionCount(t, trace, 2, playerN, eventN) - ca := cryptoAction{T: verifyPayload, M: message{UnauthenticatedProposal: payload.u()}, TaskIndex: 0} + ca := verifyPayloadAction(messageEvent{Input: message{UnauthenticatedProposal: payload.u()}}, r, p, false) requireTraceContains(t, trace, ev(ca), playerN, eventN) na := networkAction{T: relay, Tag: protocol.ProposalPayloadTag, CompoundMessage: compoundMessage{Proposal: payload.u()}} requireTraceContains(t, trace, ev(na), playerN, eventN) @@ -600,8 +659,8 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel for i := 0; i < int(cert.threshold(config.Consensus[protocol.ConsensusCurrentVersion])); i++ { votes[i] = helper.MakeVerifiedVote(t, i, r, p, cert, pV) } - bun := unauthenticatedBundle{Round: r, Period: p, Proposal: pV} - ca := cryptoAction{T: verifyBundle, M: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}, TaskIndex: 0} + bun := unauthenticatedBundle{Round: r, Period: p, Step: cert, Proposal: pV} + ca := verifyBundleAction(messageEvent{Input: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}}, r, p, cert) requireTraceContains(t, trace, ev(ca), playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: requireActionCount(t, trace, 1, playerN, eventN) @@ -623,7 +682,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -635,7 +694,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel expectIgnore(t, trace, "Player should ignore proposalvvote already received: %v, event: %v", playerN, eventN) case payloadPresentEvent: requireActionCount(t, trace, 2, playerN, eventN) - ca := cryptoAction{T: verifyPayload, M: message{UnauthenticatedProposal: payload.u()}, TaskIndex: 0} + ca := verifyPayloadAction(messageEvent{Input: message{UnauthenticatedProposal: payload.u()}}, r, p, false) requireTraceContains(t, trace, ev(ca), playerN, eventN) na := networkAction{T: relay, Tag: protocol.ProposalPayloadTag, CompoundMessage: compoundMessage{Proposal: payload.u()}} requireTraceContains(t, trace, ev(na), playerN, eventN) @@ -666,8 +725,8 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel for i := 0; i < int(cert.threshold(config.Consensus[protocol.ConsensusCurrentVersion])); i++ { votes[i] = helper.MakeVerifiedVote(t, i, r, p, cert, pV) } - bun := unauthenticatedBundle{Round: r, Period: p, Proposal: pV} - ca := cryptoAction{T: verifyBundle, M: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}, TaskIndex: 0} + bun := unauthenticatedBundle{Round: r, Period: p, Step: cert, Proposal: pV} + ca := verifyBundleAction(messageEvent{Input: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}}, r, p, cert) requireTraceContains(t, trace, ev(ca), playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: requireActionCount(t, trace, 1, playerN, eventN) @@ -689,7 +748,7 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel case softVotePresentEventSamePeriod: requireActionCount(t, trace, 1, playerN, eventN) vvote := helper.MakeVerifiedVote(t, 0, r, p, soft, pV) - a := cryptoAction{T: verifyVote, M: message{UnauthenticatedVote: vvote.u()}, TaskIndex: 0} + a := verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vvote.u()}}, r, p, 0) requireTraceContains(t, trace, ev(a), playerN, eventN) case proposeVoteVerifiedEventNextPeriod: requireActionCount(t, trace, 1, playerN, eventN) @@ -723,8 +782,8 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel for i := 0; i < int(cert.threshold(config.Consensus[protocol.ConsensusCurrentVersion])); i++ { votes[i] = helper.MakeVerifiedVote(t, i, r, p, cert, pV) } - bun := unauthenticatedBundle{Round: r, Period: p, Proposal: pV} - ca := cryptoAction{T: verifyBundle, M: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}, TaskIndex: 0} + bun := unauthenticatedBundle{Round: r, Period: p, Step: cert, Proposal: pV} + ca := verifyBundleAction(messageEvent{Input: message{Bundle: bundle{U: bun, Votes: votes}, UnauthenticatedBundle: bun}}, r, p, cert) requireTraceContains(t, trace, ev(ca), playerN, eventN) case softVoteVerifiedErrorEventSamePeriod, proposeVoteVerifiedErrorEventSamePeriod, bundleVerifiedErrorEvent: requireActionCount(t, trace, 1, playerN, eventN) @@ -745,18 +804,31 @@ func verifyPermutationExpectedActions(t *testing.T, playerN int, eventN int, hel // Generates a set of player states, router states, and messageEvents and tests all permutations of them func TestPlayerPermutation(t *testing.T) { partitiontest.PartitionTest(t) + // check with current consensus params and with consensus params that + // explicitly enable dynamic filter timeout + playerPermutationCheck(t, false) + playerPermutationCheck(t, true) +} + +func playerPermutationCheck(t *testing.T, enableDynamicFilterTimeout bool) { + // create a protocol version where dynamic filter is enabled + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() for i := 0; i < 7; i++ { for j := 0; j < 14; j++ { _, pMachine, helper := getPlayerPermutation(t, i) inMsg := getMessageEventPermutation(t, j, helper) + if enableDynamicFilterTimeout { + inMsg.Proto = ConsensusVersionView{Version: version} + } err, panicErr := pMachine.transition(inMsg) fmt.Println(pMachine.getTrace().events) fmt.Println("") require.NoErrorf(t, err, "player: %v, event: %v", i, j) require.NoErrorf(t, panicErr, "player: %v, event: %v", i, j) - verifyPermutationExpectedActions(t, i, j, helper, pMachine.getTrace()) + verifyPermutationExpectedActions(t, i, j, helper, pMachine.getTrace(), enableDynamicFilterTimeout) } } } diff --git a/agreement/player_test.go b/agreement/player_test.go index a9a9f1106d..2bb2ffe818 100644 --- a/agreement/player_test.go +++ b/agreement/player_test.go @@ -505,6 +505,7 @@ func setupP(t *testing.T, r round, p period, s step) (plyr *player, pMachine ioA rRouter := makeRootRouter(player{Round: r, Period: p, Step: s, Deadline: Deadline{Duration: FilterTimeout(p, protocol.ConsensusCurrentVersion), Type: TimeoutFilter}, lowestCredentialArrivals: history}) concreteMachine := ioAutomataConcretePlayer{rootRouter: &rRouter} plyr = concreteMachine.underlying() + plyr.lowestCredentialArrivals = makeCredentialArrivalHistory(dynamicFilterCredentialArrivalHistory) pMachine = &concreteMachine helper = &voteMakerHelper{} helper.Setup() @@ -1618,7 +1619,7 @@ func TestPlayerReproposesNextValueBundleWithoutPayload(t *testing.T) { // check player fast-forwarded, rezeros, reproposed, relays next-value bundle require.Equalf(t, p, pWhite.Period, "player did not fast forward to new period") - zeroEvent := ev(rezeroAction{}) + zeroEvent := ev(rezeroAction{Round: r}) require.Truef(t, pM.getTrace().Contains(zeroEvent), "Player should reset clock") reproposeEvent := ev(pseudonodeAction{T: repropose, Round: r, Period: p, Proposal: *pV}) require.Truef(t, pM.getTrace().Contains(reproposeEvent), "Player should repropose from next-value quorum") @@ -1688,7 +1689,7 @@ func TestPlayerReproposesNextValueBundleRelaysPayload(t *testing.T) { // check player fast-forwarded, rezeros, reproposed, relays next-value bundle require.Equalf(t, p, pWhite.Period, "player did not fast forward to new period") - zeroEvent := ev(rezeroAction{}) + zeroEvent := ev(rezeroAction{Round: r}) require.Truef(t, pM.getTrace().Contains(zeroEvent), "Player should reset clock") reproposeEvent := ev(pseudonodeAction{T: repropose, Round: r, Period: p, Proposal: *pV}) require.Truef(t, pM.getTrace().Contains(reproposeEvent), "Player should repropose from next-value quorum") @@ -2162,7 +2163,6 @@ func TestPlayerRePropagatesProposalPayload(t *testing.T) { require.NoError(t, err) require.NoError(t, panicErr) relayPayloadEvent = ev(networkAction{T: broadcast, Tag: protocol.ProposalPayloadTag, CompoundMessage: compoundMessage{Proposal: payloadNext.u()}}) - fmt.Println(relayPayloadEvent) require.Truef(t, pM.getTrace().Contains(relayPayloadEvent), "Player should relay staged payload over pinned payload on resynch") } @@ -2417,7 +2417,7 @@ func TestPlayerRequestsVoteVerification(t *testing.T) { require.NoError(t, err) require.NoError(t, panicErr) - verifyEvent := ev(cryptoAction{T: verifyVote, M: m, TaskIndex: 0}) + verifyEvent := ev(cryptoAction{T: verifyVote, M: m, Round: r, Period: p, TaskIndex: 0}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") } @@ -2440,7 +2440,7 @@ func TestPlayerRequestsProposalVoteVerification(t *testing.T) { require.NoError(t, err) require.NoError(t, panicErr) - verifyEvent := ev(cryptoAction{T: verifyVote, M: m, TaskIndex: 0}) + verifyEvent := ev(cryptoAction{T: verifyVote, M: m, Round: r, Period: p, TaskIndex: 1}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") } @@ -2464,7 +2464,7 @@ func TestPlayerRequestsBundleVerification(t *testing.T) { err, panicErr := pM.transition(inMsg) require.NoError(t, err) require.NoError(t, panicErr) - verifyEvent := ev(cryptoAction{T: verifyBundle, M: m, TaskIndex: 0}) + verifyEvent := ev(cryptoAction{T: verifyBundle, M: m, Round: r, Period: p, TaskIndex: 0}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify bundle") } @@ -2501,7 +2501,7 @@ func TestPlayerRequestsPayloadVerification(t *testing.T) { require.NoError(t, panicErr) // make sure payload verify request - verifyEvent := ev(cryptoAction{T: verifyPayload, M: m, TaskIndex: 0}) + verifyEvent := ev(cryptoAction{T: verifyPayload, M: m, Round: r, Period: p, TaskIndex: 0}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify payload") } @@ -2537,8 +2537,7 @@ func TestPlayerRequestsPipelinedPayloadVerification(t *testing.T) { require.NoError(t, err) require.NoError(t, panicErr) // make sure no payload verify request, because its for the next round - verifyEvent := ev(cryptoAction{T: verifyPayload, M: m, TaskIndex: 0}) - require.Falsef(t, pM.getTrace().Contains(verifyEvent), "Player should not verify payload from r + 1") + require.Falsef(t, pM.getTrace().ContainsString(verifyPayload.String()), "Player should not verify payload from r + 1") // now enter next round pP, pV := helper.MakeRandomProposalPayload(t, r) @@ -2596,7 +2595,7 @@ func TestPlayerRequestsPipelinedPayloadVerification(t *testing.T) { require.Truef(t, pM.getTrace().Contains(commitEvent), "Player should try to ensure block/digest on ledger") // make sure we sent out pipelined payload verify requests - verifyEvent = ev(cryptoAction{T: verifyPayload}) + verifyEvent := ev(cryptoAction{T: verifyPayload, Round: r + 1, TaskIndex: 0}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify pipelined payload first seen in previous round") } @@ -2711,7 +2710,7 @@ func TestPlayerHandlesPipelinedThresholds(t *testing.T) { err, panicErr = pM.transition(inMsg) require.NoError(t, err) require.NoError(t, panicErr) - verifyEvent := ev(cryptoAction{T: verifyPayload}) + verifyEvent := ev(cryptoAction{T: verifyPayload, Round: r + 1}) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify pipelined payload first seen in previous round") } @@ -3225,7 +3224,7 @@ func TestPlayerAlwaysResynchsPinnedValue(t *testing.T) { // Now, player should be in period 12, and should have tried to resychronize the pinned payload trace := pM.getTrace() require.Equalf(t, p, pWhite.Period, "player did not fast forward to new period") - zeroEvent := ev(rezeroAction{}) + zeroEvent := ev(rezeroAction{Round: r}) require.Truef(t, trace.Contains(zeroEvent), "Player should reset clock") resynchEvent := ev(networkAction{T: broadcast, Tag: protocol.VoteBundleTag, UnauthenticatedBundle: bun}) @@ -3241,34 +3240,58 @@ func TestPlayerAlwaysResynchsPinnedValue(t *testing.T) { func TestPlayerRetainsReceivedValidatedAtOneSample(t *testing.T) { partitiontest.PartitionTest(t) + version := protocol.ConsensusFuture const r = round(20239) - const p = period(0) + const p = period(131) pWhite, pM, helper := setupP(t, r-1, p, soft) pP, pV := helper.MakeRandomProposalPayload(t, r-1) - // send voteVerified message - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - inMsg := messageEvent{T: voteVerified, Input: message{Vote: vVote, UnauthenticatedVote: vVote.u()}} - inMsg = inMsg.AttachValidatedAt(501*time.Millisecond, r-1) - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // send voteVerified message for round r-credentialRoundLag-1, then for r-1 + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 502*time.Millisecond, nil) + // send payloadPresent message for r-1 + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) - // send payloadPresent message - m := message{UnauthenticatedProposal: pP.u()} - inMsg = messageEvent{T: payloadPresent, Input: m} - inMsg = inMsg.AttachReceivedAt(time.Second, r-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // advance player to R and check timings ensured for R-1 are correct + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) +} - assertCorrectReceivedAtSet(t, pWhite, pM, helper, r, p, pP, pV, m, protocol.ConsensusFuture, time.Second) +// test that ReceivedAt and ValidateAt timing information are retained in proposalStore +// when the payloadPresent, payloadVerified, and voteVerified events are processed, and that all timings +// are available when the ensureAction is called for the block. +func TestPlayerRetainsReceivedValidatedAtCredentialHistory(t *testing.T) { + partitiontest.PartitionTest(t) - // assert lowest vote validateAt time was recorded into payloadArrivals - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) - require.False(t, pWhite.lowestCredentialArrivals.isFull()) - require.Equal(t, 501*time.Millisecond, pWhite.lowestCredentialArrivals.history[0]) + version := protocol.ConsensusFuture + const r = round(20239) + const p = period(0) + pWhite, pM, helper := setupP(t, r-credentialRoundLag-1, p, soft) + + // send voteVerified and payloadPresent messages with timings, and advance through rounds r-credentialRoundLag-1 up to r-1 + voteVerifiedTiming := 501 * time.Millisecond + payloadPresentTiming := 1001 * time.Millisecond + payloadVerifiedTiming := 2001 * time.Millisecond + for rnd := r - credentialRoundLag - 1; rnd < r-1; rnd++ { + pP, pV := helper.MakeRandomProposalPayload(t, rnd) + sendVoteVerified(t, helper, pWhite, pM, 0, rnd, rnd, p, pV, voteVerifiedTiming, nil) + sendPayloadPresent(t, pWhite, pM, rnd, pP, payloadPresentTiming, nil) + moveToRound(t, pWhite, pM, helper, rnd+1, p, pP, pV, payloadVerifiedTiming, version) + + voteVerifiedTiming += time.Millisecond + payloadPresentTiming += time.Millisecond + payloadVerifiedTiming += time.Millisecond + } + + // send in voteVerified and payloadPresent for r-1 + pP, pV := helper.MakeRandomProposalPayload(t, r-1) + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 600*time.Millisecond, nil) + sendPayloadPresent(t, pWhite, pM, r-1, pP, 1500*time.Millisecond, nil) + // advance player to R and check timings ensured for R-1 are correct + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2500*time.Millisecond, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, 1500*time.Millisecond, 2500*time.Millisecond) + + // player is looking up arrival times from r-roundLag ago so only the 501ms vote will be in lowestCredentialArrivals + assertSingleCredentialArrival(t, pWhite, 501*time.Millisecond) } // test that ReceivedAt and ValidateAt timing information are retained in @@ -3277,43 +3300,71 @@ func TestPlayerRetainsReceivedValidatedAtOneSample(t *testing.T) { // available when the ensureAction is called for the block. func TestPlayerRetainsEarlyReceivedValidatedAtOneSample(t *testing.T) { partitiontest.PartitionTest(t) + + version := protocol.ConsensusFuture const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) - pP, pV := helper.MakeRandomProposalPayload(t, r-1) - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - // move two rounds, so the measurement from round r gets inserted to the - // history window + // send voteVerified message + pP, pV := helper.MakeRandomProposalPayload(t, r-credentialRoundLag-1) + sendVoteVerified(t, helper, pWhite, pM, 0, r-credentialRoundLag-2, r-credentialRoundLag-1, p, pV, 401*time.Millisecond, nil) - // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} + // send voteVerified message + pP, pV = helper.MakeRandomProposalPayload(t, r-1) + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) - inMsg := compoundMsg.AttachReceivedAt(time.Second, r-2) // call AttachReceivedAt like demux would - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) - // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) - require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") + // advance player to R and check timings ensured for R-1 are correct + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) - // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} - timestamp := 500 - inMsg = inMsg.AttachValidatedAt(time.Duration(timestamp)*time.Millisecond, r-2) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) - moveToRound(t, pWhite, pM, helper, r, p, pP, pV, proposalMsg, protocol.ConsensusFuture) + // assert lowest vote validateAt time was recorded into payloadArrivals + assertSingleCredentialArrival(t, pWhite, pipelinedMessageTimestamp) +} - // receive credential for the next round, check that it gets a timestamp of 1 - require.Equal(t, time.Duration(1), pWhite.lowestCredentialArrivals.history[0]) +func testClockForRound(t *testing.T, pWhite *player, fixedDur time.Duration, currentRound round, historicalClocks map[round]roundStartTimer) func(round) roundStartTimer { + return func(eventRound round) roundStartTimer { + //require.Equal(t, pWhite.Round, currentRound) // TODO make tests more realistic + return clockForRound(currentRound, constantRoundStartTimer(fixedDur), historicalClocks)(eventRound) + } +} + +// test that ReceivedAt and ValidateAt timing information are retained in +// proposalStore when the payloadPresent, payloadVerified, and voteVerified +// events are processed credentialRoundLag after the round they belong to, and +// that all timings are available when the ensureAction is called for the block. +func TestPlayerRetainsLateReceivedValidatedAtOneSample(t *testing.T) { + partitiontest.PartitionTest(t) + + version := protocol.ConsensusFuture + const r = round(20239) + const p = period(0) + pWhite, pM, helper := setupP(t, r-1, p, soft) + + historicalClocks := map[round]roundStartTimer{ + r - credentialRoundLag - 1: constantRoundStartTimer(900 * time.Millisecond), + } + + // send voteVerified message + pP, pV := helper.MakeRandomProposalPayload(t, r-credentialRoundLag-1) + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-credentialRoundLag-1, p, pV, 401*time.Millisecond, historicalClocks) + + // send voteVerified message + pP, pV = helper.MakeRandomProposalPayload(t, r-1) + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + // advance player to R and check timings ensured for R-1 are correct + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) + + // assert lowest vote validateAt time was recorded into payloadArrivals + assertSingleCredentialArrival(t, pWhite, 900*time.Millisecond) } // test that ReceivedAt and ValidateAt timing information are retained in proposalStore @@ -3322,31 +3373,61 @@ func TestPlayerRetainsEarlyReceivedValidatedAtOneSample(t *testing.T) { // DynamicFilterCredentialArrivalHistory rounds. func TestPlayerRetainsReceivedValidatedAtForHistoryWindow(t *testing.T) { partitiontest.PartitionTest(t) + testPlayerRetainsReceivedValidatedAtForHistoryWindow(t, false) +} + +func TestPlayerRetainsReceivedValidatedAtForHistoryWindowLateBetter(t *testing.T) { + partitiontest.PartitionTest(t) + testPlayerRetainsReceivedValidatedAtForHistoryWindow(t, true) +} + +func testPlayerRetainsReceivedValidatedAtForHistoryWindow(t *testing.T, addBetterLate bool) { + version := protocol.ConsensusFuture const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) require.NotZero(t, dynamicFilterCredentialArrivalHistory) - for i := 0; i < dynamicFilterCredentialArrivalHistory; i++ { + for i := 0; i < dynamicFilterCredentialArrivalHistory+int(credentialRoundLag); i++ { // send voteVerified message pP, pV := helper.MakeRandomProposalPayload(t, r+round(i)-1) vVote := helper.MakeVerifiedVote(t, 0, r+round(i)-1, p, propose, *pV) + var betterLateVote vote + if addBetterLate { + // set up better late proposal-vote from someone else, so it won't be a errProposalTrackerSenderDup + vVote2 := helper.MakeVerifiedVote(t, 1, r+round(i)-1, p, propose, *pV) + vVote.Cred.VrfOut = crypto.Digest{1} + vVote2.Cred.VrfOut = crypto.Digest{2} + if vVote2.Cred.Less(vVote.Cred) { + betterLateVote = vVote2 + } else { + betterLateVote = vVote + vVote = vVote2 + } + require.True(t, betterLateVote.Cred.Less(vVote.Cred)) + require.False(t, vVote.Cred.Less(betterLateVote.Cred)) + } inMsg := messageEvent{T: voteVerified, Input: message{Vote: vVote, UnauthenticatedVote: vVote.u()}} timestamp := 500 + i - inMsg = inMsg.AttachValidatedAt(time.Duration(timestamp)*time.Millisecond, r+round(i)-1) + inMsg = inMsg.AttachValidatedAt(testClockForRound(t, pWhite, time.Duration(timestamp)*time.Millisecond, r+round(i)-1, nil)) err, panicErr := pM.transition(inMsg) require.NoError(t, err) require.NoError(t, panicErr) // send payloadPresent message - m := message{UnauthenticatedProposal: pP.u()} - inMsg = messageEvent{T: payloadPresent, Input: m} - inMsg = inMsg.AttachReceivedAt(time.Second, r+round(i)-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) - moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, m, protocol.ConsensusFuture) + sendPayloadPresent(t, pWhite, pM, r+round(i)-1, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, 2*time.Second, version) + + // send better late voteVerified message + if addBetterLate { + inMsg = messageEvent{T: voteVerified, Input: message{Vote: betterLateVote, UnauthenticatedVote: betterLateVote.u()}} + timestamp := 600 + i + inMsg = inMsg.AttachValidatedAt(testClockForRound(t, pWhite, time.Duration(timestamp)*time.Millisecond, r+round(i)-1, nil)) + err, panicErr = pM.transition(inMsg) + require.NoError(t, err) + require.NoError(t, panicErr) + } } // assert lowest vote validateAt time was recorded into payloadArrivals @@ -3354,6 +3435,9 @@ func TestPlayerRetainsReceivedValidatedAtForHistoryWindow(t *testing.T) { for i := 0; i < dynamicFilterCredentialArrivalHistory; i++ { // only the last historyLen samples are kept, so the first one is discarded timestamp := 500 + i + if addBetterLate { + timestamp = 600 + i + } require.Equal(t, time.Duration(timestamp)*time.Millisecond, pWhite.lowestCredentialArrivals.history[i]) } } @@ -3365,41 +3449,52 @@ func TestPlayerRetainsReceivedValidatedAtForHistoryWindow(t *testing.T) { func TestPlayerRetainsReceivedValidatedAtPPOneSample(t *testing.T) { partitiontest.PartitionTest(t) + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) pP, pV := helper.MakeRandomProposalPayload(t, r-1) - // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - inMsg := compoundMsg.AttachReceivedAt(time.Second, r-1) // call AttachReceivedAt like demux would - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) - // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) + require.False(t, pWhite.lowestCredentialArrivals.isFull()) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + + // XXX this behavior only happens if dynamic timeout enabled; test the other way + + historicalClocks := map[round]roundStartTimer{ + r - credentialRoundLag: constantRoundStartTimer(900 * time.Millisecond), + } + // create a PP message for the round we're going to take the sample from when round r-1 ends + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendCompoundMessage(t, helper, pWhite, pM, r, r-credentialRoundLag, p, pP, pV, time.Second, nil, version) + + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r-credentialRoundLag, p, 1)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r, 502*time.Millisecond, historicalClocks, 1) - // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} - inMsg = inMsg.AttachValidatedAt(502*time.Millisecond, r-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, 501*time.Millisecond, nil) - assertCorrectReceivedAtSet(t, pWhite, pM, helper, r, p, pP, pV, proposalMsg, protocol.ConsensusFuture, time.Second) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) // assert lowest vote validateAt time was recorded into payloadArrivals - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) - require.False(t, pWhite.lowestCredentialArrivals.isFull()) - require.Equal(t, 502*time.Millisecond, pWhite.lowestCredentialArrivals.history[0]) + assertSingleCredentialArrival(t, pWhite, 900*time.Millisecond) } // test that ReceivedAt and ValidateAt timing information are retained in @@ -3410,41 +3505,103 @@ func TestPlayerRetainsReceivedValidatedAtPPOneSample(t *testing.T) { func TestPlayerRetainsEarlyReceivedValidatedAtPPOneSample(t *testing.T) { partitiontest.PartitionTest(t) + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() + const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) pP, pV := helper.MakeRandomProposalPayload(t, r-1) - // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - inMsg := compoundMsg.AttachReceivedAt(time.Second, r-2) // call AttachReceivedAt like demux would - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) + require.False(t, pWhite.lowestCredentialArrivals.isFull()) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + + // create a PP message for the round we're going to take the sample from when round r-1 ends + // Now we're going to pretend we got the message one round early. + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendCompoundMessage(t, helper, pWhite, pM, r-credentialRoundLag-1, r-credentialRoundLag, p, pP, pV, time.Second, nil, version) // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r-credentialRoundLag, p, 1)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") - // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} - inMsg = inMsg.AttachValidatedAt(502*time.Millisecond, r-2) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r-credentialRoundLag, 502*time.Millisecond, nil, 1) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-credentialRoundLag, pP, time.Second, nil) - assertCorrectReceivedAtSet(t, pWhite, pM, helper, r, p, pP, pV, proposalMsg, protocol.ConsensusFuture, time.Duration(1)) + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) // assert lowest vote validateAt time was recorded into payloadArrivals - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) + assertSingleCredentialArrival(t, pWhite, 502*time.Millisecond) +} + +// test that ReceivedAt and ValidateAt timing information are retained in +// proposalStore when the payloadPresent (as part of the CompoundMessage +// encoding used by PP messages), payloadVerified, and voteVerified events are +// processed credentialRoundLag after the round they belong to, and that all +// timings are available when the ensureAction is called for the block. +func TestPlayerRetainsLateReceivedValidatedAtPPOneSample(t *testing.T) { + partitiontest.PartitionTest(t) + + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() + const r = round(20239) + const p = period(0) + pWhite, pM, helper := setupP(t, r-1, p, soft) + pP, pV := helper.MakeRandomProposalPayload(t, r-1) + + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + // Go from round r-1 to r + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) require.False(t, pWhite.lowestCredentialArrivals.isFull()) - require.Equal(t, time.Duration(1), pWhite.lowestCredentialArrivals.history[0]) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + + historicalClocks := map[round]roundStartTimer{ + r - credentialRoundLag: constantRoundStartTimer(900 * time.Millisecond), + } + // create a PP message for the round we're going to take the sample from when round r-1 ends + // Now we're going to pretend we got the message credentialRoundLag too late. + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendCompoundMessage(t, helper, pWhite, pM, r, r-credentialRoundLag, p, pP, pV, time.Second, historicalClocks, version) + + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r-credentialRoundLag, p, 1)) + require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") + + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r, 502*time.Millisecond, historicalClocks, 1) + + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, 503*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) + + // assert lowest vote validateAt time was recorded into payloadArrivals + assertSingleCredentialArrival(t, pWhite, 900*time.Millisecond) } // test that ReceivedAt and ValidateAt timing information are retained in @@ -3455,39 +3612,29 @@ func TestPlayerRetainsEarlyReceivedValidatedAtPPOneSample(t *testing.T) { // DynamicFilterCredentialArrivalHistory rounds. func TestPlayerRetainsReceivedValidatedAtPPForHistoryWindow(t *testing.T) { partitiontest.PartitionTest(t) + + version := protocol.ConsensusFuture const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) - pP, pV := helper.MakeRandomProposalPayload(t, r-1) require.NotZero(t, dynamicFilterCredentialArrivalHistory) - for i := 0; i < dynamicFilterCredentialArrivalHistory; i++ { + for i := 0; i < dynamicFilterCredentialArrivalHistory+int(credentialRoundLag); i++ { // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - vVote := helper.MakeVerifiedVote(t, 0, r+round(i)-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - - inMsg := compoundMsg.AttachReceivedAt(time.Second, r+round(i)-1) // call AttachReceivedAt like demux would - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + pP, pV := helper.MakeRandomProposalPayload(t, r+round(i)-1) + vVote := sendCompoundMessage(t, helper, pWhite, pM, r+round(i)-1, r+round(i)-1, p, pP, pV, time.Second, nil, version) // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r + round(i) - 1, Period: p, Step: propose, TaskIndex: 1}) + taskIndex := uint64(i + 1) + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r+round(i)-1, p, taskIndex)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} timestamp := 500 + i - inMsg = inMsg.AttachValidatedAt(time.Duration(timestamp)*time.Millisecond, r+round(i)-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) - moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, proposalMsg, protocol.ConsensusFuture) + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r+round(i)-1, time.Duration(timestamp)*time.Millisecond, nil, taskIndex) + sendPayloadPresent(t, pWhite, pM, r+round(i)-1, pP, time.Duration(timestamp)*time.Millisecond+time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, 2*time.Second+time.Duration(timestamp)*time.Millisecond, version) } // assert lowest vote validateAt time was recorded into payloadArrivals @@ -3507,51 +3654,51 @@ func TestPlayerRetainsReceivedValidatedAtPPForHistoryWindow(t *testing.T) { func TestPlayerRetainsReceivedValidatedAtAVPPOneSample(t *testing.T) { partitiontest.PartitionTest(t) + // create a protocol version where dynamic lambda is enabled + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) pP, pV := helper.MakeRandomProposalPayload(t, r-1) + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) + require.False(t, pWhite.lowestCredentialArrivals.isFull()) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + // send votePresent message (mimicking the first AV message validating) - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - inMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg} - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendVotePresent(t, helper, pWhite, pM, 0, r-credentialRoundLag, p, pV, version) // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) + unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} + verifyEvent := ev(verifyVoteAction(messageEvent{Input: unverifiedVoteMsg}, r-credentialRoundLag, p, 1)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} - inMsg = inMsg.AttachValidatedAt(502*time.Millisecond, r-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r-credentialRoundLag, 502*time.Millisecond, nil, 1) // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - inMsg = compoundMsg.AttachReceivedAt(time.Second, r-1) // call AttachReceivedAt like demux would - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendCompoundMessageForVote(t, vVote, pWhite, pM, r-credentialRoundLag, pP, time.Second, nil, version) - // make sure no second request to verify this vote - verifyEvent = ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) - require.Equal(t, 1, pM.getTrace().CountEvent(verifyEvent), "Player should not verify second vote") + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, time.Second, nil) - assertCorrectReceivedAtSet(t, pWhite, pM, helper, r, p, pP, pV, proposalMsg, protocol.ConsensusFuture, time.Second) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) // assert lowest vote validateAt time was recorded into payloadArrivals - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) - require.False(t, pWhite.lowestCredentialArrivals.isFull()) - require.Equal(t, 502*time.Millisecond, pWhite.lowestCredentialArrivals.history[0]) + assertSingleCredentialArrival(t, pWhite, 502*time.Millisecond) } // test that ReceivedAt and ValidateAt timing information are retained in @@ -3563,95 +3710,143 @@ func TestPlayerRetainsReceivedValidatedAtAVPPOneSample(t *testing.T) { func TestPlayerRetainsEarlyReceivedValidatedAtAVPPOneSample(t *testing.T) { partitiontest.PartitionTest(t) + version := protocol.ConsensusFuture const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) pP, pV := helper.MakeRandomProposalPayload(t, r-1) + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) + require.False(t, pWhite.lowestCredentialArrivals.isFull()) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + + // create a protocol version where dynamic filter is enabled + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() + // send votePresent message (mimicking the first AV message validating) - vVote := helper.MakeVerifiedVote(t, 0, r-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - inMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg} - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendVotePresent(t, helper, pWhite, pM, 0, r-credentialRoundLag, p, pV, version) // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r-credentialRoundLag, p, 1)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") - // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} - inMsg = inMsg.AttachValidatedAt(502*time.Millisecond, r-2) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + // send voteVerified, pretend we're one round too early + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r-credentialRoundLag-1, 502*time.Millisecond, nil, 1) // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - inMsg = compoundMsg.AttachReceivedAt(time.Second, r-2) // call AttachReceivedAt like demux would - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendCompoundMessageForVote(t, vVote, pWhite, pM, r-credentialRoundLag, pP, time.Second, nil, version) - // make sure no second request to verify this vote - verifyEvent = ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r - 1, Period: p, Step: propose, TaskIndex: 1}) - require.Equal(t, 1, pM.getTrace().CountEvent(verifyEvent), "Player should not verify second vote") + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, time.Second, nil) - assertCorrectReceivedAtSet(t, pWhite, pM, helper, r, p, pP, pV, proposalMsg, protocol.ConsensusFuture, time.Duration(1)) + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) // assert lowest vote validateAt time was recorded into payloadArrivals - require.NotZero(t, dynamicFilterCredentialArrivalHistory) - require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) + assertSingleCredentialArrival(t, pWhite, pipelinedMessageTimestamp) +} + +// test that ReceivedAt and ValidateAt timing information are retained in +// proposalStore when the voteVerified event comes in first (as part of the AV +// message before PP), then the payloadPresent (as part of the CompoundMessage +// encoding used by PP messages) and payloadVerified events are processed +// credentialRoundLag after the round they belong to, and that all timings are +// available when the ensureAction is called for the block. +func TestPlayerRetainsLateReceivedValidatedAtAVPPOneSample(t *testing.T) { + partitiontest.PartitionTest(t) + + version := protocol.ConsensusFuture + const r = round(20239) + const p = period(0) + pWhite, pM, helper := setupP(t, r-1, p, soft) + pP, pV := helper.MakeRandomProposalPayload(t, r-1) + + // Move to round r, no credentials arrived. + // send voteVerified message + sendVoteVerified(t, helper, pWhite, pM, 0, r-1, r-1, p, pV, 501*time.Millisecond, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r-1, pP, time.Second, nil) + + moveToRound(t, pWhite, pM, helper, r, p, pP, pV, 2*time.Second, version) + assertPayloadTimings(t, pWhite, pM, r-1, pV, time.Second, 2*time.Second) require.False(t, pWhite.lowestCredentialArrivals.isFull()) - require.Equal(t, time.Duration(1), pWhite.lowestCredentialArrivals.history[0]) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 0) + + // create a protocol version where dynamic filter is enabled + version, _, configCleanup := createDynamicFilterConfig() + defer configCleanup() + + // send votePresent message (mimicking the first AV message validating) + pP, pV = helper.MakeRandomProposalPayload(t, r-credentialRoundLag) + vVote := sendVotePresent(t, helper, pWhite, pM, 0, r-credentialRoundLag, p, pV, version) + + // make sure vote verify requests + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r-credentialRoundLag, p, 1)) + require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") + + historicalClocks := map[round]roundStartTimer{ + r - credentialRoundLag: constantRoundStartTimer(900 * time.Millisecond), + } + // send voteVerified, pretend we're credentialRoundLag after the message was sent + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r, 502*time.Millisecond, historicalClocks, 1) + + // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage + sendCompoundMessageForVote(t, vVote, pWhite, pM, r-credentialRoundLag, pP, time.Second, nil, version) + + // move to round r+1, triggering history update + pP, pV = helper.MakeRandomProposalPayload(t, r) + sendVoteVerified(t, helper, pWhite, pM, 0, r, r, p, pV, time.Second, nil) + + // send payloadPresent message + sendPayloadPresent(t, pWhite, pM, r, pP, time.Second, nil) + moveToRound(t, pWhite, pM, helper, r+1, p, pP, pV, 2*time.Second, version) + + // assert lowest vote validateAt time was recorded into lowestCredentialArrivals + assertSingleCredentialArrival(t, pWhite, 900*time.Millisecond) } func TestPlayerRetainsReceivedValidatedAtAVPPHistoryWindow(t *testing.T) { partitiontest.PartitionTest(t) + + version := protocol.ConsensusFuture const r = round(20239) const p = period(0) pWhite, pM, helper := setupP(t, r-1, p, soft) require.NotZero(t, dynamicFilterCredentialArrivalHistory) - for i := 0; i < dynamicFilterCredentialArrivalHistory; i++ { + for i := 0; i < dynamicFilterCredentialArrivalHistory+int(credentialRoundLag); i++ { pP, pV := helper.MakeRandomProposalPayload(t, r+round(i)-1) // send votePresent message (mimicking the first AV message validating) - vVote := helper.MakeVerifiedVote(t, 0, r+round(i)-1, p, propose, *pV) - unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} - inMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg} - err, panicErr := pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + vVote := sendVotePresent(t, helper, pWhite, pM, 0, r+round(i)-1, p, pV, version) // make sure vote verify requests - verifyEvent := ev(cryptoAction{T: verifyVote, M: unverifiedVoteMsg, Round: r + round(i) - 1, Period: p, Step: propose, TaskIndex: 1}) + taskIndex := uint64(i + 1) + verifyEvent := ev(verifyVoteAction(messageEvent{Input: message{UnauthenticatedVote: vVote.u()}}, r+round(i)-1, p, taskIndex)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify vote") // send voteVerified - verifiedVoteMsg := message{Vote: vVote, UnauthenticatedVote: vVote.u()} - inMsg = messageEvent{T: voteVerified, Input: verifiedVoteMsg, TaskIndex: 1} timestamp := 500 + i - inMsg = inMsg.AttachValidatedAt(time.Duration(timestamp)*time.Millisecond, r+round(i)-1) - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendVoteVerifiedForVote(t, vVote, pWhite, pM, r+round(i)-1, time.Duration(timestamp)*time.Millisecond, nil, taskIndex) // create a PP message for an arbitrary proposal/payload similar to setupCompoundMessage - proposalMsg := message{UnauthenticatedProposal: pP.u()} - compoundMsg := messageEvent{T: votePresent, Input: unverifiedVoteMsg, - Tail: &messageEvent{T: payloadPresent, Input: proposalMsg}} - inMsg = compoundMsg.AttachReceivedAt(time.Second, r+round(i)-1) // call AttachReceivedAt like demux would - err, panicErr = pM.transition(inMsg) - require.NoError(t, err) - require.NoError(t, panicErr) + sendCompoundMessageForVote(t, vVote, pWhite, pM, r+round(i)-1, pP, time.Second, nil, version) - moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, proposalMsg, protocol.ConsensusFuture) + moveToRound(t, pWhite, pM, helper, r+round(i), p, pP, pV, 2*time.Second, version) } // assert lowest vote validateAt time was recorded into payloadArrivals @@ -3663,20 +3858,101 @@ func TestPlayerRetainsReceivedValidatedAtAVPPHistoryWindow(t *testing.T) { } } +// Helper function to send voteVerified message +func sendVoteVerified(t *testing.T, helper *voteMakerHelper, pWhite *player, pM ioAutomata, addrIndex int, + curRound round, voteRound round, votePeriod period, pV *proposalValue, validatedAt time.Duration, + historicalClocks map[round]roundStartTimer) { + vVote := helper.MakeVerifiedVote(t, addrIndex, voteRound, votePeriod, propose, *pV) + sendVoteVerifiedForVote(t, vVote, pWhite, pM, curRound, validatedAt, historicalClocks, 0) +} + +func sendVoteVerifiedForVote(t *testing.T, vVote vote, pWhite *player, pM ioAutomata, + curRound round, validatedAt time.Duration, historicalClocks map[round]roundStartTimer, taskIndex uint64) { + inMsg := messageEvent{T: voteVerified, Input: message{Vote: vVote, UnauthenticatedVote: vVote.u()}, TaskIndex: taskIndex} + inMsg = inMsg.AttachValidatedAt(testClockForRound(t, pWhite, validatedAt, curRound, historicalClocks)) + err, panicErr := pM.transition(inMsg) + require.NoError(t, err) + require.NoError(t, panicErr) +} + +func sendVotePresent(t *testing.T, helper *voteMakerHelper, pWhite *player, pM ioAutomata, addrIndex int, + voteRound round, votePeriod period, pV *proposalValue, version protocol.ConsensusVersion) vote { + vVote := helper.MakeVerifiedVote(t, addrIndex, voteRound, votePeriod, propose, *pV) + inMsg := messageEvent{T: votePresent, Input: message{UnauthenticatedVote: vVote.u()}, Proto: ConsensusVersionView{Version: version}} + err, panicErr := pM.transition(inMsg) + require.NoError(t, err) + require.NoError(t, panicErr) + return vVote +} + +// Helper function to send payloadPresent message +func sendPayloadPresent(t *testing.T, pWhite *player, pM ioAutomata, curRound round, pP *proposal, receivedAt time.Duration, historicalClocks map[round]roundStartTimer) { + m := message{UnauthenticatedProposal: pP.u()} + inMsg := messageEvent{T: payloadPresent, Input: m} + inMsg = inMsg.AttachReceivedAt(testClockForRound(t, pWhite, receivedAt, curRound, historicalClocks)) + err, panicErr := pM.transition(inMsg) + require.NoError(t, err) + require.NoError(t, panicErr) +} + +// Helper function to send a compound PP message (votePresent + payloadPresent) +func sendCompoundMessage(t *testing.T, helper *voteMakerHelper, pWhite *player, pM ioAutomata, curRound round, voteRound round, votePeriod period, pP *proposal, pV *proposalValue, receivedAt time.Duration, historicalClocks map[round]roundStartTimer, version protocol.ConsensusVersion) vote { + vVote := helper.MakeVerifiedVote(t, 0, voteRound, votePeriod, propose, *pV) + sendCompoundMessageForVote(t, vVote, pWhite, pM, curRound, pP, receivedAt, historicalClocks, version) + return vVote +} + +func sendCompoundMessageForVote(t *testing.T, vVote vote, pWhite *player, pM ioAutomata, curRound round, pP *proposal, receivedAt time.Duration, historicalClocks map[round]roundStartTimer, version protocol.ConsensusVersion) { + unverifiedVoteMsg := message{UnauthenticatedVote: vVote.u()} + proposalMsg := message{UnauthenticatedProposal: pP.u()} + compoundMsg := messageEvent{ + T: votePresent, + Input: unverifiedVoteMsg, + Tail: &messageEvent{ + T: payloadPresent, + Input: proposalMsg, + Proto: ConsensusVersionView{Version: version}, + }, + Proto: ConsensusVersionView{Version: version}, + } + inMsg := compoundMsg.AttachReceivedAt(testClockForRound(t, pWhite, receivedAt, curRound, historicalClocks)) // call AttachReceivedAt like demux would + err, panicErr := pM.transition(inMsg) + require.NoError(t, err) + require.NoError(t, panicErr) +} + +// Helper function to assert lowest vote validateAt time was recorded into lowestCredentialArrivals +func assertSingleCredentialArrival(t *testing.T, pWhite *player, expectedTime time.Duration) { + require.NotZero(t, dynamicFilterCredentialArrivalHistory) + require.Equal(t, pWhite.lowestCredentialArrivals.writePtr, 1) + require.False(t, pWhite.lowestCredentialArrivals.isFull()) + require.Equal(t, expectedTime, pWhite.lowestCredentialArrivals.history[0]) +} + +// Helper function to submit payloadVerified message and a bundleVerified for a cert threshold +// to move into the next round. +// Assumes payloadPresent has alread been sent and the verifyPayload action has already requested. func moveToRound(t *testing.T, pWhite *player, pM ioAutomata, helper *voteMakerHelper, - r round, p period, pP *proposal, pV *proposalValue, m message, ver protocol.ConsensusVersion) { + r round, p period, pP *proposal, pV *proposalValue, validatedAt time.Duration, ver protocol.ConsensusVersion) { // make sure payload verify request - verifyEvent := ev(cryptoAction{T: verifyPayload, M: m, Round: r - 1, Period: p, Step: propose, TaskIndex: 0}) + verifyEvent := ev(verifyPayloadAction(messageEvent{Input: message{UnauthenticatedProposal: pP.u()}}, r-1, p, false)) require.Truef(t, pM.getTrace().Contains(verifyEvent), "Player should verify payload") // payloadVerified inMsg := messageEvent{T: payloadVerified, Input: message{Proposal: *pP}, Proto: ConsensusVersionView{Version: ver}} - inMsg = inMsg.AttachValidatedAt(2*time.Second, r-1) // call AttachValidatedAt like demux would + inMsg = inMsg.AttachValidatedAt(testClockForRound(t, pWhite, validatedAt, r-1, nil)) // call AttachValidatedAt like demux would err, panicErr := pM.transition(inMsg) require.NoError(t, err) require.NoError(t, panicErr) + // // now, trigger soft vote timeout + // err, panicErr = pM.transition(makeTimeoutEvent()) + // require.NoError(t, err) + // require.NoError(t, panicErr) + // softVoteEvent := ev(pseudonodeAction{T: attest, Round: r - 1, Period: p, Step: soft, Proposal: *pV}) + // require.Truef(t, pM.getTrace().Contains(softVoteEvent), "Player should issue soft vote") + // gen cert to move into the next round votes := make([]vote, int(cert.threshold(config.Consensus[ver]))) for i := 0; i < int(cert.threshold(config.Consensus[ver])); i++ { @@ -3708,10 +3984,8 @@ func moveToRound(t *testing.T, pWhite *player, pM ioAutomata, helper *voteMakerH require.Truef(t, pM.getTrace().Contains(commitEvent), "Player should try to ensure block/digest on ledger") } -func assertCorrectReceivedAtSet(t *testing.T, pWhite *player, pM ioAutomata, helper *voteMakerHelper, - r round, p period, pP *proposal, pV *proposalValue, m message, ver protocol.ConsensusVersion, validationTimestamp time.Duration) { - - moveToRound(t, pWhite, pM, helper, r, p, pP, pV, m, ver) +// inspect the ensureAction for round R and assert the correct payload timings +func assertPayloadTimings(t *testing.T, pWhite *player, pM ioAutomata, r round, pV *proposalValue, receivedAt time.Duration, validatedAt time.Duration) { // find and unwrap ensureAction from trace var ea ensureAction @@ -3721,13 +3995,19 @@ func assertCorrectReceivedAtSet(t *testing.T, pWhite *player, pM ioAutomata, hel if wae.action.t() == ensure { require.False(t, foundEA) ea = wae.action.(ensureAction) - foundEA = true + // looking just for ensureAction on this round + if r == ea.Payload.Round() { + foundEA = true + break + } } } } require.True(t, foundEA) - require.Equal(t, 2*time.Second, ea.Payload.validatedAt) - require.Equal(t, validationTimestamp, ea.Payload.receivedAt) + require.Equal(t, *pV, ea.Certificate.Proposal) + require.Equal(t, r, ea.Payload.Round()) + require.Equal(t, validatedAt, ea.Payload.validatedAt) + require.Equal(t, receivedAt, ea.Payload.receivedAt) } // todo: test pipelined rounds, and round interruption diff --git a/agreement/proposalManager.go b/agreement/proposalManager.go index affa17f898..71bea3df53 100644 --- a/agreement/proposalManager.go +++ b/agreement/proposalManager.go @@ -132,9 +132,15 @@ func (m *proposalManager) handleMessageEvent(r routerHandle, p player, e filtera switch e.t() { case votePresent: - err := m.filterProposalVote(p, r, e.Input.UnauthenticatedVote, e.FreshnessData) + verifyForCredHistory, err := m.filterProposalVote(p, r, e.Input.UnauthenticatedVote, e.FreshnessData) if err != nil { - return filteredEvent{T: voteFiltered, Err: makeSerErr(err)} + credTrackingNote := NoLateCredentialTrackingImpact + if verifyForCredHistory { + // mark filtered votes that may still update the best credential arrival time + // the freshness check failed, but we still want to verify this proposal-vote for credential tracking + credTrackingNote = UnverifiedLateCredentialForTracking + } + return filteredEvent{T: voteFiltered, Err: makeSerErr(err), LateCredentialTrackingNote: credTrackingNote} } return emptyEvent{} @@ -150,9 +156,14 @@ func (m *proposalManager) handleMessageEvent(r routerHandle, p player, e filtera v := e.Input.Vote err := proposalFresh(e.FreshnessData, v.u()) + keepForLateCredentialTracking := false if err != nil { - err := makeSerErrf("proposalManager: ignoring proposal-vote due to age: %v", err) - return filteredEvent{T: voteFiltered, Err: err} + // if we should keep processing this credential message only to record its timestamp, we continue + keepForLateCredentialTracking = proposalUsefulForCredentialHistory(e.FreshnessData.PlayerRound, v.u()) + if !keepForLateCredentialTracking { + err := makeSerErrf("proposalManager: ignoring proposal-vote due to age: %v", err) + return filteredEvent{T: voteFiltered, Err: err} + } } if v.R.Round == p.Round { @@ -161,7 +172,26 @@ func (m *proposalManager) handleMessageEvent(r routerHandle, p player, e filtera r.t.timeRPlus1().RecVoteReceived(v) } - return r.dispatch(p, e.messageEvent, proposalMachineRound, v.R.Round, v.R.Period, 0) + e := r.dispatch(p, e.messageEvent, proposalMachineRound, v.R.Round, v.R.Period, 0) + + if keepForLateCredentialTracking { + // we only continued processing this vote to see whether it updates the credential arrival time + err := makeSerErrf("proposalManager: ignoring proposal-vote due to age: %v", err) + if e.t() == voteFiltered { + credNote := e.(filteredEvent).LateCredentialTrackingNote + if credNote != VerifiedBetterLateCredentialForTracking && credNote != NoLateCredentialTrackingImpact { + // It should be impossible to hit this condition + r.t.log.Debugf("vote verified may only be tagged with VerifiedBetterLateCredential/NoLateCredentialTrackingImpact but saw %v", credNote) + credNote = NoLateCredentialTrackingImpact + } + // indicate whether it updated + return filteredEvent{T: voteFiltered, Err: err, LateCredentialTrackingNote: credNote} + } + // the proposalMachineRound didn't filter the vote, so it must have had a better credential, + // indicate that it did cause updating its state + return filteredEvent{T: voteFiltered, Err: err, LateCredentialTrackingNote: VerifiedBetterLateCredentialForTracking} + } + return e case payloadPresent: propRound := e.Input.UnauthenticatedProposal.Round() @@ -215,19 +245,48 @@ func (m *proposalManager) handleMessageEvent(r routerHandle, p player, e filtera } } -// filterVote filters a vote, checking if it is both fresh and not a duplicate. -func (m *proposalManager) filterProposalVote(p player, r routerHandle, uv unauthenticatedVote, freshData freshnessData) error { +// filterVote filters a vote, checking if it is both fresh and not a duplicate, returning +// an errProposalManagerPVNotFresh or errProposalManagerPVDuplicate if so, else nil. +// It also returns a bool indicating whether this proposal-vote should still be verified for tracking credential history. +func (m *proposalManager) filterProposalVote(p player, r routerHandle, uv unauthenticatedVote, freshData freshnessData) (bool, error) { + // check if the vote is within the credential history window + credHistory := proposalUsefulForCredentialHistory(freshData.PlayerRound, uv) + + // checkDup asks proposalTracker if the vote is a duplicate, returning true if so + checkDup := func() bool { + qe := voteFilterRequestEvent{RawVote: uv.R} + sawVote := r.dispatch(p, qe, proposalMachinePeriod, uv.R.Round, uv.R.Period, 0) + return sawVote.t() == voteFiltered + } + + // check the vote against the current player's freshness rules err := proposalFresh(freshData, uv) if err != nil { - return fmt.Errorf("proposalManager: filtered proposal-vote due to age: %v", err) + // not fresh, but possibly useful for credential history: ensure not a duplicate + if credHistory && checkDup() { + credHistory = false + } + return credHistory, fmt.Errorf("proposalManager: filtered proposal-vote due to age: %v", err) } - qe := voteFilterRequestEvent{RawVote: uv.R} - sawVote := r.dispatch(p, qe, proposalMachinePeriod, uv.R.Round, uv.R.Period, 0) - if sawVote.t() == voteFiltered { - return fmt.Errorf("proposalManager: filtered proposal-vote: sender %v had already sent a vote in round %d period %d", uv.R.Sender, uv.R.Round, uv.R.Period) + if checkDup() { + return credHistory, fmt.Errorf("proposalManager: filtered proposal-vote: sender %v had already sent a vote in round %d period %d", uv.R.Sender, uv.R.Round, uv.R.Period) + } - return nil + return credHistory, nil +} + +func proposalUsefulForCredentialHistory(curRound round, vote unauthenticatedVote) bool { + if vote.R.Round < curRound && curRound <= vote.R.Round+credentialRoundLag && + vote.R.Period == 0 && + vote.R.Step == propose { + if dynamicFilterCredentialArrivalHistory > 0 { + // continue processing old period 0 votes so we could track their + // arrival times and inform setting the filter timeout dynamically. + return true + } + } + return false } // voteFresh determines whether a proposal satisfies freshness rules. diff --git a/agreement/proposalManager_test.go b/agreement/proposalManager_test.go index e76de0be5e..48481bd730 100644 --- a/agreement/proposalManager_test.go +++ b/agreement/proposalManager_test.go @@ -19,6 +19,7 @@ package agreement import ( "testing" + "github.com/algorand/go-algorand/crypto" "github.com/algorand/go-algorand/test/partitiontest" "github.com/stretchr/testify/require" ) @@ -209,6 +210,69 @@ func TestProposalManagerRejectsUnknownEvent(t *testing.T) { require.Errorf(t, panicErr, "proposalManager must reject bundleVerified event") } +func TestLateVotes(t *testing.T) { + partitiontest.PartitionTest(t) + + const r = 100 + const p = 3 + const s = soft + currentPlayerState := freshnessData{ + PlayerRound: r, + PlayerPeriod: p, + PlayerStep: s, + PlayerLastConcluding: 0, + } + b := testCaseBuilder{} + _, pM, helper := setupManager(t, r) + + // vote from credentialRoundLag rounds ago and period 0 should continue + // processing only for the purpose of tracking credentials. + pV := helper.MakeRandomProposalValue() + v1 := helper.MakeVerifiedVote(t, 0, r-credentialRoundLag, 0, 0, *pV) + inMsg1 := filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: voteVerified, + Input: message{ + UnauthenticatedVote: v1.u(), + Vote: v1, + }, + }, + } + + v2 := helper.MakeVerifiedVote(t, 0, r-credentialRoundLag, 0, 0, *pV) + inMsg2 := filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: voteVerified, + Input: message{ + UnauthenticatedVote: v2.u(), + Vote: v2, + }, + }, + } + + // Order the messages such that the first message's credential is lower + // (i.e., preferred). The first vote should be the best credential we get, + // so the second credential should be filtered without impacting the + // credential tracking mechanism. + v1.Cred.VrfOut = crypto.Digest{1} + v2.Cred.VrfOut = crypto.Digest{2} + if v1.Cred.Less(v2.Cred) { + require.False(t, v2.Cred.Less(v1.Cred)) + b.AddInOutPair(inMsg1, filteredEvent{T: voteFiltered, LateCredentialTrackingNote: VerifiedBetterLateCredentialForTracking}) + b.AddInOutPair(inMsg2, filteredEvent{T: voteFiltered, LateCredentialTrackingNote: NoLateCredentialTrackingImpact}) + } else { + require.True(t, v2.Cred.Less(v1.Cred)) + b.AddInOutPair(inMsg2, filteredEvent{T: voteFiltered, LateCredentialTrackingNote: VerifiedBetterLateCredentialForTracking}) + b.AddInOutPair(inMsg1, filteredEvent{T: voteFiltered, LateCredentialTrackingNote: NoLateCredentialTrackingImpact}) + } + + res, err := b.Build().Validate(pM) + require.NoError(t, err) + require.NoErrorf(t, res, "VerifiedVote resulted in unexpected output") +} + func TestProposalFreshAdjacentPeriods(t *testing.T) { partitiontest.PartitionTest(t) @@ -323,6 +387,63 @@ func TestProposalFreshAdjacentPeriods(t *testing.T) { } b.AddInOutPair(inMsg, filteredEvent{T: voteFiltered}) + // vote from credentialRoundLag rounds ago and period 0 should continue + // processing only for the purpose of tracking credentials. + pV = helper.MakeRandomProposalValue() + uv = helper.MakeUnauthenticatedVote(t, 0, r-credentialRoundLag, 0, 0, *pV) + inMsg = filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: votePresent, + Input: message{ + UnauthenticatedVote: uv, + }, + }, + } + b.AddInOutPair(inMsg, filteredEvent{T: voteFiltered, LateCredentialTrackingNote: UnverifiedLateCredentialForTracking}) + + // vote from credentialRoundLag ago and period > 0 should be filtered + pV = helper.MakeRandomProposalValue() + uv = helper.MakeUnauthenticatedVote(t, 0, r-credentialRoundLag, 1, 0, *pV) + inMsg = filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: votePresent, + Input: message{ + UnauthenticatedVote: uv, + }, + }, + } + b.AddInOutPair(inMsg, filteredEvent{T: voteFiltered}) + + // vote older than credentialRoundLag should be rejected even if period 0 + pV = helper.MakeRandomProposalValue() + uv = helper.MakeUnauthenticatedVote(t, 0, r-credentialRoundLag-1, 0, 0, *pV) + inMsg = filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: votePresent, + Input: message{ + UnauthenticatedVote: uv, + }, + }, + } + b.AddInOutPair(inMsg, filteredEvent{T: voteFiltered}) + + // vote older than credentialRoundLag should be rejected on any period + pV = helper.MakeRandomProposalValue() + uv = helper.MakeUnauthenticatedVote(t, 0, r-credentialRoundLag-1, 1, 0, *pV) + inMsg = filterableMessageEvent{ + FreshnessData: currentPlayerState, + messageEvent: messageEvent{ + T: votePresent, + Input: message{ + UnauthenticatedVote: uv, + }, + }, + } + b.AddInOutPair(inMsg, filteredEvent{T: voteFiltered}) + res, err := b.Build().Validate(pM) require.NoError(t, err) require.NoErrorf(t, res, "VotePresent accidentally filtered") diff --git a/agreement/proposalTracker.go b/agreement/proposalTracker.go index 603a8fd40b..de89f8e3e9 100644 --- a/agreement/proposalTracker.go +++ b/agreement/proposalTracker.go @@ -33,22 +33,46 @@ type proposalSeeker struct { // Frozen is set once freeze is called. When Frozen is set, Lowest and // Filled will no longer be modified. Frozen bool + + // lowestIncludingLate is used to track the lowest credential observed, even + // after the Lowest value has been frozen. + lowestIncludingLate vote + hasLowestIncludingLate bool } // accept compares a given vote with the current lowest-credentialled vote and -// sets it if freeze has not been called. -func (s proposalSeeker) accept(v vote) (proposalSeeker, error) { +// sets it if freeze has not been called. Returns: +// - updated proposalSeeker state, +// - a LateCredentialTrackingEffect describing the usefulness of proposal-vote's +// credential for late credential tracking (for choosing dynamic filter timeout), +// - and an error if the proposal was not better than the lowest seen, or the +// seeker was already frozen. +func (s proposalSeeker) accept(v vote) (proposalSeeker, LateCredentialTrackingEffect, error) { if s.Frozen { - return s, errProposalSeekerFrozen{} + effect := NoLateCredentialTrackingImpact + // continue tracking and forwarding the lowest proposal even when frozen + if !s.hasLowestIncludingLate || v.Cred.Less(s.lowestIncludingLate.Cred) { + s.lowestIncludingLate = v + s.hasLowestIncludingLate = true + effect = VerifiedBetterLateCredentialForTracking + } + return s, effect, errProposalSeekerFrozen{} } if s.Filled && !v.Cred.Less(s.Lowest.Cred) { - return s, errProposalSeekerNotLess{NewSender: v.R.Sender, LowestSender: s.Lowest.R.Sender} + return s, NoLateCredentialTrackingImpact, errProposalSeekerNotLess{NewSender: v.R.Sender, LowestSender: s.Lowest.R.Sender} } s.Lowest = v s.Filled = true - return s, nil + s.lowestIncludingLate = v + s.hasLowestIncludingLate = true + return s, VerifiedBetterLateCredentialForTracking, nil +} + +func (s *proposalSeeker) copyLateCredentialTrackingState(s2 proposalSeeker) { + s.hasLowestIncludingLate = s2.hasLowestIncludingLate + s.lowestIncludingLate = s2.lowestIncludingLate } // freeze freezes the state of the proposalSeeker so that future calls no longer @@ -120,7 +144,6 @@ func (t *proposalTracker) underlying() listener { // proposalTracker in period p. // // - readLowestVote returns the vote with the lowest credential that was received so far. - func (t *proposalTracker) handle(r routerHandle, p player, e event) event { switch e.t() { case voteFilterRequest: @@ -144,17 +167,18 @@ func (t *proposalTracker) handle(r routerHandle, p player, e event) event { } t.Duplicate[v.R.Sender] = true + newFreezer, effect, err := t.Freezer.accept(v) + t.Freezer.copyLateCredentialTrackingState(newFreezer) if t.Staging != bottom { - err := errProposalTrackerStaged{} - return filteredEvent{T: voteFiltered, Err: makeSerErr(err)} + err = errProposalTrackerStaged{} + return filteredEvent{T: voteFiltered, LateCredentialTrackingNote: effect, Err: makeSerErr(err)} } - var err error - t.Freezer, err = t.Freezer.accept(v) if err != nil { err := errProposalTrackerPS{Sub: err} - return filteredEvent{T: voteFiltered, Err: makeSerErr(err)} + return filteredEvent{T: voteFiltered, LateCredentialTrackingNote: effect, Err: makeSerErr(err)} } + t.Freezer = newFreezer return proposalAcceptedEvent{ Round: v.R.Round, @@ -172,6 +196,8 @@ func (t *proposalTracker) handle(r routerHandle, p player, e event) event { e := e.(readLowestEvent) e.Vote = t.Freezer.Lowest e.Filled = t.Freezer.Filled + e.LowestIncludingLate = t.Freezer.lowestIncludingLate + e.HasLowestIncludingLate = t.Freezer.hasLowestIncludingLate return e case softThreshold, certThreshold: diff --git a/agreement/proposalTracker_test.go b/agreement/proposalTracker_test.go index 641dee70e7..164e9db40b 100644 --- a/agreement/proposalTracker_test.go +++ b/agreement/proposalTracker_test.go @@ -63,36 +63,57 @@ func TestProposalTrackerProposalSeeker(t *testing.T) { var err error assert.False(t, s.Frozen) assert.False(t, s.Filled) + assert.False(t, s.hasLowestIncludingLate) // issue events in the following order: 2, 3, 1, (freeze), 0 - s, err = s.accept(votes[2]) + var effect LateCredentialTrackingEffect + s, effect, err = s.accept(votes[2]) assert.NoError(t, err) + assert.Equal(t, effect, VerifiedBetterLateCredentialForTracking) assert.False(t, s.Frozen) assert.True(t, s.Filled) assert.True(t, s.Lowest.equals(votes[2])) + assert.True(t, s.hasLowestIncludingLate) + assert.Equal(t, s.Lowest, s.lowestIncludingLate) - s, err = s.accept(votes[3]) + s, effect, err = s.accept(votes[3]) assert.Error(t, err) + assert.Equal(t, effect, NoLateCredentialTrackingImpact) assert.False(t, s.Frozen) assert.True(t, s.Filled) assert.True(t, s.Lowest.equals(votes[2])) + assert.True(t, s.hasLowestIncludingLate) + assert.Equal(t, s.Lowest, s.lowestIncludingLate) - s, err = s.accept(votes[1]) + s, effect, err = s.accept(votes[1]) assert.NoError(t, err) + assert.Equal(t, effect, VerifiedBetterLateCredentialForTracking) assert.False(t, s.Frozen) assert.True(t, s.Filled) assert.True(t, s.Lowest.equals(votes[1])) + assert.True(t, s.hasLowestIncludingLate) + assert.Equal(t, s.Lowest, s.lowestIncludingLate) + lowestBeforeFreeze := s.Lowest s = s.freeze() assert.True(t, s.Frozen) assert.True(t, s.Filled) assert.True(t, s.Lowest.equals(votes[1])) + assert.True(t, s.hasLowestIncludingLate) + assert.Equal(t, s.Lowest, s.lowestIncludingLate) - s, err = s.accept(votes[0]) + s, effect, err = s.accept(votes[0]) assert.Error(t, err) + assert.Equal(t, effect, VerifiedBetterLateCredentialForTracking) + assert.Equal(t, s.Lowest, lowestBeforeFreeze) assert.True(t, s.Frozen) assert.True(t, s.Filled) assert.True(t, s.Lowest.equals(votes[1])) + assert.True(t, s.hasLowestIncludingLate) + assert.True(t, s.lowestIncludingLate.equals(votes[0])) + assert.NotEqual(t, s.Lowest, s.lowestIncludingLate) + assert.True(t, !s.Lowest.Cred.Less(s.lowestIncludingLate.Cred)) + assert.True(t, s.lowestIncludingLate.Cred.Less(s.Lowest.Cred)) } // mimics a proposalTracker, producing a trace of events diff --git a/agreement/router.go b/agreement/router.go index 32523ee8e9..6ab144470f 100644 --- a/agreement/router.go +++ b/agreement/router.go @@ -16,6 +16,10 @@ package agreement +import ( + "github.com/algorand/go-algorand/config" +) + // A stateMachineTag uniquely identifies the type of a state machine. // // Rounds, periods, and steps may be used to further identify different state machine instances of the same type. @@ -48,6 +52,19 @@ type routerHandle struct { src stateMachineTag } +// credentialRoundLag the maximal number of rounds that could pass before a credential from +// an honest party for an old round may arrive. It uses the +// dynamicFilterTimeoutLowerBound parameter as the minimal round time. +var credentialRoundLag round + +func init() { + // credential arrival time should be at most 2*config.Protocol.SmallLambda after it was sent + credentialRoundLag = round(2 * config.Protocol.SmallLambda / dynamicFilterTimeoutLowerBound) + if credentialRoundLag*round(dynamicFilterTimeoutLowerBound) < round(2*config.Protocol.SmallLambda) { + credentialRoundLag++ + } +} + // dispatch sends an event to the given state machine listener with the given stateMachineTag. // // If there are many state machines of this type (for instance, there is one voteMachineStep for each step) @@ -136,7 +153,11 @@ func (router *rootRouter) update(state player, r round, gc bool) { if gc { children := make(map[round]*roundRouter) for r, c := range router.Children { - if r >= state.Round { + // We may still receive credential messages from old rounds. Keep + // old round routers around, for as long as those credentials may + // arrive to keep track of them. + rr := r + credentialRoundLag + if rr >= state.Round { children[r] = c } } @@ -201,7 +222,6 @@ func (router *roundRouter) update(state player, p period, gc bool) { // TODO may want regression test for correct pipelining behavior children[p] = c } - } router.Children = children } diff --git a/agreement/service.go b/agreement/service.go index b0668ac2a5..433a17d5c6 100644 --- a/agreement/service.go +++ b/agreement/service.go @@ -19,6 +19,7 @@ package agreement //go:generate dbgen -i agree.sql -p agreement -n agree -o agreeInstall.go -h ../scripts/LICENSE_HEADER import ( "context" + "time" "github.com/algorand/go-algorand/config" "github.com/algorand/go-algorand/logging" @@ -56,6 +57,9 @@ type Service struct { persistRouter rootRouter persistStatus player persistActions []action + + // Retain old rounds' period 0 start times. + historicalClocks map[round]roundStartTimer } // Parameters holds the parameters necessary to run the agreement protocol. @@ -84,6 +88,13 @@ type externalDemuxSignals struct { CurrentRound round } +// an interface allowing for measuring the duration since a clock from a previous round, +// used for measuring the arrival time of a late proposal-vote, for the dynamic filter +// timeout feature +type roundStartTimer interface { + Since() time.Duration +} + // MakeService creates a new Agreement Service instance given a set of Parameters. // // Call Start to start execution and Shutdown to finish execution. @@ -110,6 +121,8 @@ func MakeService(p Parameters) (*Service, error) { s.persistenceLoop = makeAsyncPersistenceLoop(s.log, s.Accessor, s.Ledger) + s.historicalClocks = make(map[round]roundStartTimer) + return s, nil } diff --git a/agreement/service_test.go b/agreement/service_test.go index b2ecd42f31..f6ff27fd2b 100644 --- a/agreement/service_test.go +++ b/agreement/service_test.go @@ -935,6 +935,25 @@ func simulateAgreementWithLedgerFactory(t *testing.T, numNodes int, numRounds in services[i].Shutdown() } + firstHistoricalClocksRound := startRound + if basics.Round(numRounds) > credentialRoundLag { + firstHistoricalClocksRound = startRound + basics.Round(numRounds) - credentialRoundLag + } + + // check that historical clocks map didn't get too large + for i := 0; i < numNodes; i++ { + require.LessOrEqual(t, len(services[i].historicalClocks), int(credentialRoundLag)+1, "too many historical clocks kept") + for round := firstHistoricalClocksRound + 1; round <= startRound+basics.Round(numRounds); round++ { + _, has := services[i].historicalClocks[round] + require.True(t, has) + } + } + if numRounds >= int(credentialRoundLag) { + for i := 0; i < numNodes; i++ { + require.Equal(t, len(services[i].historicalClocks), int(credentialRoundLag)+1, "not enough historical clocks kept") + } + } + sanityCheck(startRound, round(numRounds), ledgers) if len(clocks) == 0 { @@ -1021,6 +1040,16 @@ func TestAgreementSynchronous5_50(t *testing.T) { simulateAgreement(t, 5, 50, disabled) } +func TestAgreementHistoricalClocksCleanup(t *testing.T) { + partitiontest.PartitionTest(t) + + if testing.Short() { + t.Skip("Skipping agreement integration test") + } + + simulateAgreement(t, 5, int(credentialRoundLag)+10, disabled) +} + func createDynamicFilterConfig() (version protocol.ConsensusVersion, consensusVersion func(r basics.Round) (protocol.ConsensusVersion, error), configCleanup func()) { version = protocol.ConsensusVersion("test-protocol-filtertimeout") protoParams := config.Consensus[protocol.ConsensusCurrentVersion] @@ -1052,18 +1081,19 @@ func TestAgreementSynchronousFuture5_DynamicFilterRounds(t *testing.T) { return } - rounds := dynamicFilterCredentialArrivalHistory + 20 + baseHistoryRounds := dynamicFilterCredentialArrivalHistory + int(credentialRoundLag) + rounds := baseHistoryRounds + 20 filterTimeouts := simulateAgreementWithConsensusVersion(t, 5, rounds, disabled, consensusVersion) require.Len(t, filterTimeouts, rounds-1) - for i := 1; i < dynamicFilterCredentialArrivalHistory-1; i++ { + for i := 1; i < baseHistoryRounds-1; i++ { require.Equal(t, filterTimeouts[i-1], filterTimeouts[i]) } // dynamic filter timeout kicks in when history window is full - require.Less(t, filterTimeouts[dynamicFilterCredentialArrivalHistory-1], filterTimeouts[dynamicFilterCredentialArrivalHistory-2]) + require.Less(t, filterTimeouts[baseHistoryRounds-1], filterTimeouts[baseHistoryRounds-2]) - for i := dynamicFilterCredentialArrivalHistory; i < len(filterTimeouts); i++ { + for i := baseHistoryRounds; i < len(filterTimeouts); i++ { require.Equal(t, filterTimeouts[i-1], filterTimeouts[i]) } } @@ -1101,9 +1131,11 @@ func TestDynamicFilterTimeoutResets(t *testing.T) { filterTimeouts := make([][]time.Duration, numNodes, numNodes) + baseHistoryRounds := dynamicFilterCredentialArrivalHistory + int(credentialRoundLag) + // run round with round-specific consensus version first (since fix in #1896) zeroes = runRoundTriggerFilter(clocks, activityMonitor, zeroes) - for j := 1; j < dynamicFilterCredentialArrivalHistory+1; j++ { + for j := 1; j < baseHistoryRounds+2; j++ { for srvIdx, clock := range clocks { delta, err := clock.(*testingClock).when(TimeoutFilter) require.NoError(t, err) @@ -1113,11 +1145,11 @@ func TestDynamicFilterTimeoutResets(t *testing.T) { } for i := range clocks { - require.Len(t, filterTimeouts[i], dynamicFilterCredentialArrivalHistory) - for j := 1; j < dynamicFilterCredentialArrivalHistory-1; j++ { + require.Len(t, filterTimeouts[i], baseHistoryRounds+1) + for j := 1; j < baseHistoryRounds-2; j++ { require.Equal(t, filterTimeouts[i][j-1], filterTimeouts[i][j]) } - require.Less(t, filterTimeouts[i][dynamicFilterCredentialArrivalHistory-1], filterTimeouts[i][dynamicFilterCredentialArrivalHistory-2]) + require.Less(t, filterTimeouts[i][baseHistoryRounds-1], filterTimeouts[i][baseHistoryRounds-2]) } // force fast partition recovery into bottom @@ -1149,7 +1181,7 @@ func TestDynamicFilterTimeoutResets(t *testing.T) { // run round with round-specific consensus version first (since fix in #1896) zeroes = runRoundTriggerFilter(clocks, activityMonitor, zeroes) - for j := 1; j < dynamicFilterCredentialArrivalHistory+1; j++ { + for j := 1; j < baseHistoryRounds+1; j++ { for srvIdx, clock := range clocks { delta, err := clock.(*testingClock).when(TimeoutFilter) require.NoError(t, err) @@ -1159,19 +1191,19 @@ func TestDynamicFilterTimeoutResets(t *testing.T) { } for i := range clocks { - require.Len(t, filterTimeoutsPostRecovery[i], dynamicFilterCredentialArrivalHistory) + require.Len(t, filterTimeoutsPostRecovery[i], baseHistoryRounds) // check that history was discarded, so filter time increased back to its original default - require.Less(t, filterTimeouts[i][dynamicFilterCredentialArrivalHistory-1], filterTimeoutsPostRecovery[i][0]) - require.Equal(t, filterTimeouts[i][dynamicFilterCredentialArrivalHistory-2], filterTimeoutsPostRecovery[i][0]) + require.Less(t, filterTimeouts[i][baseHistoryRounds], filterTimeoutsPostRecovery[i][0]) + require.Equal(t, filterTimeouts[i][baseHistoryRounds-2], filterTimeoutsPostRecovery[i][0]) // check that filter timeout was updated to at the end of the history window - for j := 1; j < dynamicFilterCredentialArrivalHistory-1; j++ { + for j := 1; j < dynamicFilterCredentialArrivalHistory-2; j++ { require.Equal(t, filterTimeoutsPostRecovery[i][j-1], filterTimeoutsPostRecovery[i][j]) } require.Less(t, filterTimeoutsPostRecovery[i][dynamicFilterCredentialArrivalHistory-1], filterTimeoutsPostRecovery[i][dynamicFilterCredentialArrivalHistory-2]) } - sanityCheck(startRound, 2*round(dynamicFilterCredentialArrivalHistory+1)+1, ledgers) + sanityCheck(startRound, 2*round(baseHistoryRounds+2), ledgers) } func TestAgreementSynchronousFuture1(t *testing.T) { diff --git a/agreement/state_machine_test.go b/agreement/state_machine_test.go index 69b31a9866..6946a051ec 100644 --- a/agreement/state_machine_test.go +++ b/agreement/state_machine_test.go @@ -20,6 +20,7 @@ import ( "bytes" "fmt" "os" + "strings" "github.com/algorand/go-algorand/logging" ) @@ -111,7 +112,7 @@ func (t *ioTrace) String() string { var buf bytes.Buffer buf.WriteString("{\n") for i := 0; i < len(t.events); i++ { - buf.WriteString(fmt.Sprintf("\t%v |", t.events[i])) + buf.WriteString(fmt.Sprintf("\t%v |", t.events[i].ComparableStr())) if i%2 == 0 { buf.WriteString("\n") } @@ -140,6 +141,12 @@ func (t ioTrace) Contains(e event) bool { }) } +func (t ioTrace) ContainsString(s string) bool { + return t.ContainsFn(func(b event) bool { + return strings.Contains(b.ComparableStr(), s) + }) +} + func (t ioTrace) CountEvent(b event) (count int) { for _, e := range t.events { if e.ComparableStr() == b.ComparableStr() { @@ -550,7 +557,7 @@ func (e wrappedActionEvent) String() string { } func (e wrappedActionEvent) ComparableStr() string { - return e.action.String() + return e.action.ComparableStr() } // ioAutomataConcretePlayer is a concrete wrapper around root router, implementing ioAutomata. diff --git a/tools/x-repo-types/xrt_test.go b/tools/x-repo-types/xrt_test.go index 8de6e83122..4360b432d6 100644 --- a/tools/x-repo-types/xrt_test.go +++ b/tools/x-repo-types/xrt_test.go @@ -78,7 +78,7 @@ func TestCrossRepoTypes(t *testing.T) { xPkg: "github.com/algorand/go-algorand/config", xType: "ConsensusParams", yPkg: "github.com/algorand/go-algorand-sdk/v2/protocol/config", - yBranch: "b5f90353ea841fc2e3af9f77d42205c337c93dd2", + yBranch: "develop", yType: "ConsensusParams", }, {