Skip to content
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

Jump to bottom

v0.3.1 snap sync mode still requires to sync full chain #118

Closed
astudnev opened this issue May 31, 2024 · 5 comments
Closed

v0.3.1 snap sync mode still requires to sync full chain #118

astudnev opened this issue May 31, 2024 · 5 comments

Comments

@astudnev
Copy link

astudnev commented May 31, 2024 •
edited
Loading

System information

Network: mainnet

if you are running a local node, please provide the following information:
op-node version: op-node 0.3.2
op-geth version: op-geth 0.3.1
OS & Version: Linux

Expected behaviour

With snap mode it syncs the network in 1 hour as descibed in docs
In base and optimism it really happens this way

Actual behaviour

after downloading headers opbnb starts indexing full chain from 1st block

Steps to reproduce the behaviour

[Eth]
[Eth]
NetworkId = 204
SyncMode = "snap"
EthDiscoveryURLs = []
SnapDiscoveryURLs = []
NoPruning = false
NoPrefetch = false
TxLookupLimit = 2350000
StateHistory = 90000
LightPeers = 100
DatabaseCache = 4096
DatabaseFreezer = ""
TrieCleanCache = 1228
TrieDirtyCache = 2048
TrieTimeout = 3600000000000
TrieCommitInterval = 0
SnapshotCache = 819
Preimages = true
FilterLogCacheSize = 32
EnablePreimageRecording = false
RPCGasCap = 50000000
RPCEVMTimeout = 5000000000
RPCTxFeeCap = 1e+000
RollupSequencerHTTP = "https://opbnb-mainnet-rpc.bnbchain.org"
RollupHistoricalRPC = ""
RollupHistoricalRPCTimeout = 0
RollupDisableTxPoolGossip = false
RollupDisableTxPoolAdmission = false
RollupHaltOnIncompatibleProtocolVersion = ""

[Eth.Miner]
GasFloor = 0
GasCeil = 150000000
GasPrice = 1000000000
Recommit = 2000000000
NewPayloadTimeout = 2000000000
RollupComputePendingBlock = false

[Eth.TxPool]
Locals = []
NoLocals = false
Journal = "transactions.rlp"
Rejournal = 3600000000000
JournalRemote = false
PriceLimit = 1
PriceBump = 10
AccountSlots = 200
GlobalSlots = 10000
AccountQueue = 200
GlobalQueue = 5000
Lifetime = 10800000000000
ReannounceTime = 315360000000000000
ReannounceRemotes = false

[Eth.BlobPool]
Datadir = "blobpool"
Datacap = 10737418240
PriceBump = 100

[Eth.GPO]
Blocks = 20
Percentile = 60
MaxHeaderHistory = 1024
MaxBlockHistory = 1024
MaxPrice = 500000000000
IgnorePrice = 2
MinSuggestedPriorityFee = 1000000

[Node]
DataDir = "/app/data"
IPCPath = "geth.ipc"
HTTPHost = "0.0.0.0"
HTTPPort = 8545
HTTPVirtualHosts = ["*"]
HTTPModules = ["web3", "debug", "eth", "txpool", "net", "engine"]
AuthAddr = "0.0.0.0"
AuthPort = 8551
AuthVirtualHosts = ["*"]
WSHost = "0.0.0.0"
WSPort = 8546
WSModules = ["debug", "eth", "txpool", "net", "engine", "web3"]
GraphQLVirtualHosts = ["localhost"]
BatchRequestLimit = 1000
BatchResponseMaxSize = 25000000
JWTSecret = "/app/config/jwtsecret"
DBEngine = "pebble"

[Node.P2P]
MaxPeers = 10
NoDiscovery = false
DiscoveryV4 = true
StaticNodes = []
TrustedNodes = []
ListenAddr = ":30305"
DiscAddr = ""
EnableMsgEvents = false

[Node.HTTPTimeouts]
ReadTimeout = 30000000000
ReadHeaderTimeout = 30000000000
WriteTimeout = 30000000000
IdleTimeout = 120000000000

