graphprotocol / graphprotocol/graph-node

[Bug] RPC poller type firehose crash loops the graph-node when syncing subgraphs with trace

Open
#5,166 2 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug firehose
Dominant language
Rust
Stars
3.2k
Forks
1.1k
Avg merge
4d 1h
Merged PRs (30d)
1

Description

Bug report
  1. Be connected to an RPC poller type firehose without trace support
  2. Try to sync subgraphs that are using trace filters
  3. Graph-node crash loops

Expected behavior: should handle those cases gently and not kill itself after it fails.

[chains.${CHAIN_0_NAME}]
shard = "primary"
provider = [
{ label = "firehose", details = { type = "firehose", url = "${CHAIN_0_URL}", features = [ "compression" ], token = "${CHAIN_0_TOKEN}", conn_pool_size = 1 } }
]
Relevant log output
Jan 27 13:52:03.875 INFO Graph Node version: 0.34.0 (2024-01-26)
Jan 27 13:52:03.876 WARN GRAPH_POI_ACCESS_TOKEN not set; might leak POIs to the public via GraphQL
Jan 27 13:52:03.876 INFO Reading configuration file `/root/graph-node-configs/config.toml`
Jan 27 13:52:03.876 WARN No fork base URL specified, subgraph forking is disabled
Jan 27 13:52:03.876 INFO Starting up
Jan 27 13:52:03.876 INFO Trying IPFS node at: https://ipfs.network.thegraph.com/ipfs/
Jan 27 13:52:03.889 DEBG Creating firehose networks [1 chains, ingestor index_node_0]
Jan 27 13:52:03.889 INFO Configuring firehose endpoint, provider: firehose
Jan 27 13:52:03.889 DEBG Creating firehose networks [1 chains, ingestor index_node_0]
Jan 27 13:52:03.889 WARN Expensive queries file not set to a valid file: /etc/graph-node/expensive-queries.txt
Jan 27 13:52:03.889 DEBG Cleaning up large notifications after about 300s, channel: store_events, component: NotificationListener
Jan 27 13:52:03.902 INFO Connecting to Postgres, weight: 1, conn_pool_size: 10, url: postgresql://your_db_user:your_db_password@:5432/your_graphnode_db_name?host=/var/run/postgresql, pool: main, shard: primary
Jan 27 13:52:03.903 INFO Pool successfully connected to Postgres, pool: main, shard: primary, component: Store
Jan 27 13:52:03.903 DEBG Using postgres host order [Main], shard: primary, component: Store
Jan 27 13:52:03.906 INFO Setting up fdw, pool: main, shard: primary, component: ConnectionPool
Jan 27 13:52:03.910 INFO Running migrations, pool: main, shard: primary, component: ConnectionPool
Jan 27 13:52:03.911 INFO Migrations finished, pool: main, shard: primary, component: ConnectionPool
Jan 27 13:52:03.911 DEBG Release migration lock, pool: main, shard: primary, component: ConnectionPool
Jan 27 13:52:03.912 DEBG Setup finished, setup_time_s: 0, pool: main, shard: primary, component: ConnectionPool
Jan 27 13:52:03.912 DEBG Cleaning up large notifications after about 300s, channel: chain_head_updates, component: ChainHeadUpdateListener > NotificationListener
Jan 27 13:52:03.932 INFO Connecting to Firehose to get chain identifier, provider: firehose, provider: firehose
Jan 27 13:52:03.932 INFO Requesting genesis block from firehose, provider: firehose
Jan 27 13:52:03.932 DEBG Connecting to firehose to retrieve block for number 0, provider: firehose
Jan 27 13:52:04.100 INFO Successfully connected to IPFS node at: https://ipfs.network.thegraph.com/ipfs/
Jan 27 13:52:04.424 DEBG Retrieving block(s) from firehose, provider: firehose
Jan 27 13:52:04.424 INFO Connected to Firehose, genesis_block: #0 (f1999522da42d33a241a58a8e0fdfc864c9f9acca3374bad7adb255f31d92b55), provider: firehose, provider: firehose
Jan 27 13:52:04.426 INFO Creating LoadManager in disabled mode, component: LoadManager
Jan 27 13:52:04.427 INFO Started block ingestor, network_name: astar-testnet
Jan 27 13:52:04.427 INFO Starting block ingestor for network, network_name: astar-testnet
Jan 27 13:52:04.427 INFO Starting job runner with 5 jobs, component: JobRunner
Jan 27 13:52:04.427 DEBG Schedule for Vacuum subgraphs.subgraph_deployment, first_run_in_s: 0, interval_s: 60, component: JobRunner
Jan 27 13:52:04.427 DEBG Schedule for Report pg_notification_queue_usage(), first_run_in_s: 0, interval_s: 60, component: JobRunner
Jan 27 13:52:04.427 DEBG Schedule for Reconcile important tables from the primary, first_run_in_s: 9, interval_s: 900, component: JobRunner
Jan 27 13:52:04.427 DEBG Schedule for Record and remove unused deployments, first_run_in_s: 79, interval_s: 7200, component: JobRunner
Jan 27 13:52:04.427 DEBG Schedule for Refresh materialized views, first_run_in_s: 237, interval_s: 21600, component: JobRunner
Jan 27 13:52:04.429 INFO Starting JSON-RPC admin server at: http://localhost:8020, component: JsonRpcServer
Jan 27 13:52:04.429 INFO Starting GraphQL HTTP server at: http://localhost:8000, component: GraphQLServer
Jan 27 13:52:04.429 INFO Starting index node server at: http://localhost:8030, component: IndexNodeServer
Jan 27 13:52:04.429 INFO Starting metrics server at: http://localhost:8040, component: MetricsServer
Jan 27 13:52:04.429 INFO Starting GraphQL WebSocket server at: ws://localhost:8001, component: SubscriptionServer
Jan 27 13:52:04.430 INFO Trying to reconnect the Blockstream after disconnect, cursor: MTNgQADSfPpXm57wA-f5TqWwLpcyAllnUgLmIBFH0Yj-oXvE2JyjUzQmORqFxPj23B3sQ1yt3t7LQit99JEButDqy75tuyE6Rn4oltjmqrS-cfD2MAMadbM0WrmEZtvTXjXUaAipfONR6YfnPPTabkM2McMhJG6z2m5Vo4BVefIU6ycwlzr7cc3Rg_KWoIFBreInRbagnHjyBjUpJEcObM2FZKQ=, endpoint uri: firehose, network_name: astar-testnet, provider: firehose, component: EthereumFirehoseBlockIngestor
Jan 27 13:52:04.736 DEBG Subgraph started, start_ms: 307, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphRegistrar
Jan 27 13:52:04.739 INFO Resolve subgraph files using IPFS, n_templates: 1, n_data_sources: 2, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:04.800 DEBG Subgraph started, start_ms: 370, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphRegistrar
Jan 27 13:52:04.800 INFO Started all assigned subgraphs, node_id: index_node_0, count: 2, component: SubgraphRegistrar
Jan 27 13:52:04.803 INFO Resolve subgraph files using IPFS, n_templates: 0, n_data_sources: 3, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.699 INFO Successfully resolved subgraph files using IPFS, features: ø, n_templates: 0, n_data_sources: 3, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.723 INFO Starting subgraph writer, queue_size: 5, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.738 INFO Data source count at start: 3, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.758 INFO Successfully resolved subgraph files using IPFS, features: nonFatalErrors, n_templates: 1, n_data_sources: 2, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:05.765 INFO Starting subgraph writer, queue_size: 5, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:05.777 INFO Data source count at start: 2, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:05.778 DEBG Starting or restarting subgraph, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.779 DEBG Starting block stream, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.779 INFO Blockstream disconnected, connecting, provider_err_count: 0, cursor: c2189eNZNyWNIaZ0jdxXgaWwLpc_DF1tVAvmIBcQhY_z9XHNjsj3U2d8OUzTkv3y3RW_GVyt29zNRnct9pFZtdfixrpn6ic_Tn4rm4jnreXmLfr0MAMfee5kXL-EZdraWz_dZFv7frQF4920b6KKYUtjM8QkeGSzj2sCpIRRc6NDsCUxkjX0dcfX0viR94VJ-uUtRe33xCL2DjN0JUtSaMqBMg==, subgraph: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, start_block: 72104, endpoint_uri: firehose, provider: firehose, deployment: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: FirehoseBlockStream
Jan 27 13:52:05.822 DEBG Starting or restarting subgraph, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:05.822 DEBG Checking if subgraph current block is after manifest start block, manifest_start_block_number: 24771, subgraph_current_block_number: 24770, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: FirehoseBlockStream
Jan 27 13:52:05.822 DEBG Starting block stream, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: SubgraphInstanceManager
Jan 27 13:52:05.822 INFO Blockstream disconnected, connecting, provider_err_count: 0, cursor: , subgraph: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, start_block: 24771, endpoint_uri: firehose, provider: firehose, deployment: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, sgd: 1, subgraph_id: QmdcUWvTS15JBzUpaQtt1Tst5rAzAVL9sPXyL5uXANegq8, component: FirehoseBlockStream
Jan 27 13:52:05.896 INFO Blockstream connectedthread 'tokio-runtime-worker, ' panicked at 'Got a transaction trace with status UNKNOWN, datasource is brokenprovider', : chain/ethereum/src/codec.rsfirehose:, 163deployment:: 17QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa
, note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: FirehoseBlockStream
Panic in tokio task, aborting!
Jan 27 13:52:05.897 INFO Stopping subgraph, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.898 DEBG Subgraph stopped, WASM runtime thread terminated, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
Jan 27 13:52:05.900 DEBG Subgraph stopped, WASM runtime thread terminated, sgd: 2, subgraph_id: QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa, component: SubgraphInstanceManager
IPFS hash

QmdNJTN49nAx6hoiFGQi1v1vQ8fqyjHp4LVcBHcgMUVwSa

Subgraph name or link to explorer

No response

Some information to help us out
  • Tick this box if this bug is caused by a regression found in the latest release.
  • Tick this box if this bug is specific to the hosted service.
  • I have searched the issue tracker to make sure this issue is not a duplicate.
OS information

Linux

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

The reported panic is at chain/ethereum/src/codec.rs:163 when a Firehose transaction trace has UNKNOWN status. Reproduce with a firehose provider without trace support and a subgraph using trace filters; done means the failure is handled without crashing or repeatedly aborting the graph node.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
backend, blockchain
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.