diff --git a/devnet-sdk/telemetry/slog.go b/devnet-sdk/telemetry/slog.go index 81ccc0f871c..367fca6df5d 100644 --- a/devnet-sdk/telemetry/slog.go +++ b/devnet-sdk/telemetry/slog.go @@ -7,6 +7,8 @@ import ( "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/trace" + + "github.com/ethereum-optimism/optimism/op-service/logmods" ) func WrapHandler(h slog.Handler) slog.Handler { @@ -19,6 +21,12 @@ type tracingHandler struct { slog.Handler } +var _ logmods.Handler = (*tracingHandler)(nil) + +func (h *tracingHandler) Unwrap() slog.Handler { + return h.Handler +} + func (h *tracingHandler) Handle(ctx context.Context, record slog.Record) error { // Send log entries as events to the tracer if h.Handler.Enabled(ctx, record.Level) { diff --git a/go.mod b/go.mod index 8191d749f44..af72a964165 100644 --- a/go.mod +++ b/go.mod @@ -294,7 +294,7 @@ require ( rsc.io/tmplfunc v0.0.3 // indirect ) -replace github.com/ethereum/go-ethereum => github.com/ethereum-optimism/op-geth v1.101511.0-rc.1 +replace github.com/ethereum/go-ethereum => github.com/ethereum-optimism/op-geth v1.101511.1-0.20250523133920-e3f85bf38455 //replace github.com/ethereum/go-ethereum => ../op-geth diff --git a/go.sum b/go.sum index 11b222b88ca..307a874c2d5 100644 --- a/go.sum +++ b/go.sum @@ -206,10 +206,8 @@ github.com/elastic/gosigar v0.14.3 h1:xwkKwPia+hSfg9GqrCUKYdId102m9qTJIIr7egmK/u github.com/elastic/gosigar v0.14.3/go.mod h1:iXRIGg2tLnu7LBdpqzyQfGDEidKCfWcCMS0WKyPWoMs= github.com/ethereum-optimism/go-ethereum-hdwallet v0.1.3 h1:RWHKLhCrQThMfch+QJ1Z8veEq5ZO3DfIhZ7xgRP9WTc= github.com/ethereum-optimism/go-ethereum-hdwallet v0.1.3/go.mod h1:QziizLAiF0KqyLdNJYD7O5cpDlaFMNZzlxYNcWsJUxs= -github.com/ethereum-optimism/op-geth v1.101511.0-rc.1 h1:DTQwpncGhqrxUO4YqmY740mYwFc+C5eh9mqGHhRerHg= -github.com/ethereum-optimism/op-geth v1.101511.0-rc.1/go.mod h1:SkytozVEPtnUeBlquwl0Qv5JKvrN/Y5aqh+VkQo/EOI= -github.com/ethereum-optimism/superchain-registry/validation v0.0.0-20250314162817-2c60e5723c64 h1:teDhU4h4ryaE8rSBl+vJJiwKHjxdnnHPkKZ9iNr2R8k= -github.com/ethereum-optimism/superchain-registry/validation v0.0.0-20250314162817-2c60e5723c64/go.mod h1:NZ816PzLU1TLv1RdAvYAb6KWOj4Zm5aInT0YpDVml2Y= +github.com/ethereum-optimism/op-geth v1.101511.1-0.20250523133920-e3f85bf38455 h1:uIZUYbfz+KqMUgVrrhVLzIk9AGZx0BrWr+nKe6ccENo= +github.com/ethereum-optimism/op-geth v1.101511.1-0.20250523133920-e3f85bf38455/go.mod h1:SkytozVEPtnUeBlquwl0Qv5JKvrN/Y5aqh+VkQo/EOI= github.com/ethereum-optimism/superchain-registry/validation v0.0.0-20250521132634-76f6d741b33f h1:L4Q9iIthJHsrIS1rwEYcZDlMtIeKzwRRByQALNvJ3cQ= github.com/ethereum-optimism/superchain-registry/validation v0.0.0-20250521132634-76f6d741b33f/go.mod h1:NZ816PzLU1TLv1RdAvYAb6KWOj4Zm5aInT0YpDVml2Y= github.com/ethereum/c-kzg-4844/v2 v2.1.0 h1:gQropX9YFBhl3g4HYhwE70zq3IHFRgbbNPw0Shwzf5w= diff --git a/op-acceptance-tests/tests/base/advance_test.go b/op-acceptance-tests/tests/base/advance_test.go index 3a4826f8ec0..13c1565e7f2 100644 --- a/op-acceptance-tests/tests/base/advance_test.go +++ b/op-acceptance-tests/tests/base/advance_test.go @@ -25,7 +25,7 @@ func TestCLAdvance(gt *testing.T) { defer span.End() new_num, num = sys.L2CL.SafeL2BlockRef().Number, new_num - t.Logger().WithContext(ctx).Info("safe head", "number", new_num) + t.Logger().InfoContext(ctx, "safe head", "number", new_num) return new_num > num }, 30*time.Second, waitTime) } diff --git a/op-acceptance-tests/tests/base/faucet_test.go b/op-acceptance-tests/tests/base/faucet_test.go index 1846a2a87c4..9311bb3f238 100644 --- a/op-acceptance-tests/tests/base/faucet_test.go +++ b/op-acceptance-tests/tests/base/faucet_test.go @@ -22,6 +22,6 @@ func TestFaucetFund(gt *testing.T) { _, span = tracer.Start(ctx, "transfer funds") amount := eth.OneEther funded.Transfer(unfunded.Address(), amount) - t.Logger().WithContext(ctx).Info("funds transferred", "amount", amount) + t.Logger().InfoContext(ctx, "funds transferred", "amount", amount) span.End() } diff --git a/op-devstack/devtest/common.go b/op-devstack/devtest/common.go index e032dccb9ac..e618c086941 100644 --- a/op-devstack/devtest/common.go +++ b/op-devstack/devtest/common.go @@ -3,6 +3,8 @@ package devtest import ( "context" + "github.com/ethereum/go-ethereum/log" + "github.com/stretchr/testify/require" "go.opentelemetry.io/otel/trace" ) @@ -22,8 +24,29 @@ type CommonT interface { Helper() Name() string - Logger() Logger + Logger() log.Logger Tracer() trace.Tracer Ctx() context.Context Require() *require.Assertions } + +type testScopeCtxKeyType struct{} + +// testScopeCtxKey is a key added to the test-context to identify the test-scope. +var testScopeCtxKey = testScopeCtxKeyType{} + +// TestScope retrieves the test-scope from the context +func TestScope(ctx context.Context) string { + scope := ctx.Value(testScopeCtxKey) + if scope == nil { + return "" + } + return scope.(string) +} + +// AddTestScope combines the sub-scope with the test-scope of the context, +// and returns a context with the updated scope value. +func AddTestScope(ctx context.Context, scope string) context.Context { + prev := TestScope(ctx) + return context.WithValue(ctx, testScopeCtxKey, prev+"/"+scope) +} diff --git a/op-devstack/devtest/logging.go b/op-devstack/devtest/logging.go deleted file mode 100644 index fe6cd8ba6c9..00000000000 --- a/op-devstack/devtest/logging.go +++ /dev/null @@ -1,64 +0,0 @@ -package devtest - -import ( - "context" - "log/slog" - - "github.com/ethereum-optimism/optimism/devnet-sdk/telemetry" - "github.com/ethereum-optimism/optimism/op-service/testlog" - "github.com/ethereum/go-ethereum/log" -) - -// This whole file is a hack around the fact that log.Logger doesn't support context passing. - -type Logger interface { - log.Logger - WithContext(context.Context) Logger -} - -func NewLogger(ctx context.Context, t testlog.Testing, level slog.Level) Logger { - l := testlog.LoggerWithHandlerMod(t, level, func(h slog.Handler) slog.Handler { - return &tracingHandler{ctx, h} - }) - return &logger{ - Logger: l, - level: level, - t: t, - ctx: ctx, - } -} - -type logger struct { - log.Logger - - level slog.Level - t testlog.Testing - ctx context.Context -} - -func (l *logger) WithContext(ctx context.Context) Logger { - // We need to reset the handler to take the new context into account - return NewLogger(ctx, l.t, l.level) -} - -var _ Logger = (*logger)(nil) - -// a fake Logger, just so P can be a CommonT -type pkgLogger struct { - log.Logger -} - -func (l *pkgLogger) WithContext(ctx context.Context) Logger { - return l -} - -var _ Logger = (*pkgLogger)(nil) - -type tracingHandler struct { - ctx context.Context - slog.Handler -} - -func (h *tracingHandler) Handle(_ context.Context, record slog.Record) error { - return telemetry.WrapHandler(h.Handler).Handle(h.ctx, record) -} diff --git a/op-devstack/devtest/package.go b/op-devstack/devtest/package.go index 0d6b6445baf..0e596d7dd18 100644 --- a/op-devstack/devtest/package.go +++ b/op-devstack/devtest/package.go @@ -17,6 +17,12 @@ import ( type P interface { CommonT + // WithCtx makes a copy of P with a specific context. + // The ctx must match the test-scope of the existing context. + // This function is used to create a P with annotated context, e.g. a specific resource. + // The logger may be annotated with additional arguments. + WithCtx(ctx context.Context, args ...any) P + // TempDir creates a temporary directory, and returns the file-path. // This directory is cleaned up at the end of the package, // and can be shared safely between tests that run in that package scope. @@ -42,7 +48,7 @@ type implP struct { scopeName string // logger is used for logging. Regular test errors will also be redirected to get logged here. - logger Logger + logger log.Logger // fail will be called to register a critical failure. // The implementer can choose to panic, crit-log, exit, etc. as preferred. @@ -103,7 +109,7 @@ func (t *implP) Name() string { return t.scopeName } -func (t *implP) Logger() Logger { +func (t *implP) Logger() log.Logger { return t.logger } @@ -115,6 +121,34 @@ func (t *implP) Ctx() context.Context { return t.ctx } +type wrapP struct { + ctx context.Context + logger log.Logger + req *require.Assertions + P +} + +var _ P = (*wrapP)(nil) + +func (p *wrapP) Ctx() context.Context { + return p.ctx +} + +func (p *wrapP) Logger() log.Logger { + return p.logger +} + +func (t *implP) WithCtx(ctx context.Context, args ...any) P { + expected := TestScope(t.ctx) + got := TestScope(ctx) + t.req.Equal(expected, got, "cannot replace context with different test-scope") + logger := t.logger.New(args...) + logger.SetContext(ctx) + out := &wrapP{ctx: ctx, logger: logger, P: t} + out.req = require.New(out) + return out +} + func (t *implP) Require() *require.Assertions { return t.req } @@ -166,9 +200,9 @@ func NewP(ctx context.Context, logger log.Logger, onFail func()) P { ctx, cancel := context.WithCancel(ctx) out := &implP{ scopeName: "pkg", - logger: &pkgLogger{logger}, + logger: logger, fail: onFail, - ctx: ctx, + ctx: AddTestScope(ctx, "pkg"), cancel: cancel, } out.req = require.New(out) diff --git a/op-devstack/devtest/testing.go b/op-devstack/devtest/testing.go index 1d852523943..a14ad29db03 100644 --- a/op-devstack/devtest/testing.go +++ b/op-devstack/devtest/testing.go @@ -3,6 +3,7 @@ package devtest import ( "context" "fmt" + "log/slog" "os" "strconv" "testing" @@ -14,7 +15,11 @@ import ( "github.com/ethereum/go-ethereum/log" + "github.com/ethereum-optimism/optimism/devnet-sdk/telemetry" oplog "github.com/ethereum-optimism/optimism/op-service/log" + "github.com/ethereum-optimism/optimism/op-service/logfilter" + "github.com/ethereum-optimism/optimism/op-service/logmods" + "github.com/ethereum-optimism/optimism/op-service/testlog" ) const ExpectPreconditionsMet = "DEVNET_EXPECT_PRECONDITIONS_MET" @@ -45,6 +50,12 @@ type T interface { // and inherits the context of the parent-test-scope. Ctx() context.Context + // WithCtx makes a copy of T with a specific context. + // The ctx must match the test-scope of the existing context. + // This function is used to create a T with annotated context, e.g. a specific resource, rather than a sub-scope. + // The logger may be annotated with additional arguments. + WithCtx(ctx context.Context, args ...any) T + // Parallel signals that this test is to be run in parallel with (and only with) other parallel tests. Parallel() @@ -78,7 +89,7 @@ var _ require.TestingT = T(nil) // testingT implements the T interface by wrapping around a regular golang testing.T type testingT struct { t *testing.T - logger Logger + logger log.Logger tracer trace.Tracer ctx context.Context req *require.Assertions @@ -123,7 +134,7 @@ func (t *testingT) Name() string { return t.t.Name() } -func (t *testingT) Logger() Logger { +func (t *testingT) Logger() log.Logger { return t.logger } @@ -135,6 +146,23 @@ func (t *testingT) Ctx() context.Context { return t.ctx } +func (t *testingT) WithCtx(ctx context.Context, args ...any) T { + expected := TestScope(t.ctx) + got := TestScope(ctx) + t.req.Equal(expected, got, "cannot replace context with different test-scope") + logger := t.logger.New(args...) + logger.SetContext(ctx) + out := &testingT{ + t: t.t, + logger: logger, + tracer: t.tracer, + ctx: ctx, + } + out.req = require.New(out) + out.gate = require.New(&gateAdapter{out}) + return out +} + func (t *testingT) Require() *require.Assertions { return t.req } @@ -142,7 +170,9 @@ func (t *testingT) Require() *require.Assertions { func (t *testingT) Run(name string, fn func(T)) { baseName := t.Name() t.t.Run(name, func(subGoT *testing.T) { - ctx, cancel := context.WithCancel(t.ctx) + ctx := AddTestScope(t.ctx, name) + + ctx, cancel := context.WithCancel(ctx) subGoT.Cleanup(cancel) tracer := otel.Tracer(baseName + "::" + name) @@ -150,14 +180,8 @@ func (t *testingT) Run(name string, fn func(T)) { subGoT.Cleanup(func() { span.End() }) - // we know the underlying implementation, but it's pretty ugly. - level := t.logger.(*logger).level - logger := &logger{ - Logger: t.logger.New("subtest", name), - level: level, - t: t, - ctx: ctx, - } + logger := t.logger.New("subtest", name) + logger.SetContext(ctx) // attach the sub-test context as default log-context subT := &testingT{ t: subGoT, @@ -226,14 +250,30 @@ func (t *testingT) _TestOnly() { var _ T = (*testingT)(nil) +// DefaultTestLogLevel is set to the TEST_LOG_LEVEL env var value, and defaults to info-level if not set. +var DefaultTestLogLevel = func() slog.Level { + logLevel := os.Getenv("TEST_LOG_LEVEL") + if logLevel == "" { + return log.LevelInfo + } + level, err := oplog.LevelFromString(logLevel) + if err != nil { + _, _ = fmt.Fprintf(os.Stderr, "invalid TEST_LOG_LEVEL env var: %v\n", err) + return log.LevelInfo + } + return level +}() + // SerialT wraps around a test-logger and turns it into a T for devstack testing. func SerialT(t *testing.T) T { - var ctx context.Context + ctx := RootContext + ctx = AddTestScope(ctx, t.Name()) + var cancel context.CancelFunc if deadline, hasDeadline := t.Deadline(); hasDeadline { - ctx, cancel = context.WithDeadline(RootContext, deadline.Add(-3*time.Second)) + ctx, cancel = context.WithDeadline(ctx, deadline.Add(-3*time.Second)) } else { - ctx, cancel = context.WithCancel(RootContext) + ctx, cancel = context.WithCancel(ctx) } t.Cleanup(cancel) @@ -242,16 +282,16 @@ func SerialT(t *testing.T) T { t.Cleanup(func() { span.End() }) - logLevel := os.Getenv("TEST_LOG_LEVEL") - if logLevel == "" { - logLevel = "info" // default to info if not set - } - level, err := oplog.LevelFromString(logLevel) - if err != nil { - t.Errorf("Invalid log level %q: %v, defaulting to info", logLevel, err) - level = log.LevelInfo + + // Set the lowest default log-level, so the log-filters on top can apply correctly + logger := testlog.LoggerWithHandlerMod(t, log.LevelTrace, + telemetry.WrapHandler, logfilter.WrapFilterHandler) + h, ok := logmods.FindHandler[logfilter.Handler](logger.Handler()) + if ok { + // Apply default log level. This may be overridden later. + h.Set(logfilter.Minimum(DefaultTestLogLevel)) } - logger := NewLogger(ctx, t, level).WithContext(ctx) + logger.SetContext(ctx) // Set the default context; any log call without context will use this out := &testingT{ t: t, diff --git a/op-devstack/example/example_test.go b/op-devstack/example/example_test.go index ac01479bf7e..cdd7a6e1505 100644 --- a/op-devstack/example/example_test.go +++ b/op-devstack/example/example_test.go @@ -52,7 +52,7 @@ func TestExampleTxsTracing(gt *testing.T) { ctx, transfer := tracer.Start(ctx, "transferring") transferred := eth.GWei(42) tx := alice.Transfer(bob.Address(), transferred) - logger.WithContext(ctx).Info("transferred", "amount", transferred, "gas", tx.Included.Value().GasUsed) + logger.InfoContext(ctx, "transferred", "amount", transferred, "gas", tx.Included.Value().GasUsed) require.Equal(params.TxGas, tx.Included.Value().GasUsed, "transfers cost 21k gas") transfer.End() diff --git a/op-devstack/example/init_test.go b/op-devstack/example/init_test.go index 2b9382e5460..4acb2e7e694 100644 --- a/op-devstack/example/init_test.go +++ b/op-devstack/example/init_test.go @@ -3,10 +3,23 @@ package example import ( "testing" + "github.com/ethereum/go-ethereum/log" + "github.com/ethereum-optimism/optimism/op-devstack/presets" + "github.com/ethereum-optimism/optimism/op-devstack/stack" + "github.com/ethereum-optimism/optimism/op-service/logfilter" ) // TestMain creates the test-setups against the shared backend func TestMain(m *testing.M) { - presets.DoMain(m, presets.WithSimpleInterop()) + presets.DoMain(m, presets.WithSimpleInterop(), + // Logging can be adjusted with filters globally + presets.WithLogFilters( + stack.KindLogFilter(stack.L2ProposerKind, logfilter.Mute()), + stack.KindLogFilter(stack.L2BatcherKind, logfilter.Minimum(log.LevelError)), + stack.KindLogFilter(stack.L2CLNodeKind, logfilter.Add(3)), + ), + // E.g. elevate the logs of your test interactions, while keeping background resource logs quiet + presets.WithTestLogFilters(logfilter.Add(4)), + ) } diff --git a/op-devstack/presets/logging.go b/op-devstack/presets/logging.go new file mode 100644 index 00000000000..17dade7edb0 --- /dev/null +++ b/op-devstack/presets/logging.go @@ -0,0 +1,77 @@ +package presets + +import ( + "fmt" + "log/slog" + + "github.com/ethereum-optimism/optimism/op-devstack/stack" + "github.com/ethereum-optimism/optimism/op-service/logfilter" + "github.com/ethereum-optimism/optimism/op-service/logmods" +) + +// WithLogFiltersReset removes all filters, and puts a global minimum-log-level filter in place. +func WithLogFiltersReset(globalMinLevel slog.Level) stack.CommonOption { + fn := func(h logfilter.Handler) { + h.Set(logfilter.Minimum(globalMinLevel)) + } + return stack.Combine( + withPkgLogFiltering(fn), + withTestLogFiltering(fn), + ) +} + +// WithLogFilters applies the log filter to the orchestrator and each test-scope +func WithLogFilters(filters ...logfilter.LogFilter) stack.CommonOption { + fn := func(h logfilter.Handler) { + h.Add(logfilter.Combine(filters...)) + } + return stack.Combine( + withPkgLogFiltering(fn), + withTestLogFiltering(fn), + ) +} + +// WithPkgLogFilters applies the log filters to test-scope interactions +// (i.e. to things like DSL interactions, not to background services). +func WithPkgLogFilters(filters ...logfilter.LogFilter) stack.CommonOption { + fn := func(h logfilter.Handler) { + h.Add(logfilter.Combine(filters...)) + } + return withPkgLogFiltering(fn) +} + +// WithTestLogFilters applies the log filters to test-scope interactions +// (i.e. to things like DSL interactions, not to background services). +func WithTestLogFilters(filters ...logfilter.LogFilter) stack.CommonOption { + fn := func(h logfilter.Handler) { + h.Add(logfilter.Combine(filters...)) + } + return withTestLogFiltering(fn) +} + +// withPkgLogFiltering creates an option to apply changes to the log-handlers of package-level logger and test-scopes. +func withPkgLogFiltering(fn func(h logfilter.Handler)) stack.CommonOption { + return stack.BeforeDeploy(func(orch stack.Orchestrator) { + logger := orch.P().Logger() + h := logger.Handler() + filterHandler, ok := logmods.FindHandler[logfilter.Handler](h) + if !ok { + logger.Warn("Cannot apply log-filters to pkg-scope log-handler", "type", fmt.Sprintf("%T", h)) + return + } + fn(filterHandler) + }) +} + +func withTestLogFiltering(fn func(h logfilter.Handler)) stack.CommonOption { + return stack.PreHydrate[stack.Orchestrator](func(sys stack.System) { + logger := sys.T().Logger() + h := logger.Handler() + filterHandler, ok := logmods.FindHandler[logfilter.Handler](h) + if !ok { + logger.Warn("Cannot apply log-filters to test-scope log-handler", "type", fmt.Sprintf("%T", h)) + return + } + fn(filterHandler) + }) +} diff --git a/op-devstack/presets/orchestrator.go b/op-devstack/presets/orchestrator.go index d73c3edb100..82baddd59db 100644 --- a/op-devstack/presets/orchestrator.go +++ b/op-devstack/presets/orchestrator.go @@ -18,6 +18,7 @@ import ( "github.com/ethereum-optimism/optimism/op-devstack/sysgo" "github.com/ethereum-optimism/optimism/op-service/locks" oplog "github.com/ethereum-optimism/optimism/op-service/log" + "github.com/ethereum-optimism/optimism/op-service/logfilter" ) // lockedOrchestrator is the global variable that stores @@ -55,12 +56,16 @@ func DoMain(m *testing.M, opts ...stack.CommonOption) { }() // This may be tuned with env or CLI flags in the future, to customize test output - logger := oplog.NewLogger(os.Stdout, oplog.CLIConfig{ - Level: log.LevelInfo, + logHandler := oplog.NewLogHandler(os.Stdout, oplog.CLIConfig{ + Level: log.LevelTrace, Color: true, Format: oplog.FormatTerminal, Pid: false, }) + logHandler = logfilter.WrapFilterHandler(logHandler) + // The default can be changed using the WithLogFiltersReset option + logHandler.(logfilter.Handler).Set(logfilter.Minimum(devtest.DefaultTestLogLevel)) + logger := log.NewLogger(logHandler) ctx, otelShutdown, err := telemetry.SetupOpenTelemetry(context.Background()) if err != nil { @@ -72,7 +77,12 @@ func DoMain(m *testing.M, opts ...stack.CommonOption) { ctx, run := otel.Tracer("run").Start(ctx, "test suite") defer run.End() + // All tests will inherit this package-level context devtest.RootContext = ctx + + // Make the package-level logger use this context + logger.SetContext(ctx) + p := devtest.NewP(ctx, logger, func() { debug.PrintStack() failed.Store(true) @@ -119,7 +129,7 @@ func initOrchestrator(ctx context.Context, p devtest.P, opt stack.CommonOption) panic(fmt.Sprintf("Unknown backend for initializing orchestrator: %s", backend)) } - p.Logger().WithContext(ctx).Info("initializing orchestrator", "backend", backend) + p.Logger().InfoContext(ctx, "initializing orchestrator", "backend", backend) stack.ApplyOptionLifecycle(opt, lockedOrchestrator.Value) } diff --git a/op-devstack/shim/cluster.go b/op-devstack/shim/cluster.go index 132654bee2b..2fc3f7954dc 100644 --- a/op-devstack/shim/cluster.go +++ b/op-devstack/shim/cluster.go @@ -22,7 +22,7 @@ type presetCluster struct { var _ stack.Cluster = (*presetCluster)(nil) func NewCluster(cfg ClusterConfig) stack.Cluster { - cfg.Log = cfg.Log.New("id", cfg.ID) + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.ClusterKind), "id", cfg.ID) return &presetCluster{ id: cfg.ID, commonImpl: newCommon(cfg.CommonConfig), diff --git a/op-devstack/shim/common.go b/op-devstack/shim/common.go index d25fc972dfe..641291bf220 100644 --- a/op-devstack/shim/common.go +++ b/op-devstack/shim/common.go @@ -12,19 +12,16 @@ import ( // CommonConfig provides common inputs for creating a new component type CommonConfig struct { - // Log is the logger to use, annotated with metadata. - // Shim constructors generally add default annotations like the component "id" and "chain" - Log log.Logger - T devtest.T + // T may be annotated using the T.WithCtx function + T devtest.T } // NewCommonConfig is a convenience method to build the config common between all components. -// Note that component constructors will decorate the logger with metadata for internal use, -// the caller of the component constructor can generally leave the logger as-is. +// Note that component constructors will decorate the test-scope with contextual metadata, +// the caller of the component constructor can generally leave the test-context as-is. func NewCommonConfig(t devtest.T) CommonConfig { return CommonConfig{ - Log: t.Logger(), - T: t, + T: t, } } diff --git a/op-devstack/shim/el.go b/op-devstack/shim/el.go index 2a1504b4927..37515c69dab 100644 --- a/op-devstack/shim/el.go +++ b/op-devstack/shim/el.go @@ -28,7 +28,7 @@ var _ stack.ELNode = (*rpcELNode)(nil) // newRpcELNode creates a generic ELNode, safe to embed in other structs func newRpcELNode(cfg ELNodeConfig) rpcELNode { - ethCl, err := sources.NewEthClient(cfg.Client, cfg.Log, nil, sources.DefaultEthClientConfig(10)) + ethCl, err := sources.NewEthClient(cfg.Client, cfg.T.Logger(), nil, sources.DefaultEthClientConfig(10)) require.NoError(cfg.T, err) return rpcELNode{ diff --git a/op-devstack/shim/faucet.go b/op-devstack/shim/faucet.go index 9b7f3fa0f63..4035aad0724 100644 --- a/op-devstack/shim/faucet.go +++ b/op-devstack/shim/faucet.go @@ -25,6 +25,7 @@ type presetFaucet struct { var _ stack.Faucet = (*presetFaucet)(nil) func NewFaucet(cfg FaucetConfig) stack.Faucet { + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.FaucetKind), "id", cfg.ID) return &presetFaucet{ id: cfg.ID, commonImpl: newCommon(cfg.CommonConfig), diff --git a/op-devstack/shim/l1_cl.go b/op-devstack/shim/l1_cl.go index 762fc335d6f..c109111df23 100644 --- a/op-devstack/shim/l1_cl.go +++ b/op-devstack/shim/l1_cl.go @@ -22,7 +22,10 @@ type rpcL1CLNode struct { var _ stack.L1CLNode = (*rpcL1CLNode)(nil) func NewL1CLNode(cfg L1CLNodeConfig) stack.L1CLNode { - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L1CLNodeKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) return &rpcL1CLNode{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/l1_el.go b/op-devstack/shim/l1_el.go index 1ed4d2bb277..6f50704775a 100644 --- a/op-devstack/shim/l1_el.go +++ b/op-devstack/shim/l1_el.go @@ -18,8 +18,11 @@ type rpcL1ELNode struct { var _ stack.L1ELNode = (*rpcL1ELNode)(nil) func NewL1ELNode(cfg L1ELNodeConfig) stack.L1ELNode { + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L1ELNodeKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) require.Equal(cfg.T, cfg.ID.ChainID, cfg.ELNodeConfig.ChainID, "chainID must be configured to match node chainID") - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) return &rpcL1ELNode{ rpcELNode: newRpcELNode(cfg.ELNodeConfig), id: cfg.ID, diff --git a/op-devstack/shim/l1_network.go b/op-devstack/shim/l1_network.go index 2c2636ad10e..d9e7d756694 100644 --- a/op-devstack/shim/l1_network.go +++ b/op-devstack/shim/l1_network.go @@ -24,8 +24,11 @@ type presetL1Network struct { var _ stack.ExtensibleL1Network = (*presetL1Network)(nil) func NewL1Network(cfg L1NetworkConfig) stack.ExtensibleL1Network { + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L1NetworkKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID()) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID(), "id", cfg.ID) require.Equal(cfg.T, cfg.ID.ChainID(), eth.ChainIDFromBig(cfg.NetworkConfig.ChainConfig.ChainID), "chain config must match expected chain") - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID(), "id", cfg.ID) return &presetL1Network{ id: cfg.ID, presetNetwork: newNetwork(cfg.NetworkConfig), diff --git a/op-devstack/shim/l2_batcher.go b/op-devstack/shim/l2_batcher.go index fdc4602374f..9aae6f276d8 100644 --- a/op-devstack/shim/l2_batcher.go +++ b/op-devstack/shim/l2_batcher.go @@ -22,7 +22,10 @@ type rpcL2Batcher struct { var _ stack.L2Batcher = (*rpcL2Batcher)(nil) func NewL2Batcher(cfg L2BatcherConfig) stack.L2Batcher { - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2BatcherKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) return &rpcL2Batcher{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/l2_challenger.go b/op-devstack/shim/l2_challenger.go index c439867ad45..deeec8ce6fa 100644 --- a/op-devstack/shim/l2_challenger.go +++ b/op-devstack/shim/l2_challenger.go @@ -15,7 +15,7 @@ type rpcL2Challenger struct { var _ stack.L2Challenger = (*rpcL2Challenger)(nil) func NewL2Challenger(cfg L2ChallengerConfig) stack.L2Challenger { - cfg.Log = cfg.Log.New("id", cfg.ID) + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.L2ChallengerKind), "id", cfg.ID) return &rpcL2Challenger{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/l2_cl.go b/op-devstack/shim/l2_cl.go index 89eaef37105..2aca1f0e915 100644 --- a/op-devstack/shim/l2_cl.go +++ b/op-devstack/shim/l2_cl.go @@ -37,7 +37,10 @@ var _ stack.L2CLNode = (*rpcL2CLNode)(nil) var _ stack.LinkableL2CLNode = (*rpcL2CLNode)(nil) func NewL2CLNode(cfg L2CLNodeConfig) stack.L2CLNode { - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2CLNodeKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) return &rpcL2CLNode{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/l2_el.go b/op-devstack/shim/l2_el.go index f4819d1aa0f..ccd880780a3 100644 --- a/op-devstack/shim/l2_el.go +++ b/op-devstack/shim/l2_el.go @@ -25,10 +25,13 @@ type rpcL2ELNode struct { var _ stack.L2ELNode = (*rpcL2ELNode)(nil) func NewL2ELNode(cfg L2ELNodeConfig) stack.L2ELNode { - require.Equal(cfg.T, cfg.ID.ChainID, cfg.ELNodeConfig.ChainID, "chainID must be configured to match node chainID") - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2ELNodeKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) - l2Client, err := sources.NewL2Client(cfg.ELNodeConfig.Client, cfg.Log, nil, sources.L2ClientSimpleConfig(cfg.RollupCfg, false, 10, 10)) + require.Equal(cfg.T, cfg.ID.ChainID, cfg.ELNodeConfig.ChainID, "chainID must be configured to match node chainID") + l2Client, err := sources.NewL2Client(cfg.ELNodeConfig.Client, cfg.T.Logger(), nil, sources.L2ClientSimpleConfig(cfg.RollupCfg, false, 10, 10)) require.NoError(cfg.T, err) return &rpcL2ELNode{ diff --git a/op-devstack/shim/l2_network.go b/op-devstack/shim/l2_network.go index 780d68fa426..51fcc1ed5bf 100644 --- a/op-devstack/shim/l2_network.go +++ b/op-devstack/shim/l2_network.go @@ -44,11 +44,14 @@ type presetL2Network struct { var _ stack.L2Network = (*presetL2Network)(nil) func NewL2Network(cfg L2NetworkConfig) stack.ExtensibleL2Network { + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2NetworkKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID()) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID(), "id", cfg.ID) // sanity-check the configs match the expected chains require.Equal(cfg.T, cfg.ID.ChainID(), eth.ChainIDFromBig(cfg.NetworkConfig.ChainConfig.ChainID), "chain config must match expected chain") require.Equal(cfg.T, cfg.L1.ChainID(), eth.ChainIDFromBig(cfg.RollupConfig.L1ChainID), "rollup config must match expected L1 chain") require.Equal(cfg.T, cfg.ID.ChainID(), eth.ChainIDFromBig(cfg.RollupConfig.L2ChainID), "rollup config must match expected L2 chain") - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID(), "id", cfg.ID) return &presetL2Network{ id: cfg.ID, presetNetwork: newNetwork(cfg.NetworkConfig), diff --git a/op-devstack/shim/l2_proposer.go b/op-devstack/shim/l2_proposer.go index 5f2c46eb9a3..0bda3767297 100644 --- a/op-devstack/shim/l2_proposer.go +++ b/op-devstack/shim/l2_proposer.go @@ -20,7 +20,10 @@ type rpcL2Proposer struct { var _ stack.L2Proposer = (*rpcL2Proposer)(nil) func NewL2Proposer(cfg L2ProposerConfig) stack.L2Proposer { - cfg.Log = cfg.Log.New("chainID", cfg.ID.ChainID, "id", cfg.ID) + ctx := cfg.T.Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2ProposerKind) + ctx = stack.ContextWithChainID(ctx, cfg.ID.ChainID) + cfg.T = cfg.T.WithCtx(ctx, "chainID", cfg.ID.ChainID, "id", cfg.ID) return &rpcL2Proposer{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/sequencer.go b/op-devstack/shim/sequencer.go index dafa3b4ee36..618e07f092f 100644 --- a/op-devstack/shim/sequencer.go +++ b/op-devstack/shim/sequencer.go @@ -27,7 +27,7 @@ type rpcTestSequencer struct { var _ stack.TestSequencer = (*rpcTestSequencer)(nil) func NewTestSequencer(cfg TestSequencerConfig) stack.TestSequencer { - cfg.Log = cfg.Log.New("id", cfg.ID) + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.TestSequencerKind), "id", cfg.ID) s := &rpcTestSequencer{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/superchain.go b/op-devstack/shim/superchain.go index c1c9aa4af53..1c4cc899ed4 100644 --- a/op-devstack/shim/superchain.go +++ b/op-devstack/shim/superchain.go @@ -19,7 +19,7 @@ type presetSuperchain struct { var _ stack.Superchain = (*presetSuperchain)(nil) func NewSuperchain(cfg SuperchainConfig) stack.Superchain { - cfg.Log = cfg.Log.New("id", cfg.ID) + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.SuperchainKind), "id", cfg.ID) return &presetSuperchain{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/shim/supervisor.go b/op-devstack/shim/supervisor.go index 64e2e927b84..38523ad6b1a 100644 --- a/op-devstack/shim/supervisor.go +++ b/op-devstack/shim/supervisor.go @@ -24,7 +24,7 @@ type rpcSupervisor struct { var _ stack.Supervisor = (*rpcSupervisor)(nil) func NewSupervisor(cfg SupervisorConfig) stack.Supervisor { - cfg.Log = cfg.Log.New("id", cfg.ID) + cfg.T = cfg.T.WithCtx(stack.ContextWithKind(cfg.T.Ctx(), stack.SupervisorKind), "id", cfg.ID) return &rpcSupervisor{ commonImpl: newCommon(cfg.CommonConfig), id: cfg.ID, diff --git a/op-devstack/stack/context.go b/op-devstack/stack/context.go new file mode 100644 index 00000000000..8e3a982fdda --- /dev/null +++ b/op-devstack/stack/context.go @@ -0,0 +1,73 @@ +package stack + +import ( + "context" + "log/slog" + + "github.com/ethereum-optimism/optimism/op-service/eth" + "github.com/ethereum-optimism/optimism/op-service/logfilter" +) + +type kindCtxKeyType struct{} + +var kindCtxKey = kindCtxKeyType{} + +const UnknownKind Kind = "" + +// KindFromContext reads what the kind of service the context is focused on. This may be UnknownKind if unspecified. +func KindFromContext(ctx context.Context) Kind { + v := ctx.Value(kindCtxKey) + if v == nil { + return UnknownKind + } + return v.(Kind) +} + +// ContextWithKind annotates the context with the given kind of service +func ContextWithKind(ctx context.Context, kind Kind) context.Context { + return context.WithValue(ctx, kindCtxKey, kind) +} + +// KindLogFilter creates a log-filter that applies the given inner log-filter only if it matches the given kind. +// This can be composed with logfilter package utils like logfilter.Mute or logfilter.Add +// to adjust logging for a specific service kind. +func KindLogFilter(kind Kind, filter logfilter.LogFilter) logfilter.LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + v := KindFromContext(ctx) + if v == kind { + return filter(ctx, lvl) + } + return lvl + } +} + +type chainIDCtxKeyType struct{} + +var chainIDCtxKey = chainIDCtxKeyType{} + +// ChainIDFromContext reads what the chainID of service the context is focused on. This may be UnknownChainID if unspecified. +func ChainIDFromContext(ctx context.Context) eth.ChainID { + v := ctx.Value(chainIDCtxKey) + if v == nil { + return eth.ChainID{} + } + return v.(eth.ChainID) +} + +// ContextWithChainID annotates the context with the given chainID of service +func ContextWithChainID(ctx context.Context, chainID eth.ChainID) context.Context { + return context.WithValue(ctx, chainIDCtxKey, chainID) +} + +// ChainIDLogFilter creates a log-filter that applies the given inner log-filter only if it matches the given chainID. +// This can be composed with logfilter package utils like logfilter.Mute or logfilter.Add +// to adjust logging for a specific chain ID. +func ChainIDLogFilter(chainID eth.ChainID, filter logfilter.LogFilter) logfilter.LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + v := ChainIDFromContext(ctx) + if v == chainID { + return filter(ctx, lvl) + } + return lvl + } +} diff --git a/op-devstack/stack/orchestrator.go b/op-devstack/stack/orchestrator.go index df43643bfe3..8f3b16a151d 100644 --- a/op-devstack/stack/orchestrator.go +++ b/op-devstack/stack/orchestrator.go @@ -47,6 +47,10 @@ type Orchestrator interface { // } type SystemHook interface { + // PreHydrate runs before a system is hydrated, + // to prepare settings on the system like logging, or inspect test-scope + PreHydrate(sys System) + // PostHydrate runs after a system is hydrated, to run any checks. // This may register validation that runs at the end of the test, using the sys.T().Cleanup function. PostHydrate(sys System) @@ -118,6 +122,12 @@ func (c CombinedOption[O]) Finally(orch O) { } } +func (c CombinedOption[O]) PreHydrate(sys System) { + for _, opt := range c { + opt.PreHydrate(sys) + } +} + func (c CombinedOption[O]) PostHydrate(sys System) { for _, opt := range c { opt.PostHydrate(sys) @@ -131,6 +141,7 @@ type FnOption[O Orchestrator] struct { DeployFn func(orch O) AfterDeployFn func(orch O) FinallyFn func(orch O) + PreHydrateFn func(sys System) PostHydrateFn func(sys System) } @@ -160,6 +171,12 @@ func (f FnOption[O]) Finally(orch O) { } } +func (f FnOption[O]) PreHydrate(sys System) { + if f.PreHydrateFn != nil { + f.PreHydrateFn(sys) + } +} + func (f FnOption[O]) PostHydrate(sys System) { if f.PostHydrateFn != nil { f.PostHydrateFn(sys) @@ -191,6 +208,11 @@ func Finally[O Orchestrator](fn func(orch O)) Option[O] { return FnOption[O]{FinallyFn: fn} } +// PreHydrate hooks up an option callback to run before a new System has been hydrated by the Orchestrator. +func PreHydrate[O Orchestrator](fn func(sys System)) Option[O] { + return FnOption[O]{PostHydrateFn: fn} +} + // PostHydrate hooks up an option callback to run when a new System has been hydrated by the Orchestrator. // This is essentially a test-case preamble, // to globally configure checks or gates that should run on the test-scope level. @@ -234,6 +256,9 @@ func MakeCommon[O Orchestrator](opt Option[O]) CommonOption { orch.P().Logger().Debug("Finally option does not apply to this orchestrator type") } }, + PreHydrateFn: func(sys System) { + opt.PreHydrate(sys) + }, PostHydrateFn: func(sys System) { opt.PostHydrate(sys) }, diff --git a/op-devstack/sysext/orchestrator.go b/op-devstack/sysext/orchestrator.go index c5807e122d2..8566e7bdc66 100644 --- a/op-devstack/sysext/orchestrator.go +++ b/op-devstack/sysext/orchestrator.go @@ -59,6 +59,7 @@ func (o *Orchestrator) P() devtest.P { } func (o *Orchestrator) Hydrate(sys stack.ExtensibleSystem) { + o.sysHook.PreHydrate(sys) o.hydrateL1(sys) o.hydrateSuperchain(sys) o.hydrateClustersMaybe(sys) diff --git a/op-devstack/sysgo/faucet.go b/op-devstack/sysgo/faucet.go index 125b5ae6785..9c588979d9e 100644 --- a/op-devstack/sysgo/faucet.go +++ b/op-devstack/sysgo/faucet.go @@ -57,7 +57,11 @@ func (n *FaucetService) hydrate(system stack.ExtensibleSystem) { func WithFaucets(l1ELs []stack.L1ELNodeID, l2ELs []stack.L2ELNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithKind(ctx, stack.FaucetKind) + p := orch.P().WithCtx(ctx, "id", "dev-faucet") + + require := p.Require() require.Nil(orch.faucet, "can only support a single faucet-service in sysgo") @@ -102,11 +106,11 @@ func WithFaucets(l1ELs []stack.L1ELNodeID, l2ELs []stack.L2ELNodeID) stack.Optio Faucets: faucets, }, } - logger := orch.P().Logger().New("id", "dev-faucet") - srv, err := faucet.FromConfig(orch.P().Ctx(), cfg, logger) + logger := p.Logger() + srv, err := faucet.FromConfig(ctx, cfg, logger) require.NoError(err, "must setup faucet service") - require.NoError(srv.Start(orch.P().Ctx())) - orch.p.Cleanup(func() { + require.NoError(srv.Start(ctx)) + p.Cleanup(func() { ctx, cancel := context.WithCancel(context.Background()) cancel() // force-quit logger.Info("Closing faucet") diff --git a/op-devstack/sysgo/l1_nodes.go b/op-devstack/sysgo/l1_nodes.go index 151443b0956..e5cc0fbdcb5 100644 --- a/op-devstack/sysgo/l1_nodes.go +++ b/op-devstack/sysgo/l1_nodes.go @@ -56,6 +56,10 @@ func (n *L1CLNode) hydrate(system stack.ExtensibleSystem) { func WithL1Nodes(l1ELID stack.L1ELNodeID, l1CLID stack.L1CLNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { + ctx := orch.P().Ctx() + ctx = stack.ContextWithChainID(ctx, l1ELID.ChainID) + clP := orch.P().WithCtx(stack.ContextWithKind(ctx, stack.L1CLNodeKind), "id", l1CLID) + elP := orch.P().WithCtx(stack.ContextWithKind(ctx, stack.L1ELNodeKind), "id", l1ELID) require := orch.P().Require() l1Net, ok := orch.l1Nets.Get(l1ELID.ChainID) @@ -68,17 +72,18 @@ func WithL1Nodes(l1ELID stack.L1ELNodeID, l1CLID stack.L1CLNodeID) stack.Option[ l1Clock = orch.timeTravelClock } - blobPath := orch.p.TempDir() + blobPath := clP.TempDir() - logger := orch.P().Logger().New("id", l1CLID) - bcn := fakebeacon.NewBeacon(logger, e2eutils.NewBlobStore(), l1Net.genesis.Timestamp, blockTimeL1) - orch.p.Cleanup(func() { + clLogger := clP.Logger() + bcn := fakebeacon.NewBeacon(clLogger, e2eutils.NewBlobStore(), l1Net.genesis.Timestamp, blockTimeL1) + clP.Cleanup(func() { _ = bcn.Close() }) require.NoError(bcn.Start("127.0.0.1:0")) beaconApiAddr := bcn.BeaconAddr() require.NotEmpty(beaconApiAddr, "beacon API listener must be up") + elLogger := elP.Logger() l1Geth, fp, err := geth.InitL1( blockTimeL1, l1FinalizedDistance, @@ -88,8 +93,8 @@ func WithL1Nodes(l1ELID stack.L1ELNodeID, l1CLID stack.L1CLNodeID) stack.Option[ bcn) require.NoError(err) require.NoError(l1Geth.Node.Start()) - orch.p.Cleanup(func() { - logger.Info("Closing L1 geth") + elP.Cleanup(func() { + elLogger.Info("Closing L1 geth") _ = l1Geth.Close() }) @@ -105,7 +110,7 @@ func WithL1Nodes(l1ELID stack.L1ELNodeID, l1CLID stack.L1CLNodeID) stack.Option[ id: l1CLID, beaconHTTPAddr: beaconApiAddr, beacon: bcn, - fakepos: &FakePoS{fakepos: fp, p: orch.p}, + fakepos: &FakePoS{fakepos: fp, p: clP}, } require.True(orch.l1CLs.SetIfMissing(l1CLID, l1CLNode), "must not already exist") }) diff --git a/op-devstack/sysgo/l2_batcher.go b/op-devstack/sysgo/l2_batcher.go index ffd13ddf22e..f91b8d9c01a 100644 --- a/op-devstack/sysgo/l2_batcher.go +++ b/op-devstack/sysgo/l2_batcher.go @@ -54,7 +54,12 @@ func WithBatcherOption(opt BatcherOption) stack.Option[*Orchestrator] { func WithBatcher(batcherID stack.L2BatcherID, l1ELID stack.L1ELNodeID, l2CLID stack.L2CLNodeID, l2ELID stack.L2ELNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithChainID(ctx, batcherID.ChainID) + ctx = stack.ContextWithKind(ctx, stack.L2BatcherKind) + p := orch.P().WithCtx(ctx, "service", "op-batcher", "id", batcherID) + + require := p.Require() require.False(orch.batchers.Has(batcherID), "batcher must not already exist") l2Net, ok := orch.l2Nets.Get(l2CLID.ChainID) @@ -79,7 +84,8 @@ func WithBatcher(batcherID stack.L2BatcherID, l1ELID stack.L1ELNodeID, l2CLID st batcherSecret, err := orch.keys.Secret(devkeys.BatcherRole.Key(l2ELID.ChainID.ToBig())) require.NoError(err) - logger := orch.P().Logger().New("service", "op-batcher", "id", batcherID) + logger := p.Logger() + logger.SetContext(ctx) logger.Info("Batcher key acquired", "addr", crypto.PubkeyToAddress(batcherSecret.PublicKey)) batcherCLIConfig := &bss.CLIConfig{ @@ -114,12 +120,12 @@ func WithBatcher(batcherID stack.L2BatcherID, l1ELID stack.L1ELNodeID, l2CLID st } batcher, err := bss.BatcherServiceFromCLIConfig( - orch.P().Ctx(), "0.0.1", batcherCLIConfig, + ctx, "0.0.1", batcherCLIConfig, logger.New("service", "batcher")) require.NoError(err) - require.NoError(batcher.Start(orch.P().Ctx())) - orch.p.Cleanup(func() { - ctx, cancel := context.WithCancel(context.Background()) + require.NoError(batcher.Start(ctx)) + p.Cleanup(func() { + ctx, cancel := context.WithCancel(ctx) cancel() // force-quit logger.Info("Closing batcher") _ = batcher.Stop(ctx) diff --git a/op-devstack/sysgo/l2_challenger.go b/op-devstack/sysgo/l2_challenger.go index f0c2751fc0b..8b683befb91 100644 --- a/op-devstack/sysgo/l2_challenger.go +++ b/op-devstack/sysgo/l2_challenger.go @@ -39,13 +39,17 @@ func WithL2Challenger(challengerID stack.L2ChallengerID, l1ELID stack.L1ELNodeID supervisorID *stack.SupervisorID, clusterID *stack.ClusterID, l2CLID *stack.L2CLNodeID, l2ELIDs []stack.L2ELNodeID, ) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithKind(ctx, stack.L2ChallengerKind) + p := orch.P().WithCtx(ctx, "service", "op-challenger", "id", challengerID) + + require := p.Require() require.False(orch.challengers.Has(challengerID), "challenger must not already exist") challengerSecret, err := orch.keys.Secret(devkeys.ChallengerRole.Key(l1ELID.ChainID.ToBig())) require.NoError(err) - logger := orch.P().Logger().New("service", "op-challenger", "id", challengerID) + logger := p.Logger() logger.Info("Challenger key acquired", "addr", crypto.PubkeyToAddress(challengerSecret.PublicKey)) l1EL, ok := orch.l1ELs.Get(l1ELID) @@ -80,7 +84,7 @@ func WithL2Challenger(challengerID stack.L2ChallengerID, l1ELID stack.L1ELNodeID l2NetIDs = append(l2NetIDs, l2Net.id) } - dir := orch.P().TempDir() + dir := p.TempDir() var cfg *config.Config if interopScheduled { require.NotNil(supervisorID, "need supervisor to connect to in interop") @@ -122,12 +126,12 @@ func WithL2Challenger(challengerID stack.L2ChallengerID, l1ELID stack.L1ELNodeID require.NoError(err, "Failed to create pre-interop challenger config") } - svc, err := opchallenger.Main(orch.P().Ctx(), logger, cfg, metrics.NoopMetrics) + svc, err := opchallenger.Main(ctx, logger, cfg, metrics.NoopMetrics) require.NoError(err) - require.NoError(svc.Start(orch.P().Ctx())) - orch.p.Cleanup(func() { - ctx, cancel := context.WithCancel(context.Background()) + require.NoError(svc.Start(ctx)) + p.Cleanup(func() { + ctx, cancel := context.WithCancel(ctx) cancel() // force-quit logger.Info("Closing challenger") _ = svc.Stop(ctx) diff --git a/op-devstack/sysgo/l2_cl.go b/op-devstack/sysgo/l2_cl.go index ed5871f60b4..e08e8f6e305 100644 --- a/op-devstack/sysgo/l2_cl.go +++ b/op-devstack/sysgo/l2_cl.go @@ -125,7 +125,12 @@ func (n *L2CLNode) Stop() { func WithL2CLNode(l2CLID stack.L2CLNodeID, isSequencer bool, l1CLID stack.L1CLNodeID, l1ELID stack.L1ELNodeID, l2ELID stack.L2ELNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithChainID(ctx, l2CLID.ChainID) + ctx = stack.ContextWithKind(ctx, stack.L2CLNodeKind) + p := orch.P().WithCtx(ctx, "service", "op-node", "id", l2CLID) + + require := p.Require() l2Net, ok := orch.l2Nets.Get(l2CLID.ChainID) require.True(ok, "l2 network required") @@ -141,7 +146,7 @@ func WithL2CLNode(l2CLID stack.L2CLNodeID, isSequencer bool, l1CLID stack.L1CLNo jwtPath, jwtSecret := orch.writeDefaultJWT() - logger := orch.P().Logger().New("service", "op-node", "id", l2CLID) + logger := p.Logger() var p2pSignerSetup p2p.SignerSetup var p2pConfig *p2p.Config @@ -248,12 +253,12 @@ func WithL2CLNode(l2CLID stack.L2CLNodeID, isSequencer bool, l1CLID stack.L1CLNo id: l2CLID, cfg: nodeCfg, logger: logger, - p: orch.P(), + p: p, el: l2ELID, } require.True(orch.l2CLs.SetIfMissing(l2CLID, l2CLNode), "must not already exist") l2CLNode.Start() - orch.p.Cleanup(l2CLNode.Stop) + p.Cleanup(l2CLNode.Stop) }) } diff --git a/op-devstack/sysgo/l2_el.go b/op-devstack/sysgo/l2_el.go index eb2471f9b29..d2afd95c36e 100644 --- a/op-devstack/sysgo/l2_el.go +++ b/op-devstack/sysgo/l2_el.go @@ -39,7 +39,12 @@ func (n *L2ELNode) hydrate(system stack.ExtensibleSystem) { func WithL2ELNode(id stack.L2ELNodeID, supervisorID *stack.SupervisorID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithChainID(ctx, id.ChainID) + ctx = stack.ContextWithKind(ctx, stack.L2ELNodeKind) + p := orch.P().WithCtx(ctx, "id", id) + + require := p.Require() l2Net, ok := orch.l2Nets.Get(id.ChainID) require.True(ok, "L2 network required") @@ -55,7 +60,8 @@ func WithL2ELNode(id stack.L2ELNodeID, supervisorID *stack.SupervisorID) stack.O require.True(ok, "supervisor is required for interop") supervisorRPC = sup.userRPC } - logger := orch.P().Logger().New("id", id) + + logger := p.Logger() l2Geth, err := geth.InitL2(id.String(), l2Net.genesis, jwtPath, func(ethCfg *ethconfig.Config, nodeCfg *gn.Config) error { @@ -66,7 +72,7 @@ func WithL2ELNode(id stack.L2ELNodeID, supervisorID *stack.SupervisorID) stack.O require.NoError(err) require.NoError(l2Geth.Node.Start()) - orch.p.Cleanup(func() { + p.Cleanup(func() { logger.Info("Closing op-geth", "id", id) closeErr := l2Geth.Close() logger.Info("Closed op-geth", "id", id, "err", closeErr) diff --git a/op-devstack/sysgo/l2_proposer.go b/op-devstack/sysgo/l2_proposer.go index 1c8874c4a69..e46ad1c6b05 100644 --- a/op-devstack/sysgo/l2_proposer.go +++ b/op-devstack/sysgo/l2_proposer.go @@ -44,13 +44,18 @@ func (p *L2Proposer) hydrate(system stack.ExtensibleSystem) { func WithProposer(proposerID stack.L2ProposerID, l1ELID stack.L1ELNodeID, l2CLID *stack.L2CLNodeID, supervisorID *stack.SupervisorID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithChainID(ctx, proposerID.ChainID) + ctx = stack.ContextWithKind(ctx, stack.L2ProposerKind) + p := orch.P().WithCtx(ctx, "service", "op-proposer", "id", proposerID) + + require := p.Require() require.False(orch.proposers.Has(proposerID), "proposer must not already exist") proposerSecret, err := orch.keys.Secret(devkeys.ProposerRole.Key(proposerID.ChainID.ToBig())) require.NoError(err) - logger := orch.P().Logger().New("service", "op-proposer", "id", proposerID) + logger := p.Logger() logger.Info("Proposer key acquired", "addr", crypto.PubkeyToAddress(proposerSecret.PublicKey)) l1EL, ok := orch.l1ELs.Get(l1ELID) @@ -92,23 +97,23 @@ func WithProposer(proposerID stack.L2ProposerID, l1ELID stack.L1ELNodeID, proposerCLIConfig.RollupRpc = l2CL.userRPC } - proposer, err := ps.ProposerServiceFromCLIConfig(context.Background(), "0.0.1", proposerCLIConfig, logger) + proposer, err := ps.ProposerServiceFromCLIConfig(ctx, "0.0.1", proposerCLIConfig, logger) require.NoError(err) - require.NoError(proposer.Start(orch.P().Ctx())) - orch.p.Cleanup(func() { - ctx, cancel := context.WithCancel(context.Background()) + require.NoError(proposer.Start(ctx)) + p.Cleanup(func() { + ctx, cancel := context.WithCancel(ctx) cancel() // force-quit logger.Info("Closing proposer") _ = proposer.Stop(ctx) logger.Info("Closed proposer") }) - p := &L2Proposer{ + prop := &L2Proposer{ id: proposerID, service: proposer, userRPC: proposer.HTTPEndpoint(), } - orch.proposers.Set(proposerID, p) + orch.proposers.Set(proposerID, prop) }) } diff --git a/op-devstack/sysgo/orchestrator.go b/op-devstack/sysgo/orchestrator.go index c4a36e8d509..6b6ca5b4bf4 100644 --- a/op-devstack/sysgo/orchestrator.go +++ b/op-devstack/sysgo/orchestrator.go @@ -84,6 +84,7 @@ func (o *Orchestrator) writeDefaultJWT() (jwtPath string, secret [32]byte) { } func (o *Orchestrator) Hydrate(sys stack.ExtensibleSystem) { + o.sysHook.PreHydrate(sys) o.superchains.Range(rangeHydrateFn[stack.SuperchainID, *Superchain](sys)) o.clusters.Range(rangeHydrateFn[stack.ClusterID, *Cluster](sys)) o.l1Nets.Range(rangeHydrateFn[eth.ChainID, *L1Network](sys)) diff --git a/op-devstack/sysgo/sequencer.go b/op-devstack/sysgo/sequencer.go index c9626f297ed..e8b7cc69fb1 100644 --- a/op-devstack/sysgo/sequencer.go +++ b/op-devstack/sysgo/sequencer.go @@ -71,9 +71,12 @@ func (s *TestSequencer) hydrate(sys stack.ExtensibleSystem) { func WithTestSequencer(testSequencerID stack.TestSequencerID, l2CLID stack.L2CLNodeID, l1ELID stack.L1ELNodeID, l2ELID stack.L2ELNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithKind(ctx, stack.TestSequencerKind) + p := orch.P().WithCtx(ctx, "service", "op-test-sequencer", "id", testSequencerID) + require := p.Require() - logger := orch.P().Logger().New("service", "op-test-sequencer", "id", testSequencerID) + logger := p.Logger() l1EL, ok := orch.l1ELs.Get(l1ELID) require.True(ok, "l1 EL node required") @@ -189,14 +192,14 @@ func WithTestSequencer(testSequencerID stack.TestSequencerID, l2CLID stack.L2CLN MockRun: false, } - sq, err := sequencer.FromConfig(context.Background(), cfg, logger) + sq, err := sequencer.FromConfig(ctx, cfg, logger) require.NoError(err) - err = sq.Start(context.Background()) + err = sq.Start(ctx) require.NoError(err) - orch.p.Cleanup(func() { - ctx, cancel := context.WithCancel(context.Background()) + p.Cleanup(func() { + ctx, cancel := context.WithCancel(ctx) cancel() logger.Info("Closing sequencer") closeErr := sq.Stop(ctx) diff --git a/op-devstack/sysgo/supervisor.go b/op-devstack/sysgo/supervisor.go index e5d77e07f7e..388e85930c4 100644 --- a/op-devstack/sysgo/supervisor.go +++ b/op-devstack/sysgo/supervisor.go @@ -94,7 +94,10 @@ func (s *Supervisor) Stop() { func WithSupervisor(supervisorID stack.SupervisorID, clusterID stack.ClusterID, l1ELID stack.L1ELNodeID) stack.Option[*Orchestrator] { return stack.AfterDeploy(func(orch *Orchestrator) { - require := orch.P().Require() + ctx := orch.P().Ctx() + ctx = stack.ContextWithKind(ctx, stack.TestSequencerKind) + p := orch.P().WithCtx(ctx, "service", "op-supervisor", "id", supervisorID) + require := p.Require() l1EL, ok := orch.l1ELs.Get(l1ELID) require.True(ok, "need L1 EL node to connect supervisor to") @@ -133,13 +136,12 @@ func WithSupervisor(supervisorID stack.SupervisorID, clusterID stack.ClusterID, DatadirSyncEndpoint: "", } - plog := orch.P().Logger().New("service", "op-supervisor", "id", supervisorID) - + plog := p.Logger() supervisorNode := &Supervisor{ id: supervisorID, userRPC: "", // set on start cfg: cfg, - p: orch.P(), + p: p, logger: plog, service: nil, // set on start } diff --git a/op-service/README.md b/op-service/README.md index 764def0e64b..5430356854d 100644 --- a/op-service/README.md +++ b/op-service/README.md @@ -26,6 +26,8 @@ Pull requests: [monorepo](https://github.com/ethereum-optimism/optimism/pulls?q= ├── jsonutil - JSON encoding/decoding utils ├── locks - Lock utils, like read-write wrapped types ├── log - Logging CLI and middleware utils +├── logfilter - Logging filters +├── logmods - Log handler wrapping/unwrapping utils ├── metrics - Metrics types, metering abstractions, server utils ├── oppprof - P-Prof CLI types and server setup ├── plan - Utils to create a lazy evaluated value following dependencies diff --git a/op-service/log/dynamic.go b/op-service/log/dynamic.go index 0259fb15b20..c8b8746f11c 100644 --- a/op-service/log/dynamic.go +++ b/op-service/log/dynamic.go @@ -6,6 +6,7 @@ import ( ) type LvlSetter interface { + slog.Handler SetLogLevel(lvl slog.Level) } @@ -26,6 +27,10 @@ func (d *DynamicLogHandler) SetLogLevel(lvl slog.Level) { *d.minLvl = lvl } +func (d *DynamicLogHandler) Unwrap() slog.Handler { + return d.h +} + func (d *DynamicLogHandler) Handle(ctx context.Context, r slog.Record) error { if r.Level < *d.minLvl { // higher log level values are more critical return nil diff --git a/op-service/logfilter/filters.go b/op-service/logfilter/filters.go new file mode 100644 index 00000000000..b9f3193abf8 --- /dev/null +++ b/op-service/logfilter/filters.go @@ -0,0 +1,86 @@ +package logfilter + +import ( + "context" + "log/slog" + + "github.com/ethereum/go-ethereum/log" +) + +// LogFilter is a function that can adjust how a record is filtered. +// The ctx of the record logging call is provided to adapt to the call. +// The currently considered level of the logging is provided as input. +// The filter may return the same (to not affect the outcome), or adjust it up or down. +type LogFilter func(ctx context.Context, lvl slog.Level) slog.Level + +func (fn LogFilter) Add(next LogFilter) LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + return next(ctx, fn(ctx, lvl)) + } +} + +// Combine applies all filters, from left to right. +func Combine(filters ...LogFilter) LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + for _, fn := range filters { + lvl = fn(ctx, lvl) + } + return lvl + } +} + +// Noop does not apply any change to the log-level +func Noop() LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + return lvl + } +} + +// MuteLvl is a special log level, that we always consider muted. +const MuteLvl = log.LevelTrace - 10 + +// Mute will filter everything +func Mute() LogFilter { + return func(_ context.Context, lvl slog.Level) slog.Level { + return MuteLvl + } +} + +// As will consider everything to be the given replacement log level +func As(replacement slog.Level) LogFilter { + return func(_ context.Context, lvl slog.Level) slog.Level { + return replacement + } +} + +// Add will add a log level delta, to adjust up or down +func Add(delta slog.Level) LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + return lvl + delta + } +} + +// Minimum will mute the log if the minimum is not met +func Minimum(minLvl slog.Level) LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + if lvl < minLvl { + return MuteLvl + } + return lvl + } +} + +// IfMatch checks for a given key/value pair in the context, and applies the given next filter if found. +func IfMatch[K comparable, V comparable](k K, v V, next LogFilter) LogFilter { + return func(ctx context.Context, lvl slog.Level) slog.Level { + x := ctx.Value(k) + if x == nil { + return lvl + } + res, ok := x.(V) + if !ok || res != v { + return lvl + } + return next(ctx, lvl) + } +} diff --git a/op-service/logfilter/filters_test.go b/op-service/logfilter/filters_test.go new file mode 100644 index 00000000000..d1fa23c4bee --- /dev/null +++ b/op-service/logfilter/filters_test.go @@ -0,0 +1,48 @@ +package logfilter + +import ( + "context" + "log/slog" + "testing" + + "github.com/ethereum/go-ethereum/log" + "github.com/stretchr/testify/require" +) + +type ctxTestKeyType struct{} + +var ctxTestKey = ctxTestKeyType{} + +func TestFilters(t *testing.T) { + ctx := context.Background() + t.Run("noop", func(t *testing.T) { + require.Equal(t, log.LevelTrace, Noop()(ctx, log.LevelTrace)) + require.Equal(t, log.LevelError, Noop()(ctx, log.LevelError)) + }) + t.Run("mute", func(t *testing.T) { + require.Equal(t, MuteLvl, Mute()(ctx, log.LevelTrace)) + require.Equal(t, MuteLvl, Mute()(ctx, log.LevelError)) + }) + t.Run("as", func(t *testing.T) { + replacement := slog.Level(123) + require.Equal(t, replacement, As(replacement)(ctx, log.LevelTrace)) + require.Equal(t, replacement, As(replacement)(ctx, log.LevelError)) + }) + t.Run("add", func(t *testing.T) { + require.Equal(t, log.LevelTrace+2, Add(2)(ctx, log.LevelTrace)) + require.Equal(t, log.LevelError-2, Add(-2)(ctx, log.LevelError)) + }) + t.Run("minimum", func(t *testing.T) { + require.Equal(t, MuteLvl, Minimum(log.LevelError)(ctx, log.LevelTrace)) + require.Equal(t, MuteLvl, Minimum(log.LevelError)(ctx, log.LevelInfo)) + require.Equal(t, log.LevelError, Minimum(log.LevelError)(ctx, log.LevelError)) + require.Equal(t, log.LevelCrit, Minimum(log.LevelError)(ctx, log.LevelCrit)) + }) + t.Run("if-match", func(t *testing.T) { + // create a filter that sets the log level to Info if the key/value matches + f := IfMatch(ctxTestKey, "foo", As(log.LevelInfo)) + require.Equal(t, f(ctx, log.LevelDebug), log.LevelDebug, "no match because no key/val") + require.Equal(t, f(context.WithValue(ctx, ctxTestKey, "bar"), log.LevelDebug), log.LevelDebug, "no match because different key/val") + require.Equal(t, f(context.WithValue(ctx, ctxTestKey, "foo"), log.LevelDebug), log.LevelInfo, "match") + }) +} diff --git a/op-service/logfilter/handler.go b/op-service/logfilter/handler.go new file mode 100644 index 00000000000..070950dc9cb --- /dev/null +++ b/op-service/logfilter/handler.go @@ -0,0 +1,80 @@ +package logfilter + +import ( + "context" + "log/slog" + + "github.com/ethereum-optimism/optimism/op-service/locks" + "github.com/ethereum-optimism/optimism/op-service/logmods" +) + +// Handler provides access to log filtering customization. +// In the handler stack, through embedding, this can be available in the logger.Handler(). +type Handler interface { + slog.Handler + Set(fn LogFilter) + Add(fn LogFilter) +} + +type filterHandler struct { + inner slog.Handler + + all *locks.RWValue[LogFilter] +} + +var _ logmods.Handler = (*filterHandler)(nil) +var _ Handler = (*filterHandler)(nil) +var _ slog.Handler = (*filterHandler)(nil) + +func WrapFilterHandler(h slog.Handler) slog.Handler { + return &filterHandler{inner: h, all: &locks.RWValue[LogFilter]{Value: Noop()}} +} + +func (f *filterHandler) Unwrap() slog.Handler { + return f.inner +} + +// Enabled runs before the slog logger call is turned into a record. +// This thus can filter logging without allocating. +func (f *filterHandler) Enabled(ctx context.Context, level slog.Level) bool { + // pre-process / adjust level + level = f.all.Get()(ctx, level) + return f.inner.Enabled(ctx, level) +} + +// Handle receives the slog logger call +func (f *filterHandler) Handle(ctx context.Context, r slog.Record) error { + // We can add additional more expensive filters here. + // This runs once the + return f.inner.Handle(ctx, r) +} + +func (f *filterHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &filterHandler{ + inner: f.inner.WithAttrs(attrs), + all: f.all, + } +} + +func (f *filterHandler) WithGroup(name string) slog.Handler { + return &filterHandler{ + inner: f.inner.WithGroup(name), + all: f.all, + } +} + +// Set sets the logging filter. No other filters will apply. +func (f *filterHandler) Set(fn LogFilter) { + f.all.Set(fn) +} + +// Add adds the logging filter. The original filter will apply first (if any). +func (f *filterHandler) Add(fn LogFilter) { + f.all.Lock() + defer f.all.Unlock() + if f.all.Value == nil { + f.all.Value = fn + } else { + f.all.Value = f.all.Value.Add(fn) + } +} diff --git a/op-service/logfilter/handler_test.go b/op-service/logfilter/handler_test.go new file mode 100644 index 00000000000..32eeadfb9d5 --- /dev/null +++ b/op-service/logfilter/handler_test.go @@ -0,0 +1,37 @@ +package logfilter + +import ( + "context" + "testing" + + "github.com/stretchr/testify/require" + + "github.com/ethereum/go-ethereum/log" + + "github.com/ethereum-optimism/optimism/op-service/logmods" + "github.com/ethereum-optimism/optimism/op-service/testlog" +) + +func TestWrapFilterHandler(t *testing.T) { + // Create a logger, with capturing and filtering + logger := testlog.LoggerWithHandlerMod(t, log.LevelInfo, + testlog.WrapCaptureLogger, WrapFilterHandler) + + capturer, ok := logmods.FindHandler[testlog.Capturer](logger.Handler()) + require.True(t, ok) + + // The filter runs before capture (as outermost handler wrapper). + // It will mute things before it reaches the capturer + filterer := logger.Handler().(Handler) + filterer.Add(Mute()) + filterer.Add(IfMatch(ctxTestKey, "alice", As(log.LevelInfo))) + + // Log some things + logger.InfoContext(context.Background(), "unrecognized context 1") + logger.InfoContext(context.WithValue(context.Background(), ctxTestKey, "alice"), "matched context") + logger.InfoContext(context.Background(), "unrecognized context 2") + + // Now see if the filter worked + rec := capturer.FindLog(testlog.NewMessageFilter("matched context")) + require.Equal(t, "matched context", rec.Record.Message) +} diff --git a/op-service/logmods/logmods.go b/op-service/logmods/logmods.go new file mode 100644 index 00000000000..7dedcdde1d0 --- /dev/null +++ b/op-service/logmods/logmods.go @@ -0,0 +1,38 @@ +package logmods + +import ( + "log/slog" +) + +// HandlerMod is a log-handler wrapping function. +// Loggers may compose handlers. +// This returns a log handler that may be unwrapped, through the Handler extension interface. +type HandlerMod func(slog.Handler) slog.Handler + +// Handler is a slog.Handler you can unwrap, +// to access inner handler functionality. +type Handler interface { + slog.Handler + Unwrap() slog.Handler +} + +// FindHandler finds a handler with a particular handler type, or returns ok=false if not found. +func FindHandler[H slog.Handler](h slog.Handler) (out H, ok bool) { + for { + if h == nil { + ok = false + return // zero/nil out value + } + // Check if we found our handler + if found, tempOk := h.(H); tempOk { + return found, true + } + // continue to unwrap if we can + unwrappable, tempOk := h.(Handler) + if !tempOk { + ok = false + return // zero/nil out value + } + h = unwrappable.Unwrap() + } +} diff --git a/op-service/logmods/logmods_test.go b/op-service/logmods/logmods_test.go new file mode 100644 index 00000000000..1d34dc51740 --- /dev/null +++ b/op-service/logmods/logmods_test.go @@ -0,0 +1,58 @@ +package logmods + +import ( + "log/slog" + "testing" + + "github.com/stretchr/testify/require" +) + +type handlerA struct { + slog.Handler +} + +func wrapA(inner slog.Handler) slog.Handler { + return &handlerA{Handler: inner} +} + +type handlerB struct { + slog.Handler +} + +func wrapB(inner slog.Handler) slog.Handler { + return &handlerB{Handler: inner} +} + +func (w *handlerB) Unwrap() slog.Handler { + return w.Handler +} + +type handlerC struct { + slog.Handler +} + +func wrapC(inner slog.Handler) slog.Handler { + return &handlerC{Handler: inner} +} + +func (w *handlerC) Unwrap() slog.Handler { + return w.Handler +} + +func TestFindHandler(t *testing.T) { + t.Run("nested", func(t *testing.T) { + a := wrapA(nil) + b := wrapB(a) + c := wrapC(b) + h := c + got1, ok := FindHandler[*handlerA](h) + require.True(t, ok) + require.Equal(t, a.(*handlerA), got1) + got2, ok := FindHandler[*handlerB](h) + require.True(t, ok) + require.Equal(t, b.(*handlerB), got2) + got3, ok := FindHandler[*handlerC](h) + require.True(t, ok) + require.Equal(t, c.(*handlerC), got3) + }) +} diff --git a/op-service/rpc/api.go b/op-service/rpc/api.go index dcd08f2c37c..8c24c22c226 100644 --- a/op-service/rpc/api.go +++ b/op-service/rpc/api.go @@ -4,8 +4,10 @@ import ( "context" "fmt" - oplog "github.com/ethereum-optimism/optimism/op-service/log" "github.com/ethereum/go-ethereum/log" + + oplog "github.com/ethereum-optimism/optimism/op-service/log" + "github.com/ethereum-optimism/optimism/op-service/logmods" ) type CommonAdminAPI struct { @@ -27,7 +29,7 @@ func (n *CommonAdminAPI) SetLogLevel(ctx context.Context, lvlStr string) error { h := n.log.Handler() // We set the log level, and do not wrap the handler with an additional filter handler, // as the underlying handler would otherwise also still filter with the previous log level. - lvlSetter, ok := h.(oplog.LvlSetter) + lvlSetter, ok := logmods.FindHandler[oplog.LvlSetter](h) if !ok { return fmt.Errorf("log handler type %T cannot change log level", h) } diff --git a/op-service/testlog/capturing.go b/op-service/testlog/capturing.go index 37abb7d364c..de662fc238d 100644 --- a/op-service/testlog/capturing.go +++ b/op-service/testlog/capturing.go @@ -6,6 +6,8 @@ import ( "strings" "github.com/ethereum/go-ethereum/log" + + "github.com/ethereum-optimism/optimism/op-service/logmods" ) // CapturedAttributes forms a chain of inherited attributes, to traverse on captured log records. @@ -59,11 +61,23 @@ type CapturingHandler struct { attrs *CapturedAttributes } +var _ logmods.Handler = (*CapturingHandler)(nil) + +func WrapCaptureLogger(h slog.Handler) slog.Handler { + return &CapturingHandler{handler: h, Logs: new([]*CapturedRecord)} +} + func CaptureLogger(t Testing, level slog.Level) (_ log.Logger, ch *CapturingHandler) { - return LoggerWithHandlerMod(t, level, func(h slog.Handler) slog.Handler { - ch = &CapturingHandler{handler: h, Logs: new([]*CapturedRecord)} - return ch - }), ch + logger := LoggerWithHandlerMod(t, level, WrapCaptureLogger) + out, ok := logmods.FindHandler[*CapturingHandler](logger.Handler()) + if !ok { + panic("failed to get attached log-capturing handler") + } + return logger, out +} + +func (c *CapturingHandler) Unwrap() slog.Handler { + return c.handler } func (c *CapturingHandler) Enabled(context.Context, slog.Level) bool { @@ -215,3 +229,12 @@ func (h *CapturedRecord) AttrValue(name string) (v any) { } var _ slog.Handler = (*CapturingHandler)(nil) + +type Capturer interface { + slog.Handler + Clear() + FindLog(filters ...LogFilter) *CapturedRecord + FindLogs(filters ...LogFilter) []*CapturedRecord +} + +var _ Capturer = (*CapturingHandler)(nil) diff --git a/op-service/testlog/testlog.go b/op-service/testlog/testlog.go index 4f8f4a5c9b1..2363530e237 100644 --- a/op-service/testlog/testlog.go +++ b/op-service/testlog/testlog.go @@ -33,6 +33,7 @@ import ( "sync" oplog "github.com/ethereum-optimism/optimism/op-service/log" + "github.com/ethereum-optimism/optimism/op-service/logmods" "github.com/ethereum/go-ethereum/log" ) @@ -49,6 +50,7 @@ func init() { type Testing interface { Logf(format string, args ...any) Helper() + FailNow() Name() string Cleanup(func()) } @@ -64,12 +66,15 @@ type logger struct { buf *syncBuffer } +// This implements the full geth logger interface +var _ log.Logger = (*logger)(nil) + // Logger returns a logger which logs to the unit test log of t. func Logger(t Testing, level slog.Level) log.Logger { - return LoggerWithHandlerMod(t, level, func(h slog.Handler) slog.Handler { return h }) + return LoggerWithHandlerMod(t, level) } -func LoggerWithHandlerMod(t Testing, level slog.Level, handlerMod func(slog.Handler) slog.Handler) log.Logger { +func LoggerWithHandlerMod(t Testing, level slog.Level, handlerMods ...logmods.HandlerMod) log.Logger { // We use a sync wrapper around the buffer because it potentially gets passed into a handler later which can then // be retrieved using `Handler()` so it isn't guaranteed to always be guarded by the logger mutex. l := &logger{t: t, mu: new(sync.Mutex), buf: newSyncBuffer(new(bytes.Buffer))} @@ -85,7 +90,9 @@ func LoggerWithHandlerMod(t Testing, level slog.Level, handlerMod func(slog.Hand handler = log.NewTerminalHandlerWithLevel(l.buf, level, useColorInTestLog) } - handler = handlerMod(handler) + for _, mod := range handlerMods { + handler = mod(handler) + } l.l = log.NewLogger(handler) return l @@ -148,6 +155,58 @@ func (l *logger) Handler() slog.Handler { return l.l.Handler() } +func (l *logger) SetContext(ctx context.Context) { + // no-op: test-logger does not use default contexts. +} + +func (l *logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.LogAttrs(ctx, level, msg, attrs...) + l.flush() +} + +func (l *logger) TraceContext(ctx context.Context, msg string, args ...any) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.TraceContext(ctx, msg, args...) + l.flush() +} + +func (l *logger) DebugContext(ctx context.Context, msg string, args ...any) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.DebugContext(ctx, msg, args...) + l.flush() +} + +func (l *logger) InfoContext(ctx context.Context, msg string, args ...any) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.InfoContext(ctx, msg, args...) + l.flush() +} + +func (l *logger) WarnContext(ctx context.Context, msg string, args ...any) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.WarnContext(ctx, msg, args...) + l.flush() +} + +func (l *logger) ErrorContext(ctx context.Context, msg string, args ...any) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.ErrorContext(ctx, msg, args...) + l.flush() +} + func (l *logger) Trace(msg string, ctx ...any) { l.t.Helper() l.mu.Lock() @@ -195,7 +254,7 @@ func (l *logger) Crit(msg string, ctx ...any) { // We can't use l.l.Crit because that will exit the program before we can flush the buffer. l.l.Write(log.LevelCrit, msg, ctx...) l.flush() - os.Exit(1) + l.t.FailNow() } func (l *logger) Log(level slog.Level, msg string, ctx ...any) { @@ -207,7 +266,19 @@ func (l *logger) Log(level slog.Level, msg string, ctx ...any) { } func (l *logger) Write(level slog.Level, msg string, ctx ...any) { - l.Log(level, msg, ctx...) + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Log(level, msg, ctx...) + l.flush() +} + +func (l *logger) WriteCtx(ctx context.Context, level slog.Level, msg string, args ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.WriteCtx(ctx, level, msg, args...) + l.flush() } func (l *logger) New(ctx ...any) log.Logger {