search

graphprotocol / graph-node

Graph Node indexes data from blockchains such as Ethereum and serves it over GraphQL
https://thegraph.com
Apache License 2.0
2.92k stars 982 forks source link

Graph node docker process gets killed abruptly #1359

Closed puneet-khushwani-eth closed 5 years ago

puneet-khushwani-eth commented 5 years ago

What is the current behavior?

Our process starts docker containers for graph-node (with a fresh data directory) and its dependencies. To this we deploy a sub-graph and then fire some calls to it to verify if deployment was successful. In most cases the docker process for graph-node gets killed abruptly (some times even before we start deploying sub-graph)

Versions we use - docker compose : 1.23.2 geth : 1.9.5 the-graph : 0.16.0

logs we see:

wait-for-it.sh: ipfs:5001 is available after 0 seconds
wait-for-it.sh: waiting 30 seconds for postgres:5432
wait-for-it.sh: postgres:5432 is available after 6 seconds
++ echo dev:http://172.16.0.201:40005
+ graph-node --postgres-url postgresql://graph-node:let-me-in@postgres:5432/graph-node --ethereum-rpc dev:http://172.16.0.201:40005 --ipfs ipfs:5001
Nov 18 10:20:30.151 INFO Graph Node version: v0.16.0 (32a58d94a 2019-11-01)
Nov 18 10:20:30.151 INFO Starting up
Nov 18 10:20:30.154 INFO Trying IPFS node at: http://ipfs:5001/
Nov 18 10:20:30.179 INFO Creating transport, url: http://172.16.0.201:40005, network: dev
Nov 18 10:20:30.182 INFO Successfully connected to IPFS node at: http://ipfs:5001/
Nov 18 10:20:30.191 INFO Connecting to Postgres, conn_pool_size: 10, url: postgresql://graph-node:HIDDEN_PASSWORD@postgres:5432/graph-node
Nov 18 10:20:30.339 INFO Connected to Postgres, url: postgresql://graph-node:HIDDEN_PASSWORD@postgres:5432/graph-node, component: Store
Nov 18 10:20:30.339 INFO Connecting to Ethereum..., network: dev
Nov 18 10:20:30.345 INFO Connected to Ethereum, network_version: 5, network: dev
Nov 18 10:20:30.352 INFO Waiting for other graph-node instances to finish migrating, component: Store
Nov 18 10:20:30.354 INFO Running migrations, component: Store
Nov 18 10:20:30.367 INFO Migrations finished, component: Store
Nov 18 10:20:30.367 INFO Completed pending Postgres schema migrations, component: Store
Nov 18 10:20:30.367 DEBG Cleaning up large notifications after about 300s, channel: store_events, component: Store > NotificationListener
Nov 18 10:20:30.367 DEBG Cleaning up large notifications after about 300s, channel: chain_head_updates, component: Store > ChainHeadUpdateListener > NotificationListener
Nov 18 10:20:30.402 INFO Starting block ingestor
Nov 18 10:20:30.405 DEBG Subscribe, entities: [(SubgraphDeploymentId("subgraphs"), "SubgraphDeploymentAssignment")], id: 88f12a85-32e9-4f0c-bed5-81fd6482361d, component: Store
Nov 18 10:20:30.431 INFO Starting JSON-RPC admin server at: http://localhost:8020, component: JsonRpcServer
Nov 18 10:20:30.431 INFO Resolve subgraph files using IPFS, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.431 INFO Resolve manifest, link: /ipfs/QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.433 INFO Starting GraphQL HTTP server at: http://localhost:8000, component: GraphQLServer
Nov 18 10:20:30.433 INFO Starting GraphQL WebSocket server at: ws://localhost:8001, component: SubscriptionServer
Nov 18 10:20:30.433 INFO Starting index node server at: http://localhost:8030, component: IndexNodeServer
Nov 18 10:20:30.433 INFO Starting metrics server at: http://localhost:8040, component: MetricsServer
Nov 18 10:20:30.440 INFO Resolve schema, link: /ipfs/QmPE2spKHS1CzsZPciBPJrLNXbbf63dbhoy8r4szMaRKxo, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.440 INFO Resolve data source, source: 0, name: OSTComposer, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.440 INFO Resolve mapping, link: /ipfs/QmUPaXkWCo3SZmGNWwcb31FP4dPkQggNnJ777NPWr3ntqx, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve ABI, link: /ipfs/QmVUsCrNHeeCBxb9wNEem5SbwSuM2Fc1T5Lhkqy2jBnuHz, name: OSTComposer, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve data source, source: 0, name: EIP20Gateway, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve mapping, link: /ipfs/QmVwnES9n4FM5PubgWDvqWByV3TH25Lr2jowhBdVW9pKvc, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve ABI, link: /ipfs/QmYkTzjK6ZTcHcMvoT5MAFMdpRx79eQJfS4FEgMkMGU6FR, name: EIP20Gateway, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve data source, source: 0, name: Anchor, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve mapping, link: /ipfs/QmeM73eSrBHK4EgrmvwLSYf9CLsDBKTsVMSRjuaMGbiJLU, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.441 INFO Resolve ABI, link: /ipfs/QmfTSs6ZZZXoVUrEeWAxyLjEEsUpM7v1H4Y3cez9PuC1zh, name: Anchor, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.488 INFO Execute query, complexity: Ok(4050100), query: query deployment($id: ID!, $skip: Int!) { subgraphDeployment(id: $id) { dynamicDataSources(orderBy: id, skip: $skip) { kind network name source { address abi } mapping { kind apiVersion language file entities abis { name file } blockHandlers { handler filter } callHandlers { function handler } eventHandlers { event handler } } templates { kind network name source { abi } mapping { kind apiVersion language file entities abis { name file } blockHandlers { handler filter } callHandlers { function handler } eventHandlers { event handler } } } } } } , query_id: 5bdc0099-f8c9-4fac-8a7a-e98370ad4978, subgraph_id: subgraphs, component: GraphQlRunner
Nov 18 10:20:30.500 INFO Successfully resolved subgraph files using IPFS, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.500 INFO Create attribute indexes for subgraph entities, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.518 INFO Successfully created attribute indexes for subgraph entities, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphAssignmentProvider
Nov 18 10:20:30.518 DEBG Subgraph started, start_ms: 86, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphRegistrar
Nov 18 10:20:30.518 INFO Start subgraph, data_sources: 3, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Nov 18 10:20:30.518 INFO Started all subgraphs, component: SubgraphRegistrar
Nov 18 10:20:30.533 DEBG Starting or restarting subgraph, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Nov 18 10:20:30.533 DEBG Starting block stream, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Nov 18 10:20:30.548 INFO Scanning blocks [0, 99999], subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager > BlockStream
Nov 18 10:20:30.548 DEBG Requesting logs for blocks [0, 99999], contract 0xe11e76c1eca13ae4aba871eabdf37c24b8e1928b, 5 events, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager > BlockStream
Nov 18 10:20:30.548 DEBG Requesting logs for blocks [0, 99999], contract 0x4fdf26dc9a99d11ffb39a2d88a7e39e49544602a, 1 events, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager > BlockStream
Nov 18 10:20:30.549 DEBG Requesting logs for blocks [0, 99999], contract 0xeaa192d486ac5243886a28001e27a68cae5fde4b, 1 events, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager > BlockStream
Nov 18 10:20:30.627 DEBG Found 0 relevant block(s), subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager > BlockStream
thread 'tokio-runtime-worker-15' panicked at 'called `Option::unwrap()` on a `None` value', src/libcore/option.rs:378:21
stack backtrace:
   0:     0x55ba1412a17b - backtrace::backtrace::libunwind::trace::h89fcc71e59e3bc5b
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/libunwind.rs:88
   1:     0x55ba1412a17b - backtrace::backtrace::trace_unsynchronized::h0bad9be1379e729a
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/mod.rs:66
   2:     0x55ba1412a17b - std::sys_common::backtrace::_print::hd3382a1f33c473da
                               at src/libstd/sys_common/backtrace.rs:47
   3:     0x55ba1412a17b - std::sys_common::backtrace::print::h0ec6f03cfb8e76a6
                               at src/libstd/sys_common/backtrace.rs:36
   4:     0x55ba1412a17b - std::panicking::default_hook::{{closure}}::h96cbf7b454e3f557
                               at src/libstd/panicking.rs:200
   5:     0x55ba14129e56 - std::panicking::default_hook::h95a8f00337383d83
                               at src/libstd/panicking.rs:214
   6:     0x55ba1412a8ed - std::panicking::rust_panic_with_hook::h92f98b46e22f14ed
                               at src/libstd/panicking.rs:477
   7:     0x55ba1412a472 - std::panicking::continue_panic_fmt::h25abfbb4e5b7043a
                               at src/libstd/panicking.rs:384
   8:     0x55ba1412a356 - rust_begin_unwind
                               at src/libstd/panicking.rs:311
   9:     0x55ba1414791d - core::panicking::panic_fmt::h7e9f94035af782b3
                               at src/libcore/panicking.rs:85
  10:     0x55ba1414785c - core::panicking::panic::hda536e6f3accfb91
                               at src/libcore/panicking.rs:49
  11:     0x55ba135b87c5 - <futures::future::map::Map<A,F> as futures::future::Future>::poll::hbb5723ac75fadb97
  12:     0x55ba13409ae3 - futures::future::chain::Chain<A,B,C>::poll::h3ffbae9f96ce048e
  13:     0x55ba134b9f19 - <futures::future::and_then::AndThen<A,B,F> as futures::future::Future>::poll::h46e8903e1b5c6e28
  14:     0x55ba135bb57a - <futures::future::map::Map<A,F> as futures::future::Future>::poll::hf7df128f91b4c5a4
  15:     0x55ba1343a4d9 - futures::future::chain::Chain<A,B,C>::poll::hb0cc14147c0ca7a4
  16:     0x55ba134b9ec9 - <futures::future::and_then::AndThen<A,B,F> as futures::future::Future>::poll::h06733eff6b9e093c
  17:     0x55ba13418246 - futures::future::chain::Chain<A,B,C>::poll::h6091925002851fb8
  18:     0x55ba1342dfc0 - futures::future::chain::Chain<A,B,C>::poll::h8637e849ed8ac405
  19:     0x55ba1344a3cc - futures::future::chain::Chain<A,B,C>::poll::hcec6317328fef4b0
  20:     0x55ba13262e83 - <futures::future::loop_fn::LoopFn<A,F> as futures::future::Future>::poll::h461e874370c90988
  21:     0x55ba134c21fa - <graph_datasource_ethereum::block_stream::BlockStream<S,C> as futures::stream::Stream>::poll::h619660b9566a125b
  22:     0x55ba1363a217 - <futures::stream::from_err::FromErr<S,E> as futures::stream::Stream>::poll::h53d0abee96c1cf68
  23:     0x55ba134b255e - <futures::stream::then::Then<S,F,U> as futures::stream::Stream>::poll::h9729ac5eca032a10
  24:     0x55ba132f45a1 - <futures::stream::filter_map::FilterMap<S,F> as futures::stream::Stream>::poll::h78370854be0a9287
  25:     0x55ba133301a2 - <futures::stream::fold::Fold<S,F,Fut,T> as futures::future::Future>::poll::hd170a6a26212c4c4
  26:     0x55ba133f1b38 - futures::future::chain::Chain<A,B,C>::poll::h0979e26fe9936c5e
  27:     0x55ba13263369 - <futures::future::loop_fn::LoopFn<A,F> as futures::future::Future>::poll::h97b23c9cddc0eb3f
  28:     0x55ba1330a7cd - tokio_threadpool::blocking::blocking::h576c0094e90f88a2
  29:     0x55ba133f4d6a - futures::future::chain::Chain<A,B,C>::poll::h0e9d2164dfdcb0d2
  30:     0x55ba1405a3d2 - futures::task_impl::std::set::hf4b5fdceb4388110
  31:     0x55ba140591e2 - std::panicking::try::do_call::h01928b4aca2ba38e
  32:     0x55ba1412ea1a - __rust_maybe_catch_panic
                               at src/libpanic_unwind/lib.rs:80
  33:     0x55ba140571d9 - tokio_threadpool::task::Task::run::h34f5b7c81e615646
  34:     0x55ba14054946 - tokio_threadpool::worker::Worker::run_task::h8c5272120add719b
  35:     0x55ba14053de0 - tokio_threadpool::worker::Worker::run::h255c1a6d2d6b172c
  36:     0x55ba14035be0 - std::thread::local::LocalKey<T>::with::h29a751706b35efe5
  37:     0x55ba14035ec8 - std::thread::local::LocalKey<T>::with::hdaad9c3c1c34d23f
  38:     0x55ba14035d5f - std::thread::local::LocalKey<T>::with::h5f0a4ad5737d3a0e
  39:     0x55ba1403800e - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::hcc1df889e5ab1a76
  40:     0x55ba14059c6a - std::thread::local::LocalKey<T>::with::h511c94d45a241416
  41:     0x55ba14059d89 - std::thread::local::LocalKey<T>::with::hffb954323a524e4c
  42:     0x55ba14051b48 - std::sys_common::backtrace::__rust_begin_short_backtrace::h6f133eeb09e00fea
  43:     0x55ba1405922c - std::panicking::try::do_call::hde1add114619e061
  44:     0x55ba1412ea1a - __rust_maybe_catch_panic
                               at src/libpanic_unwind/lib.rs:80
  45:     0x55ba14059300 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h94dfeec3c678b0c3
  46:     0x55ba1411ba5f - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h2877b2aefb0fd627
                               at /rustc/625451e376bb2e5283fc4741caa0a3e8a2ca4d54/src/liballoc/boxed.rs:787
  47:     0x55ba1412dd40 - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h13f473dbcdaa0fef
                               at /rustc/625451e376bb2e5283fc4741caa0a3e8a2ca4d54/src/liballoc/boxed.rs:787
  48:     0x55ba1412dd40 - std::sys_common::thread::start_thread::h562a7c4953cb1d31
                               at src/libstd/sys_common/thread.rs:13
  49:     0x55ba1412dd40 - std::sys::unix::thread::Thread::new::thread_start::h382c6ae14181d163
                               at src/libstd/sys/unix/thread.rs:79
  50:     0x7fe04e75cfa3 - start_thread
  51:     0x7fe04e6714cf - clone
  52:                0x0 - <unknown>
