Frequent Synchronisation failed for Geth on both main and test net

[srirambv]

Description

Frequent Synchronisation failed for Geth on both main and test net

Steps to Reproduce

1. Build from source
2. Launch brave with either ETHERUM_NETWORK=ropsten for test net or without for main net
3. Block head count updated but every 4th message is a Sync fail rollback message

Actual result:

$ GETH_LOG=1 npm run start

> brave@0.25.0 start C:\browser-laptop
> node ./tools/start.js --user-data-dir-name=brave-development --enable-logging --v=0 --enable-extension-activity-logging --enable-sandbox-logging --enable-dcheck

Crash reporting enabled
Could not write geth.pid
GETH: spawned
INFO [08-09|17:46:43.803] Maximum peer count                       ETH=0 LES=100 total=10
INFO [08-09|17:46:43.808] Starting peer-to-peer node               instance=Geth/v1.8.13-stable-225171a4/windows-amd64/go1.10.3
INFO [08-09|17:46:43.808] Allocated cache and file handles         database=C:\\Users\\Owner\\AppData\\Roaming\\brave-development\\ethereum\\mainnet\\geth\\lightchaindata cache=10485 handles=1024
INFO [08-09|17:46:43.997] Initialised chain configuration          config="{ChainID: 1 Homestead: 1150000 DAO: 1920000 DAOSupport: true EIP150: 2463000 EIP155: 2675000 EIP158: 2675000 Byzantium: 4370000 Constantinople: <nil> Engine: ethash}"
INFO [08-09|17:46:43.997] Disk storage enabled for ethash caches   dir=C:\\Users\\Owner\\AppData\\Roaming\\brave-development\\ethereum\\mainnet\\geth\\ethash count=3
INFO [08-09|17:46:43.997] Disk storage enabled for ethash DAGs     dir=C:\\Users\\Owner\\AppData\\Ethash                                                      count=2
INFO [08-09|17:46:43.998] Added trusted checkpoint                 chain=mainnet block=5898239 hash=ae778e…76d0ea
INFO [08-09|17:46:43.998] Loaded most recent local header          number=5900159 hash=0d3c0e…d71493 td=5138814315097993797915
INFO [08-09|17:46:43.998] Starting P2P networking
INFO [08-09|17:46:46.101] UDP listener up                          net=enode://c3ff2b01ddeda2df6cf7e09142390101cad9168b7dc2b66604ed071faf6fb9a40d1d1dd25b22a1e0064c11e3cc30fbc0f3c557a463ec31d764c9fffd23f423cb@[::]:40400
INFO [08-09|17:46:46.106] RLPx listener up                         self="enode://c3ff2b01ddeda2df6cf7e09142390101cad9168b7dc2b66604ed071faf6fb9a40d1d1dd25b22a1e0064c11e3cc30fbc0f3c557a463ec31d764c9fffd23f423cb@[::]:40400?discport=0"
WARN [08-09|17:46:46.106] Light client mode is an experimental feature
INFO [08-09|17:46:46.108] IPC endpoint opened                      url=\\\\.\\pipe\\geth.ipc
INFO [08-09|17:46:46.114] HTTP endpoint opened                     url=http://127.0.0.1:40800 cors= vhosts=localhost
INFO [08-09|17:46:46.115] WebSocket endpoint opened                url=ws://127.0.0.1:40600
INFO [08-09|17:49:32.506] Block synchronisation started
INFO [08-09|17:49:33.290] Imported new block headers               count=0 elapsed=6.900ms number=5900351 hash=81ed8a…b7eaec ignored=192
INFO [08-09|17:49:33.517] Imported new block headers               count=0 elapsed=5.488ms number=5900543 hash=89435d…ee84dc ignored=192
INFO [08-09|17:49:33.850] Imported new block headers               count=192 elapsed=96.222ms number=5900735 hash=ab9e7f…a7b736 ignored=0
INFO [08-09|17:49:34.142] Imported new block headers               count=192 elapsed=74.858ms number=5900927 hash=fe2470…431a91 ignored=0
WARN [08-09|17:49:36.351] Rolled back headers                      count=384 header=5900927->5900543 fast=0->0 block=0->0
WARN [08-09|17:49:36.351] Synchronisation failed, dropping peer    peer=ea1737bf696928b4 err="retrieved hash chain is invalid"
INFO [08-09|17:52:37.441] Imported new block headers               count=0   elapsed=6.449ms  number=5900735 hash=ab9e7f…a7b736 ignored=192
INFO [08-09|17:52:37.673] Imported new block headers               count=0   elapsed=4.961ms  number=5900927 hash=fe2470…431a91 ignored=192
INFO [08-09|17:52:38.006] Imported new block headers               count=192 elapsed=90.267ms number=5901119 hash=725a8e…807b63 ignored=0
INFO [08-09|17:52:38.302] Imported new block headers               count=192 elapsed=80.351ms number=5901311 hash=bbedd6…5076f3 ignored=0
WARN [08-09|17:52:39.296] Rolled back headers                      count=384 header=5901311->5900927 fast=0->0 block=0->0
WARN [08-09|17:52:39.296] Synchronisation failed, retrying         err="receipt download canceled (requested)"
INFO [08-09|17:53:43.007] Imported new block headers               count=0   elapsed=5.952ms  number=5901119 hash=725a8e…807b63 ignored=192
INFO [08-09|17:53:43.249] Imported new block headers               count=0   elapsed=6.447ms  number=5901311 hash=bbedd6…5076f3 ignored=192
INFO [08-09|17:53:43.670] Imported new block headers               count=192 elapsed=75.886ms number=5901503 hash=9fef88…efeac9 ignored=0
INFO [08-09|17:53:44.011] Imported new block headers               count=192 elapsed=76.380ms number=5901695 hash=2866fd…079331 ignored=0
WARN [08-09|17:53:45.006] Rolled back headers                      count=384 header=5901695->5901311 fast=0->0 block=0->0
WARN [08-09|17:53:45.006] Synchronisation failed, dropping peer    peer=95176fe178be55d4 err="retrieved hash chain is invalid"
INFO [08-09|17:54:13.876] Imported new block headers               count=0   elapsed=6.447ms  number=5901503 hash=9fef88…efeac9 ignored=192
INFO [08-09|17:54:14.120] Imported new block headers               count=0   elapsed=6.447ms  number=5901695 hash=2866fd…079331 ignored=192
INFO [08-09|17:54:14.544] Imported new block headers               count=192 elapsed=91.258ms number=5901887 hash=46eee8…254c9d ignored=0
INFO [08-09|17:54:14.845] Imported new block headers               count=192 elapsed=77.376ms number=5902079 hash=d7c178…156317 ignored=0
WARN [08-09|17:54:15.843] Rolled back headers                      count=384 header=5902079->5901695 fast=0->0 block=0->0
WARN [08-09|17:54:15.843] Synchronisation failed, retrying         err="receipt download canceled (requested)"
INFO [08-09|17:54:45.713] Imported new block headers               count=0   elapsed=6.401ms  number=5901887 hash=46eee8…254c9d ignored=192
INFO [08-09|17:54:45.952] Imported new block headers               count=0   elapsed=6.448ms  number=5902079 hash=d7c178…156317 ignored=192
INFO [08-09|17:54:46.386] Imported new block headers               count=192 elapsed=89.276ms number=5902271 hash=7bbde0…e878dd ignored=0
INFO [08-09|17:54:46.729] Imported new block headers               count=192 elapsed=87.791ms number=5902463 hash=f214c8…d6a151 ignored=0
WARN [08-09|17:54:47.810] Rolled back headers                      count=384 header=5902463->5902079 fast=0->0 block=0->0
WARN [08-09|17:54:47.811] Synchronisation failed, dropping peer    peer=95176fe178be55d4 err="retrieved hash chain is invalid"

