Skip to content

Add re-exec debug log on every executed block #4438

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 2 commits into
base: master
Choose a base branch
from
Draft

Add re-exec debug log on every executed block #4438

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
13ff43e
Add debug log to re-execution on every block
aaronbuchwald Oct 29, 2025
ab7b16a
Switch to using locally defined log constructor that respects log-lev…
aaronbuchwald Oct 29, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
35 changes: 30 additions & 5 deletions tests/reexecute/c/vm_reexecute_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,6 +62,8 @@ var (
chanSizeArg int
executionTimeout time.Duration
labelsArg string
logLevelArg string
logLevel logging.Level

metricsServerEnabledArg bool
metricsCollectorEnabledArg bool
Expand Down Expand Up @@ -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, ", "))
Expand All @@ -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)
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand All @@ -239,7 +260,7 @@ func benchmarkReexecuteRange(
}()

config := vmExecutorConfig{
Log: tests.NewDefaultLogger("vm-executor"),
Log: newLogger("vm-executor"),
Registry: consensusRegistry,
ExecutionTimeout: executionTimeout,
StartBlock: startBlock,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -427,6 +448,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
Expand Down Expand Up @@ -591,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
Expand Down
Loading