Reader is slow to become ready on slow blockchains

[trader-payne]

Firehose reader node is slow to become "ready" after restarts, especially for slow blockchains like Bitcoin. Matthew Darwin suggested a potential fix would be to roll back the last block by 1 in the poller.

You can see in the snippet how long it took to become ready.

#### restarting timestamp:
Jan 22 19:55:14 firehose-bitcoin-core systemd[1]: Started SF Firehose.

#### Mon Jan 22 20:05:22 UTC 2024
ready{app="block-indexer"} 0
ready{app="firehose"} 0
ready{app="merger"} 1
ready{app="reader-node"} 0
ready{app="relayer"} 0

#### Mon Jan 22 20:10:04 UTC 2024
ready{app="block-indexer"} 0
ready{app="firehose"} 0
ready{app="merger"} 1
ready{app="reader-node"} 1
ready{app="relayer"} 1

As you can see, it took 15 minutes to go back in a working state.

Logs from restart:

Jan 22 19:55:14 firehose-bitcoin-core systemd[1]: Started SF Firehose.
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.618Z INFO (dtracing) registering development exporters from environment variables
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (firecore) starting Firehose on CORE with config file '/mnt/data/github/firehose/config.yml'
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (firecore) launching applications: firehose,merger,reader-node,relayer,substreams-tier1,substreams-tier2
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) parsing backup configs {"configs": [], "factory_count": 1}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) parsing backup known factory {"name": "gke-pvc-snapshot"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) adding superviser shutdown to plugins {"plugin_name": "ToConsoleLogPlugin"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) registered log plugin {"plugin count": 1}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) creating operator {"options": {"Bootstrapper":null,"EnableSupervisorMonitoring":true,"ShutdownDelay":0}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) creating mindreader plugin {"one_blocks_store_url": "file:///mnt/data/bitcoin/firehose/storage/one-blocks", "one_block_suffix": "default", "working_directory": "/mnt/data/bitcoin/firehose", "start_block_num": 0, "stop_block_num": 0, "channel_capacity": 5000, "with_head_block_updater": true, "with_shutdown_func": true}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) creating new mindreader plugin
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) adding superviser shutdown to plugins {"plugin_name": "MindReaderPlugin"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) registered log plugin {"plugin count": 2}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) running node manager app {"config": {"StartupDelay":0,"HTTPAddr":":10011","ConnectionWatchdog":false,"GRPCAddr":":10010"}, "mindreader": true}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) retrieved hostname from os {"hostname": "firehose-bitcoin-core"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) starting mindreader gRPC server
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (relayer) starting relayer {"sources_addr": [":10010"], "grpc_listen_addr": ":10014", "source_request_burst": 0, "max_source_latency": "1h0m0s", "one_blocks_url": "file:///mnt/data/bitcoin/firehose/storage/one-blocks"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (dgrpc) standard server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (substreams-tier1) running substreams-tier1 {"config": {"MergedBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/merged-blocks","OneBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/one-blocks","ForkedBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/forked-blocks","BlockStreamAddr":":10014","GRPCListenAddr":":10016","GRPCShutdownGracePeriod":1000000000,"ServiceDiscoveryURL":null,"StateStoreURL":"/mnt/data/bitcoin/firehose/localdata","StateStoreDefaultTag":"","StateBundleSize":1000,"MaxSubrequests":24,"SubrequestsEndpoint":":10017","SubrequestsInsecure":false,"SubrequestsPlaintext":true,"WASMExtensions":null,"PipelineOptions":null,"Tracing":false}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (merger) running merger {"config": {"StorageOneBlockFilesPath":"file:///mnt/data/bitcoin/firehose/storage/one-blocks","StorageMergedBlocksFilesPath":"file:///mnt/data/bitcoin/firehose/storage/merged-blocks","StorageForkedBlocksFilesPath":"file:///mnt/data/bitcoin/firehose/storage/forked-blocks","GRPCListenAddr":":10012","PruneForkedBlocksAfter":50000,"TimeBetweenPruning":60000000000,"TimeBetweenPolling":1000000000,"StopBlock":0}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (substreams-tier2) running substreams-tier2 {"config": {"MergedBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/merged-blocks","GRPCListenAddr":":10017","ServiceDiscoveryURL":null,"StateStoreURL":"/mnt/data/bitcoin/firehose/localdata","StateStoreDefaultTag":"","StateBundleSize":1000,"WASMExtensions":null,"PipelineOptions":null,"Tracing":false}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (dgrpc) standard server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (substreams-clients) setting up basic grpc client factory (no XDS bootstrap)
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) launching operator
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) launching operator HTTP server {"http_listen_addr": ":10011"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (firehose) running firehose {"config": {"MergedBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/merged-blocks","OneBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/one-blocks","ForkedBlocksStoreURL":"file:///mnt/data/bitcoin/firehose/storage/forked-blocks","BlockStreamAddr":":10014","GRPCListenAddr":":10015","GRPCShutdownGracePeriod":1000000000,"ServiceDiscoveryURL":null,"ServerOptions":null}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) launching gRPC server {"listen_addr": ":10010"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (substreams-service) creating new joining source {"cursor": "<nil>", "start_block_num": 0}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) serving gRPC {"listen_addr": ":10010"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (dgrpc) standard server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (firehose) registering grpc services
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (firehose) waiting until hub is real-time synced
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) starting webserver {"http_addr": ":10011"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) operator ready to receive commands
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) received operator command {"command": "start", "params": null}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (relayer) waiting for hub to be ready...
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) preparing for start
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) preparing to start chain
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (reader) starting mindreader
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.619Z INFO (relayer) new source factory created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (merger) merger initiated
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (reader) launching blocks reading loop {"capacity": 5000}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (reader) creating new command instance and launch read loop {"binary": "/mnt/data/github/firehose/bin/firebtc", "arguments": ["poller", "0", "--reader-state-storage-path=/mnt/data/bitcoin/firehose", "--rpc-endpoint=http://127.0.0.1:8332", "--headers=Authorization: Basic Yml0Y29pbjpiaXRjb2lu"]}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (reader) starting consume flow
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (reader) successfully start service
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (reader) operator ready to receive commands
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (merger) merger running
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (merger) starting merger
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.620Z INFO (dgrpc) standard server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (merger) grpc server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (merger) server registered
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (merger) starting pruning of unused (old) one-block-files {"pruning_distance_to_lib": 100, "time_between_pruning": "1m0s"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (merger) starting pruning of forked files {"pruning_distance_to_lib": 50000, "time_between_pruning": "1m0s"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (dgrpc) launching gRPC server {"listen_addr": ":10012"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.621Z INFO (dgrpc) serving gRPC {"listen_addr": ":10012"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) launching tier2 service {"block_type": "sf.bitcoin.type.v1.Block"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier1) launching tier1 service {"client_config": {}, "block_type": "sf.bitcoin.type.v1.Block", "with_live": true}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) registering substreams metrics
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) setting up trust authenticator
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (relayer.src.10010) starting block source consumption {"endpoint_url": ":10010"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (relayer.src.10010) block stream source reading messages {"endpoint_url": ":10010"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier1) waiting until hub is real-time synced
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) launching gRPC server
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (dgrpc) standard server created
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) launching gRPC server {"listen_addr": ":10017"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (reader.sub.relayer) receive block request {"trace_id": "a1192483c992cba5e5ebfb32521bfd2f", "request": {"requester":"relayer"}}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (reader.sub.relayer) sending burst {"burst_size": 0}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (reader) subscribed {"new_length": 1, "subscriber": "relayer"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.622Z INFO (substreams-tier2) serving gRPC (over HTTP router) (plain-text) {"listen_addr": ":10017"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.642Z INFO (firebtc) launching firebtc reader {"start_block_num": "0", "rpc_endpoint": "http://127.0.0.1:8332", "block_fetch_retry_count": 3, "reader_state_storage_path": "/mnt/data/bitcoin/firehose", "reader_state_storage_path": ["Authorization: Basic Yml0Y29pbjpiaXRjb2lu"], "graceful_shutdown_delay": "0s", "unready_period_delay": "0s", "ignore_cursor": false}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.642Z INFO (firebtc.poller) launching firebtc poller {"endpoint": "127.0.0.1:8332", "content": "type.googleapis.com/sf.bitcoin.type.v1.Block", "start_block_num": 0}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.643Z INFO (firebtc.poller) found best block hash {"blockhash": "000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.654Z INFO (firebtc.poller) retrieved finalized and head block {"finalized_block": "#826876 (000000000000000000003c782c8ef925a0b33bd6c9d51566713f00b6e3e4fb69)", "chain_head_block": "#826882 (000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b)"}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.654Z INFO (firebtc.poller) starting poller {"start_block_num": 0, "chain_latest_finalize_block": "#826876 (000000000000000000003c782c8ef925a0b33bd6c9d51566713f00b6e3e4fb69)", "resolved_start_block_num": 0}
Jan 22 19:55:14 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:14.656Z INFO (firebtc.poller) loaded cursor {"start_block": "826882 (000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b)", "lib": "826876 (000000000000000000003c782c8ef925a0b33bd6c9d51566713f00b6e3e4fb69)", "block_count": 8}
Jan 22 19:55:15 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:15.015Z INFO (firebtc.poller) saved cursor {"filepath": "/mnt/data/bitcoin/firehose/cursor.json", "last_fired_block": "826882 (000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b)", "lib": "826876 (000000000000000000003c782c8ef925a0b33bd6c9d51566713f00b6e3e4fb69)", "block_count": 8}
Jan 22 19:55:15 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:15.016Z INFO (firebtc.poller) found best block hash {"blockhash": "000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b"}
Jan 22 19:55:15 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:15.025Z INFO (firebtc.poller) head block is behind, waiting for it to catch up {"head_block": "#826882 (000000000000000000033c6d227dba1d00983eda485a0ce53db394525aa5812b)", "block_num": 826883, "wait_duration": "7m0s"}
Jan 22 19:55:15 firehose-bitcoin-core firehose[51414]: 2024-01-22T19:55:15.674Z INFO (merger) resetting bundler base block num {"previous_base_block_num": 0, "new_base_block_num": 826800, "lib": "#826799 (8f19ddb68d1ed418)"}

[matthewdarwin]

So I learned today that Arbitrum Orbit chains only produce a block when there is a transaction. For infrequently used chains, this means very infrequent blocks. Reader will possibly take a long time to be "ready" in this case.

[sduchesneau]

We are working on a fix for this :)

[sduchesneau]

When the 'reader node' was restarted, sometimes relayer would be very slow to detect that it missed a block (and restart...). This is one aspect of this problem, now fixed here: 5d9af0b827aff0753da7666b0a07502020d53dcb.