Fast catchup does not work on Raspberry Pi 4B

salvatorecorvaglia · December 24, 2020, 4:24pm

Hello everyone.
I happen to have “fast catchup” not working on my mainnet node.
The device is a Raspberry PI 4 Model B 4GB ARM-Cortex-A72 4X 1.50 GHz, 4 GB RAM with 32-bit Raspberry OS on 16 GB microSD (the node is located in the home folder of the device).
When it gets to 1000 Catchpoint downloaded blocks:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 361
Sync Time: 6564.2s
Catchpoint: 11020000#KT5CVUYN44C2N7RQR4GRFWSRM7QEWGL3U45CTC53J3XCHBBQT3GA
Catchpoint total accounts: 7542015
Catchpoint accounts processed: 7542015
Catchpoint accounts verified: 7542015
Catchpoint total blocks: 1000
Catchpoint downloaded blocks: 15
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

give up all work and started again with a normal non-fast sync:

Time since last block: 0.1s
Last committed block: 681
Time since last block: 0.5s
Last committed block: 706
Time since last block: 0.3s
Last committed block: 706
Time since last block: 1.3s
Sync Time: 35.5s
Last consensus protocol: https://github.com/algorandfoundation/specs/tree/5615adc36bad610c7f165fa2967f4ecfa75125f0
Next consensus protocol: https://github.com/algorandfoundation/specs/tree/5615adc36bad610c7f165fa2967f4ecfa75125f0
Round for next consensus protocol: 707

I have this setting Catchup on my config.json:
“CatchpointFileHistoryLength”: 365,
“CatchpointInterval”: 10000,
“CatchpointTracking”: 0,
“CatchupBlockDownloadRetryAttempts”: 1000,
“CatchupFailurePeerRefreshRate”: 10,
“CatchupGossipBlockFetchTimeoutSec”: 4,
“CatchupHTTPBlockFetchTimeoutSec”: 4,
“CatchupLedgerDownloadRetryAttempts”: 50,
“CatchupParallelBlocks”: 16,

I don’t understand what the problem is, whether it is due to my network connection, number of processors or something else.

tsachi · December 24, 2020, 5:17pm

Hi @salvatorecorvaglia,

I see that you’re using the latest version ( which is great ! ), and that the fast catchup passed the accounts downloading/verification phase. Based on past experience gathered by this forum, increasing the “CatchupBlockDownloadRetryAttempts” was found to be useful.

I would suggest setting the CatchupBlockDownloadRetryAttempts to 20000. ( there is no downside setting this value too high, other then the duration after which the node would “give up” )

Hope this would help, and have a happy holiday!

salvatorecorvaglia · December 24, 2020, 5:31pm

What exactly does CatchupBlockDownloadRetryAttempts do?

tsachi · December 24, 2020, 5:36pm

If you’ll look here - https://github.com/algorand/go-algorand/blob/master/config/config.go#L323 you’ll see that it’s defined as

	// CatchupLedgerDownloadRetryAttempts controls the number of attempt the block fetching would be attempted before giving up catching up to the provided catchpoint.
	CatchupBlockDownloadRetryAttempts int `version[9]:"1000"`

The fast catchup need to download the past 1000 blocks. In order to download each block, it makes an http request to one of the relays and download the block.
If one ( or more ) of the relays aren’t available, it would retry with another relay ( at random ). The number of retries for the entire fast catchup is capped by the CatchupBlockDownloadRetryAttempts variable.

salvatorecorvaglia · December 24, 2020, 5:49pm

Ok, i understand. So I try to change this value and let you know the result.

aojjazz · December 25, 2020, 6:36am

When I was discussing this with him on Discord, it appeared it hit a hardcoded ‘give up’ time duration. His machine has a slow connection and its a slower device, but even if it takes hours for the fast catchup that’s nothing compared to the time it would likely take his device to catch up from scratch (and pruning the whole way).

Assuming there is still ‘activity’ it should never reach a stop-dead total elapsed time wall, throw away all of its work and start over not using fast catchup.

tsachi · December 25, 2020, 6:58pm

@aojjazz, I think that your intuition is correct here. It does make sense that as long as the node is capable of moving forward, it should keep doing so. The number of failures is troubling regardless.

salvatorecorvaglia · December 26, 2020, 9:59am

I tried “fast catchup” on testnet always with the same device and without changing the .json and it works perfectly and also very fast:

pi@raspberrypi:~/node $ ./goal node status -d testnetdata/ -w 1000
Last committed block: 429
Sync Time: 694.8s
Catchpoint: 11320000#5HSFH424JSO7FSQCHDOF4SL7WACEMEZ6JGJ7VKDFVC4SYXA4PQIA
Catchpoint total accounts: 266145
Catchpoint accounts processed: 266145
Catchpoint accounts verified: 266145
Catchpoint total blocks: 1000
Catchpoint downloaded blocks: 1000
Genesis ID: testnet-v1.0
Genesis hash: SGO1GKSzyE7IEPItTxCByw9x8FmnrCDexi9/cOUJOiI=

So the problem is on the mainnet … I try to change the CatchupBlockDownloadRetryAttempts on the mainnet to 20000 and let’s see what happens.

salvatorecorvaglia · December 26, 2020, 12:15pm

Here is the proof with CatchupBlockDownloadRetryAttempts set to 20000 on the mainnet:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 4058
Sync Time: 7118.6s
Catchpoint: 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA
Catchpoint total accounts: 7593802
Catchpoint accounts processed: 7593802
Catchpoint accounts verified: 0
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

it got stuck like that and meanwhile the sync time continued:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 4058
Sync Time: 7702.6s
Catchpoint: 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA
Catchpoint total accounts: 7593802
Catchpoint accounts processed: 7593802
Catchpoint accounts verified: 0
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

salvatorecorvaglia · December 26, 2020, 12:29pm

UPDATE: is running the “Catchpoint accounts verified”:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 4058
Sync Time: 8994.8s
Catchpoint: 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA
Catchpoint total accounts: 7593802
Catchpoint accounts processed: 7593802
Catchpoint accounts verified: 7323648
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

it remained so. It does not go further, it is blocked, and in the meantime the sync time advances:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 4058
Sync Time: 9580.2s
Catchpoint: 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA
Catchpoint total accounts: 7593802
Catchpoint accounts processed: 7593802
Catchpoint accounts verified: 7323648
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

salvatorecorvaglia · December 26, 2020, 1:09pm

NEW UPDATE: “Catchpoint accounts verified” concluded:

pi@raspberrypi:~/node $ ./goal node status -d data/ -w 1000
Last committed block: 4058
Sync Time: 9802.4s
Catchpoint: 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA
Catchpoint total accounts: 7593802
Catchpoint accounts processed: 7593802
Catchpoint accounts verified: 7593802
Catchpoint total blocks: 1000
Catchpoint downloaded blocks: 3
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

performed the “Catchpoint downloaded blocks”. Arriving at “Catchpoint downloaded blocks” = 500 approximately, everything fails:

Last committed block: 6176
Time since last block: 0.0s
Sync Time: 170.8s
Last consensus protocol: https://github.com/algorandfoundation/specs/tree/5615adc36bad610c7f165fa2967f4ecfa75125f0
Next consensus protocol: https://github.com/algorandfoundation/specs/tree/5615adc36bad610c7f165fa2967f4ecfa75125f0
Round for next consensus protocol: 6177
Next consensus protocol supported: true
Last Catchpoint:
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

salvatorecorvaglia · December 26, 2020, 1:11pm

Nothing to do unfortunately …

tsachi · December 27, 2020, 2:08am

I’ll try that tomorrow and see what the outcomes when it runs on my side.

The one active thing that can be done here is to identify the relays that have failed to provide the needed blocks. I can’t tell if the issues that you’ve been seeing are a result of a networking or something bigger than that ( my guess is that it’s unrelated to your network ); I’ll keep you posted tomorrow with my findings.

One note is that I won’t be able to test it on RaspbPI ( since I don’t have one ). If it’s a RaspPI specific issue, it can take longer to confirm and resolve.

salvatorecorvaglia · December 27, 2020, 8:52am

Is it possible that the developers of Algorand can see what happened if I turned telemetry of my node?

tsachi · December 27, 2020, 2:26pm

I’m not sure if the telemetry is sufficiently detailed to provide constructive information around that.

Your node.log file contains details regarding the catchup failuire. If you could grep the catchpoint related entries from there, it would be great.

tsachi · December 27, 2020, 4:23pm

Following up on the test I’ve promised to conduct -

I started with an empty data directory, and placed the mainnet genesis.json on that directory.

Then, I started the node on that directory using goal node start -d ., followed by goal node catchup 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA -d ..

