agreement: Add validatedAt to proposal type and BlockAcceptedEventDetails message

agreement/actions.go

@@ -232,19 +232,21 @@ 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,
 		})
 		s.Ledger.EnsureValidatedBlock(a.Payload.ve, a.Certificate)
 	} else {
 		block := a.Payload.Block
 		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,
 		})
 		s.Ledger.EnsureBlock(block, a.Certificate)
 	}

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

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

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

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
+}

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 {

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()

logging/telemetryspec/event.go

@@ -73,9 +73,10 @@ 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
 }
 
 // TopAccountsEvent event

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
+}

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.
 	//

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)
+}