geth stuck in finalizing fast sync

[splix]

Waits for something for hours:

2018-05-28 00:20:21 Fast      #5886697 of  #5887746   99.98%          0/ 0 blk/mgas sec     100/100 peers
2018-05-28 00:21:21 Fast      #5886697 of  #5887746   99.98%          0/ 0 blk/mgas sec     100/100 peers
2018-05-28 00:22:21 Fast      #5886697 of  #5887746   99.98%          0/ 0 blk/mgas sec     100/100 peers
2018-05-28 00:23:21 Fast      #5886697 of  #5887746   99.98%          0/ 0 blk/mgas sec     100/100 peers

Same issues with v4.2.2, v5.0.0, v5.3.0

[splix]

Restart doesn't help, 2 of 3 nodes just downloaded couple of new blocks and stuck on new height:

2018-05-28 00:31:37 Discover                                                                 4/100 peers
2018-05-28 00:32:37 Fast      #5886697 of  #5893682   99.88%          0/ 0 blk/mgas sec      3/100 peers
2018-05-28 00:33:37 Fast      #5886697 of  #5893682   99.88%          0/ 0 blk/mgas sec      5/100 peers
E0528 00:34:25.523789 eth/downloader/downloader.go:366] Peer 6f77236192ea3ae5: sync: state node 0x211f7d47fa2bbb534d16d191c4e67cc6ec10945ea423cf6a97900ae6506e6350 failed with all peers (1 tries, 1 peers)
2018-05-28 00:34:37 Fast      #5888425 of  #5893682   99.91%         28/ 5 blk/mgas sec      7/100 peers
2018-05-28 00:35:37 Fast      #5892169 of  #5893692   99.97%         62/ 9 blk/mgas sec      4/100 peers
2018-05-28 00:36:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec      6/100 peers
2018-05-28 00:37:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec      6/100 peers
2018-05-28 00:38:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec      5/100 peers
2018-05-28 00:39:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec      7/100 peers
2018-05-28 00:40:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec      8/100 peers
2018-05-28 00:41:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec     10/100 peers
2018-05-28 00:42:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec     12/100 peers
2018-05-28 00:43:37 Fast      #5892169 of  #5893692   99.97%          0/ 0 blk/mgas sec     12/100 peers

and:

2018-05-28 00:31:08 Fast      #5889612 of  #5893680   99.93%          3/ 0 blk/mgas sec      2/100 peers
2018-05-28 00:32:08 Fast      #5889612 of  #5893680   99.93%          0/ 0 blk/mgas sec      3/100 peers
E0528 00:32:29.581755 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:33:08 Fast      #5891660 of  #5893680   99.97%         34/ 5 blk/mgas sec      1/100 peers
2018-05-28 00:34:07 Discover                                                                 0/100 peers
2018-05-28 00:35:07 Discover                                                                 3/100 peers
2018-05-28 00:36:07 Discover                                                                 3/100 peers
2018-05-28 00:37:07 Fast      #5892484 of  #5893696   99.98%          3/ 0 blk/mgas sec      4/100 peers
2018-05-28 00:38:08 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      4/100 peers
2018-05-28 00:39:08 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      4/100 peers
E0528 00:39:20.575670 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:39:29.188905 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:39:59.161335 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:40:08 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      4/100 peers
E0528 00:40:27.402051 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:40:32.290104 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:40:33.822667 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:41:07.800857 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:41:08 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      4/100 peers
E0528 00:41:13.990352 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:41:34.898232 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:42:08 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      4/100 peers
E0528 00:42:11.100521 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
E0528 00:42:11.786717 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:43:07 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      3/100 peers
E0528 00:43:26.872549 eth/downloader/downloader.go:316] Unregister failed: peer is not registered
2018-05-28 00:44:07 Fast      #5892484 of  #5893696   99.98%          0/ 0 blk/mgas sec      3/100 peers

Third node just ignored all downloaded state and started from the beginning, see #604

[whilei]

cc/ @twenty7, reported the same issue

[whilei]

@splix @twenty7 Can either of you attach your debug logs from these sessions?

• osx: ~/Library/EthereumClassic/mainnet/log/<geth.mh.ia.log.INFO.20180524-130000.18153>

• linux: ~/.ethereum-classic/mainnet/log/<geth.mh.ia.log.INFO.20180524-130000.18153>

[Twenty7]

geth.99b044ce23f5.root.log.INFO.20180528-060000.1.gz

[splix]

geth-5.3.0-fast.logs.180528170657.tar.gz