-
Notifications
You must be signed in to change notification settings - Fork 1.8k
Head state missing & rewind when node upgrade to v1.5.1-alpha #2796
Copy link
Copy link
Closed
Description
System information
Geth version: 1.5.1
OS & Version: Linux
Commit hash : adc9fd1
Expected behaviour
The node with v1.4.16 upgraded to v1.5.1-alpha without any error.
Actual behaviour
The issue appears in testnet & mainnet env.
After the upgrade, the log reports unexpected journal version want 1 got 0, Head state missing, repairing, and "Rewound to block with state" number=46273779. It needs to wait for resync to chain tip.
Steps to reproduce the behaviour
Run a v1.4.16 node in testnet/mainnet, stop & upgrade binary to v1.5.1-alpha, restart the node.
Backtrace
testnet:
t=2024-12-10T03:13:26+0000 lvl=info msg="Opened ancient database" database=/server/validator/geth/chaindata/ancient/chain readonly=false frozen=46269697
t=2024-12-10T03:13:26+0000 lvl=info msg="State scheme set by user" scheme=path
t=2024-12-10T03:13:26+0000 lvl=info msg="Capped dirty cache size" provided="2.57 GiB" adjusted="256.00 MiB"
t=2024-12-10T03:13:26+0000 lvl=info msg="Clean cache size" provided="1.54 GiB" adjusted="3.87 GiB"
t=2024-12-10T03:13:26+0000 lvl=info msg="Allocated memory caches" state_scheme=path trie_clean_cache="3.87 GiB" trie_dirty_cache="256.00 MiB" snapshot_cache="2.06 GiB"
t=2024-12-10T03:13:26+0000 lvl=info msg="Unprotected transactions allowed"
t=2024-12-10T03:13:26+0000 lvl=info msg=Parlia chainConfig="{ChainID: 97 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 1010000, Niels: 1014369, MirrorSync: 5582500, Bruno: 13837000, Berlin: 31103030, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31103030, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 19203503, Gibbs: 22800220, Nano: 23482428, Moran: 23603940, Planck: 28196022,Luban: 29295050, Plato: 29861024, Hertz: 31103030, Hertzfix: 35682300, ShanghaiTime: 1702972800, KeplerTime: 1702972800, FeynmanTime: 1710136800, FeynmanFixTime: 1711342800, CancunTime: 1713330442, HaberTime: 1716962820, HaberFixTime: 1719986788, BohrTime: 1724116996, PascalTime: <nil>, PragueTime: <nil>, Engine: parlia}"
t=2024-12-10T03:13:26+0000 lvl=info msg="Initialising Ethereum protocol" network=97 dbversion=8
t=2024-12-10T03:13:26+0000 lvl=info msg="New journal reader for journal kv"
t=2024-12-10T03:13:26+0000 lvl=info msg="Failed to load journal, discard it" err="unexpected journal version want 1 got 0"
t=2024-12-10T03:13:26+0000 lvl=info msg="New async node buffer" limit="256.00 MiB" layers=0
t=2024-12-10T03:13:26+0000 lvl=info msg="Opened ancient database" database=/server/validator/geth/chaindata/ancient/state readonly=false frozen=39277264
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=account.data items=39277264 limit=39191774
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=storage.data items=39277264 limit=39191774
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=history.meta items=39277264 limit=39191774
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=account.index items=39277264 limit=39191774
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=storage.index items=39277264 limit=39191774
t=2024-12-10T03:13:26+0000 lvl=warn msg="Truncated extra state histories" number=85490
t=2024-12-10T03:13:26+0000 lvl=info msg="Initialised chain configuration" config="{ChainID: 97 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 1010000, Niels: 1014369, MirrorSync: 5582500, Bruno: 13837000, Berlin: 31103030, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31103030, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 19203503, Gibbs: 22800220, Nano: 23482428, Moran: 23603940, Planck: 28196022,Luban: 29295050, Plato: 29861024, Hertz: 31103030, Hertzfix: 35682300, ShanghaiTime: 1702972800, KeplerTime: 1702972800, FeynmanTime: 1710136800, FeynmanFixTime: 1711342800, CancunTime: 1713330442, HaberTime: 1716962820, HaberFixTime: 1719986788, BohrTime: 1724116996, PascalTime: <nil>, PragueTime: <nil>, Engine: parlia}"
t=2024-12-10T03:13:26+0000 lvl=info msg="Loaded most recent local block" number=46359702 hash=0x33d0f5d9a99083167f8901c893b6e1daf32ba328ac8152201abffcaa93fb4c7e root=0x90928720c7759bbaa017dfa1280b1819b0df4b6674c18ce152bc7949c4746e0d td=92480086 age=13s
t=2024-12-10T03:13:26+0000 lvl=info msg="Loaded most recent local finalized block" number=46359700 hash=0xe67994ffb6a260c4737f3fcaf23b56b59062ec02feb1abc7870e7cc29286f69e root=0xd47c9e758393d9602d4be0bcd22967cebdd93467bec572b59a4b3f4e18df3408 td=92480082 age=19s
t=2024-12-10T03:13:27+0000 lvl=info msg="pathdb top difflayer" root=0xc17a950424b176dfe66fa5468189f9d6ade704f160c2b417e8086231e9a6e09f
t=2024-12-10T03:13:27+0000 lvl=warn msg="Head state missing, repairing" number=46359702 hash=0x33d0f5d9a99083167f8901c893b6e1daf32ba328ac8152201abffcaa93fb4c7e diskRoot=0xc17a950424b176dfe66fa5468189f9d6ade704f160c2b417e8086231e9a6e09f
t=2024-12-10T03:13:30+0000 lvl=info msg="Rewound to block with state" number=46273779 hash=0x5bb550d5e8e360abff75006af19e6c195e876069def1c00f63d480e9c1c6611f
t=2024-12-10T03:13:30+0000 lvl=info msg="Loaded most recent local header" number=46359702 hash=0x33d0f5d9a99083167f8901c893b6e1daf32ba328ac8152201abffcaa93fb4c7e hash=0x90928720c7759bbaa017dfa1280b1819b0df4b6674c18ce152bc7949c4746e0d td=92480086 age=17s
t=2024-12-10T03:13:30+0000 lvl=info msg="Loaded most recent local block" number=46273779 hash=0x5bb550d5e8e360abff75006af19e6c195e876069def1c00f63d480e9c1c6611f root=0xc17a950424b176dfe66fa5468189f9d6ade704f160c2b417e8086231e9a6e09f td=92308240 age=2d23h36m
t=2024-12-10T03:13:30+0000 lvl=info msg="Loaded most recent local snap block" number=46359702 hash=0x33d0f5d9a99083167f8901c893b6e1daf32ba328ac8152201abffcaa93fb4c7e root=0x90928720c7759bbaa017dfa1280b1819b0df4b6674c18ce152bc7949c4746e0d td=92480086 age=17s
t=2024-12-10T03:13:30+0000 lvl=info msg="Loaded most recent local finalized block" number=46359700 hash=0xe67994ffb6a260c4737f3fcaf23b56b59062ec02feb1abc7870e7cc29286f69e root=0xd47c9e758393d9602d4be0bcd22967cebdd93467bec572b59a4b3f4e18df3408 td=92480082 age=23s
t=2024-12-10T03:13:30+0000 lvl=warn msg="Enabling snapshot recovery" chainhead=46273779 diskbase=46273779
t=2024-12-10T03:13:31+0000 lvl=warn msg="Snapshot is not continuous with chain" snaproot=0x90928720c7759bbaa017dfa1280b1819b0df4b6674c18ce152bc7949c4746e0d chainroot=0xc17a950424b176dfe66fa5468189f9d6ade704f160c2b417e8086231e9a6e09f
t=2024-12-10T03:13:31+0000 lvl=info msg="Snapshot loaded" diskRoot=0xe45238aa00027278f30f9ea700d2f0e333b379c2e928c9d105abcf5e5ef8fde9 root=0xc17a950424b176dfe66fa5468189f9d6ade704f160c2b417e8086231e9a6e09f
t=2024-12-10T03:13:31+0000 lvl=info msg="Initialized transaction indexer" range="entire chain"
...
t=2024-12-10T03:13:33+0000 lvl=info msg="Importing heavy sidechain segment" blocks=2048 start=46273780 end=46275827
t=2024-12-10T03:13:41+0000 lvl=info msg="Imported new chain segment" number=46274109 hash=0x9e0eed838031a9a0b00bcb3809c962d32f6d9a01e677975186625c2301433624 miner=0xF9a1Db0d6f22Bd78ffAECCbc8F47c83Df9FBdbCf blocks=330 txs=2303 blobs=45 mgas=272.838345 elapsed=8.016s mgasps=34.034667305178395 age=2d23h20m snapdiffs="822.72 KiB" triediffs="9.51 MiB" triedirty="2.42 MiB" trieimutabledirty="0.00 B"
t=2024-12-10T03:13:42+0000 lvl=warn msg="Inserted known block" number=46274141 hash=0xa82f5b8dff98f0726820d0e42b858ff22b19e426123f190194b8441359e834c1 uncles=0 txs=0 gas=0 root=0x35faf46fd90cd450034dd660f299fb7bd68a63ea3fcd3a4c669a4cb33f55ad6c
t=2024-12-10T03:13:49+0000 lvl=info msg="Imported new chain segment" number=46274400 hash=0x160ed633f1aaa71b06dc1b8e6ba7de950ab87bd64d9fa18a6f94c517c6a7f43c miner=0x08265dA01E1A65d62b903c7B34c08cB389bF3D99 blocks=291 txs=2056 blobs=43 mgas=246.06398 elapsed=8.003s mgasps=30.7440215060895 age=2d23h5m snapdiffs="822.72 KiB" triediffs="9.90 MiB" triedirty="4.45 MiB" trieimutabledirty="0.00 B"
t=2024-12-10T03:13:51+0000 lvl=warn msg="Inserted known block" number=46274475 hash=0x1242a4bfda259218f72da1d16bca135c76adb4e519c08ef640ab7cba2d14d9c0 uncles=0 txs=0 gas=0 root=0x577185abe46744f8996055008a2a9e6d9900629fa8a6ddba0eb0561446a6f5a3mainnet:
t=2024-12-10T02:46:02+0000 lvl=info msg="Initializing the KZG library" backend=gokzg
t=2024-12-10T02:46:02+0000 lvl=info msg="Using pebble as the backing database"
t=2024-12-10T02:46:02+0000 lvl=info msg="Allocated cache and file handles" database=/server/validator/geth/chaindata cache="7.03 GiB" handles=250000 "memory table"="1.76 GiB"
t=2024-12-10T02:46:04+0000 lvl=info msg="Read ancient db item counts" items=44649277 frozen=44649277
t=2024-12-10T02:46:07+0000 lvl=info msg="Opened ancientdb with nodata mode" database=/server/validator/geth/chaindata/ancient/chain frozen=44649277
t=2024-12-10T02:46:07+0000 lvl=info msg="State scheme set to already existing disk db" scheme=path
t=2024-12-10T02:46:07+0000 lvl=info msg="Capped dirty cache size" provided="4.39 GiB" adjusted="256.00 MiB"
t=2024-12-10T02:46:07+0000 lvl=info msg="Clean cache size" provided="2.64 GiB" adjusted="6.78 GiB"
t=2024-12-10T02:46:07+0000 lvl=info msg="Allocated memory caches" state_scheme=path trie_clean_cache="6.78 GiB" trie_dirty_cache="256.00 MiB" snapshot_cache="3.52 GiB"
t=2024-12-10T02:46:07+0000 lvl=info msg="Unprotected transactions allowed"
t=2024-12-10T02:46:07+0000 lvl=info msg=Parlia chainConfig="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: 1718863500, HaberTime: 1718863500, HaberFixTime: 1727316120, BohrTime: 1727317200, PascalTime: <nil>, PragueTime: <nil>, Engine: parlia}"
t=2024-12-10T02:46:07+0000 lvl=info msg="Initialising Ethereum protocol" network=56 dbversion=8
t=2024-12-10T02:46:07+0000 lvl=info msg="New journal reader for journal kv"
t=2024-12-10T02:46:08+0000 lvl=info msg="Failed to load journal, discard it" err="unexpected journal version want 1 got 0"
t=2024-12-10T02:46:08+0000 lvl=info msg="New async node buffer" limit="256.00 MiB" layers=0
t=2024-12-10T02:46:08+0000 lvl=info msg="Opened ancient database" database=/server/validator/geth/chaindata/ancient/state readonly=false frozen=44728719
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=account.data items=44728719 limit=44728304
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=storage.data items=44728719 limit=44728304
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=history.meta items=44728719 limit=44728304
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=account.index items=44728719 limit=44728304
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncating freezer table" database=/server/validator/geth/chaindata/ancient/state table=storage.index items=44728719 limit=44728304
t=2024-12-10T02:46:08+0000 lvl=warn msg="Truncated extra state histories" number=415
t=2024-12-10T02:46:08+0000 lvl=info msg="Initialised chain configuration" config="{ChainID: 56 Homestead: 0 DAO: <nil> DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: 0, Ramanujan: 0, Niels: 0, MirrorSync: 5184000, Bruno: 13082000, Berlin: 31302048, YOLO v3: <nil>, CatalystBlock: <nil>, London: 31302048, ArrowGlacier: <nil>, MergeFork:<nil>, Euler: 18907621, Gibbs: 23846001, Nano: 21962149, Moran: 22107423, Planck: 27281024,Luban: 29020050, Plato: 30720096, Hertz: 31302048, Hertzfix: 34140700, ShanghaiTime: 1705996800, KeplerTime: 1705996800, FeynmanTime: 1713419340, FeynmanFixTime: 1713419340, CancunTime: 1718863500, HaberTime: 1718863500, HaberFixTime: 1727316120, BohrTime: 1727317200, PascalTime: <nil>, PragueTime: <nil>, Engine: parlia}"
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local block" number=44739276 hash=0x2fb8e2e6a72daa64d50026a56dbc322f80178246d1f07374bfa532fb4398ff18 root=0x1edb75fc4b6a32595374b8f0589e9ade6aef5d5ba1bb02be2f278a1ca7d62bc5 td=88901123 age=21s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local finalized block" number=44739274 hash=0xfe3c01f5aaa24c27a1df2334990e94da2f8aa5e909fc176696cee549dabc25d3 root=0x0e682e3a4f053813aff8cea2f591e5d86e7dad751f2c543d37ef3c75b56ac815 td=88901119 age=27s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded last snap-sync pivot marker" number=6920578
t=2024-12-10T02:46:08+0000 lvl=info msg="pathdb top difflayer" root=0x5a004dd67e165d3b10381242a286aacc1111a25fba015895c17b47b48fce1941
t=2024-12-10T02:46:08+0000 lvl=warn msg="Head state missing, repairing" number=44739276 hash=0x2fb8e2e6a72daa64d50026a56dbc322f80178246d1f07374bfa532fb4398ff18 diskRoot=0x5a004dd67e165d3b10381242a286aacc1111a25fba015895c17b47b48fce1941
t=2024-12-10T02:46:08+0000 lvl=info msg="Rewound to block with state" number=44738733 hash=0x659a6878f14529537e0ad5df8fd4e2ab840174e71f61096e78653560efbb1cb0
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local header" number=44739276 hash=0x2fb8e2e6a72daa64d50026a56dbc322f80178246d1f07374bfa532fb4398ff18 hash=0x1edb75fc4b6a32595374b8f0589e9ade6aef5d5ba1bb02be2f278a1ca7d62bc5 td=88901123 age=21s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local block" number=44738733 hash=0x659a6878f14529537e0ad5df8fd4e2ab840174e71f61096e78653560efbb1cb0 root=0x5a004dd67e165d3b10381242a286aacc1111a25fba015895c17b47b48fce1941 td=88900037 age=27m30s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local snap block" number=44739276 hash=0x2fb8e2e6a72daa64d50026a56dbc322f80178246d1f07374bfa532fb4398ff18 root=0x1edb75fc4b6a32595374b8f0589e9ade6aef5d5ba1bb02be2f278a1ca7d62bc5 td=88901123 age=21s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded most recent local finalized block" number=44739274 hash=0xfe3c01f5aaa24c27a1df2334990e94da2f8aa5e909fc176696cee549dabc25d3 root=0x0e682e3a4f053813aff8cea2f591e5d86e7dad751f2c543d37ef3c75b56ac815 td=88901119 age=27s
t=2024-12-10T02:46:08+0000 lvl=info msg="Loaded last snap-sync pivot marker" number=6920578
t=2024-12-10T02:46:09+0000 lvl=warn msg="Enabling snapshot recovery" chainhead=44738733 diskbase=44738733
t=2024-12-10T02:46:09+0000 lvl=warn msg="Snapshot is not continuous with chain" snaproot=0x1edb75fc4b6a32595374b8f0589e9ade6aef5d5ba1bb02be2f278a1ca7d62bc5 chainroot=0x5a004dd67e165d3b10381242a286aacc1111a25fba015895c17b47b48fce1941
t=2024-12-10T02:46:09+0000 lvl=info msg="Snapshot loaded" diskRoot=0x6be5ccde18683c8c48f0d9b07744757e39100d666ac2461f8c31c5a18fcffa5d root=0x5a004dd67e165d3b10381242a286aacc1111a25fba015895c17b47b48fce1941
t=2024-12-10T02:46:09+0000 lvl=info msg="Initialized transaction indexer" range="entire chain"
t=2024-12-10T02:46:09+0000 lvl=warn msg="Sanitizing invalid txpool reannounce time" provided=0s updated=1m0s
t=2024-12-10T02:46:09+0000 lvl=warn msg="Switch sync mode from snap sync to full sync" reason="snap sync complete"
t=2024-12-10T02:46:09+0000 lvl=info msg="Create votePool successfully"
...
t=2024-12-10T02:46:09+0000 lvl=info msg="Started P2P networking" self="enode://c1c4849748d754a401d5083edc2673713412df5cd274a4af8ffe6b18f0cf74acd0fd8d063515452c403fbf706be9f4525279e25aac553e78d6a3d1579b2dfde0@127.0.0.1:30311?discport=0"
t=2024-12-10T02:46:09+0000 lvl=info msg="Block synchronisation started"
t=2024-12-10T02:46:10+0000 lvl=info msg="Importing sidechain segment" start=44738734 end=44739267
t=2024-12-10T02:46:18+0000 lvl=info msg="Imported new chain segment" number=44738770 hash=0x076a67a1eea24862bc54b3ed0f4f3ece3c21f9bbe0688fefd0979293964b571b miner=0x7E1FdF03Eb3aC35BF0256694D7fBe6B6d7b3E0c8 blocks=37 txs=6165 blobs=9 mgas=651.373898 elapsed=8.098s mgasps=80.43370048156298 age=25m49s snapdiffs="3.30 MiB" triediffs="73.94 MiB" triedirty="0.00 B" trieimutabledirty="0.00 B"
t=2024-12-10T02:46:26+0000 lvl=info msg="Imported new chain segment" number=44738815 hash=0x8b1fc284da02a4a31c8eb8cb7c5e6ab8a353f5b101ba15389714ec9d3684e8e1 miner=0xF8B99643fAfC79d9404DE68E48C4D49a3936f787 blocks=45 txs=6743 blobs=13 mgas=802.468827 elapsed=8.043s mgasps=99.76966693962271 age=23m42s snapdiffs="3.30 MiB" triediffs="154.45 MiB" triedirty="0.00 B" trieimutabledirty="0.00 B"
t=2024-12-10T02:46:34+0000 lvl=info msg="Imported new chain segment" number=44738870 hash=0x1c41b0a803d305b07650ae3a633b71c259fd1b98d7415f0a09fb304e156660cd miner=0x9bb56C2B4DBE5a06d79911C9899B6f817696ACFc blocks=55 txs=9025 blobs=20 mgas=992.047651 elapsed=8.087s mgasps=122.66272924996751 age=21m5s snapdiffs="3.30 MiB" triediffs="240.07 MiB" triedirty="11.17 MiB" trieimutabledirty="0.00 B"
t=2024-12-10T02:46:42+0000 lvl=info msg="Imported new chain segment" number=44738926 hash=0x78858e5bd20b037aa1baeecc83476a6ad679d8f06309fb43997809b6878107f6 miner=0x5009317FD4F6F8FeEa9dAe41E5F0a4737BB7A7D5 blocks=56 txs=9229 blobs=13 mgas=966.098504 elapsed=8.131s mgasps=118.80298113366301 age=18m25s snapdiffs="3.30 MiB" triediffs="245.79 MiB" triedirty="43.04 MiB" trieimutabledirty="0.00 B"When submitting logs: please submit them as text and not screenshots.
Reactions are currently unavailable
Metadata
Metadata
Assignees
Labels
No labels