From 531fe01dbed7086f48f85a3e9876ce9048292204 Mon Sep 17 00:00:00 2001
From: chris erway <chris.erway@algorand.com>
Date: Tue, 1 Mar 2022 16:43:03 -0500
Subject: [PATCH 1/5] Add validatedAt to proposal type and
 BlockAcceptedEventDetails

---
 agreement/actions.go                | 14 ++++++++------
 agreement/agreementtest/simulate.go |  4 ++++
 agreement/demux.go                  |  4 ++++
 agreement/demux_test.go             |  5 +++++
 agreement/events.go                 |  6 ++++++
 agreement/proposal.go               |  6 ++++++
 agreement/service_test.go           |  4 ++++
 logging/telemetryspec/event.go      |  7 ++++---
 util/timers/frozen.go               |  5 +++++
 util/timers/interface.go            |  3 +++
 util/timers/monotonic.go            |  5 +++++
 11 files changed, 54 insertions(+), 9 deletions(-)

diff --git a/agreement/actions.go b/agreement/actions.go
index a272545c9b..217d4079ea 100644
--- a/agreement/actions.go
+++ b/agreement/actions.go
@@ -232,9 +232,10 @@ 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 {
@@ -242,9 +243,10 @@ 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,
 		})
 		s.Ledger.EnsureBlock(block, a.Certificate)
 	}
diff --git a/agreement/agreementtest/simulate.go b/agreement/agreementtest/simulate.go
index 086d1f5dc4..1c8e54e72a 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) DurationUntil(t time.Time) 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..40d26882ad 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.DurationUntil(time.Now()))
+		}
 	}()
 
 	var pseudonodeEvents <-chan externalEvent
diff --git a/agreement/demux_test.go b/agreement/demux_test.go
index 0c15d58de0..8cb5d3362d 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) DurationUntil(_ time.Time) 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/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..a313c96f48 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) DurationUntil(t time.Time) 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..4c9e49f70a 100644
--- a/logging/telemetryspec/event.go
+++ b/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
diff --git a/util/timers/frozen.go b/util/timers/frozen.go
index 0ff5434ea6..27450af47c 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 ""
 }
+
+// DurationUntil implements the Clock interface.
+func (m *Frozen) DurationUntil(t time.Time) time.Duration {
+	return 0
+}
diff --git a/util/timers/interface.go b/util/timers/interface.go
index dc3c1957ce..98395c9f21 100644
--- a/util/timers/interface.go
+++ b/util/timers/interface.go
@@ -27,6 +27,9 @@ type Clock interface {
 	// at which Zero was called as their reference point.
 	Zero() Clock
 
+	// DurationUntil returns the duration elapsed from this clock's zero to t.
+	DurationUntil(t time.Time) 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..2c457fdbb8 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()
 }
+
+// DurationUntil implements the Clock interface.
+func (m *Monotonic) DurationUntil(t time.Time) time.Duration {
+	return t.Sub(m.zero)
+}

From 4ec86ee79de88a0bed0a3518db6efe3eb10e28d6 Mon Sep 17 00:00:00 2001
From: chris erway <chris.erway@algorand.com>
Date: Wed, 2 Mar 2022 17:55:22 -0500
Subject: [PATCH 2/5] replace timers.DurationUntil with Since

---
 agreement/agreementtest/simulate.go | 2 +-
 agreement/demux.go                  | 2 +-
 agreement/demux_test.go             | 2 +-
 agreement/service_test.go           | 2 +-
 util/timers/frozen.go               | 4 ++--
 util/timers/interface.go            | 5 +++--
 util/timers/monotonic.go            | 6 +++---
 7 files changed, 12 insertions(+), 11 deletions(-)

diff --git a/agreement/agreementtest/simulate.go b/agreement/agreementtest/simulate.go
index 1c8e54e72a..febdd3cd4e 100644
--- a/agreement/agreementtest/simulate.go
+++ b/agreement/agreementtest/simulate.go
@@ -82,7 +82,7 @@ func (i *instant) Zero() timers.Clock {
 	return i
 }
 
