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

Current full block number unavailable during sync #22088

Closed
holiman opened this issue Dec 29, 2020 · 2 comments
Closed

Current full block number unavailable during sync #22088

holiman opened this issue Dec 29, 2020 · 2 comments
Assignees
@karalabe
Labels
type:bug

Comments

@holiman
Copy link
Contributor

holiman commented Dec 29, 2020 •
edited
Loading

Investigating this issue which occurred on one of the Rinkeby miners yesterday.

Geth/v1.9.26-unstable-a425a47d-20201227/linux-amd64/go1.15.6

More complete logs 
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.252] Starting pprof server addr=http://0.0.0.0:6060/debug/pprof
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.253] Starting Geth on Rinkeby testnet...
...
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.390] Opened ancient database database=/root/.ethereum/geth/chaindata/ancient
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.391] Writing custom genesis block
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.400] Persisted trie from memory database nodes=355 size=50.43KiB time=2.004522ms gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.400] Initialised chain configuration config="{ChainID: 4 Homestead: 1 DAO: <nil> DAOSupport: true EIP150: 2 EIP155: 3 EIP158: 3 Byzantium: 1035301 Constantinople: 3660663 Petersburg: 4321234 Istanbul: 5435345, Muir Glacier: <nil>, YOLO v2: <nil>, Engine: clique}"
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:24.400] Initialising Ethereum protocol network=4 dbversion=<nil>
Dec 28 13:49:24 rinkeby-aws-eu-west-3-001 geth WARN [12-28|12:49:24.400] Upgrade blockchain database version from=<nil> to=8
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.062] Loaded most recent local header number=0 hash="6341fd…67e177" td=1 age=3y9mo5d
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.062] Loaded most recent local full block number=0 hash="6341fd…67e177" td=1 age=3y9mo5d
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.062] Loaded most recent local fast block number=0 hash="6341fd…67e177" td=1 age=3y9mo5d
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth WARN [12-28|12:49:25.062] Failed to load snapshot, regenerating err="missing or corrupted snapshot"
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.062] Rebuilding state snapshot
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.062] Deleted state snapshot leftovers kind=accounts wiped=0 elapsed="23.138µs"
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.063] Deleted state snapshot leftovers kind=storage wiped=0 elapsed="6.394µs"
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.063] Compacting snapshot account area
...
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.097] Starting peer-to-peer node instance=Geth/v1.9.26-unstable-a425a47d-20201227/linux-amd64/go1.15.6
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.099] Stored checkpoint snapshot to disk number=0 hash="6341fd…67e177"
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.116] Compacting snapshot storage area
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.166] Compacted snapshot area in database elapsed=103.849ms
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.167] Resuming state snapshot generation root="535805…8e8c2d" accounts=0 slots=0 storage=0.00B elapsed="13.904µs"
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.172] Generated state snapshot accounts=257 slots=0 storage=9.57KiB elapsed=5.912ms
..
Dec 28 13:49:25 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:25.381] Initialized state bloom items=355 errorrate=0.000 elapsed=282.313ms
...
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.880] Unlocked account address=0x7ffC57839B00206D1ad20c69A1981b489f772031
...
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] Commit new mining work number=1 sealhash="f627a6…822e97" uncles=0 txs=0 gas=0 fees=0 elapsed="94.545µs"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] Successfully sealed new block number=1 sealhash="f627a6…822e97" hash="d9150b…52a6be" elapsed="566.539µs"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] 🔨 mined potential block number=1 hash="d9150b…52a6be"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.883] Commit new mining work number=2 sealhash="076550…222a54" uncles=0 txs=0 gas=0 fees=0 elapsed="128.132µs"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.883] Signed recently, must wait for others
Dec 28 13:49:30 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:30.127] New local node record seq=46 id=0e10a37bbbc33e44 ip=15.236.32.166 udp=30303 tcp=30303
Dec 28 13:49:38 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:38.170] Block synchronisation started
Dec 28 13:49:38 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:38.171] Mining aborted due to sync
Dec 28 13:49:38 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:38.190] Looking for peers peercount=14 tried=71 static=0
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.454] Imported new block headers count=192 elapsed=27.413ms number=192 hash="8c570c…ba360c" age=3y9mo5d
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.457] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=639.74B throttle=8192
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.457] Migrated ancient blocks count=1 elapsed="166.661µs"
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.473] Imported new block receipts count=54 elapsed=15.845ms number=54 hash="dafe6e…02bf13" age=3y9mo5d size=34.33KiB
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.531] Imported new block headers count=192 elapsed=27.739ms number=384 hash="6d95fa…a59e49" age=3y9mo5d
...
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:50:24.172] Imported new state entries count=1920 elapsed=7.846ms processed=195681 pending=25943 trieretry=0 coderetry=0 duplicate=0 unexpected=0
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:50:24.241] Imported new state entries count=384 elapsed=1.947ms processed=196065 pending=25925 trieretry=0 coderetry=0 duplicate=0 unexpected=0
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth ERROR[12-28|12:50:24.391] Current full block number unavailable hash="d9150b…52a6be"
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:50:24.614] Imported new state entries count=1152 elapsed=4.655ms processed=197217 pending=26033 trieretry=0 coderetry=0 duplicate=0 unexpected=0
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:50:24.829] Imported new state entries count=768 elapsed=3.677ms processed=197985 pending=26086 trieretry=0 coderetry=0 duplicate=0 unexpected=0
Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:50:24.898] Imported new state entries count=384 elapsed=1.399ms processed=198369 pending=26147 trieretry=0 coderetry=0 duplicate=0 unexpected=0
...