"Path": "op-node",
        "Args": [
            "--l1.trustrpc",
            "--sequencer.l1-confs=15",
            "--verifier.l1-confs=15",
            "--l1.http-poll-interval",
            "3s",
            "--l1.epoch-poll-interval",
            "45s",
            "--l1.rpc-max-batch-size",
            "20",
            "--rollup.config=/app/config/chain/rollup.json",
            "--rpc.addr=0.0.0.0",
            "--rpc.port=8546",
            "--p2p.sync.req-resp",
            "--p2p.listen.ip=0.0.0.0",
            "--p2p.listen.tcp=9003",
            "--p2p.listen.udp=9003",
            "--snapshotlog.file=/app/data/snapshot.log",
            "--p2p.bootnodes=enr:-J24QA9sgVxbZ0KoJ7-1gx_szfc7Oexzz7xL2iHS7VMHGj2QQaLc_IQZmFthywENgJWXbApj7tw7BiouKDOZD4noWEWGAYppffmvgmlkgnY0gmlwhDbjSM6Hb3BzdGFja4PMAQCJc2VjcDI1NmsxoQKetGQX7sXd4u8hZr6uayTZgHRDvGm36YaryqZkgnidS4N0Y3CCIyuDdWRwgiMs,enr:-J24QPSZMaGw3NhO6Ll25cawknKcOFLPjUnpy72HCkwqaHBKaaR9ylr-ejx20INZ69BLLj334aEqjNHKJeWhiAdVcn-GAYv28FmZgmlkgnY0gmlwhDTDWQOHb3BzdGFja4PMAQCJc2VjcDI1NmsxoQJ-_5GZKjs7jaB4TILdgC8EwnwyL3Qip89wmjnyjvDDwoN0Y3CCIyuDdWRwgiMs",
            "--metrics.enabled",
            "--metrics.addr=0.0.0.0",
            "--metrics.port=7300",
            "--pprof.enabled",
            "--rpc.enable-admin",
            "--l1=https://bsc-dataseed.bnbchain.org",
            "--l2=http://op-geth:8551",
            "--l2.jwt-secret=/app/config/jwtsecret",
            "--l2.engine-sync=true",
            "--l2.skip-sync-start-check=true",
            "--log.level=debug"
        ],

"Path": "geth",
        "Args": [
            "--config",
            "/app/config/geth/config.toml",
            "--nat=extip:65.108.105.189",
            "--bootnodes=enr:-KO4QHs5qh_kPFcjMgqkuN9dbxXT4C5Cjad4SAheaUxveCbJQ3XdeMMDHeHilHyqisyYQAByfdhzyKAdUp2SvyzWeBqGAYvRDf80g2V0aMfGhHFtSjqAgmlkgnY0gmlwhDaykUmJc2VjcDI1NmsxoQJUevTL3hJwj21IT2GC6VaNqVQEsJFPtNtO-ld5QTNCfIRzbmFwwIN0Y3CCdl-DdWRwgnZf,enr:-KO4QKIByq-YMjs6IL2YCNZEmlo3dKWNOy4B6sdqE3gjOrXeKdNbwZZGK_JzT1epqCFs3mujjg2vO1lrZLzLy4Rl7PyGAYvRA8bEg2V0aMfGhHFtSjqAgmlkgnY0gmlwhDbjSM6Jc2VjcDI1NmsxoQNQhJ5pqCPnTbK92gEc2F98y-u1OgZVAI1Msx-UiHezY4RzbmFwwIN0Y3CCdl-DdWRwgnZf",
            "--cache=32000",
            "--cache.preimages"
        ],

Backtrace

