Skip to content

feat(sae): Log state-sync updates #5932

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

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

feat(sae): Log state-sync updates #5932

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
17e7756
Add state sync logs
StephenButtolph Sep 4, 2026
8066fbb
nits
StephenButtolph Sep 4, 2026
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
2 changes: 1 addition & 1 deletion graft/evm/go.mod
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ require (
github.com/prometheus/client_golang v1.23.0
github.com/stretchr/testify v1.11.1
go.uber.org/goleak v1.3.0
go.uber.org/zap v1.27.0
golang.org/x/crypto v0.52.0
golang.org/x/exp v0.0.0-20241215155358-4a5509556b9e
golang.org/x/sync v0.20.0
Expand Down Expand Up @@ -87,7 +88,6 @@ require (
go.opentelemetry.io/otel/trace v1.44.0 // indirect
go.opentelemetry.io/proto/otlp v1.10.0 // indirect
go.uber.org/multierr v1.11.0 // indirect
go.uber.org/zap v1.27.0 // indirect
golang.org/x/net v0.55.0 // indirect
golang.org/x/sys v0.45.0 // indirect
golang.org/x/term v0.43.0 // indirect
Expand Down
1 change: 1 addition & 0 deletions graft/evm/sync/engine/client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -428,6 +428,7 @@ func (c *client) newSyncerRegistry(summary message.Syncable) (*SyncerRegistry, e
}
} else {
stateSyncer, err = evmstate.NewSyncer(
c.config.SnowCtx.Log,
c.config.LeafFetcher, c.config.ChainDB,
summary.GetBlockRoot(),
codeQueue, c.config.RequestSize,
Expand Down
3 changes: 2 additions & 1 deletion graft/evm/sync/evmstate/BUILD.bazel
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ go_library(
"//graft/evm/utils",
"//ids",
"//network/p2p",
"//utils/logging",
"//utils/math",
"//utils/timer",
"//utils/wrappers",
Expand All @@ -36,12 +37,12 @@ go_library(
"@com_github_ava_labs_libevm//core/types",
"@com_github_ava_labs_libevm//ethdb",
"@com_github_ava_labs_libevm//libevm/options",
"@com_github_ava_labs_libevm//log",
"@com_github_ava_labs_libevm//metrics",
"@com_github_ava_labs_libevm//rlp",
"@com_github_ava_labs_libevm//trie",
"@com_github_ava_labs_libevm//triedb",
"@org_golang_x_sync//errgroup",
"@org_uber_go_zap//:zap",
],
)

Expand Down
11 changes: 6 additions & 5 deletions graft/evm/sync/evmstate/state_syncer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,13 +13,13 @@ import (
"github.com/ava-labs/libevm/common"
"github.com/ava-labs/libevm/ethdb"
"github.com/ava-labs/libevm/libevm/options"
"github.com/ava-labs/libevm/log"
"github.com/ava-labs/libevm/triedb"
"golang.org/x/sync/errgroup"

"github.com/ava-labs/avalanchego/graft/evm/core/state/snapshot"
"github.com/ava-labs/avalanchego/graft/evm/sync/leaf"
"github.com/ava-labs/avalanchego/graft/evm/sync/types"
"github.com/ava-labs/avalanchego/utils/logging"
)

const (
Expand All @@ -37,6 +37,7 @@ var (

// StateSync keeps the state of the entire state sync operation.
type StateSync struct {
log logging.Logger
db ethdb.Database // database we are syncing
root common.Hash // root of the EVM state we are syncing to
trieDB *triedb.Database // trieDB on top of db we are syncing. used to restore any existing tries.
Expand Down Expand Up @@ -84,18 +85,19 @@ type CodeQueue interface {
DoneAdding()
}

func NewSyncer(fetcher leaf.Fetcher, db ethdb.Database, root common.Hash, codeQueue CodeQueue, leafsRequestSize uint16, opts ...SyncerOption) (*StateSync, error) {
func NewSyncer(log logging.Logger, fetcher leaf.Fetcher, db ethdb.Database, root common.Hash, codeQueue CodeQueue, leafsRequestSize uint16, opts ...SyncerOption) (*StateSync, error) {
if leafsRequestSize == 0 {
return nil, errLeafsRequestSizeRequired
}

// Construct with defaults, then apply options directly to stateSync.
ss := &StateSync{
log: log,
db: db,
root: root,
trieDB: triedb.NewDatabase(db, nil),
snapshot: snapshot.NewDiskLayer(db),
stats: newTrieSyncStats(),
stats: newTrieSyncStats(log),
triesInProgress: make(map[common.Hash]*trieToSync),

// [triesInProgressSem] is used to keep the number of tries syncing
Expand Down Expand Up @@ -326,8 +328,7 @@ func (t *StateSync) Finalize() error {
for _, trie := range t.triesInProgress {
for _, segment := range trie.segments {
if err := segment.batch.Write(); err != nil {
log.Error("failed to write segment batch on finalize", "err", err)
return err
return fmt.Errorf("writing segment batch on finalize: %w", err)
}
}
}
Expand Down
2 changes: 2 additions & 0 deletions graft/evm/sync/evmstate/sync_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -81,6 +81,7 @@ func testSync(t *testing.T, test syncTest, c codec.Manager, leafReqType message.

// Create the state syncer.
stateSyncer, err := NewSyncer(
loggingtest.New(t, logging.Debug),
client.NewLeafFetcher(mockClient, leafReqType, message.StateTrieNode),
clientEthDB,
root,
Expand Down Expand Up @@ -631,6 +632,7 @@ func TestSyncOverProtoLeafProtocol(t *testing.T) {
require.NoError(t, err)

stateSyncer, err := NewSyncer(
log,
leafproto.NewClient(log, net, p2p.EVMLeafRequestHandlerID, common.HashLength, tracker),
clientEthDB,
root,
Expand Down
16 changes: 12 additions & 4 deletions graft/evm/sync/evmstate/trie_segments.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@ import (
"github.com/ava-labs/libevm/common"
"github.com/ava-labs/libevm/core/rawdb"
"github.com/ava-labs/libevm/ethdb"
"github.com/ava-labs/libevm/log"
"github.com/ava-labs/libevm/trie"
"go.uber.org/zap"

"github.com/ava-labs/avalanchego/graft/evm/sync/leaf"
"github.com/ava-labs/avalanchego/graft/evm/utils"
Expand Down Expand Up @@ -133,7 +133,9 @@ func (t *trieToSync) loadSegments() error {
utils.IncrOne(lastKey)
segment.pos = lastKey // syncing will start from this key
}
log.Debug("evmstate: loading segment", "segment", segment)
t.sync.log.Debug("loading segment",
zap.Stringer("segment", segment),
)
}
return it.Error()
}
Expand Down Expand Up @@ -172,7 +174,9 @@ func (t *trieToSync) segmentFinished(ctx context.Context, idx int) error {
t.lock.Lock()
defer t.lock.Unlock()

log.Debug("evmstate: segment finished", "segment", t.segments[idx])
t.sync.log.Debug("segment finished",
zap.Stringer("segment", t.segments[idx]),
)
t.segmentsDone[idx] = struct{}{}
for {
if _, ok := t.segmentsDone[t.segmentToHashNext]; !ok {
Expand Down Expand Up @@ -323,7 +327,11 @@ func (t *trieToSync) createSegments(ctx context.Context, numSegments int) error
}
}
t.sync.stats.incTriesSegmented()
log.Debug("evmstate: trie segmented for parallel sync", "root", t.root, "account", t.account, "segments", len(t.segments))
t.sync.log.Debug("trie segmented for parallel sync",
zap.Stringer("root", t.root),
zap.Stringer("account", t.account),
zap.Int("segments", len(t.segments)),
)
return nil
}

Expand Down
18 changes: 11 additions & 7 deletions graft/evm/sync/evmstate/trie_sync_stats.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,10 @@ import (
"time"

"github.com/ava-labs/libevm/common"
"github.com/ava-labs/libevm/log"
"github.com/ava-labs/libevm/metrics"
"go.uber.org/zap"

"github.com/ava-labs/avalanchego/utils/logging"
"github.com/ava-labs/avalanchego/utils/timer"

safemath "github.com/ava-labs/avalanchego/utils/math"
Expand All @@ -26,6 +27,7 @@ const (
// trieSyncStats keeps track of the total number of leafs and tries
// completed during a sync.
type trieSyncStats struct {
log logging.Logger
lock sync.Mutex

lastUpdated time.Time
Expand All @@ -44,9 +46,10 @@ type trieSyncStats struct {
leafsRateGauge metrics.Gauge
}

func newTrieSyncStats() *trieSyncStats {
func newTrieSyncStats(log logging.Logger) *trieSyncStats {
now := time.Now()
return &trieSyncStats{
log: log,
remainingLeafs: make(map[*trieSegment]uint64),
lastUpdated: now,

Expand Down Expand Up @@ -130,16 +133,17 @@ func (t *trieSyncStats) updateETA(sinceUpdate time.Duration, now time.Time) time
if t.triesSynced == 0 {
// provide a separate ETA for the account trie syncing step since we
// don't know the total number of storage tries yet.
log.Info("state sync: syncing account trie", "ETA", roundETA(leafsTime))
t.log.Info("syncing account trie",
zap.String("ETA", roundETA(leafsTime)),
)
return leafsTime
}

triesTime := timer.EstimateETA(t.triesStartTime, uint64(t.triesSynced), uint64(t.triesSynced+t.triesRemaining))
eta := max(leafsTime, triesTime)
log.Info(
"state sync: syncing storage tries",
"triesRemaining", t.triesRemaining,
"ETA", roundETA(eta),
t.log.Info("syncing storage tries",
zap.Int("triesRemaining", t.triesRemaining),
zap.String("ETA", roundETA(eta)),
)
return eta
}
Expand Down
3 changes: 3 additions & 0 deletions graft/evm/sync/evmstate/trie_sync_stats_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@ import (

"github.com/ava-labs/libevm/metrics"
"github.com/stretchr/testify/require"

"github.com/ava-labs/avalanchego/utils/logging"
)

func TestETAShouldNotOverflow(t *testing.T) {
Expand All @@ -17,6 +19,7 @@ func TestETAShouldNotOverflow(t *testing.T) {
start := now.Add(-6 * time.Hour)

stats := &trieSyncStats{
log: logging.NoLog{},
triesStartTime: start,
triesSynced: 100_000,
triesRemaining: 450_000,
Expand Down
8 changes: 6 additions & 2 deletions graft/evm/sync/evmstate/trie_sync_tasks.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,9 @@ import (
"github.com/ava-labs/libevm/core/rawdb"
"github.com/ava-labs/libevm/core/types"
"github.com/ava-labs/libevm/ethdb"
"github.com/ava-labs/libevm/log"
"github.com/ava-labs/libevm/rlp"
"github.com/ava-labs/libevm/trie"
"go.uber.org/zap"

"github.com/ava-labs/avalanchego/graft/evm/sync/syncutils"
)
Expand Down Expand Up @@ -129,7 +129,11 @@ func (s *storageTrieTask) OnStart() (bool, error) {
if err := writeAccountStorageSnapshotFromTrie(s.sync.db.NewBatch(), s.sync.batchSize, account, storageTrie); err != nil {
// If the storage trie cannot be iterated (due to an incomplete trie from pruning this storage trie in the past)
// then we re-sync it here. Therefore, this error is not fatal and we can safely continue here.
log.Info("could not populate storage snapshot from trie with existing root, syncing from peers instead", "account", account, "root", s.root, "err", err)
s.sync.log.Info("could not populate storage snapshot from trie with existing root, syncing from peers instead",
zap.Stringer("account", account),
zap.Stringer("root", s.root),
zap.Error(err),
)
return false, nil
}
}
Expand Down
9 changes: 9 additions & 0 deletions vms/saevm/cchain/statesync/acceptor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,8 @@ package statesync
import (
"context"

"go.uber.org/zap"

"github.com/ava-labs/avalanchego/snow/engine/common"
"github.com/ava-labs/avalanchego/snow/engine/snowman/block"
"github.com/ava-labs/avalanchego/vms/saevm/cchain/state"
Expand Down Expand Up @@ -85,10 +87,17 @@ func (h *Handler) sync(ctx context.Context, evmSyncer *statesync.Syncer, s *summ
return err
}

h.snowCtx.Log.Info("syncing cross-chain state",
zap.Stringer("settledCrossChainRoot", s.settledRoot),
zap.Uint64("settledHeight", settledHeight),
zap.Stringer("acceptedHash", s.summary.AcceptedHash),
zap.Uint64("acceptedHeight", s.summary.AcceptedHeight),
)
crossChainSyncer := state.NewSyncer(h.network.Network, h.network.PeerTracker, h.state, s.settledRoot, settledHeight)
if err := crossChainSyncer.Sync(ctx); err != nil {
return err
}
h.snowCtx.Log.Info("finished syncing cross-chain state")

return evmSyncer.WriteSynced(&s.summary)
}
16 changes: 16 additions & 0 deletions vms/saevm/statesync/syncer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import (
"github.com/ava-labs/libevm/core/types"
"github.com/ava-labs/libevm/ethdb"
"github.com/ava-labs/libevm/params"
"go.uber.org/zap"
"golang.org/x/sync/errgroup"

"github.com/ava-labs/avalanchego/graft/evm/sync/evmstate"
Expand Down Expand Up @@ -103,6 +104,11 @@ func (s *Syncer) Sync(ctx context.Context, summary *Summary) error {
maxLeafRequestSize = 1024
)

s.snowCtx.Log.Info("syncing blocks",
zap.Stringer("acceptedHash", summary.AcceptedHash),
zap.Uint64("acceptedHeight", summary.AcceptedHeight),
zap.Uint64("numToFetch", numBlocksToFetch),
)
Comment on lines +107 to +111

@JonathanOppenheimer JonathanOppenheimer Sep 5, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not put this log in vms/evm/sync/block? like command click on the blockSyncer.Sync. I feel like all the logs should go as close as possible to the real source just like we do with comments.

blockSyncer := syncblock.NewSyncer(
s.snowCtx.Log,
syncblock.NewClient(s.network.Network, s.network.PeerTracker),
Expand All @@ -115,6 +121,7 @@ func (s *Syncer) Sync(ctx context.Context, summary *Summary) error {
if err := blockSyncer.Sync(ctx); err != nil {
return err
}
s.snowCtx.Log.Info("finished syncing blocks")

// With blocks now on disk, we can find the state root
hdr := rawdb.ReadHeader(s.db, summary.AcceptedHash, summary.AcceptedHeight)
Expand All @@ -139,12 +146,20 @@ func (s *Syncer) Sync(ctx context.Context, summary *Summary) error {
// The snapshot MUST either be empty or match the requested root.
// It will be regenerated anyway, so we can always wipe it.
// TODO(powerslider): Push into EVM syncer.
s.snowCtx.Log.Info("wiping snapshot before syncing state")

@JonathanOppenheimer JonathanOppenheimer Sep 5, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe put this above the comment? so the comment is still placed right above the relevant line?

if err := graftsnap.WipeSnapshotSync(ctx, s.db); err != nil {
return fmt.Errorf("wiping snapshot: %w", err)
}
s.snowCtx.Log.Info("finished wiping snapshot")

// TODO(powerslider): Remove dependency on graft.

@JonathanOppenheimer JonathanOppenheimer Sep 5, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same here?

s.snowCtx.Log.Info("syncing state",
zap.Stringer("settledRoot", hdr.Root),
zap.Stringer("acceptedHash", summary.AcceptedHash),
zap.Uint64("acceptedHeight", summary.AcceptedHeight),
)
evmSyncer, err := evmstate.NewSyncer(
s.snowCtx.Log,
hashdb.NewClient(
s.snowCtx.Log,
s.network.Network,
Expand Down Expand Up @@ -173,6 +188,7 @@ func (s *Syncer) Sync(ctx context.Context, summary *Summary) error {
// This is not required for correctness.
return errors.Join(err, evmSyncer.Finalize())
}
s.snowCtx.Log.Info("finished syncing state")
return nil
}

Expand Down
Loading