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.

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

mordor fails to sync with invalid mix digest at block 4_980_000 #439

Closed
meowsbits opened this issue Jan 7, 2022 · 7 comments · Fixed by #499
Closed

mordor fails to sync with invalid mix digest at block 4_980_000 #439

meowsbits opened this issue Jan 7, 2022 · 7 comments · Fixed by #499

Comments

@meowsbits
Copy link
Member

meowsbits commented Jan 7, 2022

System information

Geth version:

CoreGeth
Version: 1.12.4-unstable
Git Commit: 51f3e9773838367163aeb3fe8b8ef303b4415c4c
Git Commit Date: 20220103
Architecture: amd64
Go Version: go1.16
Operating System: linux
GOPATH=/root/go
GOROOT=/usr/local/go
# uname -a
Linux sf-etclabs 5.0.0-25-generic #26-Ubuntu SMP Thu Aug 1 12:04:58 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Expected behaviour

Syncs Mordor through blocks 5m+.

Actual behaviour

Loops out on encountering an invalid block.

Jan 07 18:56:57 sf-etclabs sh[29477]: WARN [01-07|18:56:57.917] Synchronisation failed, dropping peer    peer=f47a88a8505c5000ab6c4ef2723c0e713e79eb00e96c0741c3156bd94c608960 err="retrieved hash chain is invalid: invalid mix digest"
Jan 07 18:57:00 sf-etclabs sh[29477]: INFO [01-07|18:57:00.156] Looking for peers                        peercount=4 tried=16 static=0                                         
Jan 07 18:57:10 sf-etclabs sh[29477]: INFO [01-07|18:57:10.420] Looking for peers                        peercount=4 tried=13 static=0                                         
Jan 07 18:57:11 sf-etclabs sh[29477]: WARN [01-07|18:57:11.834] Stats server unreachable                 err="dial tcp 51.158.188.246:3000: i/o timeout"                       
Jan 07 18:57:12 sf-etclabs sh[29477]: INFO [01-07|18:57:12.095] Skip duplicated bad block                number=4,980,000 hash=cd4f82..c46a55                                  
Jan 07 18:57:12 sf-etclabs sh[29477]: ERROR[01-07|18:57:12.095]
Jan 07 18:57:12 sf-etclabs sh[29477]: ########## BAD BLOCK #########
Jan 07 18:57:12 sf-etclabs sh[29477]: Chain config: NetworkID: 7, ChainID: 63 Engine: ethash ECBP1100: 2380000 EIP1014: 301243 EIP1052: 301243 EIP1108: 999983 EIP1344: 999983 EIP140: 0 EIP145: 301243 EIP150: 0 EIP152: 999983 EIP155: 0 EIP160: 0 EIP161abc: 0 EIP161d: 0 EIP170: 0 EIP1884: 999983 EIP198: 0 EIP2028: 999983 EIP211: 0 EIP212: 0 EIP213: 0 EIP214: 0 EIP2200: 999983 EIP2565: 3985893 EIP2718: 3985893 EIP2929: 3985893 EIP2930: 3985893 EIP2: 0 EIP658: 0 EIP7: 0 EthashECIP1017: 0 EthashECIP1041: 0 EthashECIP1099: 2520000 EthashEIP100B: 0 EthashHomestead: 0
Jan 07 18:57:12 sf-etclabs sh[29477]: Number: 4980000
Jan 07 18:57:12 sf-etclabs sh[29477]: Hash: 0xcd4f821e7c0fb321626139e977df150d7af17c2f5ff7a8468e8860d9c5c46a55                                                                 
Jan 07 18:57:12 sf-etclabs sh[29477]: Error: invalid mix digest
Jan 07 18:57:12 sf-etclabs sh[29477]: ##############################
Jan 07 18:57:12 sf-etclabs sh[29477]:
Jan 07 18:57:12 sf-etclabs sh[29477]: WARN [01-07|18:57:12.101] Synchronisation failed, dropping peer    peer=b0b911904e1acc2956b66a165d802ce2a24b52a0e0331378414ff1dd5700f217 err="retrieved hash chain is invalid: invalid mix digest"
Jan 07 18:57:12 sf-etclabs sh[29477]: ERROR[01-07|18:57:12.895] Snapshot extension registration failed   peer=836158fb         err="peer connected on snap without compatible eth support"
Jan 07 18:57:20 sf-etclabs sh[29477]: INFO [01-07|18:57:20.475] Looking for peers                        peercount=3 tried=16 static=0
Jan 07 18:57:24 sf-etclabs sh[29477]: INFO [01-07|18:57:24.449] Skip duplicated bad block                number=4,980,000 hash=cd4f82..c46a55
Jan 07 18:57:24 sf-etclabs sh[29477]: ERROR[01-07|18:57:24.450]
Jan 07 18:57:24 sf-etclabs sh[29477]: ########## BAD BLOCK #########
Jan 07 18:57:24 sf-etclabs sh[29477]: Chain config: NetworkID: 7, ChainID: 63 Engine: ethash ECBP1100: 2380000 EIP1014: 301243 EIP1052: 301243 EIP1108: 999983 EIP1344: 999983 EIP140: 0 EIP145: 301243 EIP150: 0 EIP152: 999983 EIP155: 0 EIP160: 0 EIP161abc: 0 EIP161d: 0 EIP170: 0 EIP1884: 999983 EIP198: 0 EIP2028: 999983 EIP211: 0 EIP212: 0 EIP213: 0 EIP214: 0 EIP2200: 999983 EIP2565: 3985893 EIP2718: 3985893 EIP2929: 3985893 EIP2930: 3985893 EIP2: 0 EIP658: 0 EIP7: 0 EthashECIP1017: 0 EthashECIP1041: 0 EthashECIP1099: 2520000 EthashEIP100B: 0 EthashHomestead: 0
Jan 07 18:57:24 sf-etclabs sh[29477]: Number: 4980000
Jan 07 18:57:24 sf-etclabs sh[29477]: Hash: 0xcd4f821e7c0fb321626139e977df150d7af17c2f5ff7a8468e8860d9c5c46a55
Jan 07 18:57:24 sf-etclabs sh[29477]: Error: invalid mix digest
Jan 07 18:57:24 sf-etclabs sh[29477]: ##############################
Jan 07 18:57:24 sf-etclabs sh[29477]:  
Jan 07 18:57:24 sf-etclabs sh[29477]: WARN [01-07|18:57:24.450] Synchronisation failed, dropping peer    peer=35aabeacb0448d4505f09c93f89206441d7831fdb28afb9b10e0b5326f22a1d2 err="retrieved hash chain is invalid: invalid mix digest"
Jan 07 18:57:24 sf-etclabs systemd[1]: Stopping CoreGeth Ethereum Classic - Mordor...

