Fast catchup does not work on Raspberry Pi 4B - General - Algorand

25 / 25

May 2021

post by salvatorecorvaglia on Dec 24, 2020

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.

1.4k views 3 links

15](https://forum.algorand.co/u/salvatorecorvaglia "salvatorecorvaglia")

8](https://forum.algorand.co/u/tsachi "tsachi")

read 9 min

post by tsachi on Dec 24, 2020

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!

post by salvatorecorvaglia on Dec 24, 2020

What exactly does CatchupBlockDownloadRetryAttempts do?

post by tsachi on Dec 24, 2020

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.

post by salvatorecorvaglia on Dec 24, 2020

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

post by aojjazz on Dec 25, 2020

aojjazz

tsachi](https://forum.algorand.co/t/fast-catchup-does-not-work-on-raspberry-pi-4b/2330/26 "Load parent post")

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.

post by tsachi on Dec 25, 2020

@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.

post by salvatorecorvaglia on Dec 26, 2020

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.

post by salvatorecorvaglia on Dec 26, 2020

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=

post by salvatorecorvaglia on Dec 26, 2020

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=

post by salvatorecorvaglia on Dec 26, 2020

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

Round for next consensus protocol: 6177

Next consensus protocol supported: true

Last Catchpoint:

Genesis ID: mainnet-v1.0

Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

post by salvatorecorvaglia on Dec 26, 2020

Nothing to do unfortunately …

post by tsachi on Dec 26, 2020

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.

post by salvatorecorvaglia on Dec 27, 2020

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

post by tsachi on Dec 27, 2020

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.

post by tsachi on Dec 27, 2020

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.

post by salvatorecorvaglia on Dec 27, 2020

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”}

post by tsachi on Dec 27, 2020

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+ )

post by salvatorecorvaglia on Dec 28, 2020

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.

14 days later

post by salvatorecorvaglia on Jan 11, 2021

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

post by salvatorecorvaglia on Jan 11, 2021

Nothing, “catchpoint accounts processed” fails…

post by tsachi on Jan 11, 2021

Could you post here the log entries from the node.log file that are related to the fast catchup ?

i.e.


cat node.log | grep atchpoint

These might provide a hint for the underlying issue.

post by salvatorecorvaglia on Jan 11, 2021

I am now testing two nodes on two different machines, a PC running Ubuntu 64 bit, i.e this:

and the Raspberry PI 4 B always with Ubuntu 64 bit. Compared to the raspberry, the PC goes much faster.

So I can confirm that it depends on the processor and the number. Otherwise this would not be explained

post by salvatorecorvaglia on Jan 16, 2021