search

ethereum-optimism / op-geth

GNU Lesser General Public License v3.0
281 stars 735 forks source link

Out of sync due to "Generating state snapshot" #343

Closed andreclaro closed 3 months ago

andreclaro commented 3 months ago

Description

"Generating state snapshot" is affecting node, which gets out of sync.

System information

Expected behaviour

Node should not get out of sync.

Actual behaviour

Node gets out of sync by more than 6000 blocks.

Logs

This are the latest logs where the node is also processing blocks ("Imported new potential chain segment" / "Chain head was updated"). However for some time the node is only generating state snapshots and getting further behind the public network.

op-geth

Jun 27 19:57:35 m-optimism-02 geth[1263]: INFO [06-27|19:57:35.352] Generating state snapshot                root=04f327..4a689f in=da96cf..e517af at=b5e103..ba5cef accounts=119,253,539 slots=318,285,026 storage=30.36GiB  dangling=0 elapsed=3h22m40.833s eta=34m41.291s
Jun 27 19:57:35 m-optimism-02 geth[1263]: INFO [06-27|19:57:35.413] Imported new potential chain segment     number=121,953,090 hash=20b718..e1933a blocks=1 txs=7  mgas=2.669  elapsed=477.707ms    mgasps=5.587   age=3h41m38s triedirty=0.00B
Jun 27 19:57:35 m-optimism-02 geth[1263]: INFO [06-27|19:57:35.415] Chain head was updated                   number=121,953,090 hash=20b718..e1933a root=7b0c63..b5761f elapsed=1.015623ms   age=3h41m38s
Jun 27 19:57:35 m-optimism-02 geth[1263]: INFO [06-27|19:57:35.783] Imported new potential chain segment     number=121,953,091 hash=8fea53..930873 blocks=1 txs=7  mgas=2.111  elapsed=365.674ms    mgasps=5.774   age=3h41m36s triedirty=0.00B
Jun 27 19:57:35 m-optimism-02 geth[1263]: INFO [06-27|19:57:35.785] Chain head was updated                   number=121,953,091 hash=8fea53..930873 root=2d1371..874032 elapsed="781.358µs"  age=3h41m36s
Jun 27 19:57:43 m-optimism-02 geth[1263]: INFO [06-27|19:57:43.353] Generating state snapshot                root=04f327..4a689f in=da96cf..e517af at=c11751..b4c505 accounts=119,253,539 slots=318,541,051 storage=30.38GiB  dangling=0 elapsed=3h22m48.834s eta=34m42.66s
Jun 27 19:57:44 m-optimism-02 geth[1263]: INFO [06-27|19:57:44.433] Imported new potential chain segment     number=121,953,092 hash=22d54a..34b31b blocks=1 txs=16 mgas=9.373  elapsed=8.646s       mgasps=1.084   age=3h41m43s triedirty=0.00B
Jun 27 19:57:44 m-optimism-02 geth[1263]: WARN [06-27|19:57:44.434] Ignoring already known beacon payload    number=121,953,092 hash=22d54a..34b31b age=3h41m43s
Jun 27 19:57:44 m-optimism-02 geth[1263]: INFO [06-27|19:57:44.437] Chain head was updated                   number=121,953,092 hash=22d54a..34b31b root=44874c..81f566 elapsed=1.917279ms   age=3h41m43s
Jun 27 19:57:45 m-optimism-02 geth[1263]: INFO [06-27|19:57:45.134] Imported new potential chain segment     number=121,953,093 hash=c321c6..d76921 blocks=1 txs=14 mgas=2.868  elapsed=693.580ms    mgasps=4.134   age=3h41m42s triedirty=0.00B
Jun 27 19:57:45 m-optimism-02 geth[1263]: INFO [06-27|19:57:45.137] Chain head was updated                   number=121,953,093 hash=c321c6..d76921 root=56df25..90bc84 elapsed=1.345763ms   age=3h41m42s
Jun 27 19:57:51 m-optimism-02 geth[1263]: INFO [06-27|19:57:51.371] Generating state snapshot                root=04f327..4a689f in=da96cf..e517af at=cce8b6..5d55bb accounts=119,253,539 slots=318,810,785 storage=30.40GiB  dangling=0 elapsed=3h22m56.851s eta=34m44.032s
Jun 27 19:57:51 m-optimism-02 geth[1263]: INFO [06-27|19:57:51.650] Imported new potential chain segment     number=121,953,094 hash=d20d58..9e51b9 blocks=1 txs=14 mgas=9.753  elapsed=6.508s       mgasps=1.499   age=3h41m46s triedirty=0.00B
Jun 27 19:57:52 m-optimism-02 geth[1263]: WARN [06-27|19:57:52.178] Ignoring already known beacon payload    number=121,953,094 hash=d20d58..9e51b9 age=3h41m47s
Jun 27 19:57:52 m-optimism-02 geth[1263]: INFO [06-27|19:57:52.182] Chain head was updated                   number=121,953,094 hash=d20d58..9e51b9 root=0b5694..997667 elapsed=2.497365ms   age=3h41m47s
Jun 27 19:57:52 m-optimism-02 geth[1263]: INFO [06-27|19:57:52.268] Imported new potential chain segment     number=121,953,095 hash=7217c4..12e630 blocks=1 txs=13 mgas=1.444  elapsed=83.602ms     mgasps=17.268  age=3h41m45s triedirty=0.00B
Jun 27 19:57:52 m-optimism-02 geth[1263]: INFO [06-27|19:57:52.270] Chain head was updated                   number=121,953,095 hash=7217c4..12e630 root=be08ae..a83b79 elapsed="797.269µs"  age=3h41m45

