Can't get my participation node to sync with the blockchain

I recently installed a participation node on Raspbian Buster, but I’m unable to sync my node with the blockchain. When I run:

./goal node status -d data

I receive the output:

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

I’m not sure why it hasn’t started syncing blocks; I’m assuming there is some sort of networking error. Does anyone know what the issue might be?

It seems like my node is syncing now, although it is moving very slowly. It’s been about an hour that I’ve been trying to sync this node and I seem to have only synced two blocks:

Last committed block: 2
Time since last block: 736.2s
Sync Time: 298.0s
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: 3
Next consensus protocol supported: true
Last Catchpoint: 
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

Is it normal to be syncing at this speed? Wouldn’t the growth of the blockchain far exceed my ability to synchronize with it if this was my speed?

No, this is not normal.

Can you show you data/node.log file?
How fast is your Internet?
Do you have a firewall?
What OS are you using?
How did you install the Algorand software?
Can you check RAM use? CPU use? Space on the disk? Are you using SSD or hard drive?
What version of algod are you using (goal version -v)?

It seems like my node has caught up substantially but I’m not sure why. One minute the last committed block was 61 and the next minute it jumped to ~20,000. Now it seems to be up to ~82,477 committed blocks; definitely isn’t happening at a consistent rate.

Anyway, here’s the output of “cat node.log | tail”:

{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client relay-mumbai-mainnet-algorand.algorand-mainnet.network:4160 for block 82478","time":"2021-05-10T19:19:30.367270+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-bk.algorand-mainnet.network:4160 for block 82479","time":"2021-05-10T19:19:30.368913+01:00"}
{"file":"txSyncer.go","function":"github.com/algorand/go-algorand/rpcs.(*TxSyncer).syncFromClient","level":"info","line":113,"msg":"TxSyncer.Sync: asking client r-br.algorand-mainnet.network:4160 for missing transactions","time":"2021-05-10T19:19:34.032400+01:00"}
{"file":"httpTxSync.go","function":"github.com/algorand/go-algorand/rpcs.(*HTTPTxSync).Sync","level":"info","line":119,"msg":"http sync from http://r-lr.algorand-mainnet.network:4160/v1/mainnet-v1.0/txsync","time":"2021-05-10T19:19:34.032951+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-pd.algorand-mainnet.network:4160 for block 82478","time":"2021-05-10T19:19:34.368397+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client relay-singaporea-mainnet-algorand.algorand-mainnet.network:4160 for block 82479","time":"2021-05-10T19:19:34.369908+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-fe.algorand-mainnet.network:4160 for block 82478","time":"2021-05-10T19:19:38.369441+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-pu.algorand-mainnet.network:4160 for block 82479","time":"2021-05-10T19:19:38.370895+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-fm.algorand-mainnet.network:4160 for block 82478","time":"2021-05-10T19:19:42.370635+01:00"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":212,"msg":"networkFetcher.FetchBlock: asking client r-np.algorand-mainnet.network:4160 for block 82479","time":"2021-05-10T19:19:42.371793+01:00"}

Hey fabrice,

I’m still having some issue with my participation node; it got up to about 11 million blocks synced but now it’s stopped and I don’t know why. I was wondering if you might have any insight. I seem to be stuck on round 11912309.

I have ~150 Mbps upload/download speed. I am running my node on an 8GB Raspberry Pi 4 using Raspbian Lite. I do not have a firewall on this machine but it is behind my router.

I installed the software by following the steps under “Installing with Other Linux Distros”.

RAM and CPU usage are very low right now. Back when it was syncing, RAM usage was closer to 40%, and my CPUs were maxing out. I am using a 1TB SSD that only has about 900GB of free space left.

When I run ./goal node status -d data, I get the following:

Last committed block: 11912309
Time since last block: 0.0s
Sync Time: 0.0s
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: 11912310
Next consensus protocol supported: true
Last Catchpoint: 
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

Here is my data/node.log file:

{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":268,"msg":"fetchAndWrite(11912319): lookback block doesn't exist, cannot authenticate new block","name":"","time":"2021-06-01T02:07:14.283985+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912319","name":"","time":"2021-06-01T02:07:14.284053+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":268,"msg":"fetchAndWrite(11912321): lookback block doesn't exist, cannot authenticate new block","name":"","time":"2021-06-01T02:07:14.284165+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912321","name":"","time":"2021-06-01T02:07:14.284235+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":268,"msg":"fetchAndWrite(11912323): lookback block doesn't exist, cannot authenticate new block","name":"","time":"2021-06-01T02:07:14.284323+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912323","name":"","time":"2021-06-01T02:07:14.284391+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":268,"msg":"fetchAndWrite(11912325): lookback block doesn't exist, cannot authenticate new block","name":"","time":"2021-06-01T02:07:14.284474+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912325","name":"","time":"2021-06-01T02:07:14.284549+01:00"}
{"Context":"sync","details":{"StartRound":11912309,"EndRound":11912309,"Time":387077999,"InitSync":false},"file":"telemetry.go","function":"github.com/algorand/go-algorand/logging.(*telemetryState).logTelemetry","instanceName":"PCZtOCd5Er90Q8nE","level":"info","line":212,"msg":"/ApplicationState/CatchupStop","name":"","session":"","time":"2021-06-01T02:07:14.284656+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).sync","level":"info","line":587,"msg":"Catchup Service: finished catching up, now at round 11912309 (previously 11912309). Total time catching up 387.077999ms.","name":"","time":"2021-06-01T02:07:14.284753+01:00"}

The output of ./algod -v is:

8590327808
2.6.0.stable [rel/stable] (commit #8fe22d4e)
go-algorand is licensed with AGPLv3.0
source code available at https://github.com/algorand/go-algorand

Any help would be greatly appreciated!

Can you grep the log for 11912310, the block that you should be downloading?
Do you regularly have new lines in the log or is it stalled?

Here’s the log:

{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912310","name":"","time":"2021-06-01T07:05:15.704251+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":342,"msg":"fetchAndWrite(11912311): previous block doesn't exist (perhaps fetching block 11912310 failed)","name":"","time":"2021-06-01T07:05:15.704280+01:00"}
{"Context":"Agreement","Hash":"","ObjectPeriod":0,"ObjectRound":0,"ObjectStep":0,"Period":0,"Round":11912310,"Sender":"","Step":16,"Type":"StepTimeout","Weight":0,"WeightTotal":0,"file":"trace.go","function":"github.com/algorand/go-algorand/agreement.(*tracer).logFastTimeout","level":"info","line":204,"msg":"timeout fired on (11912310, 0, 16) with value 5h43m44.152307269s (napping: true)","time":"2021-06-01T07:05:44.276070+01:00"}
{"Context":"Agreement","Hash":"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA","ObjectPeriod":0,"ObjectRound":0,"ObjectStep":0,"Period":0,"Round":11912310,"Sender":"","Step":255,"Type":"VoteAttest","Weight":0,"WeightTotal":0,"file":"actions.go","function":"github.com/algorand/go-algorand/agreement.pseudonodeAction.do","level":"info","line":372,"msg":"attested to {{} 0 AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAY5HFKQ AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA} at (11912310, 0, 255)","time":"2021-06-01T07:05:44.277153+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"error","line":334,"msg":"fetchAndWrite(11912310): ledger write failed: transaction OHVUT5DWJ6ECUIVETSHPBT67EGCJORSVEBUAAPR6E4HN5LVWG2EA: asset 2512768 missing from YECFNUCPBGGFONXP4ZWGSFDAP2XCO3HKFHHZYJ4TCTBRT64MM4LZAGQ4QM","name":"","time":"2021-06-01T07:06:38.541050+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912310","name":"","time":"2021-06-01T07:06:38.541147+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":342,"msg":"fetchAndWrite(11912311): previous block doesn't exist (perhaps fetching block 11912310 failed)","name":"","time":"2021-06-01T07:06:38.541283+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"error","line":334,"msg":"fetchAndWrite(11912310): ledger write failed: transaction OHVUT5DWJ6ECUIVETSHPBT67EGCJORSVEBUAAPR6E4HN5LVWG2EA: asset 2512768 missing from YECFNUCPBGGFONXP4ZWGSFDAP2XCO3HKFHHZYJ4TCTBRT64MM4LZAGQ4QM","name":"","time":"2021-06-01T07:06:55.984960+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":360,"msg":"failed to fetch block 11912310","name":"","time":"2021-06-01T07:06:55.985057+01:00"}
{"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"warning","line":342,"msg":"fetchAndWrite(11912311): previous block doesn't exist (perhaps fetching block 11912310 failed)","name":"","time":"2021-06-01T07:06:55.985185+01:00"}

I do regularly get new lines in my log file. It seems like it’s unable to get past this one round.

An issue has been opened: Catchup stuck because of a missing asset · Issue #2239 · algorand/go-algorand · GitHub

Thank you, I appreciate the help!