INFO [05-31|06:28:17.562] Imported new chain segment               number=11536      hash=a1187a..636053 blocks=93  txs=93  mgas=5.004  elapsed=8.037s    mgasps=0.623 age=9mo3w2d snapdiffs=2.46MiB   triedirty=569.66KiB trieimutabledirty=0.00B
INFO [05-31|06:28:18.071] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:18.166] Forkchoice requested sync to new head    number=25,383,175 hash=b1062d..575c7f finalized=unknown
INFO [05-31|06:28:19.151] Forkchoice requested sync to new head    number=25,383,176 hash=85d814..5d37ce finalized=unknown
INFO [05-31|06:28:20.633] Forkchoice requested sync to new head    number=25,383,177 hash=729829..63c433 finalized=unknown
INFO [05-31|06:28:21.072] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:21.323] Forkchoice requested sync to new head    number=25,383,178 hash=6b0d70..45992b finalized=unknown
INFO [05-31|06:28:22.150] Forkchoice requested sync to new head    number=25,383,179 hash=88c7e2..92b516 finalized=unknown
INFO [05-31|06:28:23.154] Forkchoice requested sync to new head    number=25,383,180 hash=21b09a..dcd8f4 finalized=unknown
INFO [05-31|06:28:24.073] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:24.357] Forkchoice requested sync to new head    number=25,383,181 hash=384d96..5cc339 finalized=unknown
INFO [05-31|06:28:25.308] Forkchoice requested sync to new head    number=25,383,182 hash=193dba..ec9a21 finalized=unknown
INFO [05-31|06:28:26.334] Imported new chain segment               number=11871      hash=f4314a..74bfb9 blocks=335 txs=335 mgas=17.880 elapsed=8.771s    mgasps=2.038 age=9mo3w2d snapdiffs=2.53MiB   triedirty=569.99KiB trieimutabledirty=0.00B
INFO [05-31|06:28:26.376] Forkchoice requested sync to new head    number=25,383,183 hash=2a284c..668863 finalized=unknown
INFO [05-31|06:28:27.073] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:27.326] Forkchoice requested sync to new head    number=25,383,184 hash=c30d2c..863eac finalized=unknown
INFO [05-31|06:28:28.247] Forkchoice requested sync to new head    number=25,383,185 hash=81ec8a..9f8adc finalized=unknown
INFO [05-31|06:28:29.161] Forkchoice requested sync to new head    number=25,383,186 hash=c78e9b..54cd45 finalized=unknown
INFO [05-31|06:28:30.074] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:30.181] Forkchoice requested sync to new head    number=25,383,187 hash=557b69..49e5cc finalized=unknown
INFO [05-31|06:28:31.513] Forkchoice requested sync to new head    number=25,383,188 hash=8f52f3..143de2 finalized=unknown
INFO [05-31|06:28:32.273] Forkchoice requested sync to new head    number=25,383,189 hash=d81cba..c11323 finalized=unknown
INFO [05-31|06:28:33.074] loop print db stats                      database=/app/data/geth/chaindata               comp_time=251,633,601,223 write_delay_count=0 write_delay_time=0 non_level0_comp_count=1285 level0_comp_count=1252
INFO [05-31|06:28:33.239] Forkchoice requested sync to new head    number=25,383,190 hash=8e5be5..1c8b34 finalized=unknown

When submitting logs: please submit them as text and not screenshots.
@astudnev astudnev changed the title snap sync mode still requires to sync full chain v0.3.1 snap sync mode still requires to sync full chain May 31, 2024
@astudnev
Copy link
Author

start of logs:

