From 13ff43eec7e6fd2df9959429787bd7c215eaf02b Mon Sep 17 00:00:00 2001 From: Aaron Buchwald Date: Wed, 29 Oct 2025 13:36:13 -0400 Subject: [PATCH 1/2] Add debug log to re-execution on every block --- tests/reexecute/c/vm_reexecute_test.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/reexecute/c/vm_reexecute_test.go b/tests/reexecute/c/vm_reexecute_test.go index 605b26db9b42..c68d590a26dc 100644 --- a/tests/reexecute/c/vm_reexecute_test.go +++ b/tests/reexecute/c/vm_reexecute_test.go @@ -427,6 +427,10 @@ func (e *vmExecutor) executeSequence(ctx context.Context, blkChan <-chan blockRe zap.Uint64("height", blkResult.Height), zap.Duration("eta", eta), ) + } else { + e.config.Log.Debug("executing block", + zap.Uint64("height", blkResult.Height), + ) } if err := e.execute(ctx, blkResult.BlockBytes); err != nil { return err From ab7b16a7e92db9e3f0360a3a6d28097ed78ff2be Mon Sep 17 00:00:00 2001 From: Aaron Buchwald Date: Wed, 29 Oct 2025 13:46:01 -0400 Subject: [PATCH 2/2] Switch to using locally defined log constructor that respects log-level flag --- tests/reexecute/c/vm_reexecute_test.go | 31 +++++++++++++++++++++----- 1 file changed, 26 insertions(+), 5 deletions(-) diff --git a/tests/reexecute/c/vm_reexecute_test.go b/tests/reexecute/c/vm_reexecute_test.go index c68d590a26dc..3a4499a27dbe 100644 --- a/tests/reexecute/c/vm_reexecute_test.go +++ b/tests/reexecute/c/vm_reexecute_test.go @@ -62,6 +62,8 @@ var ( chanSizeArg int executionTimeout time.Duration labelsArg string + logLevelArg string + logLevel logging.Level metricsServerEnabledArg bool metricsCollectorEnabledArg bool @@ -107,6 +109,7 @@ func TestMain(m *testing.M) { flag.BoolVar(&metricsServerEnabledArg, "metrics-server-enabled", false, "Whether to enable the metrics server.") flag.BoolVar(&metricsCollectorEnabledArg, "metrics-collector-enabled", false, "Whether to enable the metrics collector (if true, then metrics-server-enabled must be true as well).") flag.StringVar(&labelsArg, "labels", "", "Comma separated KV list of metric labels to attach to all exported metrics. Ex. \"owner=tim,runner=snoopy\"") + flag.StringVar(&logLevelArg, "log-level", "info", "Log level for the benchmark (verbo, debug, trace, info, warn, error, fatal, off).") predefinedConfigKeys := slices.Collect(maps.Keys(predefinedConfigs)) predefinedConfigOptionsStr := fmt.Sprintf("[%s]", strings.Join(predefinedConfigKeys, ", ")) @@ -119,6 +122,14 @@ func TestMain(m *testing.M) { flag.Parse() + // Parse the log level + var err error + logLevel, err = logging.ToLevel(logLevelArg) + if err != nil { + fmt.Fprintf(os.Stderr, "invalid log level %q: %v\n", logLevelArg, err) + os.Exit(1) + } + if metricsCollectorEnabledArg && !metricsServerEnabledArg { fmt.Fprint(os.Stderr, "metrics collector is enabled but metrics server is disabled.\n") os.Exit(1) @@ -146,6 +157,16 @@ func TestMain(m *testing.M) { m.Run() } +// newLogger creates a named logger with the configured log level. +func newLogger(name string) logging.Logger { + logFormat, err := logging.ToFormat(logging.AutoString, os.Stdout.Fd()) + if err != nil { + // This should never happen since auto is a valid log format + panic(err) + } + return logging.NewLogger(name, logging.NewWrappedCore(logLevel, os.Stdout, logFormat.ConsoleEncoder())) +} + func BenchmarkReexecuteRange(b *testing.B) { require.Equalf(b, 1, b.N, "BenchmarkReexecuteRange expects to run a single iteration because it overwrites the input current-state, but found (b.N=%d)", b.N) b.Run(fmt.Sprintf("[%d,%d]-Config-%s-Runner-%s", startBlockArg, endBlockArg, configNameArg, runnerNameArg), func(b *testing.B) { @@ -189,7 +210,7 @@ func benchmarkReexecuteRange( consensusRegistry := prometheus.NewRegistry() r.NoError(prefixGatherer.Register("avalanche_snowman", consensusRegistry)) - log := tests.NewDefaultLogger("c-chain-reexecution") + log := newLogger("c-chain-reexecution") if metricsServerEnabled { serverAddr := startServer(b, log, prefixGatherer) @@ -216,7 +237,7 @@ func benchmarkReexecuteRange( blockChan, err := createBlockChanFromLevelDB(b, blockDir, startBlock, endBlock, chanSize) r.NoError(err) - dbLogger := tests.NewDefaultLogger("db") + dbLogger := newLogger("db") db, err := leveldb.New(vmDBDir, nil, dbLogger, prometheus.NewRegistry()) r.NoError(err) @@ -239,7 +260,7 @@ func benchmarkReexecuteRange( }() config := vmExecutorConfig{ - Log: tests.NewDefaultLogger("vm-executor"), + Log: newLogger("vm-executor"), Registry: consensusRegistry, ExecutionTimeout: executionTimeout, StartBlock: startBlock, @@ -303,7 +324,7 @@ func newMainnetCChainVM( CChainID: mainnetCChainID, AVAXAssetID: mainnetAvaxAssetID, - Log: tests.NewDefaultLogger("mainnet-vm-reexecution"), + Log: newLogger("mainnet-vm-reexecution"), SharedMemory: atomicMemory.NewSharedMemory(mainnetCChainID), BCLookup: ids.NewAliaser(), Metrics: metricsGatherer, @@ -595,7 +616,7 @@ func startCollector(tb testing.TB, log logging.Logger, name string, labels map[s startPromCtx, cancel := context.WithTimeout(tb.Context(), tests.DefaultTimeout) defer cancel() - logger := tests.NewDefaultLogger("prometheus") + logger := newLogger("prometheus") r.NoError(tmpnet.StartPrometheus(startPromCtx, logger)) var sdConfigFilePath string