Steps to reproduce the behaviour

Below is the system file.
I have attempted systemctl restarts multiple times. I have purged the entire datadir (which in my configuration contains the ethash dirs) mutliple times, resyncing from scratch. The issue persists.

# cat /etc/systemd/system/coregeth_ethereumclassic_mordor.service
[Unit]
Description=CoreGeth Ethereum Classic - Mordor

[Service]
Type=simple
User=root
Restart=always
RestartSec=3
TimeoutStopSec=10min
MemoryHigh=3600000000
#MemoryMax=2000000000
Environment="GETH=/home/u/go/src/github.com/ethereum/go-ethereum/build/bin/geth"
ExecStart=/bin/sh -c '${GETH} --mordor \
        --syncmode=fast \
        --datadir /mnt/volume_sfo2_01/mordor \
        --cache 512 \
        --verbosity 5 \
        --ipcpath /home/u/go/src/github.com/ethereum/go-ethereum/coregeth_ethereumclassic_mordor.ipc \
        --mine \
        --miner.etherbase=0x877bd459c9b7d8576b44e59e09d076c25946f443 \
        --light.serve 80 \
        --ethash.dagsinmem=0 \
        --ethash.dagdir /mnt/volume_sfo2_01/mordor/ethash \
        --miner.gastarget 64000000 \
        --miner.gaslimit 128000000 \
        --ethstats "ETC Labs Metrics meowsbits":Goo0y@ws://mordor.dash.fault.dev:3003 \
        --metrics \
        --metrics.expensive \
        --metrics.addr=0.0.0.0 \
        --metrics.influxdb \
        --metrics.influxdb.endpoint=https://influx.metrics.etccore.in \
        --metrics.influxdb.database=xxx \
        --metrics.influxdb.username=xxx \
        --metrics.influxdb.password=xxx \
        --metrics.influxdb.tags=chain=mordor,owner=isaac,host=isaac-sfetclabs,gethv=$(${GETH} version | grep -E '^Version' | cut -d" " -f2) \
        --pprof --pprof.addr=0.0.0.0 --pprof.port=6069 \
        --http --http.port 8111'
