Fast Catchup not working for our node on MainNet

Our node was seeing memory issues. Migrated to a new machine installed 2.1.3 and tried Fast Catchup. Node is non-archival. The process consumes large amounts of memory (over 7GB on our machine) and fails after downloading the Cachpoint blocks.

Here is a snapshot of the catchup in flight:

$ algod -v
8590000131
2.1.3.stable [rel/stable] (commit #30c8dd68)
$ cat /var/lib/algorand/config.json
{
        "Version": 11,
        "EnableMetricReporting": true
}
$ goal node catchup 8550000#MYSKTQ7KYLYLPOU275ZUBPMOBAUMI7OYZY2AZSSAJGIQQIWO4OAQ -d /var/lib/algorand
$ goal node status -w 1000
Last committed block: 11130
Sync Time: 2883.3s
Catchpoint: 8550000#MYSKTQ7KYLYLPOU275ZUBPMOBAUMI7OYZY2AZSSAJGIQQIWO4OAQ
Catchpoint total accounts: 4174171
Catchpoint accounts processed: 4174171
Catchpoint total blocks: 1000
Catchpoint downloaded blocks: 653
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

We don’t see any obvious error in the logs when searching through and the node seems to gracefully fall back into the regular sync (very obvious due to the different CPU and memory profile). We’ve already re-imaged the machine and started the process 4 different times, increasing resources each time.

Any insights or assistance is appreciated.

-jimmy

You can rest assured that the log file does contain information for “why the fast catchup aborted”. Try to grep for the word “catchpoint”. If it’s due to too many failures while downloading blocks, you can increase the max number of failed attempts in the config.json file.

We were filtering on “error” or “fatal” levels These should be the messages from the last 3 attempts.

{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageLedgerDownload","level":"warning","line":293,"msg":"unable to download ledger : http: unexpected EOF reading trailer","name":"","time":"2020-08-19T20:35:59.053312Z"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run","level":"warning","line":201,"msg":"catchpoint catchup stage error : processStageBlocksDownload failed after multiple blocks download attempts","name":"","time":"2020-08-19T21:22:01.959916Z"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageLedgerDownload","level":"warning","line":293,"msg":"unable to download ledger : No ledger available for given round","name":"","time":"2020-08-19T21:25:41.817713Z"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run","level":"warning","line":201,"msg":"catchpoint catchup stage error : processStageBlocksDownload failed after multiple blocks download attempts","name":"","time":"2020-08-19T22:18:17.268793Z"}

If we were to try again, what settings would be advisable beyond the defaults? The default number of retries seems high already. And lastly, do we remove the data directory and start clean or just change the config and restart the node with the updated configuration before we trigger the catchup?

Thanks for the advice,
-j

Thank you @tsachi, that seems to have got through and now working on the normal sync from the catch point to the current block. For future reference, Fast Catchup took around 33 minutes and algod memory utilization scratched 7GB for 3/4 of the time.

-j

I decided to reinstall a fresh node so I was trying to sync it using the Fast Catchup, during the processes something gone wrong and the sync stopped:

$ goal node status
Last committed block: 140
Sync Time: 1039.3s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1113600
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
Cannot contact Algorand node: Get http://127.0.0.1:8080/v2/status: dial tcp 127.0.0.1:8080: connect: connection refused.

I manually restart the node:

$ goal node start
Algorand node successfully started!

then I resumed the process but it started again from the beginning (loosing the accounts processed) and failed again at the same processed accounts number:

$ goal node status
Last committed block: 140
Sync Time: 1197.3s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1113600
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
Cannot contact Algorand node: Get http://127.0.0.1:8080/v2/status: dial tcp 127.0.0.1:8080: connect: connection refused.

Any idea on what is causing this failure?

Hey @cusma. That is exactly what we were seeing. In our case, algod was continuing to request memory until at some point it failed and the process(es) crashed making the REST endpoint unavailable. Definitely follow @tsachi’s advice and look into your logs to track down the issue.

-j

Followed what @tsachi suggested, setting CatchupBlockDownloadRetryAttempts to 4000 in the config.json the process passed the previous 1113600 processed accounts and got stuck at 1244672:

$ goal node status -w 1000
Last committed block: 415
Sync Time: 1266.7s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1244672
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
Cannot contact Algorand node: Get http://127.0.0.1:8080/v2/status: dial tcp 127.0.0.1:8080: connect: connection refused.

I’m trying again increasing CatchupBlockDownloadRetryAttempts up to 8000 and see if it succeed.

Didn’t work, process failed again at 1113600 processed accounts even setting CatchupBlockDownloadRetryAttempts to 8000:

$ goal node status -w 1000
Last committed block: 488
Sync Time: 1066.3s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1113600
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
Cannot contact Algorand node: Get http://127.0.0.1:8080/v2/status: dial tcp 127.0.0.1:8080: connect: connection refused.

Looking into algod-err.log seems that I have a memory issue:

runtime: out of memory: cannot allocate 98304-byte block (2838134784 in use)
fatal error: out of memory

runtime stack:
runtime.throw(0xb5d048ca, 0xd)
	/usr/local/go/src/runtime/panic.go:617 +0x60
runtime.largeAlloc(0x16b68, 0xb5100101, 0xba8)
	/usr/local/go/src/runtime/malloc.go:1057 +0x14c
runtime.mallocgc.func1()
	/usr/local/go/src/runtime/malloc.go:950 +0x38
runtime.systemstack(0xb6f0c9f0)
	/usr/local/go/src/runtime/asm_arm.s:354 +0x90
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1153

Two issues that were mentioned here :

1. Fast catchup reset after node restart:
   That’s true. Once started, it would retry up to the configured number of attempts before giving up. On each attemp, it start from the last “step”, so if it was downloading the accounts, it would reset these and try again.
2. Memory consumption during the catchup process is higher than desirable. I’ll try to reproduce it locally. It was never an issue for me, but the number of accounts are growing rapidally, so the tests which i conducted might have become obsolete.

Could be possible to partialize the catchup process into minor steps providing a set of catchup points with individual requirements lower than the latest one?

My node is also failing to succeed with the Fast Catchup on mainnet.

After 6 hours it didn’t seem to be getting any further. The syptoms visible in the status were that the sync time continued to climb, the “Catchpoint accounts processed” climbed for a while and then started back at the beginning to climb a bit higher the next time. After doing this several times it seemed unable to get passed 1113600 processed catchpoint accounts.

$ goal node status -d /var/lib/algorand -w 1000
Last committed block: 8570
Sync Time: 2382.1s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1048064
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
^C

$ goal node status -d /var/lib/algorand -w 1000
Last committed block: 8570
Sync Time: 22162.2s
Catchpoint: 8560000#JXTHWW5BRW7MDSPVHITBLYORCNUDTHIXZRIYOZYKHDHGU2WUXLZQ
Catchpoint total accounts: 4313466
Catchpoint accounts processed: 1113600
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=
^C

I gave up and aborted the catchup and stopped algod.

A quick look in node.log showed repeated messages along the lines of:

{“callee”:“github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl) .processStagingBalances.func1”,“caller”:“/root/go/s
rc/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294”,“file”:“dbutil.go”,“function”:“github.com/algorand/go-algorand/util
/db.(*Accessor).atomic”,“level”:“warning”,“line”:355,“msg”:“dbatomic: tx surpassed expected deadline by 1.131643661s”,“name”:“”,“read
only”:false,“time”:“2020-08-20T11:12:38.108569+01:00”}
{“file”:“catchpointService.go”,“function”:“github.com/algorand/go-algorand/catch
up.(*CatchpointCatchupService).processStageLedgerDownload”,“level”:“warning”,“li
ne”:293,“msg”:“unable to download ledger : unexpected EOF”,“name”:“”,“time”:“202
0-08-20T12:22:31.222640+01:00”}