INFO [05-31|05:16:32.746] Starting Geth on Ethereum mainnet...
INFO [05-31|05:16:32.747] Maximum peer count                       ETH=10 LES=0 total=10
INFO [05-31|05:16:32.748] Smartcard socket not found, disabling    err="stat /run/pcscd/pcscd.comm: no such file or directory"
INFO [05-31|05:16:32.752] Set global gas cap                       cap=50,000,000
INFO [05-31|05:16:32.752] Initializing the KZG library             backend=gokzg
INFO [05-31|05:16:32.763] Allocated trie memory caches             clean=4.69GiB dirty=7.81GiB
INFO [05-31|05:16:32.763] Using pebble as the backing database
INFO [05-31|05:16:32.763] Allocated cache and file handles         database=/app/data/geth/chaindata cache=15.62GiB handles=524,288 "memory table"=3.91GiB
INFO [05-31|05:16:32.849] loop print db stats                      database=/app/data/geth/chaindata comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:32.850] Opened ancient database                  database=/app/data/geth/chaindata/ancient/chain readonly=false
INFO [05-31|05:16:32.850] State scheme set to already existing     scheme=hash
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [05-31|05:16:32.865] Chain ID:  204 (opBNBMainnet)
INFO [05-31|05:16:32.865] Consensus: Optimism
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] Pre-Merge hard forks (block based):
INFO [05-31|05:16:32.865]  - Homestead:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/homestead.md)
INFO [05-31|05:16:32.865]  - Tangerine Whistle (EIP 150): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/tangerine-whistle.md)
INFO [05-31|05:16:32.865]  - Spurious Dragon/1 (EIP 155): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [05-31|05:16:32.865]  - Spurious Dragon/2 (EIP 158): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/spurious-dragon.md)
INFO [05-31|05:16:32.865]  - Byzantium:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/byzantium.md)
INFO [05-31|05:16:32.865]  - Constantinople:              #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/constantinople.md)
INFO [05-31|05:16:32.865]  - Petersburg:                  #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/petersburg.md)
INFO [05-31|05:16:32.865]  - Istanbul:                    #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/istanbul.md)
INFO [05-31|05:16:32.865]  - Muir Glacier:                #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/muir-glacier.md)
INFO [05-31|05:16:32.865]  - Berlin:                      #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/berlin.md)
INFO [05-31|05:16:32.865]  - London:                      #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/london.md)
INFO [05-31|05:16:32.865]  - Arrow Glacier:               #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/arrow-glacier.md)
INFO [05-31|05:16:32.865]  - Gray Glacier:                #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/gray-glacier.md)
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] Merge configured:
INFO [05-31|05:16:32.865]  - Hard-fork specification:    https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/paris.md
INFO [05-31|05:16:32.865]  - Network known to be merged: true
INFO [05-31|05:16:32.865]  - Total terminal difficulty:  0
INFO [05-31|05:16:32.865]  - Merge netsplit block:       #0
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] Post-Merge hard forks (timestamp based):
INFO [05-31|05:16:32.865]  - Regolith:                    @0
INFO [05-31|05:16:32.865] OPBNB hard forks (block based):
INFO [05-31|05:16:32.865]  - Fermat:              #9397477
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] ---------------------------------------------------------------------------------------------------------------------------------------------------------
INFO [05-31|05:16:32.865]
INFO [05-31|05:16:32.865] Loaded most recent local block           number=0 hash=4dd611..dd6df4 td=0 age=9mo3w2d
WARN [05-31|05:16:32.865] Failed to load snapshot                  err="missing or corrupted snapshot"
INFO [05-31|05:16:32.865] Rebuilding state snapshot
INFO [05-31|05:16:32.868] Initialising Ethereum protocol           network=204 dbversion=<nil>
INFO [05-31|05:16:32.868] Resuming state snapshot generation       root=5cc58a..27bf2c accounts=0 slots=0 storage=0.00B dangling=0 elapsed=2.680ms
INFO [05-31|05:16:32.868] Initialized transaction indexer          limit=2,350,000
INFO [05-31|05:16:32.868] Entered PoS stage
INFO [05-31|05:16:32.868] Regenerated local transaction journal    transactions=0 accounts=0
INFO [05-31|05:16:32.868] Enabled snap sync                        head=0 hash=4dd611..dd6df4
INFO [05-31|05:16:32.868] Chain post-merge, sync via beacon client
INFO [05-31|05:16:32.869] Gasprice oracle is ignoring threshold set threshold=2
WARN [05-31|05:16:32.869] Engine API enabled                       protocol=eth
INFO [05-31|05:16:32.869] Starting peer-to-peer node               instance=Geth/v0.1.0-unstable-e8d79859/linux-amd64/go1.21.10
INFO [05-31|05:16:32.889] New local node record                    seq=1,717,132,592,888 id=91b1fe88ec0e57ae ip=65.108.105.189 udp=30305 tcp=30305
INFO [05-31|05:16:32.889] Started P2P networking                   self=enode://e47a6ccaa620d6e532595d0d33033119d2d540c82a2830ce08949b928e4d801f3ade712275e24a0bc84d229c753e911d0278131fc5ebb58c31b842224db39d7e@65.108.105.189:30305
INFO [05-31|05:16:32.891] IPC endpoint opened                      url=/app/data/geth.ipc
INFO [05-31|05:16:32.891] Loaded JWT secret file                   path=/app/config/jwtsecret crc32=0x758e46f0
INFO [05-31|05:16:32.892] HTTP server started                      endpoint=[::]:8545 auth=false prefix= cors= vhosts=*
INFO [05-31|05:16:32.892] WebSocket enabled                        url=ws://[::]:8546
INFO [05-31|05:16:32.892] WebSocket enabled                        url=ws://[::]:8551
INFO [05-31|05:16:32.892] HTTP server started                      endpoint=[::]:8551 auth=true  prefix= cors=localhost vhosts=*
INFO [05-31|05:16:32.980] Generated state snapshot                 accounts=2064 slots=2076 storage=381.44KiB dangling=0 elapsed=114.827ms
INFO [05-31|05:16:35.849] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:38.850] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:41.851] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:44.851] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:47.852] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:50.853] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:53.854] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:56.854] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:16:59.854] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:02.855] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:05.856] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:08.857] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:11.857] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:14.858] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:17.858] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:20.858] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:23.858] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:26.859] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:29.860] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:32.861] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
WARN [05-31|05:17:34.320] Served eth_getBlockByNumber              conn=172.16.219.145:36290 reqid=3 duration="47.9µs" err="finalized block not found"
WARN [05-31|05:17:34.321] Served eth_getBlockByNumber              conn=172.16.219.145:36290 reqid=4 duration="19.146µs" err="safe block not found"
INFO [05-31|05:17:34.492] Snap sync complete, auto disabling
INFO [05-31|05:17:35.861] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:38.861] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
WARN [05-31|05:17:40.234] Ignoring payload with missing parent     number=25,378,936 hash=6ef3da..5365d3 parent=cde49d..0930a3
INFO [05-31|05:17:40.235] Forkchoice requested sync to new head    number=25,378,936 hash=6ef3da..5365d3 finalized=unknown
INFO [05-31|05:17:40.467] Syncing beacon headers                   downloaded=512 left=25,378,423 eta=3h11m37.019s
INFO [05-31|05:17:40.528] Forkchoice requested sync to new head    number=25,378,937 hash=514bbd..74a7c3 finalized=unknown
INFO [05-31|05:17:41.175] Forkchoice requested sync to new head    number=25,378,938 hash=4f0821..e5a4b3 finalized=unknown
INFO [05-31|05:17:41.861] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:42.154] Forkchoice requested sync to new head    number=25,378,939 hash=b1faa5..2b76a8 finalized=unknown
INFO [05-31|05:17:43.178] Forkchoice requested sync to new head    number=25,378,940 hash=0bddc6..f72dce finalized=unknown
INFO [05-31|05:17:44.157] Forkchoice requested sync to new head    number=25,378,941 hash=960f76..9bb7b6 finalized=unknown
INFO [05-31|05:17:44.862] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:45.152] Forkchoice requested sync to new head    number=25,378,942 hash=af1ff3..c5a3ce finalized=unknown
INFO [05-31|05:17:46.164] Forkchoice requested sync to new head    number=25,378,943 hash=9c3a1d..2fad61 finalized=unknown
INFO [05-31|05:17:47.155] Forkchoice requested sync to new head    number=25,378,944 hash=879632..d21d4c finalized=unknown
INFO [05-31|05:17:47.862] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:48.146] Forkchoice requested sync to new head    number=25,378,945 hash=cae00a..b94001 finalized=unknown
INFO [05-31|05:17:48.619] Syncing beacon headers                   downloaded=56832 left=25,322,103 eta=1h2m15.679s
INFO [05-31|05:17:49.147] Forkchoice requested sync to new head    number=25,378,946 hash=2966d8..e063ef finalized=unknown
INFO [05-31|05:17:50.169] Forkchoice requested sync to new head    number=25,378,947 hash=82b617..5313cd finalized=unknown
INFO [05-31|05:17:50.863] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:51.154] Forkchoice requested sync to new head    number=25,378,948 hash=8a849f..1d5fcd finalized=unknown
INFO [05-31|05:17:52.160] Forkchoice requested sync to new head    number=25,378,949 hash=c9b755..c3b3cf finalized=unknown
INFO [05-31|05:17:53.141] Forkchoice requested sync to new head    number=25,378,950 hash=09fbfe..671ee8 finalized=unknown
INFO [05-31|05:17:53.863] loop print db stats                      database=/app/data/geth/chaindata               comp_time=0 write_delay_count=0 write_delay_time=0 non_level0_comp_count=0 level0_comp_count=0
INFO [05-31|05:17:54.154] Forkchoice requested sync to new head    number=25,378,951 hash=d519c9..776bc4 finalized=unknown
INFO [05-31|05:17:55.152] Forkchoice requested sync to new head    number=25,378,952 hash=888990..4a86fa finalized=unknown