ExecStartPost=/bin/sh -c 'sleep 15; chmod 777 /home/u/go/src/github.com/ethereum/go-ethereum/coregeth_ethereumclassic_mordor.ipc'

[Install]
WantedBy=default.target

Backtrace

[backtrace]
@meowsbits
Copy link
Member Author

Update

I just edited my service file s/--ethash.dagsinmem=0/--ethash.dagsinmem=1/ and (reloaded and) restarted the service. It appears to be syncing normally. This may help isolate the issue to this flag.

@meowsbits
Copy link
Member Author

consensus/ethash/ethash.go enforces maxItems >= 1 silently. This is the value configured by --ethash.dagsinmem. So an assignment =0 should be equivalent to =1. The trail grows colder.

// newlru create a new least-recently-used cache for either the verification caches
// or the mining datasets.
// A constraint of maxItems >= 1 is silently enforced.
func newlru(what string, maxItems int, new func(epoch uint64, epochLength uint64) interface{}) *lru {
	if maxItems <= 0 {
		maxItems = 1
	}
	cache, _ := simplelru.NewLRU(maxItems, func(key, value interface{}) {
		log.Trace("Evicted ethash "+what, "epoch", key)
	})
	return &lru{what: what, new: new, cache: cache}
}
	ethash := &Ethash{
		config:   config,
		caches:   newlru("cache", config.CachesInMem, newCache),
		datasets: newlru("dataset", config.DatasetsInMem, newDataset),
		update:   make(chan struct{}),
		hashrate: metrics.NewMeterForced(),
	}

@meowsbits
Copy link
Member Author

+1