I see @cusma has the same symptoms.

From what @jimmy has posted it sounds as though there may be little hope for my ancient node untl I give it a memory upgrade beyond 4GB.

I’ll try increasing the CatchupBlockDownloadRetryAttempts - perhaps to 8000 and let you know how it goes.

I’ve not yet found any documentation for recomended node specifications - can you point me to it?

You’re correct about that setting.
If you add:
“CatchupBlockDownloadRetryAttempts”: 5000
to your config.json (possibly higher - the default is 1000) then fast catchup should finish. It will retry against other nodes and succeed for the failed blocks.

The problem is that not all mainnet relay nodes have been upgraded, so when it tries to fetch blocks from some of the relay nodes it will fail. There’s a default limit to block download failures and when it hits that limit it will abort the whole thing.

I will certainly try to increase the retry attempts, but I’m also going to need to recofigure my old test laptop which currently has 4GB RAM and 3GB swap. It was thrashing to the point of timeout and if it really needs 7GB of virtual memory then it will still not work until there is a way of limiting the amount of memory algod can consume.

I would need to perform some more tests but it seems that the amount of memory required by algod is proportional to the number of accounts (presumably loaded into a memory resident DB). Memory utilsation appears to be significantly inflated by the fast catchup process.

Hi @tsachi, I’ve recently changed my node’s hardware with a Raspberry Pi 4 8GB RAM, this time I mounted a Raspberry Pi OS 64bit (so each process is no more limited to 3GB RAM).

