Zebra validation can be very slow on macOS, and cause very slow syncs

[rex4539]

Bug Report

version: 1.0.0-beta.0+26.g62bfa15
Zcash network: Mainnet
state version: 10
branch: main
git commit: 62bfa15
commit timestamp: 2021-11-08T22:33:12+00:00
target triple: x86_64-apple-darwin
build profile: debug

It appears the sync is stuck and has entered in a loop. I have tried leaving it sync overnight and still nothing, same loop.

Nov 09 08:30:10.719  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: Starting zebrad
Nov 09 08:30:10.720  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: config=ZebradConfig { consensus: Config { checkpoint_sync: false }, metrics: MetricsSection { endpoint_addr: None }, network: Config { listen_addr: 0.0.0.0:8233, network: Mainnet, initial_mainnet_peers: {"dnsseed.z.cash:8233", "mainnet.seeder.zfnd.org:8233", "dnsseed.str4d.xyz:8233", "mainnet.is.yolo.money:8233"}, initial_testnet_peers: {"testnet.seeder.zfnd.org:18233", "testnet.is.yolo.money:18233", "dnsseed.testnet.z.cash:18233"}, peerset_initial_target_size: 50, crawl_new_peer_interval: 60s }, state: Config { cache_dir: "/Users/rex/Library/Caches/zebra", ephemeral: false, debug_stop_at_height: None }, tracing: TracingSection { use_color: true, filter: None, endpoint_addr: None, flamegraph: None, use_journald: false }, sync: SyncSection { max_concurrent_block_requests: 50, lookahead_limit: 2000 }, mempool: Config { debug_enable_at_height: None, tx_cost_limit: 80000000, eviction_memory_time: 3600s } }
Nov 09 08:30:10.720  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: initializing node state
Nov 09 08:30:10.720  INFO {zebrad="62bfa15" net="Main"}: zebra_state::config: the open file limit is at or above the specified limit new_limit=1024 current_limit=2560 hard_rlimit=Some(9223372036854775807)
Nov 09 08:30:10.827  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service::finalized_state: Opened Zebra state cache at /Users/rex/Library/Caches/zebra/state/v10/mainnet
Nov 09 08:30:10.827  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service::finalized_state: reading cached tip height
Nov 09 08:30:10.829  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service::finalized_state: loaded cached tip height tip_height=Height(1067743)
Nov 09 08:30:10.829  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service::finalized_state: loaded Zebra state cache tip=Some((Height(1067743), block::Hash("0000000000e859846ce2297776fcf8dc86c5a70c6c418e27a7d358a19867bada")))
Nov 09 08:30:10.831  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service: starting legacy chain check
Nov 09 08:30:10.831  INFO {zebrad="62bfa15" net="Main"}: zebra_state::service: no legacy chain found
Nov 09 08:30:10.831  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: initializing verifiers
Nov 09 08:30:10.846  INFO {zebrad="62bfa15" net="Main"}:init{config=Config { checkpoint_sync: false } network=Mainnet}: zebra_consensus::chain: initializing chain verifier tip=Some((Height(1067743), block::Hash("0000000000e859846ce2297776fcf8dc86c5a70c6c418e27a7d358a19867bada"))) max_checkpoint_height=Height(1046449)
Nov 09 08:30:10.846  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: initializing network
Nov 09 08:30:10.847  INFO {zebrad="62bfa15" net="Main"}:open_listener{addr=0.0.0.0:8233}: zebra_network::peer_set::initialize: Trying to open Zcash protocol endpoint at 0.0.0.0:8233...
Nov 09 08:30:10.847  INFO {zebrad="62bfa15" net="Main"}:open_listener{addr=0.0.0.0:8233}: zebra_network::peer_set::initialize: Opened Zcash protocol endpoint at 0.0.0.0:8233
Nov 09 08:30:11.470  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: resolved seed peer IP addresses seed="mainnet.is.yolo.money:8233" remote_ip_count=50
Nov 09 08:30:11.595  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: resolved seed peer IP addresses seed="dnsseed.z.cash:8233" remote_ip_count=25
Nov 09 08:30:12.256  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: resolved seed peer IP addresses seed="mainnet.seeder.zfnd.org:8233" remote_ip_count=17
Nov 09 08:30:14.944  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: DNS error resolving peer IP addresses host="dnsseed.str4d.xyz:8233" e=Custom { kind: Uncategorized, error: "failed to lookup address information: nodename nor servname provided, or not known" }
Nov 09 08:30:14.944  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: Retrying peer DNS resolution host="dnsseed.str4d.xyz:8233" retry_count=1
Nov 09 08:30:20.038  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: DNS error resolving peer IP addresses host="dnsseed.str4d.xyz:8233" e=Custom { kind: Uncategorized, error: "failed to lookup address information: nodename nor servname provided, or not known" }
Nov 09 08:30:20.038  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::config: Retrying peer DNS resolution host="dnsseed.str4d.xyz:8233" retry_count=2
Nov 09 08:30:25.040  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: Limiting the initial peers list from 89 to 50
Nov 09 08:30:25.041  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: connecting to initial peer set initial_peer_count=50 initial_peers={109.167.229.54:8233, 104.207.139.34:8233, [2a01:4f8:231:1101::2]:8233, 111.90.145.162:8233, 85.15.179.171:8233, 95.179.182.168:8233, 88.80.148.28:8233, 198.187.30.208:8233, [2001:41d0:306:aae::ff03]:8233, 165.232.125.107:8233, [2a01:4f8:13a:27ae::2]:8233, 148.251.22.185:8233, 39.97.255.168:8233, 5.9.7.62:8233, 147.135.11.144:8233, 195.201.11.54:8233, [2001:41d0:700:223d::]:8233, 194.163.135.109:8233, 112.65.166.69:8233, 47.253.8.99:8233, [2001:19f0:5001:2e30:5400:1ff:fed3:be49]:8233, [2a01:4f8:120:72a3::2]:8233, 120.78.209.151:8233, [2607:5300:203:f62::]:8233, 128.1.171.50:8233, 35.246.238.163:8233, [2a02:7b40:c287:513d::1]:8233, 8.135.7.215:8233, [2001:41d0:700:2233::]:8233, 65.108.6.224:8233, [2a01:4f8:10a:3169::2]:8233, 35.233.224.178:8233, 162.55.92.62:8233, [2a01:4f8:171:1f16::2]:8233, 91.206.16.214:8233, 46.4.65.10:8233, 194.135.81.61:8233, [2a01:4f8:173:230a::2]:8233, [2a01:4f8:201:838a::2]:8233, 157.90.223.151:8233, 37.59.32.10:8233, 185.86.76.62:8233, 77.93.223.9:8233, [2610:150:4000:1db:ec4:7aff:fe4a:fd2]:8233, 204.228.149.154:8233, 47.93.194.27:8233, [2a01:4f9:c010:7391::1]:8233, [2a02:c207:2022:9236::1]:8233, 136.144.215.219:8233, 138.197.174.176:8233}
Nov 09 08:30:26.678  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=10 errors=1 addr=195.201.11.54:8233 e=Connection refused (os error 61)
Nov 09 08:30:27.741  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=16 errors=2 addr=112.65.166.69:8233 e=Peer offered obsolete version: Version(170011)
Nov 09 08:30:28.401  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=25 errors=3 addr=162.55.92.62:8233 e=Connection refused (os error 61)
Nov 09 08:30:28.804  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=27 errors=4 addr=46.4.65.10:8233 e=Peer offered obsolete version: Version(170002)
Nov 09 08:30:29.045  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=29 errors=5 addr=109.167.229.54:8233 e=request timed out
Nov 09 08:30:29.074  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=29 errors=6 addr=157.90.223.151:8233 e=Connection refused (os error 61)
Nov 09 08:30:29.399  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=31 errors=7 addr=77.93.223.9:8233 e=Connection refused (os error 61)
Nov 09 08:30:29.444  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=32 errors=8 addr=85.15.179.171:8233 e=request timed out
Nov 09 08:30:30.746  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=39 errors=9 addr=194.163.135.109:8233 e=request timed out
Nov 09 08:30:32.445  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=39 errors=10 addr=91.206.16.214:8233 e=request timed out
Nov 09 08:30:33.546  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: an initial peer connection failed successes=39 errors=11 addr=47.93.194.27:8233 e=request timed out
Nov 09 08:30:33.546  INFO {zebrad="62bfa15" net="Main"}:add_initial_peers: zebra_network::peer_set::initialize: finished connecting to initial seed peers handshake_success_total=39 handshake_error_total=11 outbound_connections=40
Nov 09 08:30:33.546  INFO {zebrad="62bfa15" net="Main"}: zebra_network::peer_set::initialize: sending initial request for peers active_initial_peer_count=40
Nov 09 08:30:43.548  INFO {zebrad="62bfa15" net="Main"}: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:30:43.549  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: initializing syncer
Nov 09 08:30:43.549  INFO {zebrad="62bfa15" net="Main"}: zebrad::commands::start: initializing mempool
Nov 09 08:30:43.550  INFO zebrad::components::sync::gossip: initializing block gossip task
Nov 09 08:30:43.550  INFO zebrad::components::mempool::crawler: initializing mempool crawler task
Nov 09 08:30:43.550  INFO zebrad::components::mempool::queue_checker: initializing mempool queue checker task
Nov 09 08:30:43.550  INFO zebrad::components::mempool::gossip: initializing transaction gossip task
Nov 09 08:30:43.551  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: starting sync, obtaining new tips
Nov 09 08:30:43.552  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(1067743) min_locator_height=1067644 locators=[Height(1067743), Height(1067742), Height(1067741), Height(1067739), Height(1067735), Height(1067727), Height(1067711), Height(1067679), Height(1067644)]
Nov 09 08:30:43.552  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips: zebrad::components::sync: trying to obtain new chain tips tip=block::Hash("0000000000e859846ce2297776fcf8dc86c5a70c6c418e27a7d358a19867bada")
Nov 09 08:30:44.281  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:push_obtain_tips_length{sync_length=499}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[499]
Nov 09 08:30:48.554  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=499 lookahead_limit=2000
Nov 09 08:30:48.554  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:30:48.783  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 499]
Nov 09 08:30:51.630  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=997 lookahead_limit=2000
Nov 09 08:30:51.630  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:30:52.209  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 499]
Nov 09 08:30:55.004  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1495 lookahead_limit=2000
Nov 09 08:30:55.004  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:30:55.257  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 499]
Nov 09 08:30:57.593  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1993 lookahead_limit=2000
Nov 09 08:30:57.594  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:30:57.987  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 498]
Nov 09 08:31:00.417  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting for pending blocks tips.len=1 in_flight=2491 lookahead_limit=2000
Nov 09 08:31:53.554  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:32:57.345  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:33:14.823  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=17711 new_len=17707 prune_count=4 tip=Some((Height(1067763), block::Hash("000000000138f0ce5fd2c272fea7533a45bf0a47db95f8a12060c46e0c88a6b9")))
Nov 09 08:33:44.338  WARN {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=VerifierError(Elapsed(()))
Nov 09 08:33:44.338  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s
Nov 09 08:33:54.092  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:33:54.264  INFO {zebrad="62bfa15" net="Main"}:{peer=Out("54.93.123.118:8233")}:msg_as_req{msg=getheaders}: zebra_state::service: pruned utxo requests old_len=20036 new_len=5 prune_count=20031 tip=Some((Height(1067773), block::Hash("00000000007f072473ec21ed962b23e97af376257f7d5d2148e870dfd7765225")))
Nov 09 08:34:45.347  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: starting sync, obtaining new tips
Nov 09 08:34:45.347  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(1067773) min_locator_height=1067674 locators=[Height(1067773), Height(1067772), Height(1067771), Height(1067769), Height(1067765), Height(1067757), Height(1067741), Height(1067709), Height(1067674)]
Nov 09 08:34:45.347  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips: zebrad::components::sync: trying to obtain new chain tips tip=block::Hash("00000000007f072473ec21ed962b23e97af376257f7d5d2148e870dfd7765225")
Nov 09 08:34:53.555  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:34:54.651  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:push_obtain_tips_length{sync_length=499}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[499, 498, 498, 498]
Nov 09 08:34:58.514  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=499 lookahead_limit=2000
Nov 09 08:34:58.514  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:34:58.786  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 499, 498, 498]
Nov 09 08:35:03.042  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=997 lookahead_limit=2000
Nov 09 08:35:03.042  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:35:03.484  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 499, 498]
Nov 09 08:35:08.540  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1495 lookahead_limit=2000
Nov 09 08:35:08.540  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:35:09.180  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 499]
Nov 09 08:35:12.924  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=995 new_len=994 prune_count=1 tip=Some((Height(1067773), block::Hash("00000000007f072473ec21ed962b23e97af376257f7d5d2148e870dfd7765225")))
Nov 09 08:35:13.089  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1993 lookahead_limit=2000
Nov 09 08:35:13.089  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:35:13.279  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 498]
Nov 09 08:35:17.227  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting for pending blocks tips.len=1 in_flight=2491 lookahead_limit=2000
Nov 09 08:35:43.328  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips: zebra_state::service: pruned utxo requests old_len=4676 new_len=4670 prune_count=6 tip=Some((Height(1067773), block::Hash("00000000007f072473ec21ed962b23e97af376257f7d5d2148e870dfd7765225")))
Nov 09 08:36:03.525  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:36:53.557  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:37:43.678  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=19094 new_len=19083 prune_count=11 tip=Some((Height(1067784), block::Hash("0000000000939b55e0cadd0d1be1f059d13f91cf8d40630e0837184b55c493ea")))
Nov 09 08:37:53.908  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:37:54.715  WARN {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=VerifierError(Elapsed(()))
Nov 09 08:37:54.715  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s
Nov 09 08:38:25.379  INFO {zebrad="62bfa15" net="Main"}:{peer=Out("165.232.125.107:8233")}:msg_as_req{msg=inv}:inbound:download_and_verify{hash=00000000017a18cde911dd6ab689f97baa62089edc0974e3193f52ea17a046a9}: zebra_state::service: pruned utxo requests old_len=20178 new_len=26 prune_count=20152 tip=Some((Height(1067784), block::Hash("0000000000939b55e0cadd0d1be1f059d13f91cf8d40630e0837184b55c493ea")))
Nov 09 08:38:55.724  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: starting sync, obtaining new tips
Nov 09 08:38:55.724  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(1067784) min_locator_height=1067685 locators=[Height(1067784), Height(1067783), Height(1067782), Height(1067780), Height(1067776), Height(1067768), Height(1067752), Height(1067720), Height(1067685)]
Nov 09 08:38:55.724  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips: zebrad::components::sync: trying to obtain new chain tips tip=block::Hash("0000000000939b55e0cadd0d1be1f059d13f91cf8d40630e0837184b55c493ea")
Nov 09 08:38:55.980  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:38:56.097  INFO {zebrad="62bfa15" net="Main"}:sync:obtain_tips:push_obtain_tips_length{sync_length=499}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[499, 498, 498, 498]
Nov 09 08:39:00.810  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=499 lookahead_limit=2000
Nov 09 08:39:00.810  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:39:01.357  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 499, 498, 498]
Nov 09 08:39:06.764  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=997 lookahead_limit=2000
Nov 09 08:39:06.764  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:39:07.108  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 499, 498]
Nov 09 08:39:12.666  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1495 lookahead_limit=2000
Nov 09 08:39:12.666  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:39:18.704  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 499]
Nov 09 08:39:23.067  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: extending tips tips.len=1 in_flight=1993 lookahead_limit=2000
Nov 09 08:39:23.067  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebrad::components::sync: trying to extend chain tips tips=1
Nov 09 08:39:23.495  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips:push_extend_tips_length{sync_length=498}: zebrad::components::sync::recent_sync_lengths: sending recent sync lengths recent_lengths=[498, 498, 498, 498]
Nov 09 08:39:27.772  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting for pending blocks tips.len=1 in_flight=2491 lookahead_limit=2000
Nov 09 08:39:56.682  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=7110 new_len=7084 prune_count=26 tip=Some((Height(1067784), block::Hash("0000000000939b55e0cadd0d1be1f059d13f91cf8d40630e0837184b55c493ea")))
Nov 09 08:39:59.353  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:40:27.044  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=10890 new_len=10889 prune_count=1 tip=Some((Height(1067784), block::Hash("0000000000939b55e0cadd0d1be1f059d13f91cf8d40630e0837184b55c493ea")))
Nov 09 08:40:53.560  INFO {zebrad="62bfa15" net="Main"}:crawl_and_dial: zebra_network::peer_set::candidate_set: timeout waiting for the peer service to become ready
Nov 09 08:41:39.213  INFO {zebrad="62bfa15" net="Main"}:sync:extend_tips: zebra_state::service: pruned utxo requests old_len=20122 new_len=20118 prune_count=4 tip=Some((Height(1067786), block::Hash("000000000004db2321385d39ffedb58ff856c8c7126a3c10a5d640fc93cfbbfe")))
Nov 09 08:41:56.157  WARN {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: error downloading and verifying block e=VerifierError(Elapsed(()))
Nov 09 08:41:56.157  INFO {zebrad="62bfa15" net="Main"}:sync: zebrad::components::sync: waiting to restart sync timeout=61s

[conradoplg]

Thank you for the report. Could you provide the logs for a longer time period? (e.g. longer than one hour).

It's also possible to make the log more verbose by adding something like this to the config file:

[tracing]
filter = 'info,zebrad=debug'

[rex4539]

How long is enough? 3-4 hours or should I leave it to run overnight?

[conradoplg]

How long is enough? 3-4 hours or should I leave it to run overnight?

3-4 hours sounds good!

[rex4539]

Log is huge -> https://www.dropbox.com/s/bhjx3v0xd6k36t0/debug.log.zip?dl=0

Enjoy :)