op-node

Jun 27 19:58:14 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:14+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xac234f9146c810dea6121552580a4ed4cd864ccccde907b12a09c5120b1ba426:121959758
Jun 27 19:58:15 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:15+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkxHXmw5iw5amSc32mTxoTo2R2gZKrAfx143uBbZ9P6QQr
Jun 27 19:58:15 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:15+0000 lvl=info msg="Received signed execution payload from p2p" id=0xed2040c95470d3ab3c66b398b2d66387185658a2898a9151fab17a6b8b4ca553:121959759 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:15 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:15+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xed2040c95470d3ab3c66b398b2d66387185658a2898a9151fab17a6b8b4ca553:121959759
Jun 27 19:58:17 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:17+0000 lvl=info msg="Sync progress" reason="new chain head block" l2_finalized=0x22f88dea6338b4e91c6e68a4e71424b00079c36e7751a7e801a7c7499d3690f7:121952848 l2_safe=0x22f88dea6338b4e91c6e68a4e71424b00079c36e7751a7e801a7c7499d3690f7:121952848 l2_pending_safe=0x87dfd4a049bc84d2c31bd4a7dfa0b84e95ef9b7c0537253ec9277151b3b305f7:121952940 l2_unsafe=0xc97b9699f06ee17ac114e94ce2755c5aae861c6130affe754ad5883b02b7188c:121953102 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1719504981
Jun 27 19:58:17 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:17+0000 lvl=info msg="Received signed execution payload from p2p" id=0x999e1d918794702d659d4fa32e79beff68322863fe94385d14add76198f6de1b:121959760 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:17 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:17+0000 lvl=info msg="Sync progress" reason="new chain head block" l2_finalized=0x22f88dea6338b4e91c6e68a4e71424b00079c36e7751a7e801a7c7499d3690f7:121952848 l2_safe=0x22f88dea6338b4e91c6e68a4e71424b00079c36e7751a7e801a7c7499d3690f7:121952848 l2_pending_safe=0x87dfd4a049bc84d2c31bd4a7dfa0b84e95ef9b7c0537253ec9277151b3b305f7:121952940 l2_unsafe=0x55f4f8e3e37df26f8c43d58ee8c5dd7ac206d03a62a9314d08354047ae843a59:121953103 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1719504983
Jun 27 19:58:17 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:17+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0x999e1d918794702d659d4fa32e79beff68322863fe94385d14add76198f6de1b:121959760
Jun 27 19:58:18 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:18+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkzg2h8aN2gAq497tkHmN5hDy9EaKAkhbMScmCAbBPxNwJ
Jun 27 19:58:18 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:18+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm1zB9TgXxvtxjLXXJfhRw68ZMeCoiJ7BwSXKY2AbDAtVU
Jun 27 19:58:19 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:19+0000 lvl=info msg="Received signed execution payload from p2p" id=0x7ab504f8fb4452ca8c1fd749fec06de95a94ac93cfee6eab02b375a5bdb485d9:121959761 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:20 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:20+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm7v25THFJZJvkoK3bH4Wqjga9P96uWgBLRGQSYqggDA2N
Jun 27 19:58:20 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:20+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm1ftqsNaMCUi6JhQ6RdZrGvQ3Vt1d69xv1ZqzVMac8Cki
Jun 27 19:58:20 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:20+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm5Yo4tL1PnjeiVAvgKtr8vWzMTLSQs9xd7vYUC2fS4GJC
Jun 27 19:58:21 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:21+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmNytWmvGV1UHuUBngGFxyNsLkquzzCLeUoTLUGUrjW5Ju
Jun 27 19:58:21 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:21+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmFBzRPMeAkNUipyJ1DEN5d9XyvvNvEP41xotCiPhCb6Kz
Jun 27 19:58:21 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:21+0000 lvl=info msg="Received signed execution payload from p2p" id=0xaac5384d7406582c361803169b19e1f1fde1ff67f118bfe01662253675302340:121959762 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:22 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:22+0000 lvl=error msg="Payload execution failed" block_hash=0xf3e2cf9db49412ae31e6d9c579c1cbd96529e9f3e3452df27eaa07a78ee084b7 err="Post \"http://127.0.0.1:8551\": context deadline exceeded"
Jun 27 19:58:22 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:22+0000 lvl=warn msg="Derivation process temporary error" attempts=1 err="temp: failed to update insert payload: failed to execute payload: Post \"http://127.0.0.1:8551\": context deadline exceeded"
Jun 27 19:58:22 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:22+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0x7ab504f8fb4452ca8c1fd749fec06de95a94ac93cfee6eab02b375a5bdb485d9:121959761
Jun 27 19:58:22 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:22+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xaac5384d7406582c361803169b19e1f1fde1ff67f118bfe01662253675302340:121959762
Jun 27 19:58:23 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:23+0000 lvl=info msg="Received signed execution payload from p2p" id=0xe3607546f535e3b7b62bffecf741b044f08dac778afefe7c98f6a365349f325f:121959763 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:23 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:23+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xe3607546f535e3b7b62bffecf741b044f08dac778afefe7c98f6a365349f325f:121959763
Jun 27 19:58:25 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:25+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm2vXWR3ooDT3dnM9JuaHzeNysTmQV3tsqhXC8p1aFn3V7
Jun 27 19:58:25 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:25+0000 lvl=info msg="Received signed execution payload from p2p" id=0xcde7b7508a24f4e123734b96e724ff84d17f0afc73eb6f35ba77e87e3413345b:121959764 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:27 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:27+0000 lvl=info msg="Received signed execution payload from p2p" id=0xd4c6edd585941760e8ffc698763ed40acf3964c8176aa92ef104b39f9881ce4a:121959765 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:28 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:28+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmAPxaqqrjA8p2yUD2rma2pZoaJJaMory5af7x5vfKqBLG
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=info msg="Received signed execution payload from p2p" id=0xb1b26df341b66bb777847bc5138605f6f222fab57d195cb6fa12a0f2ab52de57:121959766 peer=16Uiu2HAkzc1eByUyVc8tmu97dXYwehh6QTo5MxK5VFTjHH4wkj6J
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=error msg="Payload execution failed" block_hash=0xf3e2cf9db49412ae31e6d9c579c1cbd96529e9f3e3452df27eaa07a78ee084b7 err="Post \"http://127.0.0.1:8551\": context deadline exceeded"
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=warn msg="Derivation process temporary error" attempts=2 err="temp: failed to update insert payload: failed to execute payload: Post \"http://127.0.0.1:8551\": context deadline exceeded"
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xcde7b7508a24f4e123734b96e724ff84d17f0afc73eb6f35ba77e87e3413345b:121959764
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xd4c6edd585941760e8ffc698763ed40acf3964c8176aa92ef104b39f9881ce4a:121959765
Jun 27 19:58:29 m-optimism-02 op-node[1264]: t=2024-06-27T19:58:29+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xb1b26df341b66bb777847bc5138605f6f222fab57d195cb6fa12a0f2ab52de57:121959766