Expected result:
Should sync properly without so many sync fail message

Reproduces how often:
100% for me on both Main and test net. @kjozwiak experienced this intermittently but syncs without problem most times

Brave Version

Brave 0.25.0
V8 6.8.275.24
rev f20fdca
Muon 8.0.6
OS Release 10.0.17134
Update Channel
OS Architecture x64
OS Platform Microsoft Windows
Node.js 7.9.0
Brave Sync v1.4.2
libchromiumcontent 68.0.3440.84

Reproducible on current live release:
N/A

Additional Information

[tildelowengrimm]

Clarifying assignment: @ryanml should track down this issue. If Ryan can't repro reliably, then try a live debugging session with @srirambv. If it transpires that there's something that @bkero can do about it, please open a separate issue for that task and assign him. General questions about this on Slack, please.

[kjozwiak]

This is still happening and it makes syncing almost impossible unless you're willing to wait 4-5hrs. I left my instance of Brave running the entire night and it only reached about 73%.

When you get into the above instance, it seems like it connects to a node, downloads a few headers and then disconnects. I've attached myself to the geth process and noticed that I'm only connected to a peer for a few seconds before being disconnected, example:

> admin.peers
[{
    caps: ["eth/62", "eth/63", "les/1", "les/2"],
    id: "fcae30c6dc37ae0bb824a4340e1307d1993412d29f9deecb8f4d49bafac8a884d584c5d8b857559ecd21661312bbd1b9b2eb2d5c9981610ba1ea6e68d8a8aa4b",
    name: "Geth/v1.8.13-stable-225171a4/linux-amd64/go1.10.3",
    network: {
      inbound: false,
      localAddress: "192.168.1.159:64975",
      remoteAddress: "34.222.77.2:30303",
      static: true,
      trusted: false
    },
    protocols: {
      les: {
        difficulty: 6.007889590952182e+21,
        head: "b1f663dd3ab7c86646ed300502840377787c4d2cd018193086fed26d15fbdf27",
        version: 2
      }
    }
}]
> admin.peers
[]
> admin.peers
[]
> admin.peers
[]
> admin.peers
[{
    caps: ["eth/62", "eth/63", "les/1", "les/2"],
    id: "fcae30c6dc37ae0bb824a4340e1307d1993412d29f9deecb8f4d49bafac8a884d584c5d8b857559ecd21661312bbd1b9b2eb2d5c9981610ba1ea6e68d8a8aa4b",
    name: "Geth/v1.8.13-stable-225171a4/linux-amd64/go1.10.3",
    network: {
      inbound: false,
      localAddress: "192.168.1.159:64994",
      remoteAddress: "34.222.77.2:30303",
      static: true,
      trusted: false
    },
    protocols: {
      les: {
        difficulty: 6.007889590952182e+21,
        head: "b1f663dd3ab7c86646ed300502840377787c4d2cd018193086fed26d15fbdf27",
        version: 2
      }
    }
}]
> admin.peers
[]
> admin.peers
[]
>