I’m still not able to fast chatchup the MainNet.

With this new setup, memory overload errors seem to be disappeared but during the Fast Catchup the Processed Accounts number restart from the beginning all of a sudden.

I’ve already set CatchupBlockDownloadRetryAttempts to 8000 in the config.json as you suggested.

Let me know if my node.log could be useful and where I can send it.

@cusma, I did not know a 8GB Raspberry Pi exists… that makes me curious : does the arm6v code ( which we compiled for all the Raspberry Pi ) supports more than 4Gb ? I thought that it’s limited to 4GB.

Regarding the memory consumption issue, I can confirm that it does seems to be correlated with the large account number on mainnet. The recent betanet release (2.1.4) did not provided a fix for this issue, unfortunately ([topic not in archive] )

To get access to the whole address space @cusma would have to build go-algorand targeting armv8, not just mount a 64-bit OS. The armv6 and armv7 ISAs are 32-bit only.

@tsachi Raspberry Pi 4 8GB has been released in May by Raspberry Pi Foundation, the PCB is slightly different from old versions due to thermal management improvements.

@jimmy as always I just followed this node installation guide for Linux distros on Raspberry Pi OS 64-bit (still in beta, old Raspbian was recently deprecated by Raspberry Pi Foundation switching to Raspberry Pi OS). Does this procedure automatically install arm6v?

So, help me undestand if is there any action I can take to build the correct version of go-alogrand in order to leverage all 8GB RAM without limitations.

I haven’t tested that, but there is an official release for arm64, which might work for the above OS.

@tsachi I think is exactly what I get doing:

wget https://raw.githubusercontent.com/algorand/go-algorand-doc/master/downloads/installers/update.sh

and then runnning the installer from node directory, isn’t it?

Doubt: the fact that the Processed Accounts number resets during the catchup without having a memory fatal error (which I had with the previous 4GB 32bit node setup) is still related to RAM issues?

I’m happy to hear that this is the method you’re using for the update. That would allow the update script to choose the optimal binary for your platform. I don’t know if the recent Raspberry PI OS was validated againt the update.sh, but it definitally should.

The fact that you’re no longer seeing memory issues might be a good indication that it does pick the correct executable. When it does fail, what is the fail reason ? The node.log should be able to tell you that. Try to grep for catchpoint.

@tsachi here is the last part of what I’ve found into node.archive.log, but I need help to interpret it:

{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 24.158404838s","name":"","readonly":false,"time":"2020-08-28T18:06:46.358071+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 25.894136324s","name":"","readonly":false,"time":"2020-08-28T18:07:26.173308+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 36.313175204s","name":"","readonly":false,"time":"2020-08-28T18:08:16.121020+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 32.541202632s","name":"","readonly":false,"time":"2020-08-28T18:09:02.541449+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 37.378767403s","name":"","readonly":false,"time":"2020-08-28T18:09:53.868994+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 46.48052051s","name":"","readonly":false,"time":"2020-08-28T18:10:56.126022+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 50.479435774s","name":"","readonly":false,"time":"2020-08-28T18:12:03.081049+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 737.804647ms","name":"","readonly":false,"time":"2020-08-28T18:12:10.024907+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 39.183075121s","name":"","readonly":false,"time":"2020-08-28T18:12:58.488246+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 43.18968605s","name":"","readonly":false,"time":"2020-08-28T18:13:56.154227+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 4.825808255s","name":"","readonly":false,"time":"2020-08-28T18:14:07.250155+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 44.390137192s","name":"","readonly":false,"time":"2020-08-28T18:15:01.509935+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 43.540042833s","name":"","readonly":false,"time":"2020-08-28T18:15:59.810084+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 55.050510895s","name":"","readonly":false,"time":"2020-08-28T18:17:14.973615+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 4.088145443s","name":"","readonly":false,"time":"2020-08-28T18:17:36.324394+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 55.802440381s","name":"","readonly":false,"time":"2020-08-28T18:18:40.209376+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m0.129440775s","name":"","readonly":false,"time":"2020-08-28T18:20:00.588336+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 195.498571ms","name":"","readonly":false,"time":"2020-08-28T18:20:06.129146+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 2.828967997s","name":"","readonly":false,"time":"2020-08-28T18:20:17.544347+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 45.798204967s","name":"","readonly":false,"time":"2020-08-28T18:21:18.176055+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m6.324626322s","name":"","readonly":false,"time":"2020-08-28T18:22:47.748188+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 58.462052979s","name":"","readonly":false,"time":"2020-08-28T18:24:03.393665+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 57.945454854s","name":"","readonly":false,"time":"2020-08-28T18:25:16.761280+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m2.030750011s","name":"","readonly":false,"time":"2020-08-28T18:26:34.305707+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 51.323908316s","name":"","readonly":false,"time":"2020-08-28T18:27:41.718411+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m7.364659879s","name":"","readonly":false,"time":"2020-08-28T18:29:06.456129+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 55.107420792s","name":"","readonly":false,"time":"2020-08-28T18:30:17.960202+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m1.831749736s","name":"","readonly":false,"time":"2020-08-28T18:31:35.993411+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 52.790472832s","name":"","readonly":false,"time":"2020-08-28T18:32:45.943488+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 41.468215ms","name":"","readonly":false,"time":"2020-08-28T18:32:48.285959+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m1.348392513s","name":"","readonly":false,"time":"2020-08-28T18:34:05.164043+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m3.733541615s","name":"","readonly":false,"time":"2020-08-28T18:35:26.309374+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m3.73249174s","name":"","readonly":false,"time":"2020-08-28T18:36:47.864061+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m0.203957939s","name":"","readonly":false,"time":"2020-08-28T18:38:05.270018+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m5.350465578s","name":"","readonly":false,"time":"2020-08-28T18:39:28.035255+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 76.896063ms","name":"","readonly":false,"time":"2020-08-28T18:39:33.606887+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m4.980213627s","name":"","readonly":false,"time":"2020-08-28T18:40:49.843544+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m8.832519488s","name":"","readonly":false,"time":"2020-08-28T18:42:15.452258+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 78.769431ms","name":"","readonly":false,"time":"2020-08-28T18:42:22.196299+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m6.459185189s","name":"","readonly":false,"time":"2020-08-28T18:43:39.777069+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m13.385987757s","name":"","readonly":false,"time":"2020-08-28T18:45:09.561494+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 2m8.306212157s","name":"","readonly":false,"time":"2020-08-28T18:47:35.677501+02:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageLedgerDownload","level":"warning","line":293,"msg":"unable to download ledger : context deadline exceeded","name":"","time":"2020-08-28T18:47:35.717078+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).ResetStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:177","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1m50.095259397s","name":"","readonly":false,"time":"2020-08-28T18:49:26.820994+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 1.183327372s","name":"","readonly":false,"time":"2020-08-28T18:49:38.152356+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 3.540351281s","name":"","readonly":false,"time":"2020-08-28T18:49:51.393872+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 5.493225476s","name":"","readonly":false,"time":"2020-08-28T18:50:07.143107+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 7.743167959s","name":"","readonly":false,"time":"2020-08-28T18:50:25.649590+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 9.940710385s","name":"","readonly":false,"time":"2020-08-28T18:50:46.744273+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 14.350936266s","name":"","readonly":false,"time":"2020-08-28T18:51:12.518498+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 17.284236443s","name":"","readonly":false,"time":"2020-08-28T18:51:41.286341+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 22.317491183s","name":"","readonly":false,"time":"2020-08-28T18:52:15.490093+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 22.399006263s","name":"","readonly":false,"time":"2020-08-28T18:52:50.167527+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 36.401643ms","name":"","readonly":false,"time":"2020-08-28T18:52:58.084855+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 21.223299657s","name":"","readonly":false,"time":"2020-08-28T18:53:24.194351+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 28.283678467s","name":"","readonly":false,"time":"2020-08-28T18:54:05.231913+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 33.25351547s","name":"","readonly":false,"time":"2020-08-28T18:54:51.433467+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 30.176835061s","name":"","readonly":false,"time":"2020-08-28T18:55:34.874454+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).processStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:294","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 36.497417191s","name":"","readonly":false,"time":"2020-08-28T18:56:26.479127+02:00"}
{"callee":"github.com/algorand/go-algorand/ledger.(*CatchpointCatchupAccessorImpl).ResetStagingBalances.func1","caller":"/home/ubuntu/go/src/github.com/algorand/go-algorand/ledger/catchupaccessor.go:177","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).atomic","level":"warning","line":355,"msg":"dbatomic: tx surpassed expected deadline by 16.487308757s","name":"","readonly":false,"time":"2020-08-28T18:56:43.967612+02:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run","level":"warning","line":201,"msg":"catchpoint catchup stage error : context canceled","name":"","time":"2020-08-28T18:56:43.967876+02:00"}
{"file":"node.go","function":"github.com/algorand/go-algorand/node.(*AlgorandFullNode).SetCatchpointCatchupMode.func1","level":"info","line":935,"msg":"Indexer is not available - indexer is not active","name":"","time":"2020-08-28T18:56:44.044601+02:00"}

