search

algorand / conduit

Algorand's data pipeline framework.
MIT License
36 stars 26 forks source link

Misleading logs from monitorCatchpointCatchup #153

Open wparr-circle opened 9 months ago

wparr-circle commented 9 months ago

Subject of the issue

having deployed a new instance of Conduit, and an associated follower algod node. Seeing logs from https://github.com/algorand/conduit/blob/83dec6a37e0bac87209575e3a23597326547fb7f/conduit/plugins/importers/algod/algod_importer.go#L127C7-L127C7

Which misleadingly seems like it's stuck in processing the last account for a long period of time. ie. 

{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:05:53.074811297Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:05:58.075682352Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:03.078998746Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:08.08002411Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:13.083078998Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:18.0878116Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:23.092429377Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:28.097163644Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:33.101860947Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:38.106651798Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:43.11147604Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:48.116030708Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:53.120644347Z"}
{"__type":"importer","_name":"algod","level":"info","msg":"catchup phase Processed Accounts: 1999967 / 1999967","time":"2023-10-05T16:06:58.121731938Z"}

The node however as part of catchup is doing other work, unrelated to processing accounts. ie. 

Last committed block: 4
Sync Time: 637.1s
Catchpoint: 33510000#CCEB37DYVCA4BWFYT2OOMXCRUQGASAEXOOPZNXPGZ336Q64MAW7Q
Catchpoint total accounts: 1999967
Catchpoint accounts processed: 1999967
Catchpoint accounts verified: 0
Catchpoint total KVs: 7167638
Catchpoint KVs processed: 3864576 <- NOTE: moving non-zero value, after accounts have been processed
Catchpoint KVs verified: 0
Genesis ID: testnet-v1.0
Genesis hash: SGO1GKSzyE7IEPItTxCByw9x8FmnrCDexi9/cOUJOiI=

Subsequently during KV verification, monitor logs are emitted suggesting the final account is still being processed - before finally processing account verifications and subsequently block acquisitions.

Last committed block: 4
Sync Time: 637.1s
Catchpoint: 33510000#CCEB37DYVCA4BWFYT2OOMXCRUQGASAEXOOPZNXPGZ336Q64MAW7Q
Catchpoint total accounts: 1999967
Catchpoint accounts processed: 1999967
Catchpoint accounts verified: 0
Catchpoint total KVs: 7167638
Catchpoint KVs processed: 7167638
Catchpoint KVs verified: 3864576 <- NOTE: moving non-zero value, after accounts and KVs have been processed
Genesis ID: testnet-v1.0
Genesis hash: SGO1GKSzyE7IEPItTxCByw9x8FmnrCDexi9/cOUJOiI=

Please add conditions for non-zero KVs processed and KVs verified, to produce more meaningful logs from the algod catchpoint monitor.

Your environment

Steps to reproduce

  1. Deploy Follower Node.
  2. Deploy Conduit.
  3. Conduit triggers catchup.
  4. Wait until all accounts are processed.

Expected behaviour

Logs should indicate that algod catchup is not stuck on the last account during processing, and start logging status of processed KVs and verified KVs.

Actual behaviour

Logs do not change from account processing while catchup processes and verifies KVs.

gmalouf commented 3 weeks ago

Hi there,

While we don't necessarily want to implement detailed algod status into conduit logging, we might consider it in the future to be more informative.