[teor2345]

In these logs, the tip isn't actually stuck. But syncing is very slow:

Nov 09 08:30:43.552 INFO ... tip_height=Height(1067743)
Nov 09 08:34:45.347 INFO ... tip_height=Height(1067773)
Nov 09 08:38:55.724 INFO ... tip_height=Height(1067784)

We can also see that syncing is slow because the logs have repeated timeout errors:

Nov 09 08:33:44.338 WARN ... error downloading and verifying block e=VerifierError(Elapsed(()))
Nov 09 08:37:54.715 WARN ... error downloading and verifying block e=VerifierError(Elapsed(()))
Nov 09 08:41:56.157 WARN ... error downloading and verifying block e=VerifierError(Elapsed(()))

So you might not have enough CPU, RAM, or bandwidth to run Zebra in debug mode, with the default configuration.

@rex4539 can you try:

Release build

Can you rebuild Zebra in release mode?

The README has instructions for installing a release build of Zebra:
https://github.com/ZcashFoundation/zebra#build-and-run-instructions

Since you're using a custom build command:

• you can add --release to the cargo command you're using, or
• run export RUSTFLAGS="-O" before running the build command.

Reduce Zebra resource usage

If that doesn't work, or you want to run a debug build, you can try reducing Zebra's resource usage in your zebrad.toml:

[sync]
max_concurrent_block_requests = 25
lookahead_limit = 800

Note for Zebra developers

We should add these instructions to the README or a troubleshooting doc.

[rex4539]

[sync]
max_concurrent_block_requests = 25
lookahead_limit = 400

FYI

The application panicked (crashed).
Message:  configured lookahead limit 400 too low, must be at least 800

Location: zebrad/src/components/sync.rs:263

Metadata:
version: 1.0.0-beta.0+36.g7457edc
Zcash network: Mainnet
state version: 10
branch: main
git commit: 7457edc
commit timestamp: 2021-11-15T14:32:18+00:00
target triple: x86_64-apple-darwin
build profile: debug

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
  
   0: zebrad::application:: with zebrad="7457edc" net="Main"
      at zebrad/src/application.rs:368

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
   1: backtrace::backtrace::libunwind::trace::hb697fa474682cbe3
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.54/src/backtrace/libunwind.rs:90
        88 │ #[inline(always)]
        89 │ pub unsafe fn trace(mut cb: &mut dyn FnMut(&super::Frame) -> bool) {
        90 >     uw::_Unwind_Backtrace(trace_fn, &mut cb as *mut _ as *mut _);
        91 │ 
        92 │     extern "C" fn trace_fn(
   2: backtrace::backtrace::trace_unsynchronized::h30c4410b803d9f02
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.54/src/backtrace/mod.rs:66
        64 │ /// See information on `trace` for caveats on `cb` panicking.
        65 │ pub unsafe fn trace_unsynchronized<F: FnMut(&Frame) -> bool>(mut cb: F) {
        66 >     trace_imp(&mut cb)
        67 │ }
        68 │ 
   3: backtrace::backtrace::trace::h9c556537c129993f
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.54/src/backtrace/mod.rs:53
        51 │ pub fn trace<F: FnMut(&Frame) -> bool>(cb: F) {
        52 │     let _guard = crate::lock::lock();
        53 >     unsafe { trace_unsynchronized(cb) }
        54 │ }
        55 │ 
   4: backtrace::capture::Backtrace::create::h7820f0a98255bddc
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.54/src/capture.rs:176
       174 │         let mut frames = Vec::new();
       175 │         let mut actual_start_index = None;
       176 >         trace(|frame| {
       177 │             frames.push(BacktraceFrame {
       178 │                 frame: Frame::Raw(frame.clone()),
   5: backtrace::capture::Backtrace::new::hcb5446d00bcbcd86
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.54/src/capture.rs:140
       138 │     #[inline(never)] // want to make sure there's a frame here to remove
       139 │     pub fn new() -> Backtrace {
       140 >         let mut bt = Self::create(Self::new as usize);
       141 │         bt.resolve();
       142 │         bt
   6: color_eyre::config::PanicHook::panic_report::hd2946d495121bb49
      at /Users/rex/.cargo/registry/src/github.com-1ecc6299db9ec823/color-eyre-0.5.11/src/config.rs:982
       980 │ 
       981 │         let backtrace = if capture_bt {
       982 >             Some(backtrace::Backtrace::new())
       983 │         } else {
       984 │             None

[teor2345]

configured lookahead limit 400 too low, must be at least 800

@rex4539 please use lookahead_limit = 800 then.

I've edited my comment above.

[teor2345]

We really do recommend you use a release build. It's the build we support and document in the README.

[teor2345]

It's also possible to make the log more verbose by adding something like this to the config file:

[tracing]
filter = 'info,zebrad=debug'

Also, enabling debug logging will slow down Zebra, and make it harder for it to sync. So please turn off debug logging when you're not using it.

[mpguerra]

Hey team! Please add your planning poker estimate with ZenHub @conradoplg @dconnolly @jvff @oxarbitrage @teor2345 @upbqdn

[rex4539]

Just to note than none of the suggestions helped.

The sync is as slow as before.

I'm still unable to sync.

I don't understand why it's so hard to sync with zebra. zcashd syncs fast for me.

[teor2345]

Just to note than none of the suggestions helped.

The sync is as slow as before.

I'm still unable to sync.

I don't understand why it's so hard to sync with zebra. zcashd syncs fast for me.

When you were using the debug build, the logs showed that your machine was verifying blocks really slowly. That's not surprising, because debug builds are not optimised.

Here are some more things you can try:

1. Verify one block at a time. This reduces RAM and CPU usage.

In zebrad.toml:

[sync]
max_concurrent_block_requests = 1
lookahead_limit = 800

2. If that doesn't work, please send us the logs from a release build. We need to check if the verifier is still slow in a release build, or if it's something else.

3. Send us the "About This Mac" or "System Report" for your machine. We need to check if we should reduce Zebra's CPU or RAM usage. (If you have an M1 Mac, you could also be running an emulated build, which could be very slow.)

[teor2345]

We think this will be solved by upcoming fixes, or configuration changes, or a more powerful machine or network.