@astudnev astudnev mentioned this issue May 31, 2024
Closed
@astudnev
Copy link
Author

very strange to see this log:

Snap sync complete, auto disabling

which is for this code:

// enableSyncedFeatures enables the post-sync functionalities when the initial
// sync is finished.
func (h *handler) enableSyncedFeatures() {
	// Mark the local node as synced.
	h.synced.Store(true)

	// If we were running snap sync and it finished, disable doing another
	// round on next sync cycle
	if h.snapSync.Load() {
		log.Info("Snap sync complete, auto disabling")
		h.snapSync.Store(false)
	}

@welkin22
Copy link
Contributor

welkin22 commented Jun 3, 2024

very strange to see this log:

Snap sync complete, auto disabling

which is for this code:

// enableSyncedFeatures enables the post-sync functionalities when the initial
// sync is finished.
func (h *handler) enableSyncedFeatures() {
	// Mark the local node as synced.
	h.synced.Store(true)

	// If we were running snap sync and it finished, disable doing another
	// round on next sync cycle
	if h.snapSync.Load() {
		log.Info("Snap sync complete, auto disabling")
		h.snapSync.Store(false)
	}

I reproduced the issue locally and will try to find the cause. I will keep you updated on any progress.

@welkin22
Copy link
Contributor

welkin22 commented Jun 4, 2024

very strange to see this log:

Snap sync complete, auto disabling

which is for this code:

// enableSyncedFeatures enables the post-sync functionalities when the initial
// sync is finished.
func (h *handler) enableSyncedFeatures() {
	// Mark the local node as synced.
	h.synced.Store(true)

	// If we were running snap sync and it finished, disable doing another
	// round on next sync cycle
	if h.snapSync.Load() {
		log.Info("Snap sync complete, auto disabling")
		h.snapSync.Store(false)
	}

I reproduced the issue locally and will try to find the cause. I will keep you updated on any progress.

@astudnev Hello, I am sure this issue is caused by the upstream code merge in version 0.3.0 and has been fixed by the upstream code in version v0.4.0. You can avoid this issue by using version v0.4.2 directly.
The following are technical details:
In PR, we merged the upstream code, causing enableSyncedFeatures to be called in the forkchoiceUpdated interface. In version v0.3.x of op-node, forkchoiceUpdated interface is called at startup and the hash of the genesis block is passed in, causing enableSyncedFeatures to be called and snapsync to be converted to fullsync. In version v0.4.x, op-node has made significant adjustments to the behavior of engine sync. When engine sync is enabled, forkchoiceUpdated interface is not called at startup with the genesis block passed in, thus not triggering the call to enableSyncedFeatures.

@astudnev
Copy link
Author

astudnev commented Jun 5, 2024 •
edited
Loading

According to logs, v0.4.2 syncing using snap method. However it stuck on the following:

INFO [06-05|12:17:47.906] Syncing: state download in progress      synced=9.48%   state=8.35GiB   accounts=5,277,[email protected] slots=39,333,[email protected]  [email protected] eta=40h35m25.091s

not progressing for several hours - is it normal?

after that it downloaded pretty fast to 22% and stuck again

INFO [06-05|13:12:47.256] Syncing: state download in progress      synced=23.26%  state=24.83GiB accounts=12,273,[email protected]   slots=112,408,[email protected] [email protected] eta=2h51m33.154s

it keeps progressing however...

@astudnev astudnev closed this as completed Jun 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@astudnev @welkin22