Nov 18 10:20:30.702 DEBG Subgraph stopped, WASM runtime thread terminated, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Nov 18 10:20:30.702 DEBG Subgraph stopped, WASM runtime thread terminated, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Nov 18 10:20:30.704 DEBG Subgraph stopped, WASM runtime thread terminated, subgraph_id: QmUWFLXttdJ5heCPJimM3YDREE2aCyLAHvTteXLuNFPQ3J, component: SubgraphInstanceManager
Runtime cleaned up and shutdown successfully
Nov 18 10:20:31.435 DEBG Shutting down contention checker thread

What is the expected behavior?

docker process should be running and we should be able to make calls to the server

leoyvens commented 5 years ago

@puneet-khushwani-eth Hi, sorry you're having this issue, could you provide instructions to reproduce this?

puneet-khushwani-eth commented 5 years ago

from our repo https://github.com/mosaicdao/mosaic-chains, you can run either of the below commands:

npm run test:smoke:goerli
npm run test:smoke:ropsten

they would internally spawn processes which would host the-graph server and its dependencies. We then deploy dub graph and verify its deployment.

To see crash logs of the graph docker process you can use the following command

docker logs --follow mosaic_graph_goerli_graph-node_1
leoyvens commented 5 years ago

@puneet-khushwani-eth Thanks for the instructions, I've reproduced it. What happened is that we were previously allowing a configuration that's really unsupported, which is to have ETHEREUM_REORG_THRESHOLD be larger than the chain. Than env var defaults to 50, and in your case your chain size is 0 from what I can tell, so you can fix this by setting ETHEREUM_REORG_THRESHOLD=0. Please let me know if that works for you!