root@sf-etclabs:~/go/src/github.com/ethereum/go-ethereum# ./build/bin/geth version
CoreGeth
Version: 1.12.7-unstable
Git Commit: 9090b5ee2e92fa06932289611c35338bda5a1cbc
Git Commit Date: 20220405
Architecture: amd64
Go Version: go1.16
Operating System: linux
GOPATH=/root/go
GOROOT=/usr/local/go
Apr 11 14:17:01 sf-etclabs sh[27732]: INFO [04-11|14:17:01.858] Looking for peers                        peercount=2 tried=13 static=0
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.520] Loaded most recent local header          number=4,977,538 hash=9e72ee..9b3c4d td=30,036,281,432,318 age=5mo2w3d
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.520] Loaded most recent local full block      number=0         hash=a68ebd..59a3f1 td=131,072            age=2y6mo2w
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.520] Loaded most recent local fast block      number=4,977,283 hash=6eb35a..1467a8 td=30,035,957,711,157 age=5mo2w3d
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.520] Loaded last fast-sync pivot marker       number=6,116,750
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.520] Rolled back chain segment                header=4979587->4977538 snap=4977283->4977283 block=0->0 reason="invalid mix digest"
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.520] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=hashes   items=4,977,539 limit=4,977,284                            
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.521] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=bodies   items=4,977,539 limit=4,977,284                            
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.521] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=receipts items=4,977,539 limit=4,977,284                            
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.521] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=diffs    items=4,977,539 limit=4,977,284                            
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.521] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=headers  items=4,977,539 limit=4,977,284                            
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.521] State heal in progress                   accounts=2401@118.91KiB    slots=215@17.31KiB      codes=9@82.87KiB      nodes=16400@5.90MiB   pending=1                             
Apr 11 14:17:02 sf-etclabs sh[27732]: WARN [04-11|14:17:02.522] Synchronisation failed, dropping peer    peer=b0b911904e1acc2956b66a165d802ce2a24b52a0e0331378414ff1dd5700f217 err="retrieved hash chain is invalid: invalid mix digest"      
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.526] Commit new sealing work                  number=1         sealhash=2f2330..5c750a uncles=0 txs=0 gas=0 fees=0 elapsed="784.25µs"                                              
Apr 11 14:17:02 sf-etclabs sh[27732]: INFO [04-11|14:17:02.527] Commit new sealing work                  number=1         sealhash=2f2330..5c750a uncles=0 txs=0 gas=0 fees=0 elapsed=1.065ms
Apr 11 14:17:09 sf-etclabs sh[27732]: WARN [04-11|14:17:09.274] Stats server unreachable                 err="dial tcp 51.158.188.246:3000: i/o timeout"
Apr 11 14:17:12 sf-etclabs sh[27732]: INFO [04-11|14:17:12.192] Looking for peers                        peercount=1 tried=9  static=0
Apr 11 14:17:12 sf-etclabs sh[27732]: INFO [04-11|14:17:12.524] Mining aborted due to sync
Apr 11 14:17:14 sf-etclabs sh[27732]: INFO [04-11|14:17:14.871] Imported new block headers               count=1281  elapsed=108.926ms     number=4,978,819 hash=8182f8..6961d7 age=5mo2w3d                ignored=255                        
Apr 11 14:17:14 sf-etclabs sh[27732]: INFO [04-11|14:17:14.899] Imported new block headers               count=192   elapsed=27.476ms      number=4,979,011 hash=92ea11..71b6d3 age=5mo2w3d
Apr 11 14:17:15 sf-etclabs sh[27732]: INFO [04-11|14:17:15.594] Imported new block receipts              count=663   elapsed=707.723ms     number=4,977,946 hash=328f96..13e1e4 age=5mo2w3d                size=219.87KiB                     
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.720] Invalid header encountered               number=4,980,036 hash=60d6c6..c3c1ce parent=c3835a..4f29ba err="invalid mix digest"
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.720] Rewinding blockchain                     target=4,976,962
Apr 11 14:17:15 sf-etclabs sh[27732]: INFO [04-11|14:17:15.898] Imported new block receipts              count=510   elapsed=300.070ms     number=4,978,456 hash=1e671a..b00613 age=5mo2w3d                size=169.45KiB                     
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.905] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=hashes   items=4,979,012 limit=4,978,698                            
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.905] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=bodies   items=4,979,012 limit=4,978,698                            
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.906] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=receipts items=4,979,012 limit=4,978,698                            
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.906] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=diffs    items=4,979,012 limit=4,978,698                            
Apr 11 14:17:15 sf-etclabs sh[27732]: WARN [04-11|14:17:15.906] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=headers  items=4,979,012 limit=4,978,698                            
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.931] Loaded most recent local header          number=4,976,962 hash=287678..a67a7e td=30,035,553,603,778 age=5mo2w3d
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.931] Loaded most recent local full block      number=0         hash=a68ebd..59a3f1 td=131,072            age=2y6mo2w
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.931] Loaded most recent local fast block      number=4,976,962 hash=287678..a67a7e td=30,035,553,603,778 age=5mo2w3d
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.931] Loaded last fast-sync pivot marker       number=6,116,746
Apr 11 14:17:17 sf-etclabs sh[27732]: WARN [04-11|14:17:17.931] Rolled back chain segment                header=4979011->4976962 snap=4978456->4976962 block=0->0 reason="invalid mix digest"
Apr 11 14:17:17 sf-etclabs sh[27732]: WARN [04-11|14:17:17.932] Synchronisation failed, dropping peer    peer=35aabeacb0448d4505f09c93f89206441d7831fdb28afb9b10e0b5326f22a1d2 err="retrieved hash chain is invalid: side blocks can't be accepted as ancient chain data"
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.938] Commit new sealing work                  number=1         sealhash=233bb7..a6951e uncles=0 txs=0 gas=0 fees=0 elapsed="716.239µs"                                             
Apr 11 14:17:17 sf-etclabs sh[27732]: INFO [04-11|14:17:17.938] Commit new sealing work                  number=1         sealhash=233bb7..a6951e uncles=0 txs=0 gas=0 fees=0 elapsed=1.342ms
Apr 11 14:17:19 sf-etclabs sh[27732]: ERROR[04-11|14:17:19.628] Snapshot extension registration failed   peer=480e0cf6         err="peer connected on snap without compatible eth support"
Apr 11 14:17:24 sf-etclabs sh[27732]: WARN [04-11|14:17:24.275] Stats server unreachable                 err="dial tcp 51.158.188.246:3000: i/o timeout"
Apr 11 14:17:25 sf-etclabs sh[27732]: ERROR[04-11|14:17:25.441] Snapshot extension registration failed   peer=d2a5789e         err="peer connected on snap without compatible eth support"
Apr 11 14:17:27 sf-etclabs sh[27732]: INFO [04-11|14:17:27.940] Mining aborted due to sync
Apr 11 14:17:28 sf-etclabs sh[27732]: ERROR[04-11|14:17:28.673] Snapshot extension registration failed   peer=fa643f2e         err="peer connected on snap without compatible eth support"
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.045] Imported new block headers               count=192   elapsed=23.218ms      number=4,977,154 hash=7b0ecf..a5d9e0 age=5mo2w3d
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.046] Downloader queue stats                   receiptTasks=0   blockTasks=0     itemSize=582.84B  throttle=8192
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.089] Imported new block receipts              count=95    elapsed=41.214ms      number=4,977,057 hash=aabdc8..296d5f age=5mo2w3d                size=31.56KiB                      
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.198] State heal in progress                   accounts=2401@118.91KiB    slots=215@17.31KiB      codes=9@82.87KiB      nodes=16400@5.90MiB   pending=1                             
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.486] Imported new block headers               count=960   elapsed=116.182ms     number=4,978,114 hash=266bf3..acb64c age=5mo2w3d
Apr 11 14:17:32 sf-etclabs sh[27732]: INFO [04-11|14:17:32.581] Imported new block headers               count=576   elapsed=93.982ms      number=4,978,690 hash=00bb90..827a81 age=5mo2w3d
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.082] Invalid header encountered               number=4,980,075 hash=e03fa7..d4d6a3 parent=7753e0..48faf1 err="invalid mix digest"
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.082] Rewinding blockchain                     target=4,976,641
Apr 11 14:17:33 sf-etclabs sh[27732]: INFO [04-11|14:17:33.365] Imported new block receipts              count=97    elapsed=996.936ms     number=4,977,154 hash=7b0ecf..a5d9e0 age=5mo2w3d                size=32.51KiB                      
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.389] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=hashes   items=4,978,691 limit=4,978,108                            
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.389] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=bodies   items=4,978,691 limit=4,978,108                            
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.389] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=receipts items=4,978,691 limit=4,978,108                            
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.390] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=diffs    items=4,978,691 limit=4,978,108                            
Apr 11 14:17:33 sf-etclabs sh[27732]: WARN [04-11|14:17:33.390] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=headers  items=4,978,691 limit=4,978,108                            
Apr 11 14:17:34 sf-etclabs sh[27732]: INFO [04-11|14:17:34.678] State heal in progress                   accounts=2403@119.01KiB    slots=215@17.31KiB      codes=9@82.87KiB      nodes=16412@5.90MiB   pending=0                             
Apr 11 14:17:44 sf-etclabs systemd-journald[454]: Suppressed 767 messages from coregeth_ethereumclassic_mordor.service
Apr 11 14:17:44 sf-etclabs sh[27732]: INFO [04-11|14:17:44.989] Mining aborted due to sync
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.145] Imported new block headers               count=960   elapsed=77.379ms      number=4,977,601 hash=d07c15..ff7a4f age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.172] Imported new block headers               count=192   elapsed=26.383ms      number=4,977,793 hash=b59d66..5e988e age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.278] Imported new block headers               count=384   elapsed=35.882ms      number=4,978,177 hash=97e76f..596aa9 age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.315] Imported new block headers               count=192   elapsed=36.279ms      number=4,978,369 hash=f27788..7ef2a8 age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.325] Imported new block receipts              count=416   elapsed=170.804ms     number=4,977,057 hash=aabdc8..296d5f age=5mo2w3d                size=138.04KiB                     
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.496] Imported new block headers               count=576   elapsed=74.660ms      number=4,978,945 hash=57b9cb..7f37a3 age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.534] Imported new block headers               count=192   elapsed=37.167ms      number=4,979,137 hash=92b91f..f0fb69 age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.642] Imported new block headers               count=384   elapsed=46.973ms      number=4,979,521 hash=090f37..413f79 age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.685] Imported new block headers               count=192   elapsed=37.507ms      number=4,979,713 hash=e6003a..bcc6fe age=5mo2w3d                                                   
Apr 11 14:17:47 sf-etclabs sh[27732]: WARN [04-11|14:17:47.809] Invalid header encountered               number=4,980,030 hash=ab6f9b..7e441f parent=a44364..c654a4 err="invalid mix digest"                                                  
Apr 11 14:17:47 sf-etclabs sh[27732]: WARN [04-11|14:17:47.810] Rewinding blockchain                     target=4,977,664                                                                                                                     
Apr 11 14:17:47 sf-etclabs sh[27732]: INFO [04-11|14:17:47.997] Imported new block receipts              count=1312  elapsed=578.102ms     number=4,978,369 hash=f27788..7ef2a8 age=5mo2w3d                size=435.78KiB                     
Apr 11 14:17:48 sf-etclabs sh[27732]: WARN [04-11|14:17:48.013] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=hashes   items=4,979,714 limit=4,979,237                            
Apr 11 14:17:48 sf-etclabs sh[27732]: WARN [04-11|14:17:48.014] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=bodies   items=4,979,714 limit=4,979,237                            
Apr 11 14:17:48 sf-etclabs sh[27732]: WARN [04-11|14:17:48.014] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=receipts items=4,979,714 limit=4,979,237                            
Apr 11 14:17:48 sf-etclabs sh[27732]: WARN [04-11|14:17:48.014] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=diffs    items=4,979,714 limit=4,979,237                            
Apr 11 14:17:48 sf-etclabs sh[27732]: WARN [04-11|14:17:48.014] Truncating freezer table                 database=/mnt/volume_sfo2_01/mordor/geth/chaindata/ancient table=headers  items=4,979,714 limit=4,979,237                            
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.122] Loaded most recent local header          number=4,977,664 hash=8257e8..09eee6 td=30,036,441,412,755 age=5mo2w3d                                                               
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.122] Loaded most recent local full block      number=0         hash=a68ebd..59a3f1 td=131,072            age=2y6mo2w                                                               
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.122] Loaded most recent local fast block      number=4,977,664 hash=8257e8..09eee6 td=30,036,441,412,755 age=5mo2w3d                                                               
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.122] Loaded last fast-sync pivot marker       number=6,116,752                                                                                                                     
Apr 11 14:17:50 sf-etclabs sh[27732]: WARN [04-11|14:17:50.122] Rolled back chain segment                header=4979713->4977664 snap=4978369->4977664 block=0->0 reason="invalid mix digest"                                                 
Apr 11 14:17:50 sf-etclabs sh[27732]: WARN [04-11|14:17:50.123] Synchronisation failed, dropping peer    peer=35aabeacb0448d4505f09c93f89206441d7831fdb28afb9b10e0b5326f22a1d2 err="retrieved hash chain is invalid: invalid mix digest"      
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.128] Commit new sealing work                  number=1         sealhash=d4fc4e..af8fcb uncles=0 txs=0 gas=0 fees=0 elapsed="697.535µs"                                             
Apr 11 14:17:50 sf-etclabs sh[27732]: INFO [04-11|14:17:50.128] Commit new sealing work                  number=1         sealhash=d4fc4e..af8fcb uncles=0 txs=0 gas=0 fees=0 elapsed="868.807µs"                                             
Apr 11 14:17:52 sf-etclabs sh[27732]: ERROR[04-11|14:17:52.064] Snapshot extension registration failed   peer=52823145         err="peer connected on snap without compatible eth support"                                                    
Apr 11 14:17:52 sf-etclabs sh[27732]: INFO [04-11|14:17:52.858] Looking for peers                        peercount=2 tried=9  static=0                                                                                                        
Apr 11 14:17:54 sf-etclabs sh[27732]: WARN [04-11|14:17:54.278] Stats server unreachable                 err="dial tcp 51.158.188.246:3000: i/o timeout"                                                                                      
Apr 11 14:18:00 sf-etclabs sh[27732]: INFO [04-11|14:18:00.124] Mining aborted due to sync
Apr 11 14:18:01 sf-etclabs sh[27732]: INFO [04-11|14:18:01.880] State heal in progress                   accounts=2403@119.01KiB    slots=215@17.31KiB      codes=9@82.87KiB      nodes=16412@5.90MiB   pending=1                             
Apr 11 14:18:02 sf-etclabs sh[27732]: INFO [04-11|14:18:02.748] Imported new block headers               count=2048  elapsed=148.713ms     number=4,979,712 hash=57bf90..4cdfb8 age=5mo2w3d                                                   
Apr 11 14:18:02 sf-etclabs sh[27732]: WARN [04-11|14:18:02.770] Invalid header encountered               number=4,980,109 hash=8cd698..2d2a0a parent=2f13b5..e22271 err="invalid mix digest"                                                  
Apr 11 14:18:02 sf-etclabs sh[27732]: WARN [04-11|14:18:02.770] Rewinding blockchain                     target=4,977,663                                                                                                                     
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.524] State heal in progress                   accounts=2404@119.06KiB    slots=215@17.31KiB      codes=9@82.87KiB      nodes=16418@5.91MiB   pending=0                             
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.826] Loaded most recent local header          number=4,977,663 hash=7b4cb3..9c1902 td=30,036,440,137,808 age=5mo2w3d                                                               
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.826] Loaded most recent local full block      number=0         hash=a68ebd..59a3f1 td=131,072            age=2y6mo2w                                                               
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.826] Loaded most recent local fast block      number=4,977,663 hash=7b4cb3..9c1902 td=30,036,440,137,808 age=5mo2w3d                                                               
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.826] Loaded last fast-sync pivot marker       number=6,116,754                                                                                                                     
Apr 11 14:18:03 sf-etclabs sh[27732]: WARN [04-11|14:18:03.826] Rolled back chain segment                header=4979712->4977663 snap=4977664->4977663 block=0->0 reason="invalid mix digest"                                                 
Apr 11 14:18:03 sf-etclabs sh[27732]: WARN [04-11|14:18:03.827] Synchronisation failed, dropping peer    peer=35aabeacb0448d4505f09c93f89206441d7831fdb28afb9b10e0b5326f22a1d2 err="retrieved hash chain is invalid: invalid mix digest"      
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.831] Commit new sealing work                  number=1         sealhash=f45a76..238bf2 uncles=0 txs=0 gas=0 fees=0 elapsed="322.232µs"                                             
Apr 11 14:18:03 sf-etclabs sh[27732]: INFO [04-11|14:18:03.831] Commit new sealing work                  number=1         sealhash=f45a76..238bf2 uncles=0 txs=0 gas=0 fees=0 elapsed="525.616µs"                                             
Apr 11 14:18:07 sf-etclabs sh[27732]: ERROR[04-11|14:18:07.609] Snapshot extension registration failed   peer=91455906         err="peer connected on snap without compatible eth support"                                                    
Apr 11 14:18:07 sf-etclabs systemd[1]: Stopping CoreGeth Ethereum Classic - Mordor...
Apr 11 14:18:07 sf-etclabs systemd[1]: coregeth_ethereumclassic_mordor.service: Main process exited, code=killed, status=15/TERM                                                                                                              
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.919] Got interrupt, shutting down...
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.923] HTTP server stopped                      endpoint=127.0.0.1:8111                                                                                                              
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.929] IPC endpoint closed                      url=/root/go/src/github.com/ethereum/go-ethereum/coregeth_ethereumclassic_mordor.ipc                                                 
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.930] Stats daemon stopped
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.940] Les server stopped
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.945] Ethereum protocol stopped
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.945] Transaction pool stopped
Apr 11 14:18:07 sf-etclabs sh[27732]: ERROR[04-11|14:18:07.950] Failed to journal state snapshot         err="snapshot [0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421] missing"                                          
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.950] Writing clean trie cache to disk         path=/mnt/volume_sfo2_01/mordor/geth/triecache threads=2                                                                             
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.951] Persisted the clean trie cache           path=/mnt/volume_sfo2_01/mordor/geth/triecache elapsed=1.336ms                                                                       
Apr 11 14:18:07 sf-etclabs sh[27732]: INFO [04-11|14:18:07.952] Blockchain stopped
Apr 11 14:18:09 sf-etclabs sh[27732]: WARN [04-11|14:18:09.279] Stats server unreachable                 err="dial tcp 51.158.188.246:3000: i/o timeout"      