Within less than 10 minutes, I had the node completed the fast catchup without any config.json file changes.

Reviewing the node.log file for anomalies during the catchup process, I found the following:

> cat node.log|grep catchpoint
{"file":"catchpointlabel.go","function":"github.com/algorand/go-algorand/ledger.CatchpointLabel.String","level":"info","line":59,"msg":"Creating a catchpoint label 11070000#Z5GVD2WLQ2MIG37UJPGPMA2JG7EWAFEDJKHBXAAOWP63ABV553TA for round=11070000, block digest=WGNMAVTSQMBA5F5ZQJZ66HEJJJMNE6JHWTEFZDRTGSIQD3DCBMTQ, accounts digest=246NK5IJAKKOJKCR5YX35FTIP7WEU75Q4P5VPJG7TF7OLHBCA4RQ","time":"2020-12-27T11:06:41.090885-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069724 on attempt 276 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l9gc\": context deadline exceeded","name":"","time":"2020-12-27T11:08:27.732597-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069662 on attempt 339 out of 1000. Peer r-pm.algorand-mainnet.network:4160: context deadline exceeded","name":"","time":"2020-12-27T11:08:51.883859-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069645 on attempt 357 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l9e5\": context deadline exceeded","name":"","time":"2020-12-27T11:09:01.768629-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069567 on attempt 436 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l9bz\": context deadline exceeded","name":"","time":"2020-12-27T11:09:32.744012-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069534 on attempt 470 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l9b2\": context deadline exceeded","name":"","time":"2020-12-27T11:09:46.429295-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069162 on attempt 843 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l90q\": context deadline exceeded","name":"","time":"2020-12-27T11:12:02.586166-05:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload","level":"info","line":483,"msg":"Failed to download block 11069088 on attempt 918 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get \"http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6l8yo\": context deadline exceeded","name":"","time":"2020-12-27T11:12:32.047300-05:00"}

which indicates that r-ac.algorand-mainnet.network and r-pm.algorand-mainnet.network might have some issue that need to be resolved. ( I’m saying “might”, since it could be a connectivity issue between my computer and the relay, whereas the relay itself would work perfectly fine with others )

If you could respond with the output to the above grep, it could be helpful.

salvatorecorvaglia · December 27, 2020, 7:18pm

ok, i did the same procedure, i created a new folder “maindata” and i put the genesis.json of the mainnet (with no changes to the config.json). I run the “fast catchup” and it worked until “Catchpoint accounts verified”:

pi@raspberrypi:~/node $ ./goal node status -d maindata/ -w 1000
Last committed block: 257
Sync Time: 5642.8s
Catchpoint: 11090000#SM4MLOIGVIXPPGLYNJZJU5QP5SK2CCDNQQJTNFQH7VBLQH2A3EAQ
Catchpoint total accounts: 7617140
Catchpoint accounts processed: 7617140
Catchpoint accounts verified: 7617140
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

then he did the “Catchpoint downloaded blocks” and failed at about 989/1000.

Reviewing the node.log:

pi@raspberrypi:~/node/maindata $ cat node.log | grep catchpoint
{“file”:“node.go”,“function”:“github.com/algorand/go-algorand/node.(*AlgorandFullNode).StartCatchup”,“level”:“info”,“line”:870,“msg”:“starting catching up toward catchpoint 11090000#SM4MLOIGVIXPPGLYNJZJU5QP5SK2CCDNQQJTNFQH7VBLQH2A3EAQ”,“name”:"",“time”:“2020-12-27T18:27:58.150431+01:00”}
{“file”:“catchpointlabel.go”,“function”:“github.com/algorand/go-algorand/ledger.CatchpointLabel.String",“level”:“info”,“line”:59,“msg”:"Creating a catchpoint label 11090000#SM4MLOIGVIXPPGLYNJZJU5QP5SK2CCDNQQJTNFQH7VBLQH2A3EAQ for round=11090000, block digest=I3CLCG7FWDOBOA3AENHIQ4DMI5VTZF5CQLVKHYIYX7OWE2CH3CYQ, accounts digest=PMMHRQAY3XCXUA6P5FG6LWBLQEVLZHB3UOC2NCN33DEVFVXMII3A”,“time”:“2020-12-27T20:02:07.277313+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089946 on attempt 54 out of 1000. Peer r-te.algorand-mainnet.network:4160: Get “http://r-te.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lp22”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:02:53.772872+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089878 on attempt 123 out of 1000. Peer r-ge.algorand-mainnet.network:4160: Get “http://r-ge.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lp06”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:03:51.897555+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089860 on attempt 142 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:04:16.206270+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089755 on attempt 248 out of 1000. Peer r-fm.algorand-mainnet.network:4160: Get “http://r-fm.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lowr”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:05:32.479157+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089734 on attempt 270 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6low6”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:05:51.384825+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089730 on attempt 275 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6low2”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:05:56.979099+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089688 on attempt 318 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:06:28.284455+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089624 on attempt 383 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:07:26.993789+01:00”}
{“details”:{“Metrics”:{“algod_agreement_dropped”:“2”,“algod_agreement_handled”:“2670”,“algod_ledger_reward_claims_total”:“285”,“algod_ledger_transactions_total”:“0”,“algod_network_broadcast_queue_micros_total”:“489858”,“algod_network_broadcast_send_micros_total”:“420872”,“algod_network_broadcasts_total”:“17121”,“algod_network_connections_dropped_total”:“1”,“algod_network_incoming_connections”:“0”,“algod_network_incoming_peers”:“0”,“algod_network_message_received_total”:“1552858”,“algod_network_message_sent_queue_micros_total”:“7973125”,“algod_network_message_sent_total”:“50862”,“algod_network_outgoing_connections”:“4”,“algod_network_outgoing_peers”:“4”,“algod_network_peers”:“4”,“algod_network_received_bytes_total”:“707514000”,“algod_network_rx_buffer_micros_total”:“99328630”,“algod_network_rx_handle_micros_total”:“2381377”,“algod_network_sent_bytes_total”:“1729308”,“branch”:“rel/stable”,“channel”:“stable”,“commit-hash”:“07bc97b7”,“ledger_accountsinit_count”:“1”,“ledger_accountsinit_micros”:“1430611”,“ledger_blockq_getblock_count”:“17”,“ledger_blockq_getblock_micros”:“5329”,“ledger_blockq_getblockhdr_count”:“2”,“ledger_blockq_getblockhdr_micros”:“575”,“ledger_blockq_init_count”:“1”,“ledger_blockq_init_micros”:“894”,“ledger_blockq_sync_forget_count”:“183”,“ledger_blockq_sync_forget_micros”:“149306”,“ledger_blockq_sync_put_count”:“183”,“ledger_blockq_sync_put_micros”:“19867090”,“ledger_catchup_catchpoint_ensureblock1_count”:“1”,“ledger_catchup_catchpoint_ensureblock1_micros”:“1290”,“ledger_catchup_catchpoint_storeblock_count”:“378”,“ledger_catchup_catchpoint_storeblock_micros”:“73178136”,“ledger_catchup_processstagingbalances_count”:“14878”,“ledger_catchup_processstagingbalances_micros”:“5031603700”,“ledger_catchup_processstagingcontent_count”:“1”,“ledger_catchup_processstagingcontent_micros”:“5075353”,“ledger_catchup_resetstagingbalances_count”:“1”,“ledger_catchup_resetstagingbalances_micros”:“1125896”,“ledger_catchup_storebalancesround_count”:“1”,“ledger_catchup_storebalancesround_micros”:“32485”,“ledger_catchup_storefirstblock_count”:“1”,“ledger_catchup_storefirstblock_micros”:“2166224”,“ledger_catchup_verifycatchpoint_count”:“1”,“ledger_catchup_verifycatchpoint_micros”:“1549”,“ledger_initblocksdb_count”:“1”,“ledger_initblocksdb_micros”:“36950”,“ledger_vacuum_count”:“1”,“ledger_vacuum_micros”:“29805”,“ledger_verifygenhash_count”:“1”,“ledger_verifygenhash_micros”:“333”,“version”:“2.3.0”,“version-num”:“8590131200”}},“file”:“telemetry.go”,“function”:“github.com/algorand/go-algorand/logging.(*telemetryState).logTelemetry”,“instanceName”:“uR/SCmEZNxMsbYEz”,“level”:“info”,“line”:211,“msg”:"/ApplicationState/Heartbeat",“session”:“709770b4-fce5-4bd6-8b59-4f14408cde8b”,“time”:“2020-12-27T20:07:33.780947+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089574 on attempt 434 out of 1000. Peer r12.algorand-mainnet.network:80: Get “http://r12.algorand-mainnet.network:80/v1/mainnet-v1.0/block/6lorq”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:08:13.434135+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089550 on attempt 459 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:08:31.971865+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089533 on attempt 477 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6loql”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:08:49.104668+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089489 on attempt 522 out of 1000. Peer r-cl.algorand-mainnet.network:4160: Get “http://r-cl.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lopd”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:09:38.522808+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089465 on attempt 547 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:09:58.366228+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089435 on attempt 578 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lonv”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:10:24.614022+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089426 on attempt 588 out of 1000. Peer r-lu.algorand-mainnet.network:4160: Get “http://r-lu.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lonm”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:10:37.557674+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089383 on attempt 632 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lomf”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:11:24.804253+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089356 on attempt 660 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lolo”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:11:50.677242+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089263 on attempt 754 out of 1000. Peer r-ac.algorand-mainnet.network:4160: Get “http://r-ac.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6loj3”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:12:59.502245+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089241 on attempt 777 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:13:18.776786+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089238 on attempt 781 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:13:24.508169+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089187 on attempt 833 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:14:05.679168+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089118 on attempt 903 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:15:02.714142+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089061 on attempt 961 out of 1000. Peer r-lu.algorand-mainnet.network:4160: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:15:42.210385+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089058 on attempt 965 out of 1000. Peer r-os.algorand-mainnet.network:4160: Get “http://r-os.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lode”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:15:52.217841+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run”,“level”:“warning”,“line”:202,“msg”:“catchpoint catchup stage error : processStageBlocksDownload failed after multiple blocks download attempts”,“name”:"",“time”:“2020-12-27T20:16:35.335091+01:00”}
{“details”:{“Metrics”:{“algod_agreement_dropped”:“3”,“algod_agreement_handled”:“9576”,“algod_ledger_reward_claims_total”:“1035”,“algod_ledger_round”:“1035”,“algod_ledger_transactions_total”:“0”,“algod_network_broadcast_queue_micros_total”:“632675”,“algod_network_broadcast_send_micros_total”:“466699”,“algod_network_broadcasts_total”:“19005”,“algod_network_connections_dropped_total”:“1”,“algod_network_incoming_connections”:“0”,“algod_network_incoming_peers”:“0”,“algod_network_message_received_total”:“1705664”,“algod_network_message_sent_queue_micros_total”:“8857358”,“algod_network_message_sent_total”:“56514”,“algod_network_outgoing_connections”:“4”,“algod_network_outgoing_peers”:“4”,“algod_network_peers”:“4”,“algod_network_received_bytes_total”:“782400000”,“algod_network_rx_buffer_micros_total”:“110393470”,“algod_network_rx_handle_micros_total”:“2811167”,“algod_network_sent_bytes_total”:“1921476”,“algod_transaction_messages_dropped_backlog”:“384”,“algod_tx_pool_count”:“0”,“branch”:“rel/stable”,“channel”:“stable”,“commit-hash”:“07bc97b7”,“ledger_accountsinit_count”:“1”,“ledger_accountsinit_micros”:“1430611”,“ledger_blockq_getblock_count”:“34”,“ledger_blockq_getblock_micros”:“14903”,“ledger_blockq_getblockhdr_count”:“6”,“ledger_blockq_getblockhdr_micros”:“1768”,“ledger_blockq_init_count”:“1”,“ledger_blockq_init_micros”:“894”,“ledger_blockq_sync_forget_count”:“475”,“ledger_blockq_sync_forget_micros”:“651044”,“ledger_blockq_sync_put_count”:“475”,“ledger_blockq_sync_put_micros”:“51309708”,“ledger_catchup_catchpoint_ensureblock1_count”:“1”,“ledger_catchup_catchpoint_ensureblock1_micros”:“1290”,“ledger_catchup_catchpoint_storeblock_count”:“988”,“ledger_catchup_catchpoint_storeblock_micros”:“199736320”,“ledger_catchup_processstagingbalances_count”:“14878”,“ledger_catchup_processstagingbalances_micros”:“5031603700”,“ledger_catchup_processstagingcontent_count”:“1”,“ledger_catchup_processstagingcontent_micros”:“5075353”,“ledger_catchup_resetstagingbalances_count”:“2”,“ledger_catchup_resetstagingbalances_micros”:“9785483”,“ledger_catchup_storebalancesround_count”:“1”,“ledger_catchup_storebalancesround_micros”:“32485”,“ledger_catchup_storefirstblock_count”:“1”,“ledger_catchup_storefirstblock_micros”:“2166224”,“ledger_catchup_verifycatchpoint_count”:“1”,“ledger_catchup_verifycatchpoint_micros”:“1549”,“ledger_commitround_count”:“12”,“ledger_commitround_micros”:“5159100”,“ledger_initblocksdb_count”:“1”,“ledger_initblocksdb_micros”:“36950”,“ledger_vacuum_count”:“1”,“ledger_vacuum_micros”:“29805”,“ledger_verifygenhash_count”:“1”,“ledger_verifygenhash_micros”:“333”,“version”:“2.3.0”,“version-num”:“8590131200”}},“file”:“telemetry.go”,“function”:“github.com/algorand/go-algorand/logging.(*telemetryState).logTelemetry”,“instanceName”:“uR/SCmEZNxMsbYEz”,“level”:“info”,“line”:211,“msg”:"/ApplicationState/Heartbeat",“session”:“709770b4-fce5-4bd6-8b59-4f14408cde8b”,“time”:“2020-12-27T20:17:33.781070+01:00”}

tsachi · December 28, 2020, 1:11am

Looking arbitrarily on the log, I see

{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageBlocksDownload”,“level”:“info”,“line”:483,“msg”:“Failed to download block 11089755 on attempt 248 out of 1000. Peer r-fm.algorand-mainnet.network:4160: Get “http://r-fm.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lowr”: context deadline exceeded”,“name”:"",“time”:“2020-12-27T20:05:32.479157+01:00”}

which tells me that the node was trying to retrieve the block using the URL http://r-fm.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lowr, but have timed out after waiting for CatchupHTTPBlockFetchTimeoutSec seconds. You could, naturally, increase that timeout in the config.json file. ( the default is 4, which stands for 4 second ).

However, I don’t really understand why it would take so long. On my laptop it took about half a second.

> time curl -v http://r-fm.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lowr -o 6lowr.block
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 52.194.243.26...
* TCP_NODELAY set
* Connected to r-fm.algorand-mainnet.network (52.194.243.26) port 4160 (#0)
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0> GET /v1/mainnet-v1.0/block/6lowr HTTP/1.1
> Host: r-fm.algorand-mainnet.network:4160
> User-Agent: curl/7.64.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Cache-Control: public, max-age=31536000, immutable
< Content-Length: 33564
< Content-Type: application/x-algorand-block-v1
< Date: Mon, 28 Dec 2020 01:10:40 GMT
<
{ [3918 bytes data]
100 33564  100 33564    0     0  58270      0 --:--:-- --:--:-- --:--:-- 58169
* Connection #0 to host r-fm.algorand-mainnet.network left intact
* Closing connection 0
curl -v http://r-fm.algorand-mainnet.network:4160/v1/mainnet-v1.0/block/6lowr  0.01s user 0.01s system 2% cpu 0.584 total

Do you have any reason to believe that your device doesn’t have a stable broadband connection ?
( i.e. 10Mbps+ )

salvatorecorvaglia · December 28, 2020, 8:50am

My connection isn’t the best, that’s for sure. The last thing I could do is try with the connection of the university campus by connecting it to the ethernet (the connection of my university is excellent). So as soon as I get back to work at the University I will do this test and we’ll see if it’s all a question of connection.

salvatorecorvaglia · January 11, 2021, 11:23am

Returning to this discourse. I’m trying to do the “fast catchup” on the
RASPBERRY PI 4 Model B 4GB, but now with my university connection which is very good (ethernet cable).
Unfortunately “catchpoint accounts processed” goes really slow. So I really don’t know what the reason is. It may be that it depends on the number of CPUs or GPUs or OS of Raspberry 32-bit whatever, I really don’t know. Let’s at least see if the process ends

Topic		Replies	Views
Sync Algorand Node Network using Fast Catchup (default install) on Raspberry Pi 4 Computer Model B 4GB RAM on 32 GB MicroSD AlgoSDK mainnet , noderunner , fast-catchup	8	1001	June 14, 2021
Fast Catchup not working for our node on MainNet	53	4652	October 7, 2020
Fast Catchup not working on testnet TestNet	8	1169	August 26, 2020
Error on doing fast catchup TestNet	7	616	January 9, 2021
Can't complete catchup operation on mainnet -- timeout after 45 minutes (~4m accounts) General	13	1237	November 10, 2020

Fast catchup does not work on Raspberry Pi 4B

Related Topics