Slow/failed syncing with testnet

[wileyj]

Running a follower node for testnet was failing to sync stacks blocks as expected.
Initially, the burnchain sync went through fine - but then it took roughly 48 hours of continued operation to sync a single stacks block (the only event that happened on my side was a disconnection due to laptop lid being closed for a bit - reopened the lid, service became active again and blocks started to download).

Steps To Reproduce

Run a testnet node with the following config.toml:

[node]
working_dir = "/root/stacks-node/data"
rpc_bind = "0.0.0.0:20443"
p2p_bind = "0.0.0.0:20444"
bootstrap_node="047435c194e9b01b3d7f7a2802d6684a3af68d05bbf4ec8f17021980d777691f1d51651f7f1d566532c804da506c117bbf79ad62eea81213ba58f8808b4d9504ad@testnet.stacks.co:20444"
wait_time_for_microblocks = 10000

[[events_observer]]
endpoint = "stacks-node-api:3700"
retry_count = 255
events_keys = ["*"]

[burnchain]
chain = "bitcoin"
mode = "xenon"
peer_host = "bitcoin.testnet.blockstack.com"
username = "blockstack"
password = "blockstacksystem"
rpc_port = 18332
peer_port = 18333

[[ustx_balance]]
address = "STB44HYPYAT2BB2QE513NSP81HTMYWBJP02HPGK6"
amount = 10000000000000000

[[ustx_balance]]
address = "ST11NJTTKGVT6D1HY4NJRVQWMQM7TVAR091EJ8P2Y"
amount = 10000000000000000

[[ustx_balance]]
address = "ST1HB1T8WRNBYB0Y3T7WXZS38NKKPTBR3EG9EPJKR"
amount = 10000000000000000

[[ustx_balance]]
address = "STRYYQQ9M8KAF4NS7WNZQYY59X93XEKR31JP64CP"
amount = 10000000000000000

[connection_options]
read_only_call_limit_write_length = 0
read_only_call_limit_read_length = 100000
read_only_call_limit_write_count = 0
read_only_call_limit_read_count = 30
read_only_call_limit_runtime = 1000000000

Expected behavior

Node will sync stacks blocks in a timely manner

Environment

• OS: Docker (Docker version 20.10.6, build 370c289)
• Image: blockstack/stacks-blockchain:latest (same as tagged image 2.0.11.1.0)
  • sha256:c77148c2b62c19602caece38a0bfc1a7b5fe88baa082c5e3ac4439d806968ffe

Additional context

Logs of the the node are attached in txt format
testnet.txt

[dantrevino]

I had similar issues early on when trying to run bitcoind in pruned mode.

[wileyj]

Also to note: when switching to mainnet these sync issues disappear

[jcnelson]

My testnet node has been running for about 14 hours now. I don't know if this is the cause of what you've been seeing, but I've noticed that the node does a lot of needless full inventory syncs. If the node ever diverges from its always-allowed peers -- i.e. if it is missing a PoX anchor block but proceeds to the next reward cycle anyway (which does happen occasionally during initial block download), the node will do a complete inventory rescan. This can take a long, long time, given the number of reward cycles we have on testnet. The fix for this would be to not do a complete inventory scan, but to simply retry scanning at the reward cycle prior to the one in which the divergence was detected. I've opened issue #2728 to track this.

[wileyj]

Interesting - have you seen the same behaviour where the stacks tip height isn't progressing?
At this point, i can reliably reproduce and can provide some DEBUG logs if you need additional data here.

[jcnelson]

Another source of slowness as the chain progresses is that the PoX synchronization watchdog (which makes sure that the node doesn't try to download the next reward cycle until it's reasonably confident that it has all the blocks it's gonna get for the current reward cycle) requires that the downloader state-machine does a full pass over the set of reward cycles. Watching my node this morning, this is taking longer and longer as the node gets closer and closer to the chain tip. The requirement for a full pass is probably too aggressive. I've opened issue #2730 to track this.

[jcnelson]

At this point, i can reliably reproduce and can provide some DEBUG logs if you need additional data here.

That'd be great! I'd love to confirm whether or not your node is encountering the same problem as mine.

[wileyj]

At this point, i can reliably reproduce and can provide some DEBUG logs if you need additional data here.

That'd be great! I'd love to confirm whether or not your node is encountering the same problem as mine.

Thanks for the updates - i'll do the needful today and get those logs for you later this evening

[wileyj]

hmm, this definitely feels exacerbated on slower machines - on a standalone VM, i was able to start syncing stacks testnet blocks much faster than a local laptop (started to sync stacks blocks after roughly 1-2 hours).

still generating logs, i'll upload once i have them

[jcnelson]

So, it takes about 30 minutes on my (6 year old) laptop with a spinning-rust drive to instantiate the boot code. After that, I get blocks immediately.

Also, I'm not running the API side-car; I'm running the node directly. Because the side-car blocks the node from doing stuff until it fully receives the node's pushed data, that might be slowing things down.

[wileyj]

So, it takes about 30 minutes on my (6 year old) laptop with a spinning-rust drive to instantiate the boot code. After that, I get blocks immediately.

Also, I'm not running the API side-car; I'm running the node directly. Because the side-car blocks the node from doing stuff until it fully receives the node's pushed data, that might be slowing things down.

Well, i definitely cannot upload these logs as is.
The VM log is roughly 1.6Gb, working on the local log now - i'll see what i can do re:compression and a suitable place to store them - i may share some links privately for you.

[wileyj]

So, it takes about 30 minutes on my (6 year old) laptop with a spinning-rust drive to instantiate the boot code. After that, I get blocks immediately.

Also, I'm not running the API side-car; I'm running the node directly. Because the side-car blocks the node from doing stuff until it fully receives the node's pushed data, that might be slowing things down.

best I could compress to was around 300Mb - shared the link