From 249d9e78740b222b7f202b7d3915bd88b8c660fa Mon Sep 17 00:00:00 2001 From: Tei Im Date: Mon, 30 Oct 2023 19:44:08 +0900 Subject: [PATCH 1/2] batches_test refactoring Support log based test for batch validation rules Add more test cases for span batch --- op-node/rollup/derive/batches.go | 4 +- op-node/rollup/derive/batches_test.go | 735 ++++++++++++++------------ 2 files changed, 407 insertions(+), 332 deletions(-) diff --git a/op-node/rollup/derive/batches.go b/op-node/rollup/derive/batches.go index ee64eda4519c..622d4bc2068f 100644 --- a/op-node/rollup/derive/batches.go +++ b/op-node/rollup/derive/batches.go @@ -199,11 +199,11 @@ func checkSpanBatch(ctx context.Context, cfg *rollup.Config, log log.Logger, l1B if batch.GetTimestamp() < nextTimestamp { if batch.GetTimestamp() > l2SafeHead.Time { // batch timestamp cannot be between safe head and next timestamp - log.Warn("batch has misaligned timestamp") + log.Warn("batch has misaligned timestamp, block time is too short") return BatchDrop } if (l2SafeHead.Time-batch.GetTimestamp())%cfg.BlockTime != 0 { - log.Warn("batch has misaligned timestamp") + log.Warn("batch has misaligned timestamp, not overlapped exactly") return BatchDrop } parentNum = l2SafeHead.Number - (l2SafeHead.Time-batch.GetTimestamp())/cfg.BlockTime - 1 diff --git a/op-node/rollup/derive/batches_test.go b/op-node/rollup/derive/batches_test.go index a3948fa1a27a..25934f0acd2b 100644 --- a/op-node/rollup/derive/batches_test.go +++ b/op-node/rollup/derive/batches_test.go @@ -1,10 +1,12 @@ package derive import ( + "bytes" "context" "errors" "math/big" "math/rand" + "strings" "testing" "github.com/stretchr/testify/require" @@ -20,27 +22,31 @@ import ( ) type ValidBatchTestCase struct { - Name string - L1Blocks []eth.L1BlockRef - L2SafeHead eth.L2BlockRef - Batch BatchWithL1InclusionBlock - Expected BatchValidity + Name string + L1Blocks []eth.L1BlockRef + L2SafeHead eth.L2BlockRef + Batch BatchWithL1InclusionBlock + Expected BatchValidity + ExpectedLog string // log message that must be included + NotExpectedLog string // log message that must not be included + SpanBatchTime *uint64 } -type SpanBatchHardForkTestCase struct { - Name string - L1Blocks []eth.L1BlockRef - L2SafeHead eth.L2BlockRef - Batch BatchWithL1InclusionBlock - Expected BatchValidity - SpanBatchTime uint64 +type TestLogHandler struct { + handler log.Handler + logs *bytes.Buffer +} + +func (th *TestLogHandler) Log(r *log.Record) error { + th.logs.WriteString(r.Msg + "\n") + return th.handler.Log(r) } var HashA = common.Hash{0x0a} var HashB = common.Hash{0x0b} -func TestValidSingularBatch(t *testing.T) { - conf := rollup.Config{ +func TestValidBatch(t *testing.T) { + defaultConf := rollup.Config{ Genesis: rollup.Genesis{ L2Time: 31, // a genesis time that itself does not align to make it more interesting }, @@ -48,9 +54,17 @@ func TestValidSingularBatch(t *testing.T) { SeqWindowSize: 4, MaxSequencerDrift: 6, // other config fields are ignored and can be left empty. + SpanBatchTime: nil, } rng := rand.New(rand.NewSource(1234)) + + minTs := uint64(0) + chainId := new(big.Int).SetUint64(rng.Uint64()) + signer := types.NewLondonSigner(chainId) + randTx := testutils.RandomTx(rng, new(big.Int).SetUint64(rng.Uint64()), signer) + randTxData, _ := randTx.MarshalBinary() + l1A := testutils.RandomBlockRef(rng) l1B := eth.L1BlockRef{ Hash: testutils.RandomHash(rng), @@ -96,7 +110,7 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: l2A0.Number + 1, ParentHash: l2A0.Hash, - Time: l2A0.Time + conf.BlockTime, + Time: l2A0.Time + defaultConf.BlockTime, L1Origin: l1A.ID(), SequenceNumber: 1, } @@ -105,7 +119,7 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: l2A1.Number + 1, ParentHash: l2A1.Hash, - Time: l2A1.Time + conf.BlockTime, + Time: l2A1.Time + defaultConf.BlockTime, L1Origin: l1A.ID(), SequenceNumber: 2, } @@ -114,7 +128,7 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: l2A2.Number + 1, ParentHash: l2A2.Hash, - Time: l2A2.Time + conf.BlockTime, + Time: l2A2.Time + defaultConf.BlockTime, L1Origin: l1A.ID(), SequenceNumber: 3, } @@ -123,11 +137,29 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: l2A3.Number + 1, ParentHash: l2A3.Hash, - Time: l2A3.Time + conf.BlockTime, // 8 seconds larger than l1A0, 1 larger than origin + Time: l2A3.Time + defaultConf.BlockTime, // 8 seconds larger than l1A0, 1 larger than origin L1Origin: l1B.ID(), SequenceNumber: 0, } + l2B1 := eth.L2BlockRef{ + Hash: testutils.RandomHash(rng), + Number: l2B0.Number + 1, + ParentHash: l2B0.Hash, + Time: l2B0.Time + defaultConf.BlockTime, + L1Origin: l1B.ID(), + SequenceNumber: 1, + } + + l2B2 := eth.L2BlockRef{ + Hash: testutils.RandomHash(rng), + Number: l2B1.Number + 1, + ParentHash: l2B1.Hash, + Time: l2B1.Time + defaultConf.BlockTime, + L1Origin: l1B.ID(), + SequenceNumber: 1, + } + l1X := eth.L1BlockRef{ Hash: testutils.RandomHash(rng), Number: 42, @@ -150,7 +182,7 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: 1000, ParentHash: testutils.RandomHash(rng), - Time: 10_000 + 12 + 6 - 1, // add one block, and you get ahead of next l1 block by more than the drift + Time: 10_000 + 24 + 6 - 1, // add one block, and you get ahead of next l1 block by more than the drift L1Origin: l1X.ID(), SequenceNumber: 0, } @@ -158,16 +190,24 @@ func TestValidSingularBatch(t *testing.T) { Hash: testutils.RandomHash(rng), Number: l2X0.Number + 1, ParentHash: l2X0.Hash, - Time: l2X0.Time + conf.BlockTime, // exceeds sequencer time drift, forced to be empty block + Time: l2X0.Time + defaultConf.BlockTime, // exceeds sequencer time drift, forced to be empty block L1Origin: l1Y.ID(), SequenceNumber: 0, } + l2Z0 := eth.L2BlockRef{ + Hash: testutils.RandomHash(rng), + Number: l2Y0.Number + 1, + ParentHash: l2Y0.Hash, + Time: l2Y0.Time + defaultConf.BlockTime, // exceeds sequencer time drift, forced to be empty block + L1Origin: l1Z.ID(), + SequenceNumber: 0, + } l2A4 := eth.L2BlockRef{ Hash: testutils.RandomHash(rng), Number: l2A3.Number + 1, ParentHash: l2A3.Hash, - Time: l2A3.Time + conf.BlockTime, // 4*2 = 8, higher than seq time drift + Time: l2A3.Time + defaultConf.BlockTime, // 4*2 = 8, higher than seq time drift L1Origin: l1A.ID(), SequenceNumber: 4, } @@ -179,7 +219,7 @@ func TestValidSingularBatch(t *testing.T) { Time: l2A4.Time + 1, // too late for l2A4 to adopt yet } - testCases := []ValidBatchTestCase{ + singularBatchTestCases := []ValidBatchTestCase{ { Name: "missing L1 info", L1Blocks: []eth.L1BlockRef{}, @@ -286,7 +326,7 @@ func TestValidSingularBatch(t *testing.T) { ParentHash: l2B0.Hash, // build on top of safe head to continue EpochNum: rollup.Epoch(l2A3.L1Origin.Number), // epoch A is no longer valid EpochHash: l2A3.L1Origin.Hash, - Timestamp: l2B0.Time + conf.BlockTime, // pass the timestamp check to get too epoch check + Timestamp: l2B0.Time + defaultConf.BlockTime, // pass the timestamp check to get too epoch check Transactions: nil, }, }, @@ -520,173 +560,14 @@ func TestValidSingularBatch(t *testing.T) { ParentHash: l2A2.Hash, EpochNum: rollup.Epoch(l2B0.L1Origin.Number), EpochHash: l2B0.L1Origin.Hash, - Timestamp: l2A2.Time + conf.BlockTime, + Timestamp: l2A2.Time + defaultConf.BlockTime, Transactions: nil, }, }, Expected: BatchDrop, }, } - - // Log level can be increased for debugging purposes - logger := testlog.Logger(t, log.LvlError) - - for _, testCase := range testCases { - t.Run(testCase.Name, func(t *testing.T) { - ctx := context.Background() - validity := CheckBatch(ctx, &conf, logger, testCase.L1Blocks, testCase.L2SafeHead, &testCase.Batch, nil) - require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level") - }) - } -} - -func TestValidSpanBatch(t *testing.T) { - minTs := uint64(0) - conf := rollup.Config{ - Genesis: rollup.Genesis{ - L2Time: 31, // a genesis time that itself does not align to make it more interesting - }, - BlockTime: 2, - SeqWindowSize: 4, - MaxSequencerDrift: 6, - SpanBatchTime: &minTs, - // other config fields are ignored and can be left empty. - } - - rng := rand.New(rand.NewSource(1234)) - chainId := new(big.Int).SetUint64(rng.Uint64()) - signer := types.NewLondonSigner(chainId) - randTx := testutils.RandomTx(rng, new(big.Int).SetUint64(rng.Uint64()), signer) - randTxData, _ := randTx.MarshalBinary() - l1A := testutils.RandomBlockRef(rng) - l1B := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1A.Number + 1, - ParentHash: l1A.Hash, - Time: l1A.Time + 7, - } - l1C := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1B.Number + 1, - ParentHash: l1B.Hash, - Time: l1B.Time + 7, - } - l1D := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1C.Number + 1, - ParentHash: l1C.Hash, - Time: l1C.Time + 7, - } - l1E := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1D.Number + 1, - ParentHash: l1D.Hash, - Time: l1D.Time + 7, - } - l1F := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1E.Number + 1, - ParentHash: l1E.Hash, - Time: l1E.Time + 7, - } - - l2A0 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: 100, - ParentHash: testutils.RandomHash(rng), - Time: l1A.Time, - L1Origin: l1A.ID(), - SequenceNumber: 0, - } - - l2A1 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A0.Number + 1, - ParentHash: l2A0.Hash, - Time: l2A0.Time + conf.BlockTime, - L1Origin: l1A.ID(), - SequenceNumber: 1, - } - - l2A2 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A1.Number + 1, - ParentHash: l2A1.Hash, - Time: l2A1.Time + conf.BlockTime, - L1Origin: l1A.ID(), - SequenceNumber: 2, - } - - l2A3 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A2.Number + 1, - ParentHash: l2A2.Hash, - Time: l2A2.Time + conf.BlockTime, - L1Origin: l1A.ID(), - SequenceNumber: 3, - } - - l2B0 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A3.Number + 1, - ParentHash: l2A3.Hash, - Time: l2A3.Time + conf.BlockTime, // 8 seconds larger than l1A0, 1 larger than origin - L1Origin: l1B.ID(), - SequenceNumber: 0, - } - - l1X := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: 42, - ParentHash: testutils.RandomHash(rng), - Time: 10_000, - } - l1Y := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1X.Number + 1, - ParentHash: l1X.Hash, - Time: l1X.Time + 12, - } - l1Z := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1Y.Number + 1, - ParentHash: l1Y.Hash, - Time: l1Y.Time + 12, - } - l2X0 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: 1000, - ParentHash: testutils.RandomHash(rng), - Time: 10_000 + 12 + 6 - 1, // add one block, and you get ahead of next l1 block by more than the drift - L1Origin: l1X.ID(), - SequenceNumber: 0, - } - l2Y0 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2X0.Number + 1, - ParentHash: l2X0.Hash, - Time: l2X0.Time + conf.BlockTime, // exceeds sequencer time drift, forced to be empty block - L1Origin: l1Y.ID(), - SequenceNumber: 0, - } - - l2A4 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A3.Number + 1, - ParentHash: l2A3.Hash, - Time: l2A3.Time + conf.BlockTime, // 4*2 = 8, higher than seq time drift - L1Origin: l1A.ID(), - SequenceNumber: 4, - } - - l1BLate := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1A.Number + 1, - ParentHash: l1A.Hash, - Time: l2A4.Time + 1, // too late for l2A4 to adopt yet - } - - testCases := []ValidBatchTestCase{ + spanBatchTestCases := []ValidBatchTestCase{ { Name: "missing L1 info", L1Blocks: []eth.L1BlockRef{}, @@ -703,7 +584,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchUndecided, + Expected: BatchUndecided, + ExpectedLog: "missing L1 block input, cannot proceed with batch checking", + SpanBatchTime: &minTs, }, { Name: "future timestamp", @@ -721,25 +604,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchFuture, - }, - { - Name: "old timestamp", - L1Blocks: []eth.L1BlockRef{l1A, l1B, l1C}, - L2SafeHead: l2A0, - Batch: BatchWithL1InclusionBlock{ - L1InclusionBlock: l1B, - Batch: NewSpanBatch([]*SingularBatch{ - { - ParentHash: l2A1.ParentHash, - EpochNum: rollup.Epoch(l2A1.L1Origin.Number), - EpochHash: l2A1.L1Origin.Hash, - Timestamp: l2A0.Time, // repeating the same time - Transactions: nil, - }, - }), - }, - Expected: BatchDrop, + Expected: BatchFuture, + ExpectedLog: "received out-of-order batch for future processing after next batch", + SpanBatchTime: &minTs, }, { Name: "misaligned timestamp", @@ -757,7 +624,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "span batch has no new blocks after safe head", + SpanBatchTime: &minTs, }, { Name: "invalid parent block hash", @@ -775,7 +644,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "ignoring batch with mismatching parent hash", + SpanBatchTime: &minTs, }, { Name: "sequence window expired", @@ -793,7 +664,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch was included too late, sequence window expired", + SpanBatchTime: &minTs, }, { Name: "epoch too old, but good parent hash and timestamp", // repeat of now outdated l2A3 data @@ -806,18 +679,20 @@ func TestValidSpanBatch(t *testing.T) { ParentHash: l2B0.Hash, // build on top of safe head to continue EpochNum: rollup.Epoch(l2A3.L1Origin.Number), // epoch A is no longer valid EpochHash: l2A3.L1Origin.Hash, - Timestamp: l2B0.Time + conf.BlockTime, // pass the timestamp check to get too epoch check + Timestamp: l2B0.Time + defaultConf.BlockTime, // pass the timestamp check to get too epoch check Transactions: nil, }, { EpochNum: rollup.Epoch(l1B.Number), EpochHash: l1B.Hash, // pass the l1 origin check - Timestamp: l2B0.Time + conf.BlockTime*2, + Timestamp: l2B0.Time + defaultConf.BlockTime*2, Transactions: nil, }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "dropped batch, epoch is too old", + SpanBatchTime: &minTs, }, { Name: "insufficient L1 info for eager derivation", @@ -835,7 +710,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchUndecided, + Expected: BatchUndecided, + ExpectedLog: "need more l1 blocks to check entire origins of span batch", + SpanBatchTime: &minTs, }, { Name: "epoch too new", @@ -853,7 +730,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch is for future epoch too far ahead, while it has the next timestamp, so it must be invalid", + SpanBatchTime: &minTs, }, { Name: "epoch hash wrong", @@ -871,7 +750,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch is for different L1 chain, epoch hash does not match", + SpanBatchTime: &minTs, }, { Name: "epoch hash wrong - long span", @@ -896,7 +777,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch is for different L1 chain, epoch hash does not match", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with non-empty txs", @@ -914,7 +797,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch exceeded sequencer time drift, sequencer must adopt new L1 origin to include transactions again", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with non-empty txs - long span", @@ -939,7 +824,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch exceeded sequencer time drift, sequencer must adopt new L1 origin to include transactions again", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on changing epoch with non-empty txs", @@ -957,7 +844,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "batch exceeded sequencer time drift, sequencer must adopt new L1 origin to include transactions again", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with empty txs and late next epoch", @@ -975,7 +864,8 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchAccept, // accepted because empty & preserving L2 time invariant + Expected: BatchAccept, // accepted because empty & preserving L2 time invariant + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on changing epoch with empty txs", @@ -991,9 +881,18 @@ func TestValidSpanBatch(t *testing.T) { Timestamp: l2Y0.Time, // valid, but more than 6 ahead of l1Y.Time Transactions: nil, }, + { + ParentHash: l2Z0.ParentHash, + EpochNum: rollup.Epoch(l2Z0.L1Origin.Number), + EpochHash: l2Z0.L1Origin.Hash, + Timestamp: l2Z0.Time, // valid, but more than 6 ahead of l1Y.Time + Transactions: nil, + }, }), }, - Expected: BatchAccept, // accepted because empty & still advancing epoch + Expected: BatchAccept, // accepted because empty & still advancing epoch + SpanBatchTime: &minTs, + NotExpectedLog: "continuing with empty batch before late L1 block to preserve L2 time invariant", }, { Name: "sequencer time drift on same epoch with empty txs and no next epoch in sight yet", @@ -1011,7 +910,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchUndecided, // we have to wait till the next epoch is in sight to check the time + Expected: BatchUndecided, // we have to wait till the next epoch is in sight to check the time + ExpectedLog: "without the next L1 origin we cannot determine yet if this empty batch that exceeds the time drift is still valid", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with empty txs and no next epoch in sight yet - long span", @@ -1036,7 +937,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchUndecided, // we have to wait till the next epoch is in sight to check the time + Expected: BatchUndecided, // we have to wait till the next epoch is in sight to check the time + ExpectedLog: "without the next L1 origin we cannot determine yet if this empty batch that exceeds the time drift is still valid", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with empty txs and but in-sight epoch that invalidates it", @@ -1054,7 +957,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, // dropped because it could have advanced the epoch to B + Expected: BatchDrop, // dropped because it could have advanced the epoch to B + ExpectedLog: "batch exceeded sequencer time drift without adopting next origin, and next L1 origin would have been valid", + SpanBatchTime: &minTs, }, { Name: "sequencer time drift on same epoch with empty txs and but in-sight epoch that invalidates it - long span", @@ -1079,7 +984,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, // dropped because it could have advanced the epoch to B + Expected: BatchDrop, // dropped because it could have advanced the epoch to B + ExpectedLog: "batch exceeded sequencer time drift without adopting next origin, and next L1 origin would have been valid", + SpanBatchTime: &minTs, }, { Name: "empty tx included", @@ -1099,7 +1006,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "transaction data must not be empty, but found empty tx", + SpanBatchTime: &minTs, }, { Name: "deposit tx included", @@ -1119,7 +1028,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "sequencers may not embed any deposits into batch data, but found tx that has one", + SpanBatchTime: &minTs, }, { Name: "valid batch same epoch", @@ -1137,7 +1048,8 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchAccept, + Expected: BatchAccept, + SpanBatchTime: &minTs, }, { Name: "valid batch changing epoch", @@ -1155,7 +1067,8 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchAccept, + Expected: BatchAccept, + SpanBatchTime: &minTs, }, { Name: "batch with L2 time before L1 time", @@ -1168,12 +1081,14 @@ func TestValidSpanBatch(t *testing.T) { ParentHash: l2A2.Hash, EpochNum: rollup.Epoch(l2B0.L1Origin.Number), EpochHash: l2B0.L1Origin.Hash, - Timestamp: l2A2.Time + conf.BlockTime, + Timestamp: l2A2.Time + defaultConf.BlockTime, Transactions: nil, }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "block timestamp is less than L1 origin timestamp", + SpanBatchTime: &minTs, }, { Name: "batch with L2 time before L1 time - long span", @@ -1193,12 +1108,14 @@ func TestValidSpanBatch(t *testing.T) { ParentHash: l2A2.Hash, EpochNum: rollup.Epoch(l2B0.L1Origin.Number), EpochHash: l2B0.L1Origin.Hash, - Timestamp: l2A2.Time + conf.BlockTime, + Timestamp: l2A2.Time + defaultConf.BlockTime, Transactions: nil, }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "block timestamp is less than L1 origin timestamp", + SpanBatchTime: &minTs, }, { Name: "valid overlapping batch", @@ -1223,7 +1140,8 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchAccept, + Expected: BatchAccept, + SpanBatchTime: &minTs, }, { Name: "longer overlapping batch", @@ -1255,7 +1173,8 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchAccept, + Expected: BatchAccept, + SpanBatchTime: &minTs, }, { Name: "fully overlapping batch", @@ -1280,7 +1199,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "span batch has no new blocks after safe head", + SpanBatchTime: &minTs, }, { Name: "overlapping batch with invalid parent hash", @@ -1305,7 +1226,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "ignoring batch with mismatching parent hash", + SpanBatchTime: &minTs, }, { Name: "overlapping batch with invalid origin number", @@ -1330,7 +1253,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "overlapped block's L1 origin number does not match", + SpanBatchTime: &minTs, }, { Name: "overlapping batch with invalid tx", @@ -1355,7 +1280,9 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchDrop, + Expected: BatchDrop, + ExpectedLog: "overlapped block's tx count does not match", + SpanBatchTime: &minTs, }, { Name: "overlapping batch l2 fetcher error", @@ -1387,89 +1314,91 @@ func TestValidSpanBatch(t *testing.T) { }, }), }, - Expected: BatchUndecided, + Expected: BatchUndecided, + ExpectedLog: "failed to fetch L2 block", + SpanBatchTime: &minTs, }, - } - - // Log level can be increased for debugging purposes - logger := testlog.Logger(t, log.LvlError) - - l2Client := testutils.MockL2Client{} - var nilErr error - // will be return error for block #99 (parent of l2A0) - tempErr := errors.New("temp error") - l2Client.Mock.On("L2BlockRefByNumber", l2A0.Number-1).Times(9999).Return(eth.L2BlockRef{}, &tempErr) - l2Client.Mock.On("PayloadByNumber", l2A0.Number-1).Times(9999).Return(nil, &tempErr) - - // make payloads for L2 blocks and set as expected return value of MockL2Client - for _, l2Block := range []eth.L2BlockRef{l2A0, l2A1, l2A2, l2A3, l2A4, l2B0} { - l2Client.ExpectL2BlockRefByNumber(l2Block.Number, l2Block, nil) - txData := l1InfoDepositTx(t, l2Block.L1Origin.Number) - payload := eth.ExecutionPayload{ - ParentHash: l2Block.ParentHash, - BlockNumber: hexutil.Uint64(l2Block.Number), - Timestamp: hexutil.Uint64(l2Block.Time), - BlockHash: l2Block.Hash, - Transactions: []hexutil.Bytes{txData}, - } - l2Client.Mock.On("L2BlockRefByNumber", l2Block.Number).Times(9999).Return(l2Block, &nilErr) - l2Client.Mock.On("PayloadByNumber", l2Block.Number).Times(9999).Return(&payload, &nilErr) - } - - for _, testCase := range testCases { - t.Run(testCase.Name, func(t *testing.T) { - ctx := context.Background() - validity := CheckBatch(ctx, &conf, logger, testCase.L1Blocks, testCase.L2SafeHead, &testCase.Batch, &l2Client) - require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level") - }) - } -} - -func TestSpanBatchHardFork(t *testing.T) { - minTs := uint64(0) - conf := rollup.Config{ - Genesis: rollup.Genesis{ - L2Time: 31, // a genesis time that itself does not align to make it more interesting + { + Name: "short block time", + L1Blocks: []eth.L1BlockRef{l1A, l1B}, + L2SafeHead: l2A0, + Batch: BatchWithL1InclusionBlock{ + L1InclusionBlock: l1B, + Batch: NewSpanBatch([]*SingularBatch{ + { + ParentHash: l2A0.Hash, + EpochNum: rollup.Epoch(l2A1.L1Origin.Number), + EpochHash: l2A1.L1Origin.Hash, + Timestamp: l2A0.Time + 1, + Transactions: nil, + }, + { + ParentHash: l2A1.Hash, + EpochNum: rollup.Epoch(l2A2.L1Origin.Number), + EpochHash: l2A2.L1Origin.Hash, + Timestamp: l2A1.Time + 1, + Transactions: nil, + }, + }), + }, + Expected: BatchDrop, + ExpectedLog: "batch has misaligned timestamp, block time is too short", + SpanBatchTime: &minTs, + }, + { + Name: "misaligned batch", + L1Blocks: []eth.L1BlockRef{l1A, l1B}, + L2SafeHead: l2A0, + Batch: BatchWithL1InclusionBlock{ + L1InclusionBlock: l1B, + Batch: NewSpanBatch([]*SingularBatch{ + { + ParentHash: l2A0.Hash, + EpochNum: rollup.Epoch(l2A1.L1Origin.Number), + EpochHash: l2A1.L1Origin.Hash, + Timestamp: l2A0.Time - 1, + Transactions: nil, + }, + { + ParentHash: l2A1.Hash, + EpochNum: rollup.Epoch(l2A2.L1Origin.Number), + EpochHash: l2A2.L1Origin.Hash, + Timestamp: l2A1.Time, + Transactions: nil, + }, + }), + }, + Expected: BatchDrop, + ExpectedLog: "batch has misaligned timestamp, not overlapped exactly", + SpanBatchTime: &minTs, + }, + { + Name: "failed to fetch overlapping block payload", + L1Blocks: []eth.L1BlockRef{l1A, l1B}, + L2SafeHead: l2A3, + Batch: BatchWithL1InclusionBlock{ + L1InclusionBlock: l1B, + Batch: NewSpanBatch([]*SingularBatch{ + { + ParentHash: l2A2.Hash, + EpochNum: rollup.Epoch(l2A3.L1Origin.Number), + EpochHash: l2A3.L1Origin.Hash, + Timestamp: l2A3.Time, + Transactions: nil, + }, + { + ParentHash: l2A3.Hash, + EpochNum: rollup.Epoch(l2B0.L1Origin.Number), + EpochHash: l2B0.L1Origin.Hash, + Timestamp: l2B0.Time, + Transactions: nil, + }, + }), + }, + Expected: BatchUndecided, + ExpectedLog: "failed to fetch L2 block payload", + SpanBatchTime: &minTs, }, - BlockTime: 2, - SeqWindowSize: 4, - MaxSequencerDrift: 6, - SpanBatchTime: &minTs, - // other config fields are ignored and can be left empty. - } - - rng := rand.New(rand.NewSource(1234)) - chainId := new(big.Int).SetUint64(rng.Uint64()) - signer := types.NewLondonSigner(chainId) - randTx := testutils.RandomTx(rng, new(big.Int).SetUint64(rng.Uint64()), signer) - randTxData, _ := randTx.MarshalBinary() - l1A := testutils.RandomBlockRef(rng) - l1B := eth.L1BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l1A.Number + 1, - ParentHash: l1A.Hash, - Time: l1A.Time + 7, - } - - l2A0 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: 100, - ParentHash: testutils.RandomHash(rng), - Time: l1A.Time, - L1Origin: l1A.ID(), - SequenceNumber: 0, - } - - l2A1 := eth.L2BlockRef{ - Hash: testutils.RandomHash(rng), - Number: l2A0.Number + 1, - ParentHash: l2A0.Hash, - Time: l2A0.Time + conf.BlockTime, - L1Origin: l1A.ID(), - SequenceNumber: 1, - } - - testCases := []SpanBatchHardForkTestCase{ { Name: "singular batch before hard fork", L1Blocks: []eth.L1BlockRef{l1A, l1B}, @@ -1484,7 +1413,7 @@ func TestSpanBatchHardFork(t *testing.T) { Transactions: []hexutil.Bytes{randTxData}, }, }, - SpanBatchTime: l2A1.Time + 2, + SpanBatchTime: &l2A2.Time, Expected: BatchAccept, }, { @@ -1503,7 +1432,7 @@ func TestSpanBatchHardFork(t *testing.T) { }, }), }, - SpanBatchTime: l2A1.Time + 2, + SpanBatchTime: &l2A2.Time, Expected: BatchDrop, }, { @@ -1520,7 +1449,7 @@ func TestSpanBatchHardFork(t *testing.T) { Transactions: []hexutil.Bytes{randTxData}, }, }, - SpanBatchTime: l2A1.Time - 2, + SpanBatchTime: &l2A0.Time, Expected: BatchAccept, }, { @@ -1539,21 +1468,167 @@ func TestSpanBatchHardFork(t *testing.T) { }, }), }, - SpanBatchTime: l2A1.Time - 2, + SpanBatchTime: &l2A0.Time, Expected: BatchAccept, }, } // Log level can be increased for debugging purposes - logger := testlog.Logger(t, log.LvlInfo) + logger := testlog.Logger(t, log.LvlError) + + // Create a test log handler to check expected logs + var logBuf bytes.Buffer + handler := TestLogHandler{handler: logger.GetHandler(), logs: &logBuf} + logger.SetHandler(&handler) + + l2Client := testutils.MockL2Client{} + var nilErr error + tempErr := errors.New("temp error") + // will return an error for block #99 (parent of l2A0) + l2Client.Mock.On("L2BlockRefByNumber", l2A0.Number-1).Return(eth.L2BlockRef{}, &tempErr) + // will return an error for l2A3 + l2Client.Mock.On("PayloadByNumber", l2A3.Number).Return(ð.ExecutionPayload{}, &tempErr) + + // make payloads for L2 blocks and set as expected return value of MockL2Client + for _, l2Block := range []eth.L2BlockRef{l2A0, l2A1, l2A2, l2B0} { + l2Client.ExpectL2BlockRefByNumber(l2Block.Number, l2Block, nil) + txData := l1InfoDepositTx(t, l2Block.L1Origin.Number) + payload := eth.ExecutionPayload{ + ParentHash: l2Block.ParentHash, + BlockNumber: hexutil.Uint64(l2Block.Number), + Timestamp: hexutil.Uint64(l2Block.Time), + BlockHash: l2Block.Hash, + Transactions: []hexutil.Bytes{txData}, + } + l2Client.Mock.On("L2BlockRefByNumber", l2Block.Number).Return(l2Block, &nilErr) + l2Client.Mock.On("PayloadByNumber", l2Block.Number).Return(&payload, &nilErr) + } - for _, testCase := range testCases { - t.Run(testCase.Name, func(t *testing.T) { - rcfg := conf - rcfg.SpanBatchTime = &testCase.SpanBatchTime - ctx := context.Background() - validity := CheckBatch(ctx, &rcfg, logger, testCase.L1Blocks, testCase.L2SafeHead, &testCase.Batch, nil) - require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level") + runTestCase := func(t *testing.T, testCase ValidBatchTestCase) { + ctx := context.Background() + rcfg := defaultConf + if testCase.SpanBatchTime != nil { + rcfg.SpanBatchTime = testCase.SpanBatchTime + } + validity := CheckBatch(ctx, &rcfg, logger, testCase.L1Blocks, testCase.L2SafeHead, &testCase.Batch, &l2Client) + require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level") + if testCase.ExpectedLog != "" { + // Check if ExpectedLog is contained in the log buffer + if !strings.Contains(logBuf.String(), testCase.ExpectedLog) { + t.Errorf("Expected log message was not found in the buffer: %s", testCase.ExpectedLog) + } + } + if testCase.NotExpectedLog != "" { + // Check if NotExpectedLog is contained in the log buffer + if strings.Contains(logBuf.String(), testCase.NotExpectedLog) { + t.Errorf("Not expected log message was found in the buffer: %s", testCase.NotExpectedLog) + } + } + logBuf.Reset() + } + + // Run singular batch test cases + for _, testCase := range singularBatchTestCases { + t.Run("singular_"+testCase.Name, func(t *testing.T) { + runTestCase(t, testCase) }) } + + // Run span batch test cases + for _, testCase := range spanBatchTestCases { + t.Run("span_"+testCase.Name, func(t *testing.T) { + runTestCase(t, testCase) + }) + } + + // ====== Test different TX for overlapping batches ====== + l2Client.ExpectL2BlockRefByNumber(l2B1.Number, l2B1, nil) + txData := l1InfoDepositTx(t, l2B1.L1Origin.Number) + randTx = testutils.RandomTx(rng, new(big.Int).SetUint64(rng.Uint64()), signer) + randTxData, _ = randTx.MarshalBinary() + payload := eth.ExecutionPayload{ + ParentHash: l2B0.Hash, + BlockNumber: hexutil.Uint64(l2B1.Number), + Timestamp: hexutil.Uint64(l2B1.Time), + BlockHash: l2B1.Hash, + Transactions: []hexutil.Bytes{txData, randTxData}, + } + l2Client.Mock.On("PayloadByNumber", l2B1.Number).Return(&payload, &nilErr).Once() + + randTx = testutils.RandomTx(rng, new(big.Int).SetUint64(rng.Uint64()), signer) + randTxData, _ = randTx.MarshalBinary() + differentTxtestCase := ValidBatchTestCase{ + Name: "different_tx_overlapping_batch", + L1Blocks: []eth.L1BlockRef{l1B}, + L2SafeHead: l2B1, + Batch: BatchWithL1InclusionBlock{ + L1InclusionBlock: l1B, + Batch: NewSpanBatch([]*SingularBatch{ + { + ParentHash: l2B0.Hash, + EpochNum: rollup.Epoch(l2B1.L1Origin.Number), + EpochHash: l2B1.L1Origin.Hash, + Timestamp: l2B1.Time, + Transactions: []hexutil.Bytes{randTxData}, // Random generated TX that does not match overlapping block + }, + { + ParentHash: l2B1.Hash, + EpochNum: rollup.Epoch(l2B2.L1Origin.Number), + EpochHash: l2B2.L1Origin.Hash, + Timestamp: l2B2.Time, + Transactions: nil, + }, + }), + }, + Expected: BatchDrop, + ExpectedLog: "overlapped block's transaction does not match", + SpanBatchTime: &minTs, + } + + t.Run(differentTxtestCase.Name, func(t *testing.T) { + runTestCase(t, differentTxtestCase) + }) + + // ====== Test invalid TX for overlapping batches ====== + payload = eth.ExecutionPayload{ + ParentHash: l2B0.Hash, + BlockNumber: hexutil.Uint64(l2B1.Number), + Timestamp: hexutil.Uint64(l2B1.Time), + BlockHash: l2B1.Hash, + // First TX is not a deposit TX. it will make error when extracting L2BlockRef from the payload + Transactions: []hexutil.Bytes{randTxData}, + } + l2Client.Mock.On("PayloadByNumber", l2B1.Number).Return(&payload, &nilErr).Once() + + invalidTxTestCase := ValidBatchTestCase{ + Name: "invalid_tx_overlapping_batch", + L1Blocks: []eth.L1BlockRef{l1B}, + L2SafeHead: l2B1, + Batch: BatchWithL1InclusionBlock{ + L1InclusionBlock: l1B, + Batch: NewSpanBatch([]*SingularBatch{ + { + ParentHash: l2B0.Hash, + EpochNum: rollup.Epoch(l2B1.L1Origin.Number), + EpochHash: l2B1.L1Origin.Hash, + Timestamp: l2B1.Time, + Transactions: []hexutil.Bytes{randTxData}, + }, + { + ParentHash: l2B1.Hash, + EpochNum: rollup.Epoch(l2B2.L1Origin.Number), + EpochHash: l2B2.L1Origin.Hash, + Timestamp: l2B2.Time, + Transactions: nil, + }, + }), + }, + Expected: BatchDrop, + ExpectedLog: "failed to extract L2BlockRef from execution payload", + SpanBatchTime: &minTs, + } + + t.Run(invalidTxTestCase.Name, func(t *testing.T) { + runTestCase(t, invalidTxTestCase) + }) } From 87a064415a1b384895a2d64c226acedec5ec9434 Mon Sep 17 00:00:00 2001 From: protolambda Date: Tue, 31 Oct 2023 23:56:29 +0100 Subject: [PATCH 2/2] op-node: span-batch test log level tweak, minor test-vector fix --- op-node/rollup/derive/batches.go | 4 ++-- op-node/rollup/derive/batches_test.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/op-node/rollup/derive/batches.go b/op-node/rollup/derive/batches.go index 622d4bc2068f..b5ca17088a41 100644 --- a/op-node/rollup/derive/batches.go +++ b/op-node/rollup/derive/batches.go @@ -210,7 +210,7 @@ func checkSpanBatch(ctx context.Context, cfg *rollup.Config, log log.Logger, l1B var err error parentBlock, err = l2Fetcher.L2BlockRefByNumber(ctx, parentNum) if err != nil { - log.Error("failed to fetch L2 block", "number", parentNum, "err", err) + log.Warn("failed to fetch L2 block", "number", parentNum, "err", err) // unable to validate the batch for now. retry later. return BatchUndecided } @@ -332,7 +332,7 @@ func checkSpanBatch(ctx context.Context, cfg *rollup.Config, log log.Logger, l1B safeBlockNum := parentNum + i + 1 safeBlockPayload, err := l2Fetcher.PayloadByNumber(ctx, safeBlockNum) if err != nil { - log.Error("failed to fetch L2 block payload", "number", parentNum, "err", err) + log.Warn("failed to fetch L2 block payload", "number", parentNum, "err", err) // unable to validate the batch for now. retry later. return BatchUndecided } diff --git a/op-node/rollup/derive/batches_test.go b/op-node/rollup/derive/batches_test.go index 25934f0acd2b..7021a714031e 100644 --- a/op-node/rollup/derive/batches_test.go +++ b/op-node/rollup/derive/batches_test.go @@ -157,7 +157,7 @@ func TestValidBatch(t *testing.T) { ParentHash: l2B1.Hash, Time: l2B1.Time + defaultConf.BlockTime, L1Origin: l1B.ID(), - SequenceNumber: 1, + SequenceNumber: 2, } l1X := eth.L1BlockRef{