search

NethermindEth / nethermind

A robust execution client for Ethereum node operators.
https://nethermind.io/nethermind-client
GNU General Public License v3.0
1.25k stars 431 forks source link

Could not find common ancestor with [HBR ] #3250

Open Antyk1234 opened 3 years ago

Antyk1234 commented 3 years ago

On Thursday on 22/07/2021 node stopped syncing. The latest block number is 10689829. Here is an example of logs after docker restart:

nethermind_1     | 2021-07-26 18-44-18.4236|Nethermind starting initialization.
nethermind_1     | 2021-07-26 18-44-18.5335|Loading embedded plugins
nethermind_1     | 2021-07-26 18-44-18.5337|  Found plugin type Nethermind.Consensus.Clique.CliquePlugin
nethermind_1     | 2021-07-26 18-44-18.5337|  Found plugin type Nethermind.Consensus.Ethash.EthashPlugin
nethermind_1     | 2021-07-26 18-44-18.5337|  Found plugin type Nethermind.Consensus.Ethash.NethDevPlugin
nethermind_1     | Resolved executing directory as /nethermind.
nethermind_1     | 2021-07-26 18-44-18.6059|Loading 2 assemblies from /nethermind/plugins
nethermind_1     | 2021-07-26 18-44-18.6060|Loading assembly Nethermind.Merge.Plugin
nethermind_1     | 2021-07-26 18-44-18.6274|  Found plugin type Nethermind.Merge.Plugin
nethermind_1     | 2021-07-26 18-44-18.6275|Loading assembly Nethermind.HealthChecks
nethermind_1     | 2021-07-26 18-44-18.6314|  Found plugin type Nethermind.HealthChecks
nethermind_1     | 2021-07-26 18-44-18.7866|Loading standard NLog.config file from /nethermind/NLog.config.
nethermind_1     | 2021-07-26 18-44-19.1444|NLog.config loaded in 357ms.
nethermind_1     | 2021-07-26 18-44-19.1456|Reading config file from /nethermind/configs/ropsten.cfg
nethermind_1     | 2021-07-26 18-44-19.5602|Incorrect config settings found:
nethermind_1     | Nethermind.Config.ArgsConfigSource:config:
nethermind_1     | Nethermind.Config.ArgsConfigSource:JsonRpc:Enabled
nethermind_1     | Nethermind.Config.ArgsConfigSource:JsonRpc:Host
nethermind_1     | 2021-07-26 18-44-19.5603|Configuration initialized.
nethermind_1     | 2021-07-26 18:44:20.0122|Using http://ipv4.icanhazip.com to get external ip 
nethermind_1     | 2021-07-26 18:44:22.5103|Setting up memory allowances 
nethermind_1     | 2021-07-26 18:44:22.5103|  memory hint:        1024MB 
nethermind_1     | 2021-07-26 18:44:22.5103|  general memory:     32MB 
nethermind_1     | 2021-07-26 18:44:22.5103|  peers memory:       50MB 
nethermind_1     | 2021-07-26 18:44:22.5103|  Netty memory:       67MB 
nethermind_1     | 2021-07-26 18:44:22.5103|  mempool memory:     74MB 
nethermind_1     | 2021-07-26 18:44:22.5123|  fast blocks memory: 80MB 
nethermind_1     | 2021-07-26 18:44:22.5123|  trie memory:        144MB 
nethermind_1     | 2021-07-26 18:44:22.5199|  DB memory:          576MB 
nethermind_1     | 2021-07-26 18:44:23.6596|Using http://ipv4bot.whatismyipaddress.com to get external ip 
nethermind_1     | 2021-07-26 18:44:30.5509|Start block loaded from reorg boundary - 10689772 - 10689772 (0xea9aa4...37b377) 
nethermind_1     | 2021-07-26 18:44:30.6513|Numbers resolved, level = Max(10689772, 10689829), header = Max(10689772, 10689829), body = Max(10689772, 10689829) 
nethermind_1     | 2021-07-26 18:44:30.6524|Block tree initialized, last processed is 10689772 (0xea9aa4...37b377), best queued is 10689829, best known is 10689829, lowest inserted header 1, body 0 
nethermind_1     | 2021-07-26 18:44:30.6603|Initializing 5 plugins 
nethermind_1     | 2021-07-26 18:44:30.6603|  Clique by Nethermind 
nethermind_1     | 2021-07-26 18:44:30.6603|  Clique by Nethermind initialized in 0ms 
nethermind_1     | 2021-07-26 18:44:30.6603|  Ethash by Nethermind 
nethermind_1     | 2021-07-26 18:44:30.6671|  Ethash by Nethermind initialized in 5ms 
nethermind_1     | 2021-07-26 18:44:30.6683|  NethDev by Nethermind 
nethermind_1     | 2021-07-26 18:44:30.6683|  NethDev by Nethermind initialized in 0ms 
nethermind_1     | 2021-07-26 18:44:30.6683|  Merge by Nethermind 
nethermind_1     | 2021-07-26 18:44:30.6683|  Merge by Nethermind initialized in 0ms 
nethermind_1     | 2021-07-26 18:44:30.6683|  HealthChecks by Nethermind 
nethermind_1     | 2021-07-26 18:44:30.6683|  HealthChecks by Nethermind initialized in 0ms 
nethermind_1     | 2021-07-26 18:44:31.0421|Loaded 0 static nodes from file: /nethermind/Data/static-nodes.json 
nethermind_1     | 2021-07-26 18:44:31.0986|Using pivot 10660000 and barrier 1 in bodies sync 
nethermind_1     | 2021-07-26 18:44:31.0986|Using pivot 10660000 and barrier 1 in receipts sync 
nethermind_1     | 2021-07-26 18:44:31.1092|Now syncing nodes starting from root of block 0 
nethermind_1     | 2021-07-26 18:44:31.1092|HeadersSyncDispatcher has finished work. 
nethermind_1     | 2021-07-26 18:44:31.1092|Fast blocks headers task completed. 
nethermind_1     | 2021-07-26 18:44:31.1468|Found 57 block tree levels to review for fixes starting from 10689773 
nethermind_1     | 2021-07-26 18:44:31.1637|Reviewed 0 blocks out of 57 
nethermind_1     | 2021-07-26 18:44:31.2316|Rerunning block after reorg or pruning: 10689773 (0x762d97aa76e3bb9c7b635dfd432717ec5ac68023ac7caf060dda211ec51d054a) 
nethermind_1     | 2021-07-26 18:44:31.3396|Numbers resolved, level = Max(10689772, 10689829), header = Max(10689772, 10689829), body = Max(10689772, 10689829) 
nethermind_1     | 2021-07-26 18:44:31.3938|Grafana / Prometheus metrics are disabled in configuration 
nethermind_1     | 2021-07-26 18:44:31.8133|Peers | with known best block: 0 | all: 0 | 
nethermind_1     | 2021-07-26 18:44:31.8133|Waiting for peers... 1s 
nethermind_1     | 2021-07-26 18:44:31.8229|Sync peers - Initialized: 0 | All: 0 | Max: 50 
nethermind_1     | 2021-07-26 18:44:32.5274|