@meowsbits
Copy link
Member Author

meowsbits commented Apr 11, 2022

I just restarted with a new version (current master head) and the problem disappeared. Sync continued normally immediately.

CoreGeth
Version: 1.12.7-unstable
Git Commit: c74f1b8ae5bb3793d1c0b38c4863958e6b217641
Git Commit Date: 20220407
Architecture: amd64
Go Version: go1.16
Operating System: linux
GOPATH=/root/go
GOROOT=/usr/local/go

@ziogaschr
Copy link
Member

Can we close this one? Do you prefer the release to come first?

@meowsbits
Copy link
Member Author

I'm OK closing it for now, though I'm not entirely convinced that the issue is actually resolved in the latest version. It could be that just restarting fixes it, but we'll see. I haven't seen any other reports of this issue, so whatever it is, it's uncommon and inconsistent. Probably its related to the shape of the Mordor chain and network.

@ziogaschr
Copy link
Member

I am playing with mordor a lot lately and I didn't have this issue so far.

meowsbits added a commit that referenced this issue Aug 30, 2022
This test reproduces an error encountered on
the Mordor testnet and reported here
#439

Ethash returns a cache value with epoch
length of 30k, where it should return one
appropriate for the ECIP1099-era with
an epoch length of 60k.

This caused header verification to fail
because the mix digest was incorrect.

This issue only occurred while syncing the Mordor
network because the cache was in-memory and
because the original-era epoch was matched
later by the ECIP1099-era epoch and the LRU
future item was anachronistic.

Date: 2022-08-30 08:35:32-07:00
Signed-off-by: meows <b5c6@protonmail.com>
meowsbits added a commit that referenced this issue Aug 30, 2022
This test reproduces an error encountered on
the Mordor testnet and reported here
#439

Ethash returns a cache value with epoch
length of 30k, where it should return one
appropriate for the ECIP1099-era with
an epoch length of 60k.

This caused header verification to fail
because the mix digest was incorrect.

This issue only occurred while syncing the Mordor
network because the cache was in-memory and
because the original-era epoch was matched
later by the ECIP1099-era epoch and the LRU
future item was anachronistic.

Date: 2022-08-30 08:35:32-07:00
Signed-off-by: meows <b5c6@protonmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants