search

maticnetwork / bor

Official repository for the Polygon Blockchain
https://polygon.technology/
GNU Lesser General Public License v3.0
1.02k stars 491 forks source link

Failed to fetch latest milestone for whitelisting err="context deadline exceeded" #1014

Closed pitbred2 closed 1 year ago

pitbred2 commented 1 year ago

Hello. heimdall v1.0.1 bor v1.0.4

curl localhost:26657/status => "catching_up": false

journalctl -u bor.service -f

Sep 21 08:10:52 ubnt bor[134404]: WARN [09-21|08:10:52.745] an error while trying fetching from Heimdall attempt=1 error="error while fetching data from Heimdall: response code 500"

Sep 21 08:10:52 ubnt bor[134404]: INFO [09-21|08:10:52.745] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=1

Sep 21 08:10:54 ubnt bor[134404]: INFO [09-21|08:10:54.372] Imported new chain segment number=47,674,930 hash=69c5c2..5e83ff blocks=3 txs=148 mgas=41.270 elapsed=26.466s mgasps=1.559 age=3d5h17m dirty=393.90MiB

Sep 21 08:10:57 ubnt bor[134404]: INFO [09-21|08:10:57.747] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=2

Sep 21 08:11:02 ubnt bor[134404]: INFO [09-21|08:11:02.748] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=3

Sep 21 08:11:07 ubnt bor[134404]: INFO [09-21|08:11:07.747] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=4

Sep 21 08:11:12 ubnt bor[134404]: WARN [09-21|08:11:12.748] an error while trying fetching from Heimdall attempt=5 error="error while fetching data from Heimdall: response code 500"

Sep 21 08:11:12 ubnt bor[134404]: INFO [09-21|08:11:12.748] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=5

Sep 21 08:11:16 ubnt bor[134404]: INFO [09-21|08:11:16.126] Imported new chain segment number=47,674,932 hash=546fe9..79968f blocks=2 txs=92 mgas=31.306 elapsed=21.754s mgasps=1.439 age=3d5h18m dirty=395.51MiB

Sep 21 08:11:17 ubnt bor[134404]: INFO [09-21|08:11:17.748] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=6

Sep 21 08:11:22 ubnt bor[134404]: ERROR[09-21|08:11:22.744] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"

Sep 21 08:11:22 ubnt bor[134404]: WARN [09-21|08:11:22.744] unable to handle whitelist milestone err="failed to fetch latest milestone"

Sep 21 08:11:22 ubnt bor[134404]: WARN [09-21|08:11:22.746] an error while trying fetching from Heimdall attempt=1 error="error while fetching data from Heimdall: response code 500"

Sep 21 08:11:22 ubnt bor[134404]: INFO [09-21|08:11:22.746] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest attempt=1

.....

And bor fetching from Heimdall new blocks very very slow, I think that way bor never catch up current block. Any ideas? Thanks.

artree222 commented 1 year ago

I had the same problem when upgrading the mainnet. The 1.0.1 version of heimdall implies that the mainnet will have a hard fork at block 15950759, right?

VAIBHAVJINDAL3012 commented 1 year ago

@artree222 This hardfork is on the Heimdall layer, not on the Bor layer. This warning will come till the hardfork

manav2401 commented 1 year ago

To add to what @VAIBHAVJINDAL3012 already mentioned, fetching milestones is a background process and shouldn't affect the syncing of bor. Until the HF kicks in, bor won't get any milestone and will keep throwing these errors.

And bor fetching from Heimdall new blocks very very slow, I think that way bor never catch up current block.

Bor only fetches this data for serving finality. The actual bor blocks are propagated via p2p and not heimdall as it's an independent process. These service shouldn't affect the syncing of bor.

pitbred2 commented 1 year ago

To add to what @VAIBHAVJINDAL3012 already mentioned, fetching milestones is a background process and shouldn't affect the syncing of bor. Until the HF kicks in, bor won't get any milestone and will keep throwing these errors.

And bor fetching from Heimdall new blocks very very slow, I think that way bor never catch up current block.

Bor only fetches this data for serving finality. The actual bor blocks are propagated via p2p and not heimdall as it's an independent process. These service shouldn't affect the syncing of bor.

Thanks for the answer. Bor is lagging behind the creation of current blocks and will never catch up at this speed.

Sep 22 08:13:56 ubnt bor[158502]: INFO [09-22|08:13:56.609] Imported new chain segment               number=47,680,472 hash=116248..209a13 blocks=1   txs=47    mgas=21.490  elapsed=1m11.412s mgasps=0.301  age=4d1h56m  dirty=313.27MiB
Sep 22 08:14:46 ubnt bor[158502]: INFO [09-22|08:14:46.595] Imported new chain segment               number=47,680,474 hash=5db7d7..8851a2 blocks=2   txs=87    mgas=33.377  elapsed=49.985s   mgasps=0.668  age=4d1h56m   dirty=315.54MiB
Sep 22 08:15:33 ubnt bor[158502]: INFO [09-22|08:15:33.813] Imported new chain segment               number=47,680,476 hash=1b57ec..e9e0ad blocks=2   txs=83    mgas=24.913  elapsed=47.218s   mgasps=0.528  age=4d1h57m   dirty=316.91MiB

My test server:

I don't see much load on the processor, network or disk subsystem. How many thousand of dollars should a server cost for the bor to work properly?

manav2401 commented 1 year ago

@pitbred2, I believe it's more to do with your p2p connections instead of machine specs. Could you try setting the new bootnodes which are updated on our docs recently and let us know how it goes?

pitbred2 commented 1 year ago

@pitbred2, I believe it's more to do with your p2p connections instead of machine specs. Could you try setting the new bootnodes which are updated on our docs recently and let us know how it goes?

Thanks for the answer. I renewed bootnodes from here: https://wiki.polygon.technology/docs/pos/operate/node/full-node-binaries/#configure-bor-seeds-mainnet

Bor start logs:

Sep 25 08:41:21 ubnt systemd[1]: Started bor.
Sep 25 08:41:22 ubnt bor[211367]: WARN [09-25|08:41:22.127] Config File provided, this will overwrite the cli flags path=/var/lib/bor/config.toml
Sep 25 08:41:22 ubnt bor[211367]: INFO [09-25|08:41:22.130] GRPC Server started                      addr=[::]:3131
Sep 25 08:41:22 ubnt bor[211367]: WARN [09-25|08:41:22.131] Found deprecated node list file /var/lib/bor/data/bor/static-nodes.json, please use the TOML config file instead.
Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.139] Node URL <replace with enode://validator_machine_enodeID@validator_machine_ip:30303>: missing 'enr:' prefix for base64-encoded r>
Sep 25 08:41:22 ubnt bor[211367]:  
Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.139] Node URL <replace with enode://other_public_machine_enode@sentry_machine_ip:30303>: missing 'enr:' prefix for base64-encoded rec>
Sep 25 08:41:22 ubnt bor[211367]:  
Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.147] The static-nodes.json file is deprecated and ignored. Use P2P.StaticNodes in config.toml instead.
Sep 25 08:41:22 ubnt bor[211367]: WARN [09-25|08:41:22.176] Sanitizing cache to Go's GC limits       provided=16384 updated=16071
Sep 25 08:41:22 ubnt bor[211367]: INFO [09-25|08:41:22.176] Set global gas cap                       cap=50,000,000
Sep 25 08:41:22 ubnt bor[211367]: INFO [09-25|08:41:22.176] Allocated trie memory caches             clean=2.35GiB dirty=3.92GiB
Sep 25 08:41:24 ubnt bor[211367]: INFO [09-25|08:41:24.320] Using leveldb as the backing database
Sep 25 08:41:24 ubnt bor[211367]: INFO [09-25|08:41:24.321] Allocated cache and file handles         database=/var/lib/bor/data/bor/chaindata cache=7.84GiB handles=262,144 compactionTableS>
Sep 25 08:41:47 ubnt bor[211367]: INFO [09-25|08:41:47.790] Using LevelDB as the backing database
Sep 25 08:41:47 ubnt bor[211367]: INFO [09-25|08:41:47.806] Found legacy ancient chain path          location=/var/lib/bor/data/bor/chaindata/ancient
Sep 25 08:41:48 ubnt bor[211367]: INFO [09-25|08:41:48.387] Opened ancient database                  database=/var/lib/bor/data/bor/chaindata/ancient readonly=false
Sep 25 08:41:48 ubnt bor[211367]: INFO [09-25|08:41:48.900] Initialising Ethereum protocol           network=137 dbversion=8
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.822]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] -------------------------------------------------------------------------------------------------------------------------------->
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] Chain ID:  137 (bor)
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] Consensus: Bor (proof-of-stake), merged from Ethash (proof-of-work)
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] Pre-Merge hard forks (block based):
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Homestead:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Tangerine Whistle (EIP 150): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Spurious Dragon/1 (EIP 155): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Spurious Dragon/2 (EIP 158): #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Byzantium:                   #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Constantinople:              #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Petersburg:                  #0        (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Istanbul:                    #3395000  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Muir Glacier:                #3395000  (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Berlin:                      #14750000 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - London:                      #23850000 (https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgr>
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] The Merge is not yet available for this network!
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]  - Hard-fork specification: https://github.com/ethereum/execution-specs/blob/master/network-upgrades/mainnet-upgrades/paris.md
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] Post-Merge hard forks (timestamp based):
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823] -------------------------------------------------------------------------------------------------------------------------------->
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.823]
Sep 25 08:41:49 ubnt bor[211367]: INFO [09-25|08:41:49.865] Loaded most recent local block           number=47,704,744 hash=03bd05..1d9b5b td=833,267,539 age=6d11h54m
Sep 25 08:41:50 ubnt bor[211367]: INFO [09-25|08:41:50.907] Gasprice oracle is ignoring threshold set threshold=30,000,000,000
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Old unclean shutdowns found              count=151
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-01T18:24:37+0000 age=10mo3w6d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-01T18:24:46+0000 age=10mo3w6d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-01T18:24:55+0000 age=10mo3w6d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-01T18:25:04+0000 age=10mo3w6d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-21T14:20:55+0000 age=10mo1w18h
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2022-11-22T22:01:29+0000 age=10mo6d10h
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2023-07-11T14:39:29+0000 age=2mo2w1d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2023-08-08T00:22:02+0000 age=1mo2w4d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2023-08-08T15:59:32+0000 age=1mo2w3d
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.096] Unclean shutdown detected                booted=2023-08-08T21:06:10+0000 age=1mo2w3d
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.096] Enabling metrics collection
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.096] Enabling metrics export to prometheus    path=http://127.0.0.1:7071/debug/metrics/prometheus
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.096] Starting peer-to-peer node               instance=bor/v1.0.4/linux-amd64/go1.20.8
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.865] New local node record                    seq=1,667,323,765,379 id=6ee9005e34591f44 ip=127.0.0.1 udp=30303 tcp=30303
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.866] Started P2P networking                   self=enode://4bf93e09f29480e895ce42c64b8cfac2de47b45f04e16b7ee447cc88aeaf051eecf7cd083b>
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.869] IPC endpoint opened                      url=/var/lib/bor/bor.ipc
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.869] Sanitizing invalid HTTP read header timeout provided=0s    updated=30s
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.869] HTTP server started                      endpoint=127.0.0.1:8545 auth=false prefix= cors=* vhosts=*
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.870] TxFetcher                                txArrivalWait=500ms
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.872] an error while trying fetching from Heimdall attempt=1 error="error while fetching data from Heimdall: response code 500"
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.872] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=1
Sep 25 08:41:51 ubnt bor[211367]: INFO [09-25|08:41:51.873] Got new checkpoint from heimdall         start=47,958,694 end=47,959,205 rootHash=0x4597faaa8fdd21ca61de31367575f91eb4d06f781674>
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.873] Failed to whitelist checkpoint           err="missing blocks"
Sep 25 08:41:51 ubnt bor[211367]: WARN [09-25|08:41:51.873] unable to start the whitelist checkpoint service - first run err="missing blocks"
Sep 25 08:41:56 ubnt bor[211367]: INFO [09-25|08:41:56.875] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=2
Sep 25 08:42:00 ubnt bor[211367]: INFO [09-25|08:42:00.766] New local node record                    seq=1,667,323,765,380 id=6ee9005e34591f44 ip=217.112.35.111 udp=30303 tcp=30303
Sep 25 08:42:01 ubnt bor[211367]: INFO [09-25|08:42:01.875] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=3
Sep 25 08:42:03 ubnt bor[211367]: INFO [09-25|08:42:03.076] Looking for peers                        peercount=0 tried=215 static=0
Sep 25 08:42:06 ubnt bor[211367]: INFO [09-25|08:42:06.875] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=4
Sep 25 08:42:11 ubnt bor[211367]: WARN [09-25|08:42:11.875] an error while trying fetching from Heimdall attempt=5 error="error while fetching data from Heimdall: response code 500"
Sep 25 08:42:11 ubnt bor[211367]: INFO [09-25|08:42:11.875] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=5
Sep 25 08:42:14 ubnt bor[211367]: INFO [09-25|08:42:14.243] Looking for peers                        peercount=0 tried=285 static=0
Sep 25 08:42:16 ubnt bor[211367]: INFO [09-25|08:42:16.874] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=6
Sep 25 08:42:21 ubnt bor[211367]: ERROR[09-25|08:42:21.871] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:42:21 ubnt bor[211367]: WARN [09-25|08:42:21.871] unable to start the whitelist milestone service - first run err="failed to fetch latest milestone"
Sep 25 08:42:24 ubnt bor[211367]: INFO [09-25|08:42:24.916] Looking for peers                        peercount=0 tried=90  static=0
Sep 25 08:42:27 ubnt bor[211367]: INFO [09-25|08:42:27.260] Block synchronisation started
Sep 25 08:42:33 ubnt bor[211367]: WARN [09-25|08:42:33.874] an error while trying fetching from Heimdall attempt=1 error="error while fetching data from Heimdall: response code 500"
Sep 25 08:42:33 ubnt bor[211367]: INFO [09-25|08:42:33.874] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=1
Sep 25 08:42:35 ubnt bor[211367]: INFO [09-25|08:42:35.653] Looking for peers                        peercount=1 tried=191 static=0
Sep 25 08:42:38 ubnt bor[211367]: INFO [09-25|08:42:38.876] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=2
Sep 25 08:42:41 ubnt bor[211367]: INFO [09-25|08:42:41.862] Imported new chain segment               number=47,704,745 hash=e39393..eef1b8 blocks=1 txs=50 mgas=6.677 elapsed=7.322s mgasps=>
Sep 25 08:42:41 ubnt bor[211367]: INFO [09-25|08:42:41.866] Commit Interrupt. Pre-committing the current block block=47,704,746
Sep 25 08:42:43 ubnt bor[211367]: INFO [09-25|08:42:43.876] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=3
Sep 25 08:42:45 ubnt bor[211367]: INFO [09-25|08:42:45.696] Looking for peers                        peercount=1 tried=101 static=0
Sep 25 08:42:48 ubnt bor[211367]: INFO [09-25|08:42:48.876] Retrying again in 5 seconds to fetch data from Heimdall path=/milestone/latest        attempt=4

'ERROR' grep:

Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.139] Node URL <replace with enode://validator_machine_enodeID@validator_machine_ip:30303>: missing 'enr:' prefix for base64-encoded record
Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.139] Node URL <replace with enode://other_public_machine_enode@sentry_machine_ip:30303>: missing 'enr:' prefix for base64-encoded record
Sep 25 08:41:22 ubnt bor[211367]: ERROR[09-25|08:41:22.147] The static-nodes.json file is deprecated and ignored. Use P2P.StaticNodes in config.toml instead.
Sep 25 08:42:21 ubnt bor[211367]: ERROR[09-25|08:42:21.871] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:43:03 ubnt bor[211367]: ERROR[09-25|08:43:03.872] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:43:33 ubnt bor[211367]: ERROR[09-25|08:43:33.872] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:44:03 ubnt bor[211367]: ERROR[09-25|08:44:03.873] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:44:05 ubnt bor[211367]: ERROR[09-25|08:44:05.950] Expired request does not exist           peer=37c7d2215d7be2cd226817f22259476bb02f8132d7d733d5b6adfb8cc1d83a9f
Sep 25 08:44:33 ubnt bor[211367]: ERROR[09-25|08:44:33.874] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:45:03 ubnt bor[211367]: ERROR[09-25|08:45:03.874] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:45:33 ubnt bor[211367]: ERROR[09-25|08:45:33.874] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:46:03 ubnt bor[211367]: ERROR[09-25|08:46:03.874] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:46:33 ubnt bor[211367]: ERROR[09-25|08:46:33.875] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:47:03 ubnt bor[211367]: ERROR[09-25|08:47:03.876] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"
Sep 25 08:47:33 ubnt bor[211367]: ERROR[09-25|08:47:33.877] Failed to fetch latest milestone for whitelisting err="context deadline exceeded"

'Imported new chain segment' grep:

Sep 25 09:34:05 ubnt bor[211367]: INFO [09-25|09:34:05.505] Imported new chain segment               number=47,705,153 hash=cda6ae..b44963 blocks=2 txs=105 mgas=34.563 elapsed=10.394s  mgasps=3.325 age=6d12h32m  dirty=256.69MiB
Sep 25 09:34:18 ubnt bor[211367]: INFO [09-25|09:34:18.383] Imported new chain segment               number=47,705,157 hash=03b4b3..1ebfea blocks=4 txs=150 mgas=53.961 elapsed=12.878s  mgasps=4.190 age=6d12h32m  dirty=257.28MiB
Sep 25 09:34:28 ubnt bor[211367]: INFO [09-25|09:34:28.061] Imported new chain segment               number=47,705,161 hash=5a3f64..214104 blocks=4 txs=172 mgas=48.819 elapsed=9.677s   mgasps=5.045 age=6d12h32m  dirty=257.94MiB
Sep 25 09:34:41 ubnt bor[211367]: INFO [09-25|09:34:41.408] Imported new chain segment               number=47,705,165 hash=26d2dd..31da04 blocks=4 txs=186 mgas=41.551 elapsed=13.347s  mgasps=3.113 age=6d12h32m  dirty=259.10MiB
Sep 25 09:34:51 ubnt bor[211367]: INFO [09-25|09:34:51.093] Imported new chain segment               number=47,705,168 hash=1e9b07..dc6104 blocks=3 txs=162 mgas=41.325 elapsed=9.685s   mgasps=4.267 age=6d12h32m  dirty=259.59MiB
Sep 25 09:35:25 ubnt bor[211367]: INFO [09-25|09:35:25.300] Imported new chain segment               number=47,705,169 hash=22e9ee..e4c119 blocks=1 txs=70  mgas=21.177 elapsed=34.207s  mgasps=0.619 age=6d12h33m  dirty=261.15MiB
Sep 25 09:35:34 ubnt bor[211367]: INFO [09-25|09:35:34.587] Imported new chain segment               number=47,705,172 hash=6928f5..776ba2 blocks=3 txs=134 mgas=29.499 elapsed=9.286s   mgasps=3.176 age=6d12h33m  dirty=261.15MiB
Sep 25 09:35:45 ubnt bor[211367]: INFO [09-25|09:35:45.295] Imported new chain segment               number=47,705,176 hash=a6b4c4..e0f3ca blocks=4 txs=320 mgas=59.050 elapsed=10.707s  mgasps=5.515 age=6d12h33m  dirty=262.32MiB
Sep 25 09:35:54 ubnt bor[211367]: INFO [09-25|09:35:54.292] Imported new chain segment               number=47,705,179 hash=057e16..ca9c68 blocks=3 txs=139 mgas=33.858 elapsed=8.997s   mgasps=3.763 age=6d12h33m  dirty=262.70MiB
Sep 25 09:36:49 ubnt bor[211367]: INFO [09-25|09:36:49.259] Imported new chain segment               number=47,705,181 hash=f10946..bed098 blocks=2 txs=68  mgas=19.946 elapsed=54.967s  mgasps=0.363 age=6d12h34m  dirty=264.62MiB
Sep 25 09:37:19 ubnt bor[211367]: INFO [09-25|09:37:19.598] Imported new chain segment               number=47,705,182 hash=800f13..9648f4 blocks=1 txs=32  mgas=19.801 elapsed=30.338s  mgasps=0.653 age=6d12h34m  dirty=265.68MiB
Sep 25 09:37:32 ubnt bor[211367]: INFO [09-25|09:37:32.797] Imported new chain segment               number=47,705,185 hash=473f94..63bfb5 blocks=3 txs=149 mgas=48.503 elapsed=13.198s  mgasps=3.675 age=6d12h34m  dirty=265.84MiB
Sep 25 09:38:10 ubnt bor[211367]: INFO [09-25|09:38:10.145] Imported new chain segment               number=47,705,189 hash=6f1665..374cc2 blocks=4 txs=135 mgas=39.943 elapsed=37.348s  mgasps=1.069 age=6d12h35m  dirty=266.77MiB

It seems like nothing has changed.

github-actions[bot] commented 1 year ago

This issue is stale because it has been open 14 days with no activity. Remove stale label or comment or this will be closed in 14 days.

anshalshukla commented 1 year ago

@pitbred2 were you able to get it fixed, please share the current status

pitbred2 commented 1 year ago

@pitbred2 were you able to get it fixed, please share the current status

I couldn't found the fix. Now I'm trying another client - erigon.

marcello33 commented 1 year ago

@pitbred2 any success with erigon client? Can the issue be closed? Thanks

manav2401 commented 1 year ago

Closing this for now, feel free to reopen.

cryptophonic commented 1 year ago

getting similar issues with polygon sync. it's impossible for it to catch up. bor is the only client and matic is the only network that gives these types of issues.

andreicupaciu commented 10 months ago

Hi!

I'm having exact same issues when using clients versions: bor: 1.1.0 & 1x 1.2.3 (2 nodes) heimdall: 1.0.3

Errors seen on bor:

WARN [01-30|07:18:30.964] an error while trying fetching from Heimdall path="/milestone/ID/9839a926-38ee-460c-9b19-05d7bbbc31cd - 0xa1dff281c5b731b6da4d384055de73f683902000" attempt=1 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:18:50.966] an error while trying fetching from Heimdall path="/milestone/ID/9839a926-38ee-460c-9b19-05d7bbbc31cd - 0xa1dff281c5b731b6da4d384055de73f683902000" attempt=5 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:19:34.309] an error while trying fetching from Heimdall path="/milestone/ID/53007ce6-46c3-4905-9778-bd278cd71623 - 0x1ab64376e7369d35b3921d0d7114a61a8114b9a7" attempt=1 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:19:54.311] an error while trying fetching from Heimdall path="/milestone/ID/53007ce6-46c3-4905-9778-bd278cd71623 - 0x1ab64376e7369d35b3921d0d7114a61a8114b9a7" attempt=5 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:20:04.211] an error while trying fetching from Heimdall path="/milestone/ID/73e21045-3b94-4be1-a1ee-c2bd2682b6a6 - 0x01805ff9d0a87650f52de7d12a80d75a995cf3b7" attempt=1 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:20:22.876] an error while trying fetching from Heimdall path="/milestone/ID/73e21045-3b94-4be1-a1ee-c2bd2682b6a6 - 0x01805ff9d0a87650f52de7d12a80d75a995cf3b7" attempt=1 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:20:51.873] an error while trying fetching from Heimdall path="/milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521 - 0x4099f90e3f700b78bf98fa43617b2ce8f40f48a8" attempt=1 error="error while fetching data from Heimdall: response code 500" WARN [01-30|07:21:11.876] an error while trying fetching from Heimdall path="/milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521 - 0x4099f90e3f700b78bf98fa43617b2ce8f40f48a8" attempt=5 error="error while fetching data from Heimdall: response code 500"

During this time, bor stops syncing and following log appears:

WARN [01-30|07:25:16.510] Served bor_getVoteOnHash conn=192.168.0.3:46018 reqid=6309 duration=29.90012752s err="Milestone ID doesn't exist in Heimdall" INFO [01-30|07:25:16.513] Got new milestone from heimdall start=52,915,439 end=52,915,458 hash=0xb30a388c47a0422624b9ec3ba72d03a16560e8f258d287f544d28c3527dc7ce0

After mentioned logs, bor eth.syncing returns true and it catches up (~ 20 - 30 blocks behind) This happens each 3 - 5 minutes. Each time, bor fells behind with ~ 20 - 30 blocks.

On heimdallr, I see GETs like:

