search

etclabscore / core-geth

A highly configurable Go implementation of the Ethereum protocol.
https://etclabscore.github.io/core-geth
GNU Lesser General Public License v3.0
276 stars 152 forks source link

`--snapshot` flag emits too many logs #253

Open ziogaschr opened 3 years ago

ziogaschr commented 3 years ago

While testing --snapshot on #230, geth was printing too many logs where snapshot was looping on aborting and resuming state.

System information

CoreGeth
Version: 1.11.18-unstable
Architecture: amd64
Protocol Versions: [65 64 63]
Go Version: go1.15.5
Operating System: darwin
GOPATH=/Users/ziogaschr/Sites/go
GOROOT=/usr/local/Cellar/go/1.15.5/libexec

Expected behaviour

Either the snapshot generator must wait under certain circumstances or the log level has to be changed.

Actual behaviour

Was retrying like crazy and was emitting to many logs

Steps to reproduce the behaviour

Having a chain synced on mordor 1-2 weeks ago.

export ETC_DATADIR=/Volumes/Work/chain-datadirs/mordor.full.archive
export ETC_OUTPUT=/dev/ttys001

geth --datadir=$ETC_DATADIR --http --http.api web3,eth,debug,personal,net,trace --vmdebug --cache 2048 --gcmode=archive --syncmode full --mordor --snapshot console 2>> $ETC_OUTPUT

Backtrace

this is part of the trace, but it was like this for the whole buffer.

INFO [12-12|16:06:45.119] Aborting state snapshot generation       root="53ad61…fc2960" at="0170f1…cd235c" accounts=2104 slots=5368 storage=551.17KiB elapsed=23.039s    eta=1h7m49.589s
INFO [12-12|16:06:45.119] Resuming state snapshot generation       root="2e0d94…390fa5" at="0170f1…cd235c" accounts=2104 slots=5368 storage=551.17KiB elapsed=23.039s    eta=1h7m49.589s
INFO [12-12|16:06:45.130] Aborting state snapshot generation       root="2e0d94…390fa5" at="017107…51510c" accounts=2105 slots=5368 storage=551.22KiB elapsed=23.049s    eta=1h7m50.4s
INFO [12-12|16:06:45.130] Resuming state snapshot generation       root="be407a…5456e8" at="017107…51510c" accounts=2105 slots=5368 storage=551.22KiB elapsed=23.049s    eta=1h7m50.4s
INFO [12-12|16:06:45.131] Aborting state snapshot generation       root="be407a…5456e8" at="01714b…7e52f3" accounts=2107 slots=5368 storage=551.30KiB elapsed=23.051s    eta=1h7m47.794s
INFO [12-12|16:06:45.131] Resuming state snapshot generation       root="ff6a54…f5bea0" at="01714b…7e52f3" accounts=2107 slots=5368 storage=551.30KiB elapsed=23.051s    eta=1h7m47.794s
INFO [12-12|16:06:45.133] Aborting state snapshot generation       root="ff6a54…f5bea0" at="0171c5…eab2de" accounts=2109 slots=5368 storage=551.39KiB elapsed=23.052s    eta=1h7m42.73s
INFO [12-12|16:06:45.133] Resuming state snapshot generation       root="3a7a93…039ae3" at="0171c5…eab2de" accounts=2109 slots=5368 storage=551.39KiB elapsed=23.052s    eta=1h7m42.73s
INFO [12-12|16:06:45.138] Aborting state snapshot generation       root="3a7a93…039ae3" at="0171c5…eab2de" accounts=2109 slots=5368 storage=551.39KiB elapsed=23.058s    eta=1h7m43.787s
INFO [12-12|16:06:45.139] Resuming state snapshot generation       root="450a40…b715b8" at="0171c5…eab2de" accounts=2109 slots=5368 storage=551.39KiB elapsed=23.058s    eta=1h7m43.787s
INFO [12-12|16:06:45.140] Aborting state snapshot generation       root="450a40…b715b8" at="0171c5…880e33" accounts=2110 slots=5368 storage=551.49KiB elapsed=23.059s    eta=1h7m43.958s
INFO [12-12|16:06:45.140] Resuming state snapshot generation       root="590126…600e99" at="0171c5…880e33" accounts=2110 slots=5368 storage=551.49KiB elapsed=23.059s    eta=1h7m43.958s
INFO [12-12|16:06:45.141] Aborting state snapshot generation       root="590126…600e99" in="0171c5…880e33" at="290dec…f3e563" accounts=2110 slots=5370 storage=551.66KiB elapsed=23.061s    eta=1h7m44.311s
INFO [12-12|16:06:45.141] Resuming state snapshot generation       root="556221…8a775e" in="0171c5…880e33" at="290dec…f3e563" accounts=2110 slots=5370 storage=551.66KiB elapsed=23.061s    eta=1h7m44.311s
INFO [12-12|16:06:45.142] Aborting state snapshot generation       root="556221…8a775e" at="0171c5…880e33" accounts=2110 slots=5370 storage=551.66KiB elapsed=23.062s    eta=1h7m44.487s
INFO [12-12|16:06:45.143] Resuming state snapshot generation       root="134fd1…0696c5" in="0171c5…880e33" at="290dec…f3e563" accounts=2110 slots=5370 storage=551.66KiB elapsed=23.062s    eta=1h7m44.487s
INFO [12-12|16:06:45.144] Aborting state snapshot generation       root="134fd1…0696c5" in="0171c5…880e33" at="c2575a…71f85b" accounts=2110 slots=5373 storage=551.89KiB elapsed=23.063s    eta=1h7m44.663s
INFO [12-12|16:06:45.144] Resuming state snapshot generation       root="5a1f15…97eb2c" in="0171c5…880e33" at="c2575a…71f85b" accounts=2110 slots=5373 storage=551.89KiB elapsed=23.063s    eta=1h7m44.663s
INFO [12-12|16:06:45.145] Aborting state snapshot generation       root="5a1f15…97eb2c" at="0171e1…e9d75d" accounts=2111 slots=5374 storage=552.03KiB elapsed=23.064s    eta=1h7m43.602s
INFO [12-12|16:06:45.145] Resuming state snapshot generation       root="66daa7…41de01" at="0171e1…e9d75d" accounts=2111 slots=5374 storage=552.03KiB elapsed=23.064s    eta=1h7m43.602s
INFO [12-12|16:06:45.146] Aborting state snapshot generation       root="66daa7…41de01" at="0171e1…e9d75d" accounts=2111 slots=5374 storage=552.03KiB elapsed=23.065s    eta=1h7m43.778s
INFO [12-12|16:06:45.146] Resuming state snapshot generation       root="05decd…556291" at="0171e1…e9d75d" accounts=2111 slots=5374 storage=552.03KiB elapsed=23.065s    eta=1h7m43.778s
INFO [12-12|16:06:45.147] Aborting state snapshot generation       root="05decd…556291" in="0171e3…938359" at="290dec…f3e563" accounts=2112 slots=5375 storage=552.21KiB elapsed=23.066s    eta=1h7m43.909s
INFO [12-12|16:06:45.147] Resuming state snapshot generation       root="194518…0c6080" in="0171e3…938359" at="290dec…f3e563" accounts=2112 slots=5375 storage=552.21KiB elapsed=23.066s    eta=1h7m43.909s
INFO [12-12|16:06:45.149] Aborting state snapshot generation       root="194518…0c6080" at="017223…7ef032" accounts=2113 slots=5378 storage=552.55KiB elapsed=23.068s    eta=1h7m41.484s
INFO [12-12|16:06:45.149] Resuming state snapshot generation       root="063ab5…94686b" at="017223…7ef032" accounts=2113 slots=5378 storage=552.55KiB elapsed=23.068s    eta=1h7m41.484s
INFO [12-12|16:06:45.161] Aborting state snapshot generation       root="063ab5…94686b" in="017278…4736fa" at="8a35ac…6bd19b" accounts=2115 slots=5389 storage=553.67KiB elapsed=23.080s    eta=1h7m39.914s
INFO [12-12|16:06:45.161] Resuming state snapshot generation       root="d4856d…2e84f1" in="017278…4736fa" at="8a35ac…6bd19b" accounts=2115 slots=5389 storage=553.67KiB elapsed=23.081s    eta=1h7m40.09s
INFO [12-12|16:06:45.170] Aborting state snapshot generation       root="d4856d…2e84f1" at="0172ee…a1fe40" accounts=2116 slots=5393 storage=554.04KiB elapsed=23.089s    eta=1h7m36.443s
INFO [12-12|16:06:45.170] Resuming state snapshot generation       root="7af516…bb93f6" at="0172ee…a1fe40" accounts=2116 slots=5393 storage=554.04KiB elapsed=23.089s    eta=1h7m36.443s
INFO [12-12|16:06:45.172] Aborting state snapshot generation       root="7af516…bb93f6" at="017301…051d40" accounts=2117 slots=5393 storage=554.09KiB elapsed=23.091s    eta=1h7m35.964s
INFO [12-12|16:06:45.172] Resuming state snapshot generation       root="36a798…64e3b3" at="017301…051d40" accounts=2117 slots=5393 storage=554.09KiB elapsed=23.092s    eta=1h7m36.139s
INFO [12-12|16:06:45.174] Aborting state snapshot generation       root="36a798…64e3b3" at="017341…677a9b" accounts=2119 slots=5393 storage=554.18KiB elapsed=23.093s    eta=1h7m33.595s
INFO [12-12|16:06:45.174] Resuming state snapshot generation       root="8f9e93…3323b6" at="017341…677a9b" accounts=2119 slots=5393 storage=554.18KiB elapsed=23.093s    eta=1h7m33.595s
INFO [12-12|16:06:45.175] Aborting state snapshot generation       root="8f9e93…3323b6" at="01739a…29bfec" accounts=2121 slots=5393 storage=554.26KiB elapsed=23.094s    eta=1h7m29.918s
INFO [12-12|16:06:45.175] Resuming state snapshot generation       root="ee494d…3321bd" at="01739a…29bfec" accounts=2121 slots=5393 storage=554.26KiB elapsed=23.094s    eta=1h7m29.918s
INFO [12-12|16:06:45.176] Aborting state snapshot generation       root="ee494d…3321bd" at="017408…93d2f9" accounts=2123 slots=5393 storage=554.40KiB elapsed=23.095s    eta=1h7m25.431s
INFO [12-12|16:06:45.176] Resuming state snapshot generation       root="b359e7…4426d7" at="017408…93d2f9" accounts=2123 slots=5393 storage=554.40KiB elapsed=23.095s    eta=1h7m25.431s
INFO [12-12|16:06:45.177] Aborting state snapshot generation       root="b359e7…4426d7" in="017408…93d2f9" at="290dec…f3e563" accounts=2123 slots=5394 storage=554.47KiB elapsed=23.096s    eta=1h7m25.606s
INFO [12-12|16:06:45.177] Resuming state snapshot generation       root="90013c…e890d8" in="017408…93d2f9" at="290dec…f3e563" accounts=2123 slots=5394 storage=554.47KiB elapsed=23.096s    eta=1h7m25.606s
INFO [12-12|16:06:45.177] Aborting state snapshot generation       root="90013c…e890d8" in="017408…93d2f9" at="eb2c1c…8628a2" accounts=2123 slots=5398 storage=554.77KiB elapsed=23.097s    eta=1h7m25.781s
INFO [12-12|16:06:45.178] Resuming state snapshot generation       root="229c8e…18f070" in="017408…93d2f9" at="eb2c1c…8628a2" accounts=2123 slots=5398 storage=554.77KiB elapsed=23.097s    eta=1h7m25.781s
INFO [12-12|16:06:45.178] Aborting state snapshot generation       root="229c8e…18f070" at="017449…7e9b9e" accounts=2124 slots=5399 storage=554.89KiB elapsed=23.098s    eta=1h7m23.166s
INFO [12-12|16:06:45.179] Resuming state snapshot generation       root="6464aa…d39770" at="017449…7e9b9e" accounts=2124 slots=5399 storage=554.89KiB elapsed=23.098s    eta=1h7m23.166s
INFO [12-12|16:06:45.181] Aborting state snapshot generation       root="6464aa…d39770" in="01748c…2b3103" at="0175b7…a01db9" accounts=2125 slots=5400 storage=555.06KiB elapsed=23.100s    eta=1h7m20.659s
INFO [12-12|16:06:45.181] Resuming state snapshot generation       root="af7173…1faf9c" in="01748c…2b3103" at="0175b7…a01db9" accounts=2125 slots=5400 storage=555.06KiB elapsed=23.100s    eta=1h7m20.659s
INFO [12-12|16:06:45.182] Aborting state snapshot generation       root="af7173…1faf9c" in="01748c…2b3103" at="290dec…f3e563" accounts=2125 slots=5403 storage=555.29KiB elapsed=23.101s    eta=1h7m20.833s
INFO [12-12|16:06:45.182] Resuming state snapshot generation       root="430160…948093" in="01748c…2b3103" at="290dec…f3e563" accounts=2125 slots=5403 storage=555.29KiB elapsed=23.101s    eta=1h7m20.833s
INFO [12-12|16:06:45.183] Aborting state snapshot generation       root="430160…948093" in="01748c…2b3103" at="405787…bb5ace" accounts=2125 slots=5405 storage=555.45KiB elapsed=23.102s    eta=1h7m21.008s
INFO [12-12|16:06:45.183] Resuming state snapshot generation       root="f7e4ef…92fe68" in="01748c…2b3103" at="405787…bb5ace" accounts=2125 slots=5405 storage=555.45KiB elapsed=23.102s    eta=1h7m21.008s
INFO [12-12|16:06:45.188] Aborting state snapshot generation       root="f7e4ef…92fe68" at="01748c…2b3103" accounts=2125 slots=5405 storage=555.45KiB elapsed=23.107s    eta=1h7m21.883s
INFO [12-12|16:06:45.188] Resuming state snapshot generation       root="52ea5e…0769ba" in="01748c…2b3103" at="405787…bb5ace" accounts=2125 slots=5405 storage=555.45KiB elapsed=23.108s    eta=1h7m22.058s
INFO [12-12|16:06:45.189] Aborting state snapshot generation       root="52ea5e…0769ba" in="01748c…2b3103" at="8a35ac…6bd19b" accounts=2125 slots=5409 storage=555.80KiB elapsed=23.109s    eta=1h7m22.233s
INFO [12-12|16:06:45.189] Resuming state snapshot generation       root="277e0f…01c57c" in="01748c…2b3103" at="8a35ac…6bd19b" accounts=2125 slots=5409 storage=555.80KiB elapsed=23.109s    eta=1h7m22.233s
INFO [12-12|16:06:45.191] Aborting state snapshot generation       root="277e0f…01c57c" in="01748c…2b3103" at="a66cc9…36c688" accounts=2125 slots=5411 storage=555.99KiB elapsed=23.111s    eta=1h7m22.583s
INFO [12-12|16:06:45.191] Resuming state snapshot generation       root="c04d16…86df36" in="01748c…2b3103" at="a66cc9…36c688" accounts=2125 slots=5411 storage=555.99KiB elapsed=23.111s    eta=1h7m22.583s
INFO [12-12|16:06:45.207] Aborting state snapshot generation       root="c04d16…86df36" in="01748c…2b3103" at="b10e2d…fa0cf6" accounts=2125 slots=5413 storage=556.19KiB elapsed=23.127s    eta=1h7m25.381s
INFO [12-12|16:06:45.208] Resuming state snapshot generation       root="da9349…8ac9ec" in="01748c…2b3103" at="b10e2d…fa0cf6" accounts=2125 slots=5413 storage=556.19KiB elapsed=23.127s    eta=1h7m25.381s
INFO [12-12|16:06:45.209] Aborting state snapshot generation       root="da9349…8ac9ec" in="01748c…2b3103" at="c2575a…71f85b" accounts=2125 slots=5416 storage=556.47KiB elapsed=23.128s    eta=1h7m25.556s
INFO [12-12|16:06:45.209] Resuming state snapshot generation       root="9db2b8…9a8309" in="01748c…2b3103" at="c2575a…71f85b" accounts=2125 slots=5416 storage=556.47KiB elapsed=23.128s    eta=1h7m25.556s
INFO [12-12|16:06:45.210] Aborting state snapshot generation       root="9db2b8…9a8309" in="01748c…2b3103" at="f3f7a9…636ee3" accounts=2125 slots=5420 storage=556.80KiB elapsed=23.129s    eta=1h7m25.731s
INFO [12-12|16:06:45.210] Resuming state snapshot generation       root="a4f07a…b62849" in="01748c…2b3103" at="f3f7a9…636ee3" accounts=2125 slots=5420 storage=556.80KiB elapsed=23.129s    eta=1h7m25.731s
INFO [12-12|16:06:45.211] Aborting state snapshot generation       root="a4f07a…b62849" at="0174b8…93a564" accounts=2126 slots=5422 storage=557.00KiB elapsed=23.130s    eta=1h7m24.008s
INFO [12-12|16:06:45.211] Resuming state snapshot generation       root="4eac93…9d1ed5" at="0174b8…93a564" accounts=2126 slots=5422 storage=557.00KiB elapsed=23.131s    eta=1h7m24.183s
INFO [12-12|16:06:45.212] Aborting state snapshot generation       root="4eac93…9d1ed5" in="0174b9…999e62" at="0175b7…a01db9" accounts=2127 slots=5423 storage=557.17KiB elapsed=23.132s    eta=1h7m24.343s
INFO [12-12|16:06:45.213] Resuming state snapshot generation       root="6c9d36…8db1f3" in="0174b9…999e62" at="0175b7…a01db9" accounts=2127 slots=5423 storage=557.17KiB elapsed=23.132s    eta=1h7m24.343s
INFO [12-12|16:06:45.214] HTTP server stopped                      endpoint=127.0.0.1:8546
INFO [12-12|16:06:45.214] Aborting state snapshot generation       root="6c9d36…8db1f3" in="0174b9…999e62" at="20d145…9ed14a" accounts=2127 slots=5426 storage=557.39KiB elapsed=23.133s    eta=1h7m24.518s
INFO [12-12|16:06:45.214] Resuming state snapshot generation       root="782e8d…a2b90d" in="0174b9…999e62" at="20d145…9ed14a" accounts=2127 slots=5426 storage=557.39KiB elapsed=23.133s    eta=1h7m24.518s
INFO [12-12|16:06:45.214] IPC endpoint closed                      url=/Volumes/Work/chain-datadirs/mordor.full.archive/geth.ipc
WARN [12-12|16:06:45.215] Synchronisation failed, retrying         err="content processing canceled (requested)"
INFO [12-12|16:06:45.216] Ethereum protocol stopped 
INFO [12-12|16:06:45.216] Transaction pool stopped 
INFO [12-12|16:06:45.216] Aborting state snapshot generation       root="782e8d…a2b90d" in="0174b9…999e62" at="297b73…bbb8eb" accounts=2127 slots=5429 storage=557.64KiB elapsed=23.135s    eta=1h7m24.868s
INFO [12-12|16:06:45.216] Journalling in-progress snapshot         root="782e8d…a2b90d" in="0174b9…999e62" at="297b73…bbb8eb" accounts=2127 slots=5429 storage=557.64KiB elapsed=23.135s    eta=1h7m24.868s
INFO [12-12|16:06:45.216] Writing clean trie cache to disk         path=/Volumes/Work/chain-datadirs/mordor.full.archive/geth/triecache threads=8
INFO [12-12|16:06:45.343] Persisted the clean trie cache           path=/Volumes/Work/chain-datadirs/mordor.full.archive/geth/triecache elapsed=126.719ms
INFO [12-12|16:06:45.343] Blockchain stopped

