diff --git a/agreement/actions.go b/agreement/actions.go index a272545c9b..be216da4e6 100644 --- a/agreement/actions.go +++ b/agreement/actions.go @@ -232,9 +232,11 @@ func (a ensureAction) do(ctx context.Context, s *Service) { logEvent.Type = logspec.RoundConcluded s.log.with(logEvent).Infof("committed round %d with pre-validated block %v", a.Certificate.Round, a.Certificate.Proposal) s.log.EventWithDetails(telemetryspec.Agreement, telemetryspec.BlockAcceptedEvent, telemetryspec.BlockAcceptedEventDetails{ - Address: a.Certificate.Proposal.OriginalProposer.String(), - Hash: a.Certificate.Proposal.BlockDigest.String(), - Round: uint64(a.Certificate.Round), + Address: a.Certificate.Proposal.OriginalProposer.String(), + Hash: a.Certificate.Proposal.BlockDigest.String(), + Round: uint64(a.Certificate.Round), + ValidatedAt: a.Payload.validatedAt, + PreValidated: true, }) s.Ledger.EnsureValidatedBlock(a.Payload.ve, a.Certificate) } else { @@ -242,9 +244,11 @@ func (a ensureAction) do(ctx context.Context, s *Service) { logEvent.Type = logspec.RoundConcluded s.log.with(logEvent).Infof("committed round %d with block %v", a.Certificate.Round, a.Certificate.Proposal) s.log.EventWithDetails(telemetryspec.Agreement, telemetryspec.BlockAcceptedEvent, telemetryspec.BlockAcceptedEventDetails{ - Address: a.Certificate.Proposal.OriginalProposer.String(), - Hash: a.Certificate.Proposal.BlockDigest.String(), - Round: uint64(a.Certificate.Round), + Address: a.Certificate.Proposal.OriginalProposer.String(), + Hash: a.Certificate.Proposal.BlockDigest.String(), + Round: uint64(a.Certificate.Round), + ValidatedAt: a.Payload.validatedAt, + PreValidated: false, }) s.Ledger.EnsureBlock(block, a.Certificate) } diff --git a/agreement/agreementtest/simulate.go b/agreement/agreementtest/simulate.go index 086d1f5dc4..febdd3cd4e 100644 --- a/agreement/agreementtest/simulate.go +++ b/agreement/agreementtest/simulate.go @@ -82,6 +82,10 @@ func (i *instant) Zero() timers.Clock { return i } +func (i *instant) Since() time.Duration { + return 0 +} + func (i *instant) runRound(r basics.Round) { <-i.Z1 // wait until Zero is called <-i.timeoutAtCalled diff --git a/agreement/demux.go b/agreement/demux.go index 65a5d06a0d..0191499b4b 100644 --- a/agreement/demux.go +++ b/agreement/demux.go @@ -188,6 +188,10 @@ func (d *demux) next(s *Service, deadline time.Duration, fastDeadline time.Durat } proto, err := d.ledger.ConsensusVersion(ParamsRound(e.ConsensusRound())) e = e.AttachConsensusVersion(ConsensusVersionView{Err: makeSerErr(err), Version: proto}) + + if e.t() == payloadVerified { + e = e.(messageEvent).AttachValidatedAt(s.Clock.Since()) + } }() var pseudonodeEvents <-chan externalEvent diff --git a/agreement/demux_test.go b/agreement/demux_test.go index 0c15d58de0..7d7bbc71bd 100644 --- a/agreement/demux_test.go +++ b/agreement/demux_test.go @@ -455,6 +455,11 @@ func (t *demuxTester) Decode([]byte) (timers.Clock, error) { return t, nil } +// implement timers.Clock +func (t *demuxTester) Since() time.Duration { + return 0 +} + // implement Ledger func (t *demuxTester) NextRound() basics.Round { return 1234 diff --git a/agreement/events.go b/agreement/events.go index 7b631624a1..a75a32774b 100644 --- a/agreement/events.go +++ b/agreement/events.go @@ -18,6 +18,7 @@ package agreement import ( "fmt" + "time" "github.com/algorand/go-algorand/logging" "github.com/algorand/go-algorand/protocol" @@ -932,3 +933,8 @@ func (e checkpointEvent) ConsensusRound() round { func (e checkpointEvent) AttachConsensusVersion(v ConsensusVersionView) externalEvent { return e } + +func (e messageEvent) AttachValidatedAt(d time.Duration) messageEvent { + e.Input.Proposal.validatedAt = d + return e +} diff --git a/agreement/msgp_gen.go b/agreement/msgp_gen.go index 4eb67496e8..8df6c47a99 100644 --- a/agreement/msgp_gen.go +++ b/agreement/msgp_gen.go @@ -1356,7 +1356,7 @@ func (z *proposal) MarshalMsg(b []byte) (o []byte) { o = msgp.Require(b, z.Msgsize()) // omitempty: check for empty values zb0004Len := uint32(28) - var zb0004Mask uint64 /* 34 bits */ + var zb0004Mask uint64 /* 35 bits */ if len((*z).unauthenticatedProposal.Block.BlockHeader.CompactCert) == 0 { zb0004Len-- zb0004Mask |= 0x20 diff --git a/agreement/proposal.go b/agreement/proposal.go index 30eb2ef735..232fa6f5f4 100644 --- a/agreement/proposal.go +++ b/agreement/proposal.go @@ -19,6 +19,7 @@ package agreement import ( "context" "fmt" + "time" "github.com/algorand/go-algorand/crypto" "github.com/algorand/go-algorand/data/basics" @@ -88,6 +89,11 @@ type proposal struct { // to disk, so after a crash, we will fall back to applying the // raw Block to the ledger (and re-computing the state delta). ve ValidatedBlock + + // validatedAt indicates the time at which this proposal was + // validated (and thus was ready to be delivered to the state + // machine), relative to the zero of that round. + validatedAt time.Duration } func makeProposal(ve ValidatedBlock, pf crypto.VrfProof, origPer period, origProp basics.Address) proposal { diff --git a/agreement/service_test.go b/agreement/service_test.go index 5825e17054..ff1d19d87d 100644 --- a/agreement/service_test.go +++ b/agreement/service_test.go @@ -71,6 +71,10 @@ func (c *testingClock) Zero() timers.Clock { return c } +func (c *testingClock) Since() time.Duration { + return 0 +} + func (c *testingClock) TimeoutAt(d time.Duration) <-chan time.Time { c.mu.Lock() defer c.mu.Unlock() diff --git a/logging/telemetryspec/event.go b/logging/telemetryspec/event.go index 0fc1a33811..f721fd7bda 100644 --- a/logging/telemetryspec/event.go +++ b/logging/telemetryspec/event.go @@ -73,9 +73,11 @@ const BlockAcceptedEvent Event = "BlockAccepted" // BlockAcceptedEventDetails contains details for the BlockAcceptedEvent type BlockAcceptedEventDetails struct { - Address string - Hash string - Round uint64 + Address string + Hash string + Round uint64 + ValidatedAt time.Duration + PreValidated bool } // TopAccountsEvent event diff --git a/util/timers/frozen.go b/util/timers/frozen.go index 0ff5434ea6..a9aa6c1b71 100644 --- a/util/timers/frozen.go +++ b/util/timers/frozen.go @@ -55,3 +55,8 @@ func (m *Frozen) Decode([]byte) (Clock, error) { func (m *Frozen) String() string { return "" } + +// Since implements the Clock interface. +func (m *Frozen) Since() time.Duration { + return 0 +} diff --git a/util/timers/interface.go b/util/timers/interface.go index dc3c1957ce..6c8c493e12 100644 --- a/util/timers/interface.go +++ b/util/timers/interface.go @@ -27,6 +27,10 @@ type Clock interface { // at which Zero was called as their reference point. Zero() Clock + // Since returns the time spent between the last time the clock was zeroed out and the current + // wall clock time. + Since() time.Duration + // TimeoutAt returns a channel that fires delta time after Zero was called. // If delta has already passed, it returns a closed channel. // diff --git a/util/timers/monotonic.go b/util/timers/monotonic.go index 9d720ba869..80b1a7de45 100644 --- a/util/timers/monotonic.go +++ b/util/timers/monotonic.go @@ -86,3 +86,8 @@ func (m *Monotonic) Decode(data []byte) (Clock, error) { func (m *Monotonic) String() string { return time.Time(m.zero).String() } + +// Since returns the time that has passed between the time the clock was last zeroed out and now +func (m *Monotonic) Since() time.Duration { + return time.Since(m.zero) +}