x.x.x.x - - [30/Jan/2024:07:20:51 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-" x.x.x.x - - [30/Jan/2024:07:20:56 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-" x.x.x.x - - [30/Jan/2024:07:21:01 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-" x.x.x.x - - [30/Jan/2024:07:21:06 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-" x.x.x.x - - [30/Jan/2024:07:21:11 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-" x.x.x.x - - [30/Jan/2024:07:21:16 +0000] "GET /milestone/ID/914ad250-c2a7-4161-ba9f-ea771da23521%20-%200x4099f90e3f700b78bf98fa43617b2ce8f40f48a8 HTTP/1.1" 500 173 "-" "Go-http-client/1.1" "-"

s-sohani commented 7 months ago

I also have same problem

Apr 27 17:27:54 xxx bor[280435]: WARN [04-27|17:27:54.556] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:28:03 xxx bor[280435]: INFO [04-27|17:28:03.709] Looking for peers                        peercount=0 tried=193 static=0
Apr 27 17:28:06 xxx bor[280435]: INFO [04-27|17:28:06.556] Got new milestone from heimdall          start=56,319,764 end=56,319,797 hash=0x5c89fbd7d1093b2dbfc284c7cac68ae8d4c1d92e6eb83694e1a8a459c997a302
Apr 27 17:28:06 xxx bor[280435]: WARN [04-27|17:28:06.556] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:28:13 xxx bor[280435]: INFO [04-27|17:28:13.791] Looking for peers                        peercount=0 tried=212 static=0
Apr 27 17:28:18 xxx bor[280435]: INFO [04-27|17:28:18.555] Got new milestone from heimdall          start=56,319,764 end=56,319,797 hash=0x5c89fbd7d1093b2dbfc284c7cac68ae8d4c1d92e6eb83694e1a8a459c997a302
Apr 27 17:28:18 xxx bor[280435]: WARN [04-27|17:28:18.556] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:28:23 xxx bor[280435]: INFO [04-27|17:28:23.797] Looking for peers                        peercount=0 tried=186 static=0
Apr 27 17:28:30 xxx bor[280435]: INFO [04-27|17:28:30.557] Got new milestone from heimdall          start=56,319,764 end=56,319,797 hash=0x5c89fbd7d1093b2dbfc284c7cac68ae8d4c1d92e6eb83694e1a8a459c997a302
Apr 27 17:28:30 xxx bor[280435]: WARN [04-27|17:28:30.558] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:28:33 xxx bor[280435]: INFO [04-27|17:28:33.959] Looking for peers                        peercount=1 tried=145 static=0
Apr 27 17:28:42 xxx bor[280435]: INFO [04-27|17:28:42.556] Got new milestone from heimdall          start=56,319,798 end=56,319,903 hash=0x84ff287051c76f793441c75883117dced6cf3e4e6636accdf24394b27d600057
Apr 27 17:28:42 xxx bor[280435]: WARN [04-27|17:28:42.556] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:28:43 xxx bor[280435]: INFO [04-27|17:28:43.967] Looking for peers                        peercount=0 tried=123 static=0
Apr 27 17:28:54 xxx bor[280435]: INFO [04-27|17:28:54.003] Looking for peers                        peercount=0 tried=174 static=0
Apr 27 17:28:54 xxx bor[280435]: INFO [04-27|17:28:54.555] Got new milestone from heimdall          start=56,319,798 end=56,319,903 hash=0x84ff287051c76f793441c75883117dced6cf3e4e6636accdf24394b27d600057
Apr 27 17:28:54 xxx bor[280435]: WARN [04-27|17:28:54.555] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:29:04 xxx bor[280435]: INFO [04-27|17:29:04.007] Looking for peers                        peercount=0 tried=133 static=0
Apr 27 17:29:06 xxx bor[280435]: INFO [04-27|17:29:06.554] Got new milestone from heimdall          start=56,319,798 end=56,319,903 hash=0x84ff287051c76f793441c75883117dced6cf3e4e6636accdf24394b27d600057
Apr 27 17:29:06 xxx bor[280435]: WARN [04-27|17:29:06.554] unable to handle whitelist milestone     err="missing blocks"
Apr 27 17:29:06 xxx bor[280435]: INFO [04-27|17:29:06.559] Got new checkpoint from heimdall         start=56,317,862 end=56,318,373 rootHash=0x8e72029899a66a85549ec76b94d2642c6161422a2e06adf3d99d13a4c100fc9d
Apr 27 17:29:06 xxx bor[280435]: WARN [04-27|17:29:06.559] Failed to whitelist checkpoint           err="missing blocks"
Apr 27 17:29:06 xxx bor[280435]: WARN [04-27|17:29:06.559] unable to handle whitelist checkpoint    err="missing blocks"
Apr 27 17:29:14 xxx bor[280435]: INFO [04-27|17:29:14.020] Looking for peers                        peercount=0 tried=131 static=0
HuzShakir commented 7 months ago

@s-sohani Did you find the solution for this? I am facing the same issue

s-sohani commented 7 months ago

No, I haven't found the solution yet. I am re-downloading all the snapshots to run with the new version of bor, hoping it will work. @HuzShakir