after a node restart without the --snapshot flag

....
INFO [12-12|16:22:15.918] IPC endpoint opened                      url=/Volumes/Work/chain-datadirs/mordor.full.archive/geth.ipc
INFO [12-12|16:22:15.919] HTTP server started                      endpoint=127.0.0.1:8545 cors=http://remix.ethereum.org vhosts=localhost
INFO [12-12|16:22:15.919] WebSocket enabled                        url=ws://127.0.0.1:8546
INFO [12-12|16:22:15.985] Etherbase automatically configured       address=0x8F10D3A6283672EcfAeea0377d460BdEd489EC44
INFO [12-12|16:22:16.851] Deep froze chain segment                 blocks=7820 elapsed=1.032s number=2688524 hash="337c0a…fbe841"
INFO [12-12|16:22:16.909] Block synchronisation started 
INFO [12-12|16:22:18.486] Downloader queue stats                   receiptTasks=0 blockTasks=0 itemSize=260.35B throttle=8192
INFO [12-12|16:22:18.500] Imported new chain segment               blocks=6    txs=0 mgas=0.000 elapsed=13.802ms mgasps=0.000 number=2778530 hash="280a86…84afd1" age=2w1d9h dirty=0.00B
INFO [12-12|16:22:18.662] Imported new chain segment               blocks=33   txs=0 mgas=0.000 elapsed=59.090ms mgasps=0.000 number=2778563 hash="ae8439…00f71d" age=2w1d9h dirty=0.00B
INFO [12-12|16:22:20.372] Imported new chain segment               blocks=153  txs=1 mgas=0.021 elapsed=192.457ms mgasps=0.109 number=2778716 hash="1829df…dc9313" age=2w1d6h dirty=0.00B
INFO [12-12|16:22:21.003] Imported new chain segment               blocks=474  txs=3 mgas=0.063 elapsed=628.410ms mgasps=0.100 number=2779190 hash="cf76a3…f04310" age=2w1d55m dirty=0.00B
INFO [12-12|16:22:23.592] Imported new chain segment               blocks=2048 txs=3 mgas=0.063 elapsed=2.579s    mgasps=0.024 number=2781238 hash="f4af22…8cf5c1" age=2w15h35m dirty=0.00B
ziogaschr commented 3 years ago

Not sure how snapshot works, but it might be that it would have to wait for the chain to be synced first

meowsbits commented 3 years ago

So the abort/resume pattern was happening the whole time? Or could this be a race around a shutdown channel?

ziogaschr commented 3 years ago

The abort/resume pattern was happening the whole time I think