-func (i *instant) DurationUntil(t time.Time) time.Duration {
+func (i *instant) Since() time.Duration {
 	return 0
 }
 
diff --git a/agreement/demux.go b/agreement/demux.go
index 40d26882ad..0191499b4b 100644
--- a/agreement/demux.go
+++ b/agreement/demux.go
@@ -190,7 +190,7 @@ func (d *demux) next(s *Service, deadline time.Duration, fastDeadline time.Durat
 		e = e.AttachConsensusVersion(ConsensusVersionView{Err: makeSerErr(err), Version: proto})
 
 		if e.t() == payloadVerified {
-			e = e.(messageEvent).AttachValidatedAt(s.Clock.DurationUntil(time.Now()))
+			e = e.(messageEvent).AttachValidatedAt(s.Clock.Since())
 		}
 	}()
 
diff --git a/agreement/demux_test.go b/agreement/demux_test.go
index 8cb5d3362d..f9d7bb3d39 100644
--- a/agreement/demux_test.go
+++ b/agreement/demux_test.go
@@ -456,7 +456,7 @@ func (t *demuxTester) Decode([]byte) (timers.Clock, error) {
 }
 
 // implement timers.Clock
-func (t *demuxTester) DurationUntil(_ time.Time) time.Duration {
+func (t *demuxTester) Since(_ time.Time) time.Duration {
 	return 0
 }
 
diff --git a/agreement/service_test.go b/agreement/service_test.go
index a313c96f48..ff1d19d87d 100644
--- a/agreement/service_test.go
+++ b/agreement/service_test.go
@@ -71,7 +71,7 @@ func (c *testingClock) Zero() timers.Clock {
 	return c
 }
 
-func (c *testingClock) DurationUntil(t time.Time) time.Duration {
+func (c *testingClock) Since() time.Duration {
 	return 0
 }
 
diff --git a/util/timers/frozen.go b/util/timers/frozen.go
index 27450af47c..a9aa6c1b71 100644
--- a/util/timers/frozen.go
+++ b/util/timers/frozen.go
@@ -56,7 +56,7 @@ func (m *Frozen) String() string {
 	return ""
 }
 
-// DurationUntil implements the Clock interface.
-func (m *Frozen) DurationUntil(t time.Time) time.Duration {
+// 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 98395c9f21..6c8c493e12 100644
--- a/util/timers/interface.go
+++ b/util/timers/interface.go
@@ -27,8 +27,9 @@ type Clock interface {
 	// at which Zero was called as their reference point.
 	Zero() Clock
 
-	// DurationUntil returns the duration elapsed from this clock's zero to t.
-	DurationUntil(t time.Time) time.Duration
+	// 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 2c457fdbb8..80b1a7de45 100644
--- a/util/timers/monotonic.go
+++ b/util/timers/monotonic.go
@@ -87,7 +87,7 @@ func (m *Monotonic) String() string {
 	return time.Time(m.zero).String()
 }
 
-// DurationUntil implements the Clock interface.
-func (m *Monotonic) DurationUntil(t time.Time) time.Duration {
-	return t.Sub(m.zero)
+// 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)
 }

From 7cb816851a4369e68aa9dda2b0b05fc99cd19088 Mon Sep 17 00:00:00 2001
From: chris erway <chris.erway@algorand.com>
Date: Wed, 2 Mar 2022 19:08:59 -0500
Subject: [PATCH 3/5] fix demuxTester

---
 agreement/demux_test.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/agreement/demux_test.go b/agreement/demux_test.go
index f9d7bb3d39..7d7bbc71bd 100644
--- a/agreement/demux_test.go
+++ b/agreement/demux_test.go
@@ -456,7 +456,7 @@ func (t *demuxTester) Decode([]byte) (timers.Clock, error) {
 }
 
 // implement timers.Clock
-func (t *demuxTester) Since(_ time.Time) time.Duration {
+func (t *demuxTester) Since() time.Duration {
 	return 0
 }
 

From ee83ea184abbceda2ab16eac8632f04ca61041c5 Mon Sep 17 00:00:00 2001
From: chris erway <chris.erway@algorand.com>
Date: Wed, 2 Mar 2022 20:36:49 -0500
Subject: [PATCH 4/5] re-run msgp generator

---
 agreement/msgp_gen.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

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

From e8a4470fc4fb40e93aea33883c485f747a7c7686 Mon Sep 17 00:00:00 2001
From: chris erway <chris.erway@algorand.com>
Date: Thu, 3 Mar 2022 10:22:37 -0500
Subject: [PATCH 5/5] add PreValidated to BlockAcceptedEventDetails

---
 agreement/actions.go           | 18 ++++++++++--------
 logging/telemetryspec/event.go |  9 +++++----
 2 files changed, 15 insertions(+), 12 deletions(-)

diff --git a/agreement/actions.go b/agreement/actions.go
index 217d4079ea..be216da4e6 100644
--- a/agreement/actions.go
+++ b/agreement/actions.go
@@ -232,10 +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),
-			ValidatedAt: a.Payload.validatedAt,
+			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 {
@@ -243,10 +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),
-			ValidatedAt: a.Payload.validatedAt,
+			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/logging/telemetryspec/event.go b/logging/telemetryspec/event.go
index 4c9e49f70a..f721fd7bda 100644
--- a/logging/telemetryspec/event.go
+++ b/logging/telemetryspec/event.go
@@ -73,10 +73,11 @@ const BlockAcceptedEvent Event = "BlockAccepted"
 
 // BlockAcceptedEventDetails contains details for the BlockAcceptedEvent
 type BlockAcceptedEventDetails struct {
-	Address     string
-	Hash        string
-	Round       uint64
-	ValidatedAt time.Duration
+	Address      string
+	Hash         string
+	Round        uint64
+	ValidatedAt  time.Duration
+	PreValidated bool
 }
 
 // TopAccountsEvent event