Catchpoint verification stops near the end and processing is restarted - processed accounts count +1 more than total accounts

[ipaleka]

I'm having a problem with installing a Node instance.

It processes +1 than total accounts:

Catchpoint total accounts: 15251246
Catchpoint accounts processed: 15251247

Verification stops somewhere near, and then processing starts again.

Last committed block: 6881
Sync Time: 5228.3s
Catchpoint: 24200000#UKQGNZJWP3B6D6ANUJZFJ35TXIBHPSJ2FLULZ6OAVCBL2BCPBUEA
Catchpoint total accounts: 15251246
Catchpoint accounts processed: 15251247
Catchpoint accounts verified: 15246247
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

Last committed block: 6881
Sync Time: 5661.0s
Catchpoint: 24200000#UKQGNZJWP3B6D6ANUJZFJ35TXIBHPSJ2FLULZ6OAVCBL2BCPBUEA
Catchpoint total accounts: 15251246
Catchpoint accounts processed: 2483200
Catchpoint accounts verified: 15246247
Genesis ID: mainnet-v1.0
Genesis hash: wGHE2Pwdvd7S12BL5FaOP20EGYesN73ktiC1qzkkit8=

I tried twice with DEB installation (Ubuntu 20.04) and this last one is with updater script installation.

The VPS provider is OVH and it doesn't offer disks other than SSD, tho ROTA is 1 in some places. But the number of accounts processed is bigger than 15K per second and also this VPS has been running for 7-8 months without problems.

Your environment

algod -v

12885557248
3.10.0.stable [rel/stable] (commit #9869cd96)
go-algorand is licensed with AGPLv3.0
source code available at https://github.com/algorand/go-algorand

• Operating System details.

Ubuntu 20.04; 8 cores; 8GB RAM, 160 GB SSD

[algorandskiy]

Thank you for the report. Could you attach node.log for the time period from few minutes before starting fast catchup and to right after it finished?

[ipaleka]

Thank you for the report. Could you attach node.log for the time period from few minutes before starting fast catchup and to right after it finished?

Well, there's no "finished" part, it just did restart processing after verification.

Here's the log of failed catch with updater script

{"file":"node.go","function":"github.com/algorand/go-algorand/node.(*AlgorandFullNode).StartCatchup","level":"info","line":1129,"msg":"starting catching up toward catchpoint 24200000#UKQGNZJWP3B6D6ANUJZFJ35TXIBHPSJ2FLULZ6OAVCBL2BCPBUEA","name":"","time":"2022-10-18T10:01:26.251728Z"} {"file":"logger.go","function":"github.com/algorand/go-algorand/daemon/algod/api/server/lib/middlewares.(*LoggerMiddleware).handler.func1","level":"info","line":56,"msg":"127.0.0.1:34474 - - [2022-10-18 10:01:26.25161378 +0000 UTC m=+76.209681236] \"POST /v2/catchup/24200000%23UKQGNZJWP3B6D6ANUJZFJ35TXIBHPSJ2FLULZ6OAVCBL2BCPBUEA HTTP/1.1\" 201 84 \"Go-http-client/1.1\" 252.569µs","time":"2022-10-18T10:01:26.251898Z"} {"Context":"Agreement","Hash":"","ObjectPeriod":0,"ObjectRound":0,"ObjectStep":0,"Period":0,"Round":6880,"Sender":"","Step":0,"Type":"RoundInterrupted","Weight":0,"WeightTotal":0,"file":"demux.go","function":"github.com/algorand/go-algorand/agreement.(*demux).next","level":"info","line":292,"msg":"agreement: round 6880 ended early due to concurrent write; next round is 6882","time":"2022-10-18T10:01:26.253646Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6896): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-no.algorand-mainnet.network:4160).requestBlock(6896): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.262775Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6896): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.262873Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6890): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.262950Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6891): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263009Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6889): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263076Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6899): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-pd.algorand-mainnet.network:4160).requestBlock(6899): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263156Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6899): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263215Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6888): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263245Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6898): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-s1.algorand-mainnet.network:4160).requestBlock(6898): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263188Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6898): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263384Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6895): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-no.algorand-mainnet.network:4160).requestBlock(6895): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263389Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6895): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263459Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6886): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263479Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6887): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263504Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":265,"msg":"fetchAndWrite(6892): lookback block doesn't exist, won't try to retrieve block again : wsFetcherClient(r-pd.algorand-mainnet.network:4160).requestBlock(6892): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263327Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6892): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263579Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6894): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-no.algorand-mainnet.network:4160).requestBlock(6894): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263575Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6894): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263620Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":265,"msg":"fetchAndWrite(6893): lookback block doesn't exist, won't try to retrieve block again : wsFetcherClient(r-pd.algorand-mainnet.network:4160).requestBlock(6893): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263358Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6893): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.263677Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).fetchAndWrite","level":"info","line":261,"msg":"fetchAndWrite(6897): Aborted while waiting for lookback block to ledger after failing once : wsFetcherClient(r-pd.algorand-mainnet.network:4160).requestBlock(6897): Request failed: context canceled","name":"","time":"2022-10-18T10:01:26.263440Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6897): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.268489Z"} {"Context":"sync","file":"service.go","function":"github.com/algorand/go-algorand/catchup.(*Service).pipelineCallback.func1","level":"info","line":404,"msg":"pipelineCallback(6885): did not fetch or write the block","name":"","time":"2022-10-18T10:01:26.275719Z"} {"Context":"sync","details":{"StartRound":0,"EndRound":6884,"Time":75667964489,"InitSync":true},"file":"telemetry.go","function":"github.com/algorand/go-algorand/logging.(*telemetryState).logTelemetry","instanceName":"yYxtZvCqq3CT28HV","level":"info","line":261,"msg":"/ApplicationState/CatchupStop","name":"","session":"","time":"2022-10-18T10:01:26.275797Z","v":"3.10.0"}

Btw, building from source version 3.11 solved the problem. :)

[algorandskiy]

Resolved by #4668

[jsgranados]

Closing issue as #4668 fixes this discrepancy.