Hi,

The only entry here that could be adjusted is ‘unable to download ledger : context deadline exceeded’. It means that the accumulated time it was processing this catchpoint exceeded the time limits, and the node decided to terminate the processing. I think that there is a config option to extend that, but can’t recall which one was it. I’ll try to look into that next week.

Just for sake of completeness I add few more errors referred to the last fast catchup trial, maybe could be useful to identify what is going on:

{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageLedgerDownload","level":"warning","line":293,"msg":"unable to download ledger : context deadline exceeded","name":"","time":"2020-08-29T21:22:28.409267+02:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).processStageLedgerDownload","level":"warning","line":293,"msg":"unable to download ledger : getPeerLedger : http ledger fetcher response has an invalid content type : text/html; charset=UTF-8","name":"","time":"2020-08-29T21:24:40.184665+02:00"}
{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run","level":"warning","line":201,"msg":"catchpoint catchup stage error : context canceled","name":"","time":"2020-08-29T21:27:39.876930+02:00"}

The getPeerLedger : http ledger fetcher response has an invalid content type : text/html; charset=UTF-8 is clearly something that need to be worked on; I suspect ( but don’t have enough information to be sure of ) that there is a relay out there that wasn’t upgraded. While this is not an issue for the protocol and/or the operation of the catchpoint catchup, it should get addressed.

Is this problem solved? I also encountered this problem here, Catchpoint accounts processed has been processing in a loop, I hope to get help

Just to verify, since this is your first appearance here - you’ve ran into this issue while trying to run this on a Raspberry PI 4 with 8GB memory, correct ?

( i.e. I’m able to run the fast catchup from mainnet on my MacBook with no issues. I’d like to verify the above issue is limited to Raspberry PI )

No, mine is centos 64 8h 16g. I have no problem catching up quickly on the test network, but it is always unsuccessful on the mainnet. The number of Catchpoint accounts processed is always in the loop. I have modified the number of retries and the timeout period, but no Works, and I can’t get any error logs

Exactly the same experience.

The Fast catchup was successful on the TestNet, both on a Raspberry Pi 4 with 4GB and with 8GB.

The Fast catchup failed on MainNet instead, it keeps looping forever.

I will see if I could repeat the testing for that tomorrow on centos as well. You haven’t specified which version of centos you’re running, so I’ll be using version 8.

also, just to confirm @shixiaofeia - your centos machine is connected to the internet using a broadband connection with a bandwidth of 10mbps or more, right ? ( I’m just trying to make sure it’s not a spotty cellular connection or a dial up… )

@shixiaofeia - that’s only telling me that the centos machine is connected via it’s ethernet port, and that the ethernet adapter speed is super-awesome.

Could you also confirm that the router that connect this computer to the internet ( i.e. cable/dsl/fiber/other ) has ~10mbps ? ( i.e. mega bit per second ).

I’m not sure, how should I confirm?

I’m not affiliated in any way with the following site, but I used to find it useful:

As long as you have at least 10mbps, it shouldn’t be an issue.

Alternatively, you can try to use the command line to get these metrics :

According to the above, you appear to have an excellent internet connection.
I will double check the reported behavior on my end using a centos machine.

Thank you, I noticed that many people encountered the same problem as me, but I am curious that testnet and mainnet shouldn’t be the same?

The main difference from the perspective of the fast catchup is the number of accounts.
Testnet has far fewer accounts.

Following up on @shixiaofeia experiment -
I created a centos 7.7.1 docker container, grabbed version 2.1.4 using the rpm installer, and attempted to catchup to 8980000#KRIDEMKJI3SVXAMV5RKUBUEFQWZLYFMPJKLSA7LKLG4EOWZQDYXQ.

image1126×360 28.3 KB

following this experiment, I have two more questions:

1. What type of storage do you use on the centos machine ? is it a nvme, ssd, magnetic, or network storage disk ?
2. Could you provide some metrics regarding the duration after which it “restarted” ?

I know that in the past, we’ve seen issues with people running their nodes on network storage disks ( such as EBS volumes ).

I should be using a SATA hard drive. There are no corresponding indicators. I have tried directly using the default configuration or modifying the number of synchronizations and the timeout period, but they all failed. I want to know that the total blocks and total blocks will appear after the accounts processed. Are these two indicators down blocks? I have always been accounts processed and restarted from 0 after the processing is completed. I have never seen blocks related parameters. One thing may be related to this. I use the Installing with Other Linux Distros method Installed, i.e. wget https://raw.githubusercontent.com/algorand/go-algorand-doc/master/downloads/installers/update.sh, will it be related to this?

Because I need to specify the storage path, if rpm is used, even if ALGORAND_DATA is set, it is useless

No, it should not matter whether you used the wget method or the rpm. I have explicitly mentioned the above just to make sure someone else would be able to repeat that.

Regarding the “Catchpoint total blocks” and “Catchpoint downloaded blocks” that you seems to be surprised to see: these would appear once the following three are complete:

1. all the accounts were downloaded and processed
2. the first block ( the one that matches round 9890000 in my example ) was downloaded
3. the hash of the catchpoint matches the accounts and the first block, combined.

You mentioned that you’re using a SATA hard drive. Is that an SSD drive or magnetic drive ?
The reason I’m asking is that large portion of the time is being spent on writing these 5.6M accounts to disk. Using a slower disk could extend that even further.

This is why I was asking also about the duration. I don’t know if the timeout that you’re seeing is client side or server side. Having the elapsed duration could help me determine that.

SATA is a mechanical hard disk, which is slower than SSD, but I don’t think it’s a hard disk problem, because I have waited long enough (two days), all accounts are processed repeatedly, and there is no err log, I will post Part of node.log

image1889×473 60.6 KB

I’ll try to get a system with a mechanical hard disk to repeat the experiment. I don’t know if this is the issue or not.

I suggest you also use wget to install it, I’m not sure if it’s the installation method

I’m almost sure it is the problem of the installation method. I installed with rpm and then used Quick Catch, all indicators are correct

The quick catch-up of the rpm installation method has been successful. The quick catch-up of the wget method should indeed have some problems. I hope that its full node synchronization is okay. I have synchronized the full node for 4 days. If there is a problem, the mentality will collapse.

If this can help: also in my case I used wget method for the installation (and I had fast catch-up issues). I didn’t try directly the ARM installation yet to check if fast catch-up works in this way.

There is no problem with the rpm quick installation method. At the same time, I completed the full node synchronization of wget. It took a week, the synchronization speed of the indexer was slow, and it took more than a week

@cusma and @shixiaofeia - the recent release (2.1.5) includes few changes that would improve the performance of the fast catchup, both in term of memory consumption as well as the time it takes to catch up.

I have documented the issue here: https://github.com/algorand/go-algorand/issues/1558

@shixiaofeia and others, can you confirm this is the error message that appears in the logs after the “downloaded blocks” reaches 1000?

{"file":"catchpointService.go","function":"github.com/algorand/go-algorand/catchup.(*CatchpointCatchupService).run","level":"warning","line":201,"msg":"catchpoint catchup stage error : processStageBlocksDownload failed after multiple blocks download attempts","name":"","time":"2020-09-26T12:41:26.174291+02:00"}

@Thireus, thanks for your detailed issue you’ve created. This ticket is very well written, and I really appreciate that.

The issue, I believe, is that your client is receiving more than 1000 errors during the download of the blocks. This is not expected. There should be no failures.

The retry mechanism was designed to allow certain number of relays to be unresponsive while letting the fast catchup work regardless. It seems that in your case, that retry threshold doesn’t align with what is “visible” from your endpoint. ( note that I’m not implying that you and/or your setup is wrong/incorrect ).

While the source of the issue still need to be addressed ( i.e. verifying that all the relays are serving the blocks correctly, without generating any errors ), my suggestion to you would be to increase the retry count by adjusting the corresponding entry in the config.json file. That should allow you to complete the catchup process.

Please let us know if it resolved the issue for you.
( note that I’m answering here since I’d like to have that information available for everyone )

Hi @tsachi,

I appreciate the quick and detailed answer. It worked after I bumped the default “CatchupBlockDownloadRetryAttempts” from 1000 to 100000!

Last few seconds of fast catchup:

$ goal node status -d /var/lib/algorand -w 300
Last committed block: 4147581
Sync Time: 1386.0s
Catchpoint: 9310000#KZLT572KA72JS5GJR4A6FZQLOI6O72IHJQ6V2I5ZS2VHO7BUJYVQ
Catchpoint total accounts: 5896700
Catchpoint accounts processed: 5896700
Catchpoint total blocks: 1000
Catchpoint downloaded blocks: 917
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

Fast catchup completed:

$ goal node status -d /var/lib/algorand -w 300
Last committed block: 9310070
Time since last block: 0.5s
Sync Time: 4.3s
Last consensus protocol: https://github.com/algorandfoundation/specs/tree/3a83c4c743f8b17adfd73944b4319c25722a6782
Next consensus protocol: https://github.com/algorandfoundation/specs/tree/3a83c4c743f8b17adfd73944b4319c25722a6782
Round for next consensus protocol: 9310071
Next consensus protocol supported: true
Last Catchpoint: 
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

I was also able to identify which nodes often return error 400:

r-rh.algorand-mainnet.network:4160 --> failure rate is ~87%
r-ti.algorand-mainnet.network:4160 --> failure rate is ~82%

Evidence:

cat /var/lib/algorand/node.log | grep -E 'algorand-mainnet.network:4160|http block fetcher response status code' | grep -B1 'http block fetcher response status code : 400' > /tmp/algofail.txt

cat /tmp/algofail.txt | grep -o '[a-z-]*.algorand-mainnet.network:4160' | sort | uniq -c
      1 r-ac.algorand-mainnet.network:4160
      1 r-ba.algorand-mainnet.network:4160
      1 r-bk.algorand-mainnet.network:4160
      1 r-cr.algorand-mainnet.network:4160
      1 r-eu.algorand-mainnet.network:4160
      1 r-gd.algorand-mainnet.network:4160
      1 r-hf.algorand-mainnet.network:4160
     26 r-rh.algorand-mainnet.network:4160
     18 r-ti.algorand-mainnet.network:4160
      1 r-zr.algorand-mainnet.network:4160

cat /var/lib/algorand/node.log | grep -E 'r-ti.algorand-mainnet.network:4160|r-rh.algorand-mainnet.network:4160' | grep 'networkFetcher.FetchBlock: asking client' | grep -o '[a-z-]*.algorand-mainnet.network:4160' | sort | uniq -c
     30 r-rh.algorand-mainnet.network:4160
     22 r-ti.algorand-mainnet.network:4160

Is there any chance whoever owns those two instances or load balancers can have a look at them?

Additional errors (note that there are other nodes that give similar messages):

{"file":"wsNetwork.go","function":"github.com/algorand/go-algorand/network.(*WebsocketNetwork).tryConnect","level":"warning","line":1842,"msg":"ws connect(ws://r-ti.algorand-mainnet.network:4160/v1/mainnet-v1.0/gossip) fail - bad handshake, precondition failed : 'mismatching genesis ID'","name":"","time":"2020-09-26T23:28:57.224613+02:00"}
{"file":"wsNetwork.go","function":"github.com/algorand/go-algorand/network.(*WebsocketNetwork).tryConnect","level":"warning","line":1842,"msg":"ws connect(ws://r-ti.algorand-mainnet.network:4160/v1/mainnet-v1.0/gossip) fail - bad handshake, precondition failed : 'mismatching genesis ID'","name":"","time":"2020-09-27T00:23:57.219086+02:00"}

Thank you.

We adjusted relay records to remove some that were showing errors at the end of the month, so I would be interested to hear if this is still an issue for people.