CLIs

op-geth:

/usr/local/bin/geth \
    --op-network=op-mainnet \
    --datadir=/var/lib/optimism/data \
    --syncmode=snap \
    --gcmode=archive \
    --http \
    --http.addr=0.0.0.0 \
    --http.port=8545 \
    --http.vhosts="*" \
    --http.corsdomain="*" \
    --http.api=web3,debug,eth,net,engine,geth \
    --ws \
    --ws.port=8546 \
    --ws.addr=0.0.0.0 \
    --ws.origins="*" \
    --ws.api=debug,eth,net,engine \
    --authrpc.addr=127.0.0.1 \
    --authrpc.port=8551 \
    --authrpc.jwtsecret=/var/lib/optimism/jwt.txt \
    --authrpc.vhosts="*" \
    --metrics \
    --metrics.addr=0.0.0.0 \
    --metrics.port=6060 \
    --port=30303 \
    --discovery.port=30303 \
    --maxpeers=500 \
    --rollup.historicalrpc=https://mainnet.optimism.io \
    --rollup.disabletxpoolgossip=true \
    --rollup.sequencerhttp=https://mainnet-sequencer.optimism.io \
    --rollup.superchain-upgrades \
    --rollup.halt=major \
    --verbosity=3

op-node

/usr/local/bin/op-node \
    --syncmode=execution-layer \
    --l1.trustrpc \
    --l1.rpckind=basic \
    --l1=http://ETH_ADDRESS:8545 \
    --l1.beacon=http://ETH_ADDRESS:5052 \
    --l2=http://127.0.0.1:8551 \
    --rpc.addr=127.0.0.1 \
    --rpc.port=9545 \
    --l2.jwt-secret=/var/lib/optimism/jwt.txt \
    --network=op-mainnet \
    --p2p.peerstore.path=/var/lib/optimism/data/opnode_peerstore_db \
    --p2p.priv.path=/var/lib/optimism/data/opnode_p2p_priv.txt \
    --p2p.discovery.path=/var/lib/optimism/data/opnode_discovery_db \
    --rollup.load-protocol-versions=true \
    --rollup.halt=major
andreclaro commented 3 months ago

duplicate: https://github.com/ethereum-optimism/op-geth/issues/337