op-e2e/actions: improve Holocene tests by adding log assertions (ethe…

…reum-optimism#12889)

* fix double error in inferring isHolocene

* add capture logging to l2faultproofenv

* fold log expectations into holoceneExpectations

* improve test failure output

* attach log expectations to invalid batch test case

* add more log expectations

* add more log expectations

* add more test expectations for invalid payloads

* add log assertion for deposits-only attributes

* improve test names

* improve subtest names

* move holocene helpers to separate file

* remove shadow

* add log assertions for holocene_batches_test.go

* remove assertion on logs in frame queue

op-e2e/actions/proofs/helpers/env.go

@@ -28,6 +28,7 @@ import (
 // L2FaultProofEnv is a test harness for a fault provable L2 chain.
 type L2FaultProofEnv struct {
 	log       log.Logger
+	Logs      *testlog.CapturingHandler
 	Batcher   *helpers.L2Batcher
 	Sequencer *helpers.L2Sequencer
 	Engine    *helpers.L2Engine
@@ -40,7 +41,8 @@ type L2FaultProofEnv struct {
 }
 
 func NewL2FaultProofEnv[c any](t helpers.Testing, testCfg *TestCfg[c], tp *e2eutils.TestParams, batcherCfg *helpers.BatcherCfg) *L2FaultProofEnv {
-	log := testlog.Logger(t, log.LvlDebug)
+	log, logs := testlog.CaptureLogger(t, log.LevelDebug)
+
 	dp := NewDeployParams(t, tp, func(dp *e2eutils.DeployParams) {
 		genesisBlock := hexutil.Uint64(0)
 
@@ -111,6 +113,7 @@ func NewL2FaultProofEnv[c any](t helpers.Testing, testCfg *TestCfg[c], tp *e2eut
 
 	return &L2FaultProofEnv{
 		log:       log,
+		Logs:      logs,
 		Batcher:   batcher,
 		Sequencer: sequencer,
 		Engine:    engine,

op-e2e/actions/proofs/holocene_batches_test.go

@@ -25,41 +25,54 @@ func Test_ProgramAction_HoloceneBatches(gt *testing.T) {
 	testCases := []testCase{
 		// Standard channel composition
 		{
-			name: "case-0", blocks: []uint{1, 2, 3},
+			name: "ordered", blocks: []uint{1, 2, 3},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3,
-				safeHeadHolocene:    3,
+				preHolocene: expectations{safeHead: 3},
+				holocene:    expectations{safeHead: 3},
 			},
 		},
 
 		// Non-standard channel composition
 		{
-			name: "case-2a", blocks: []uint{1, 3, 2},
+			name: "disordered-a", blocks: []uint{1, 3, 2},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // batches are buffered, so the block ordering does not matter
-				safeHeadHolocene:    1, // batch for block 3 is considered invalid because it is from the future. This batch + remaining channel is dropped.
+				preHolocene: expectations{safeHead: 3}, // batches are buffered, so the block ordering does not matter
+				holocene: expectations{safeHead: 1, // batch for block 3 is considered invalid because it is from the future. This batch + remaining channel is dropped.
+					logs: append(
+						sequencerOnce("dropping future batch"),
+						sequencerOnce("Dropping invalid singular batch, flushing channel")...,
+					)},
 			},
 		},
 		{
-			name: "case-2b", blocks: []uint{2, 1, 3},
+			name: "disordered-b", blocks: []uint{2, 1, 3},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // batches are buffered, so the block ordering does not matter
-				safeHeadHolocene:    0, // batch for block 2 is considered invalid because it is from the future. This batch + remaining channel is dropped.
+				preHolocene: expectations{safeHead: 3}, // batches are buffered, so the block ordering does not matter
+				holocene: expectations{safeHead: 0, // batch for block 2 is considered invalid because it is from the future. This batch + remaining channel is dropped.
+					logs: append(
+						sequencerOnce("dropping future batch"),
+						sequencerOnce("Dropping invalid singular batch, flushing channel")...,
+					)},
 			},
 		},
 
 		{
-			name: "case-2c", blocks: []uint{1, 1, 2, 3},
+			name: "duplicates-a", blocks: []uint{1, 1, 2, 3},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // duplicate batches are silently dropped, so this reduceds to case-0
-				safeHeadHolocene:    3, // duplicate batches are silently dropped
+				preHolocene: expectations{safeHead: 3}, // duplicate batches are dropped, so this reduces to the "ordered" case
+				holocene: expectations{safeHead: 3, // duplicate batches are dropped, so this reduces to the "ordered" case
+					logs: sequencerOnce("dropping past batch with old timestamp")},
 			},
 		},
 		{
-			name: "case-2d", blocks: []uint{2, 2, 1, 3},
+			name: "duplicates-b", blocks: []uint{2, 2, 1, 3},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // duplicate batches are silently dropped, so this reduces to case-2b
-				safeHeadHolocene:    0, // duplicate batches are silently dropped, so this reduces to case-2b
+				preHolocene: expectations{safeHead: 3}, // duplicate batches are silently dropped, so this reduces to disordered-2b
+				holocene: expectations{safeHead: 0, // duplicate batches are silently dropped, so this reduces to disordered-2b
+					logs: append(
+						sequencerOnce("dropping future batch"),
+						sequencerOnce("Dropping invalid singular batch, flushing channel")...,
+					)},
 			},
 		},
 	}
@@ -112,8 +125,8 @@ func Test_ProgramAction_HoloceneBatches(gt *testing.T) {
 		env.Sequencer.ActL2PipelineFull(t)
 
 		l2SafeHead := env.Sequencer.L2Safe()
-		testCfg.Custom.RequireExpectedProgress(t, l2SafeHead, testCfg.Hardfork.Precedence < helpers.Holocene.Precedence, env.Engine)
-
+		isHolocene := testCfg.Hardfork.Precedence >= helpers.Holocene.Precedence
+		testCfg.Custom.RequireExpectedProgressAndLogs(t, l2SafeHead, isHolocene, env.Engine, env.Logs)
 		t.Log("Safe head progressed as expected", "l2SafeHeadNumber", l2SafeHead.Number)
 
 		env.RunFaultProofProgram(t, l2SafeHead.Number, testCfg.CheckResult, testCfg.InputParams...)

op-e2e/actions/proofs/holocene_frame_test.go

@@ -7,28 +7,10 @@ import (
 	actionsHelpers "github.com/ethereum-optimism/optimism/op-e2e/actions/helpers"
 	"github.com/ethereum-optimism/optimism/op-e2e/actions/proofs/helpers"
 	"github.com/ethereum-optimism/optimism/op-program/client/claim"
-	"github.com/ethereum-optimism/optimism/op-service/eth"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/stretchr/testify/require"
 )
 
-type holoceneExpectations struct {
-	safeHeadPreHolocene uint64
-	safeHeadHolocene    uint64
-}
-
-func (h holoceneExpectations) RequireExpectedProgress(t actionsHelpers.StatefulTesting, actualSafeHead eth.L2BlockRef, isHolocene bool, engine *actionsHelpers.L2Engine) {
-	if isHolocene {
-		require.Equal(t, h.safeHeadPreHolocene, actualSafeHead.Number)
-		expectedHash := engine.L2Chain().GetBlockByNumber(h.safeHeadPreHolocene).Hash()
-		require.Equal(t, expectedHash, actualSafeHead.Hash)
-	} else {
-		require.Equal(t, h.safeHeadHolocene, actualSafeHead.Number)
-		expectedHash := engine.L2Chain().GetBlockByNumber(h.safeHeadHolocene).Hash()
-		require.Equal(t, expectedHash, actualSafeHead.Hash)
-	}
-}
-
 func Test_ProgramAction_HoloceneFrames(gt *testing.T) {
 	type testCase struct {
 		name   string
@@ -42,33 +24,33 @@ func Test_ProgramAction_HoloceneFrames(gt *testing.T) {
 	testCases := []testCase{
 		// Standard frame submission,
 		{
-			name: "case-0", frames: []uint{0, 1, 2},
+			name: "ordered", frames: []uint{0, 1, 2},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3,
-				safeHeadHolocene:    3,
+				preHolocene: expectations{safeHead: 3},
+				holocene:    expectations{safeHead: 3},
 			},
 		},
 
 		// Non-standard frame submission
 		{
-			name: "case-1a", frames: []uint{2, 1, 0},
+			name: "disordered-a", frames: []uint{2, 1, 0},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // frames are buffered, so ordering does not matter
-				safeHeadHolocene:    0, // non-first frames will be dropped b/c it is the first seen with that channel Id. The safe head won't move until the channel is closed/completed.
+				preHolocene: expectations{safeHead: 3}, // frames are buffered, so ordering does not matter
+				holocene:    expectations{safeHead: 0}, // non-first frames will be dropped b/c it is the first seen with that channel Id. The safe head won't move until the channel is closed/completed.
 			},
 		},
 		{
-			name: "case-1b", frames: []uint{0, 1, 0, 2},
+			name: "disordered-b", frames: []uint{0, 1, 0, 2},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // frames are buffered, so ordering does not matter
-				safeHeadHolocene:    0, // non-first frames will be dropped b/c it is the first seen with that channel Id. The safe head won't move until the channel is closed/completed.
+				preHolocene: expectations{safeHead: 3}, // frames are buffered, so ordering does not matter
+				holocene:    expectations{safeHead: 0}, // non-first frames will be dropped b/c it is the first seen with that channel Id. The safe head won't move until the channel is closed/completed.
 			},
 		},
 		{
-			name: "case-1c", frames: []uint{0, 1, 1, 2},
+			name: "duplicates", frames: []uint{0, 1, 1, 2},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, // frames are buffered, so ordering does not matter
-				safeHeadHolocene:    3, // non-contiguous frames are dropped. So this reduces to case-0.
+				preHolocene: expectations{safeHead: 3}, // frames are buffered, so ordering does not matter
+				holocene:    expectations{safeHead: 3}, // non-contiguous frames are dropped. So this reduces to case-0.
 			},
 		},
 	}
@@ -126,8 +108,8 @@ func Test_ProgramAction_HoloceneFrames(gt *testing.T) {
 
 		l2SafeHead := env.Sequencer.L2Safe()
 
-		testCfg.Custom.RequireExpectedProgress(t, l2SafeHead, testCfg.Hardfork.Precedence < helpers.Holocene.Precedence, env.Engine)
-
+		isHolocene := testCfg.Hardfork.Precedence >= helpers.Holocene.Precedence
+		testCfg.Custom.RequireExpectedProgressAndLogs(t, l2SafeHead, isHolocene, env.Engine, env.Logs)
 		t.Log("Safe head progressed as expected", "l2SafeHeadNumber", l2SafeHead.Number)
 
 		env.RunFaultProofProgram(t, l2SafeHead.Number, testCfg.CheckResult, testCfg.InputParams...)

op-e2e/actions/proofs/holocene_helpers_test.go

@@ -0,0 +1,45 @@
+package proofs
+
+import (
+	actionsHelpers "github.com/ethereum-optimism/optimism/op-e2e/actions/helpers"
+	"github.com/ethereum-optimism/optimism/op-service/eth"
+	"github.com/ethereum-optimism/optimism/op-service/testlog"
+	"github.com/stretchr/testify/require"
+)
+
+type logExpectations struct {
+	role   string
+	filter string
+	num    int
+}
+type expectations struct {
+	safeHead uint64
+	logs     []logExpectations
+}
+type holoceneExpectations struct {
+	preHolocene, holocene expectations
+}
+
+func (h holoceneExpectations) RequireExpectedProgressAndLogs(t actionsHelpers.StatefulTesting, actualSafeHead eth.L2BlockRef, isHolocene bool, engine *actionsHelpers.L2Engine, logs *testlog.CapturingHandler) {
+	var exp expectations
+	if isHolocene {
+		exp = h.holocene
+	} else {
+		exp = h.preHolocene
+	}
+
+	require.Equal(t, exp.safeHead, actualSafeHead.Number)
+	expectedHash := engine.L2Chain().GetBlockByNumber(exp.safeHead).Hash()
+	require.Equal(t, expectedHash, actualSafeHead.Hash)
+
+	for _, l := range exp.logs {
+		t.Helper()
+		recs := logs.FindLogs(testlog.NewMessageContainsFilter(l.filter), testlog.NewAttributesFilter("role", l.role))
+		require.Len(t, recs, l.num, "searching for %d instances of '%s' in logs from role %s", l.num, l.filter, l.role)
+	}
+
+}
+
+func sequencerOnce(filter string) []logExpectations {
+	return []logExpectations{{filter: filter, role: "sequencer", num: 1}}
+}

op-e2e/actions/proofs/holocene_invalid_batch_test.go

@@ -62,41 +62,59 @@ func Test_ProgramAction_HoloceneInvalidBatch(gt *testing.T) {
 		{
 			name: "valid", blocks: []uint{1, 2, 3},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 3, safeHeadHolocene: 3,
+				preHolocene: expectations{safeHead: 3}, holocene: expectations{safeHead: 3},
 			},
 		},
 
 		{
 			name: "invalid-payload", blocks: []uint{1, 2, 3}, blockModifiers: []actionsHelpers.BlockModifier{nil, invalidPayload, nil},
 			useSpanBatch: false,
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 1, // Invalid signature in block 2 causes an invalid _payload_ in the engine queue. Entire span batch is invalidated.
-				safeHeadHolocene:    2, // We expect the safe head to move to 2 due to creation of an deposit-only block.
+				preHolocene: expectations{safeHead: 1, // Invalid signature in block 2 causes an invalid _payload_ in the engine queue. Entire span batch is invalidated.
+					logs: sequencerOnce("could not process payload attributes"),
+				},
+				holocene: expectations{safeHead: 2, // We expect the safe head to move to 2 due to creation of a deposit-only block.
+					logs: append(
+						sequencerOnce("Holocene active, requesting deposits-only attributes"),
+						sequencerOnce("could not process payload attributes")...,
+					),
+				},
 			},
 		},
 		{
 			name: "invalid-payload-span", blocks: []uint{1, 2, 3}, blockModifiers: []actionsHelpers.BlockModifier{nil, invalidPayload, nil},
 			useSpanBatch: true,
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 0, // Invalid signature in block 2 causes an invalid _payload_ in the engine queue. Entire span batch is invalidated.
-				safeHeadHolocene:    2, // We expect the safe head to move to 2 due to creation of an deposit-only block.
+				preHolocene: expectations{safeHead: 0, // Invalid signature in block 2 causes an invalid _payload_ in the engine queue. Entire span batch is invalidated.
+					logs: sequencerOnce("could not process payload attributes"),
+				},
+
+				holocene: expectations{safeHead: 2, // We expect the safe head to move to 2 due to creation of an deposit-only block.
+					logs: sequencerOnce("could not process payload attributes"),
+				},
 			},
 		},
 
 		{
 			name: "invalid-parent-hash", blocks: []uint{1, 2, 3}, blockModifiers: []actionsHelpers.BlockModifier{nil, invalidParentHash, nil},
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 1, // Invalid parentHash in block 2 causes an invalid batch to be dropped.
-				safeHeadHolocene:    1, // Same with Holocene.
+				preHolocene: expectations{safeHead: 1, // Invalid parentHash in block 2 causes an invalid batch to be dropped.
+					logs: sequencerOnce("ignoring batch with mismatching parent hash")},
+				holocene: expectations{safeHead: 1, // Same with Holocene.
+					logs: sequencerOnce("Dropping invalid singular batch, flushing channel")},
 			},
 		},
 		{
 			name: "seq-drift-span", blocks: twoThousandBlocks, // if we artificially stall the l1 origin, this should be enough to trigger violation of the max sequencer drift
 			useSpanBatch:            true,
 			breachMaxSequencerDrift: true,
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 0,    // Entire span batch invalidated.
-				safeHeadHolocene:    1800, // We expect partial validity until we hit sequencer drift.
+				preHolocene: expectations{safeHead: 0, // Entire span batch invalidated.
+					logs: sequencerOnce("batch exceeded sequencer time drift without adopting next origin, and next L1 origin would have been valid"),
+				},
+				holocene: expectations{safeHead: 1800, // We expect partial validity until we hit sequencer drift.
+					logs: sequencerOnce("batch exceeded sequencer time drift without adopting next origin, and next L1 origin would have been valid"),
+				},
 			},
 		},
 		{
@@ -105,8 +123,12 @@ func Test_ProgramAction_HoloceneInvalidBatch(gt *testing.T) {
 			useSpanBatch:        true,
 			overAdvanceL1Origin: 3, // this will over-advance the L1 origin of block 3
 			holoceneExpectations: holoceneExpectations{
-				safeHeadPreHolocene: 0, // Entire span batch invalidated.
-				safeHeadHolocene:    2, // We expect partial validity, safe head should move to block 2, dropping invalid block 3 and remaining channel.
+				preHolocene: expectations{safeHead: 0, // Entire span batch invalidated.
+					logs: sequencerOnce("block timestamp is less than L1 origin timestamp"),
+				},
+				holocene: expectations{safeHead: 2, // We expect partial validity, safe head should move to block 2, dropping invalid block 3 and remaining channel.
+					logs: sequencerOnce("batch timestamp is less than L1 origin timestamp"),
+				},
 			},
 		},
 	}
@@ -204,8 +226,8 @@ func Test_ProgramAction_HoloceneInvalidBatch(gt *testing.T) {
 
 		l2SafeHead := env.Sequencer.L2Safe()
 
-		testCfg.Custom.RequireExpectedProgress(t, l2SafeHead, testCfg.Hardfork.Precedence < helpers.Holocene.Precedence, env.Engine)
-
+		isHolocene := testCfg.Hardfork.Precedence >= helpers.Holocene.Precedence
+		testCfg.Custom.RequireExpectedProgressAndLogs(t, l2SafeHead, isHolocene, env.Engine, env.Logs)
 		t.Log("Safe head progressed as expected", "l2SafeHeadNumber", l2SafeHead.Number)
 
 		if safeHeadNumber := l2SafeHead.Number; safeHeadNumber > 0 {