Because of this, you'll run into the following as mentioned above:

WARN [08-16|13:16:14.518] Rolled back headers                      count=64   header=5967743->5967679 fast=0->0 block=0->0
WARN [08-16|13:16:14.518] Synchronisation failed, retrying         err="receipt download canceled (requested)"
INFO [08-16|13:16:42.324] Imported new block headers               count=128  elapsed=142.355ms number=5967871 hash=f669f6…df361d ignored=64
INFO [08-16|13:16:42.800] Imported new block headers               count=192  elapsed=209.128ms number=5968063 hash=7bd10d…d3df82 ignored=0
WARN [08-16|13:16:59.456] Rolled back headers                      count=320  header=5968063->5967743 fast=0->0 block=0->0
WARN [08-16|13:16:59.456] Synchronisation failed, retrying         err="receipt download canceled (requested)"
WARN [08-16|13:17:06.536] Synchronisation failed, retrying         err="block header download canceled (requested)"
INFO [08-16|13:17:29.359] Imported new block headers               count=0    elapsed=3.278ms   number=5967935 hash=b4582d…bf6cfd ignored=192
INFO [08-16|13:17:29.794] Imported new block headers               count=256  elapsed=287.639ms number=5968319 hash=ddafb1…104b51 ignored=128
INFO [08-16|13:17:30.080] Imported new block headers               count=192  elapsed=259.283ms number=5968511 hash=de46b9…442f8d ignored=0
WARN [08-16|13:17:30.116] Rolled back headers                      count=448  header=5968511->5968063 fast=0->0 block=0->0