Interesting parts -- it mines block 1 as d9150b…52a6be, and starts working on block 2, before block synchronization kicks in:

Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] Commit new mining work number=1 sealhash="f627a6…822e97" uncles=0 txs=0 gas=0 fees=0 elapsed="94.545µs"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] Successfully sealed new block number=1 sealhash="f627a6…822e97" hash="d9150b…52a6be" elapsed="566.539µs"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.881] 🔨 mined potential block number=1 hash="d9150b…52a6be"
Dec 28 13:49:29 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:29.883] Commit new mining work number=2 sealhash="076550…222a54" uncles=0 txs=0 gas=0 fees=0 elapsed="128.132µs"

Once the sync starts, it imports headers, and also migrates the previously self-mined block to ancients:

Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.454] Imported new block headers count=192 elapsed=27.413ms number=192 hash="8c570c…ba360c" age=3y9mo5d
...
Dec 28 13:49:40 rinkeby-aws-eu-west-3-001 geth INFO [12-28|12:49:40.457] Migrated ancient blocks count=1 elapsed="166.661µs"

After a while, we hit this:

Dec 28 13:50:24 rinkeby-aws-eu-west-3-001 geth ERROR[12-28|12:50:24.391] Current full block number unavailable hash="d9150b…52a6be"

This is printed in the background freezer thread -- which afaik is not supposed to be active during sync, as we should be shoving data directly into the freezer, and not do this "lift from leveldb to freezer in the background" procedure.

So it apparently has d9150b…52a6be (it's self-mind bock 1) marked as a full block, and it is also shoved into ancients, but we do not have the hash to number mapping for that same block.
@holiman
Copy link
Contributor Author

holiman commented Dec 29, 2020

Seems to be a regression of something that was fixed in #20780

@ligi ligi removed the status:triage label Jan 7, 2021
@MariusVanDerWijden
Copy link
Member

This issue can not be hit post-merge anymore, since the node will not start mining any blocks before we get info about the current state from the consensus layer. I think we can close this issue for now

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@karalabe karalabe

Labels
type:bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@ligi @karalabe @holiman @MariusVanDerWijden