nethermind_1 | 2021-07-26 18:44:44.9046|Changing state Full to FastSync at processed:10689829|state:10689829|block:10689829|header:10689829|peer block:10712939 nethermind_1 | 2021-07-26 18:44:44.9046|Sync mode changed from Full to FastSync nethermind_1 | 2021-07-26 18:44:50.9158|Peers | with known best block: 24 | all: 24 | nethermind_1 | 2021-07-26 18:44:54.1435|100 % of nodes did not respond to a Ping message - 22/22 nethermind_1 | 2021-07-26 18:45:02.2732|Could not find common ancestor with [HBR ][ ][Peer|eth65|10712940|Geth/v1.10.6-stable-576681f2/linux-amd64/go1.16.4|3.84.15.223:30303] `

Os: Ubuntu 18.04.2 LTS Node version: latest

tkstanczak commented 3 years ago

hi @Antyk1234 , thank you for reporting, please give us some time to investigate

was it a fast synced node?

Antyk1234 commented 3 years ago

Yes, it was.

svanegmond commented 3 years ago

I've had four different nodes on different chains, including some run by colleagues, fail in this way. Nobody is pruning, everyone is using Fast Sync.

Glad to help debug this.

ETA versions in my cases are 1.10.77 and 1.9.54

svanegmond commented 3 years ago

I read the source, it appears to me that if the node has been disconnected from peers and sealing for longer than 1024 blocks it will fail to find a common ancestor. This is a fraction of a day on most chains. A better-chosen _ancestorJumps will address this.

dceleda commented 2 years ago

@tkstanczak what is the status of this?