search

paritytech / cumulus

Write Parachains on Substrate
GNU General Public License v3.0
618 stars 378 forks source link

ERROR reports occur when parallelchain synchronize KSM blocks #1293

Open 99Kies opened 2 years ago

99Kies commented 2 years ago 
2022-05-24 08:13:38.060  INFO                 main sc_service::builder: [Parachain] 📦 Highest known block at #0    
2022-05-24 08:13:38.060  INFO tokio-runtime-worker substrate_prometheus_endpoint: [Parachain] 〽️ Prometheus exporter started at 0.0.0.0:9779    
2022-05-24 08:13:38.062  WARN tokio-runtime-worker parachain::bitfield-distribution: [Relaychain] Failed to fetch basics from runtime API relay_parent=0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe err=Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }
2022-05-24 08:13:38.062  WARN tokio-runtime-worker parachain::dispute-coordinator: [Relaychain] error=RollingSessionWindow(SessionsUnavailable { kind: RuntimeApi(Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }), info: None })
2022-05-24 08:13:38.062 ERROR tokio-runtime-worker parachain::bitfield-distribution: [Relaychain] Our view contains 0xb0a8…dafe, but not in active heads added=0xb0a8…dafe
2022-05-24 08:13:38.063  INFO                 main parity_ws: [Parachain] Listening for new connections on 0.0.0.0:8847.    
2022-05-24 08:13:38.071  WARN tokio-runtime-worker parachain::candidate-backing: [Relaychain] Failed to fetch runtime API data for job err=Execution { runtime_api_name: "validator_groups", source: Application(Execution(Other("Exported method ParachainHost_validator_groups is not found"))) }
2022-05-24 08:13:38.073  WARN tokio-runtime-worker parachain::dispute-distribution: [Relaychain] error=Sender(Runtime(RuntimeRequest(Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }))) ctx="on FromOverseer"
2022-05-24 08:13:38.076 ERROR tokio-runtime-worker polkadot_node_subsystem_util: [Relaychain] job finished with an error job="bitfield-signing-job" parent_hash=0xb0a8…dafe err=Util(RuntimeApi(Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }))
2022-05-24 08:13:38.572  INFO tokio-runtime-worker sub-libp2p: [Parachain] 🔍 Discovered new external address for our node: /ip6/240e:390:e57:f950:4a6:6409:91fb:8040/tcp/40336/p2p/12D3KooWHJ8XuP92wAG5qgoUTiDbGvgwFbB1WAQpvKxCp77Km5ZN    
2022-05-24 08:13:38.572  INFO tokio-runtime-worker sub-libp2p: [Relaychain] 🔍 Discovered new external address for our node: /ip6/240e:390:e57:f950:4a6:6409:91fb:8040/tcp/30346/ws/p2p/12D3KooWJA8i7TCgjBZKcZWnchrMsKN7dFJvrtRSfoE86dPgAPjc    
2022-05-24 08:13:39.085  INFO tokio-runtime-worker sub-libp2p: [Relaychain] 🔍 Discovered new external address for our node: /ip4/115.198.90.209/tcp/30346/ws/p2p/12D3KooWJA8i7TCgjBZKcZWnchrMsKN7dFJvrtRSfoE86dPgAPjc    
2022-05-24 08:13:41.105  WARN tokio-runtime-worker parachain::dispute-coordinator: [Relaychain] Received msg before first active leaves update. This is not expected - message will be dropped. msg=ActiveDisputes(Sender { complete: false })
2022-05-24 08:13:41.105  WARN tokio-runtime-worker parachain::dispute-distribution: [Relaychain] error=Sender(AskActiveDisputesCanceled) ctx="on FromOverseer"
2022-05-24 08:13:43.047  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing, target=#12816475 (17 peers), best: #2826 (0xd05d…92e7), finalized #2560 (0x95cd…876e), ⬇ 362.8kiB/s ⬆ 34.9kiB/s    
2022-05-24 08:13:43.063  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 0.7kiB/s ⬆ 0.6kiB/s    
2022-05-24 08:13:48.048  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing 1073.2 bps, target=#12816475 (25 peers), best: #8192 (0x4b7e…af70), finalized #8192 (0x4b7e…af70), ⬇ 477.8kiB/s ⬆ 26.5kiB/s    
2022-05-24 08:13:48.066  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 58 B/s ⬆ 60 B/s    
2022-05-24 08:13:53.049  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing 843.2 bps, target=#12816476 (25 peers), best: #12408 (0x79e4…c0ff), finalized #12288 (0xe1b8…1b9f), ⬇ 347.5kiB/s ⬆ 17.2kiB/s    
2022-05-24 08:13:53.066  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 0 ⬆ 0    
2022-05-24 08:13:58.049  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing 611.2 bps, target=#12816477 (26 peers), best: #15464 (0xe8e1…660d), finalized #14849 (0x7ad6…e8e7), ⬇ 409.8kiB/s ⬆ 46.4kiB/s    
2022-05-24 08:13:58.066  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 61 B/s ⬆ 61 B/s    
2022-05-24 08:14:03.049  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing 1154.2 bps, target=#12816478 (27 peers), best: #21235 (0x16bb…7f18), finalized #20480 (0xa143…9640), ⬇ 405.2kiB/s ⬆ 22.2kiB/s    
2022-05-24 08:14:03.067  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 0 ⬆ 0    
2022-05-24 08:14:08.051  INFO tokio-runtime-worker substrate: [Relaychain] ⚙️  Syncing 856.8 bps, target=#12816479 (28 peers), best: #25520 (0x311a…0fbf), finalized #25088 (0xbb53…2395), ⬇ 418.9kiB/s ⬆ 27.3kiB/s    
2022-05-24 08:14:08.070  INFO tokio-runtime-worker substrate: [Parachain] 💤 Idle (0 peers), best: #0 (0x1cf1…a1b9), finalized #0 (0x1cf1…a1b9), ⬇ 0 ⬆ 0    
......etc

My parachain version is polkadot-v0.9.19, kusama version is polkadot-0.9.22.

I don't know if this affects the operation of parallel chains.

this is my start command:

./target/release/node \
--collator \
--force-authoring \
--chain ksm-mainnet.json \
--base-path /tmp/parachain--log=info,xcm=trace,xcm-executor=trace \
--port 40336 \
--ws-port 8847 --ws-external --rpc-external --rpc-methods=unsafe --prometheus-port 9779 --prometheus-external \
-- \
--execution wasm \
--chain kusama.json \
--port 30346 \
--ws-port 9980
bkchr commented 2 years ago

CC @drahnr @eskimor I have also seen this and other errors. All of them should be degraded to Debug. Makes no sense to spam the user.

drahnr commented 2 years ago

Triage: Iiuc we see these errors, since the node side assumes the presence of some runtime functions that might not be there during sync, since we have an older runtime ( 6months and older, session_index_for_child and validator_groups were both introduced a while ago ) - but this is something we see on every node syncing with a somewhat old node release.

We should consider making all runtime calls fail silently in case the desired runtime_api fn does not exist.

brunopgalvao commented 2 years ago

I am also seeing this. I am syncing a collator to Polkadot and I was able to see this in my logs. I am able to replicate it with the collator using the following dependencies: polkadot-v0.9.20, polkadot-v0.9.24, and polkadot-v0.9.25.

Here are my logs:

2022-07-22 19:44:18 Parachain Collator Template    
2022-07-22 19:44:18 ✌️  version 0.1.0-a48fc05fce6    
2022-07-22 19:44:18 ❤️  by Anonymous, 2020-2022    
2022-07-22 19:44:18 📋 Chain specification: Local Testnet    
2022-07-22 19:44:18 🏷  Node name: Alice    
2022-07-22 19:44:18 👤 Role: AUTHORITY    
2022-07-22 19:44:18 💾 Database: RocksDb at /tmp/parachain/alice01/chains/local_testnet/db/full    
2022-07-22 19:44:18 ⛓  Native runtime: template-parachain-1 (template-parachain-0.tx1.au1)    
2022-07-22 19:44:20 Parachain id: Id(2055)    
2022-07-22 19:44:20 Parachain Account: 5Ec4AhNnfVGEaNLSMjUb2FqH56XQ2HqUdvNPE17bMknvbf6x    
2022-07-22 19:44:20 Parachain genesis state: 0x000000000000000000000000000000000000000000000000000000000000000000714fdf863cc72e383fb52f28c55e4d70c46fd86c0cbaa124aa0e2f7fe4e8e15503170a2e7597b7b7e3d84c05391d139a62b157e78786d8c082f29dcf4c11131400    
2022-07-22 19:44:20 Is collating: yes    
2022-07-22 19:44:20 [Parachain] 🔨 Initializing Genesis block/state (state: 0x714f…e155, header-hash: 0x5b21…5593)    
2022-07-22 19:44:25 [Relaychain] 🔨 Initializing Genesis block/state (state: 0x29d0…4e17, header-hash: 0x91b1…90c3)    
2022-07-22 19:44:25 [Relaychain] 👴 Loading GRANDPA authority set from genesis on what appears to be first startup.    
2022-07-22 19:44:25 [Relaychain] 👶 Creating empty BABE epoch changes on what appears to be first startup.    
2022-07-22 19:44:25 [Relaychain] 🏷  Local node identity is: 12D3KooWEky53mfJXdBLjWYxi68h4RyaopNLw8Se6Z5qQYFE8cDa    
2022-07-22 19:44:25 [Relaychain] 💻 Operating system: macos    
2022-07-22 19:44:25 [Relaychain] 💻 CPU architecture: aarch64    
2022-07-22 19:44:25 [Relaychain] 📦 Highest known block at #0    
2022-07-22 19:44:25 [Relaychain] 〽️ Prometheus exporter started at 127.0.0.1:9616    
2022-07-22 19:44:25 [Relaychain] Running JSON-RPC HTTP server: addr=127.0.0.1:9934, allowed origins=Some(["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"])    
2022-07-22 19:44:25 [Relaychain] Running JSON-RPC WS server: addr=127.0.0.1:9977, allowed origins=Some(["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"])    
2022-07-22 19:44:25 [Relaychain] 🏁 CPU score: 970MB/s    
2022-07-22 19:44:25 [Relaychain] 🏁 Memory score: 37808MB/s    
2022-07-22 19:44:25 [Relaychain] 🏁 Disk score (seq. writes): 1395MB/s    
2022-07-22 19:44:25 [Relaychain] 🏁 Disk score (rand. writes): 377MB/s    
2022-07-22 19:44:25 [Relaychain] creating instance on iface 192.168.4.49    
2022-07-22 19:44:25 [Parachain] 🏷  Local node identity is: 12D3KooWSzrn9KpJorvytUpF1eqGeTegGWkYYaHdzWpAUSNoqXdR    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip4/192.168.4.49/tcp/30353/ws    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip4/127.0.0.1/tcp/30353/ws    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip6/::1/tcp/30353/ws    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip4/192.168.4.49/tcp/40343    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip4/127.0.0.1/tcp/40343    
2022-07-22 19:44:25 [Relaychain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip6/::1/tcp/40343    
2022-07-22 19:44:25 [Parachain] 💻 Operating system: macos    
2022-07-22 19:44:25 [Parachain] 💻 CPU architecture: aarch64    
2022-07-22 19:44:25 [Parachain] 📦 Highest known block at #0    
2022-07-22 19:44:25 [Parachain] 〽️ Prometheus exporter started at 127.0.0.1:9615    
2022-07-22 19:44:25 [Relaychain] error=RollingSessionWindow(SessionsUnavailable { kind: RuntimeApi(Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }), info: None })
2022-07-22 19:44:25 [Parachain] Running JSON-RPC HTTP server: addr=127.0.0.1:9933, allowed origins=Some(["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"])    
2022-07-22 19:44:25 [Parachain] Running JSON-RPC WS server: addr=127.0.0.1:8844, allowed origins=Some(["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"])    
2022-07-22 19:44:25 [Parachain] 🏁 CPU score: 970MB/s    
2022-07-22 19:44:25 [Parachain] 🏁 Memory score: 37808MB/s    
2022-07-22 19:44:25 [Parachain] 🏁 Disk score (seq. writes): 1395MB/s    
2022-07-22 19:44:25 [Parachain] 🏁 Disk score (rand. writes): 377MB/s    
2022-07-22 19:44:25 [Parachain] creating instance on iface 192.168.4.49    
2022-07-22 19:44:25 [Relaychain] Failed to fetch basics from runtime API relay_parent=0x91b171bb158e2d3848fa23a9f1c25182fb8e20313b2c1eb49219da7a70ce90c3 err=Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }
2022-07-22 19:44:25 [Relaychain] Our view contains 0x91b1…90c3, but not in active heads added=0x91b1…90c3
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip4/192.168.4.49/tcp/30353/ws    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip4/127.0.0.1/tcp/30353/ws    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWKY271kBZVcYgeaLgpfLi6TUywpXQRFCHuJM4KHFeuy6s /ip6/::1/tcp/30353/ws    
2022-07-22 19:44:26 [Relaychain] discovered: 12D3KooWSzrn9KpJorvytUpF1eqGeTegGWkYYaHdzWpAUSNoqXdR /ip4/192.168.4.49/tcp/40333    
2022-07-22 19:44:26 [Relaychain] discovered: 12D3KooWSzrn9KpJorvytUpF1eqGeTegGWkYYaHdzWpAUSNoqXdR /ip4/127.0.0.1/tcp/40333    
2022-07-22 19:44:26 [Relaychain] discovered: 12D3KooWSzrn9KpJorvytUpF1eqGeTegGWkYYaHdzWpAUSNoqXdR /ip6/::1/tcp/40333    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWEky53mfJXdBLjWYxi68h4RyaopNLw8Se6Z5qQYFE8cDa /ip4/192.168.4.49/tcp/30343/ws    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWEky53mfJXdBLjWYxi68h4RyaopNLw8Se6Z5qQYFE8cDa /ip4/127.0.0.1/tcp/30343/ws    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWEky53mfJXdBLjWYxi68h4RyaopNLw8Se6Z5qQYFE8cDa /ip6/::1/tcp/30343/ws    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip4/192.168.4.49/tcp/40343    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip4/127.0.0.1/tcp/40343    
2022-07-22 19:44:26 [Parachain] discovered: 12D3KooWGsMiUpRPgsEmkM4MjEDcJpmssN8YnQNQ6mjH5mgLjR1s /ip6/::1/tcp/40343    
2022-07-22 19:44:26 [Relaychain] Failed to fetch runtime API data for job err=Execution { runtime_api_name: "validator_groups", source: Application(Execution(Other("Exported method ParachainHost_validator_groups is not found"))) }
2022-07-22 19:44:26 [Relaychain] error=Sender(Runtime(RuntimeRequest(Execution { runtime_api_name: "session_index_for_child", source: Application(Execution(Other("Exported method ParachainHost_session_index_for_child is not found"))) }))) ctx="on FromOrchestra"
2022-07-22 19:44:26 [Relaychain] 🔍 Discovered new external address for our node: /ip4/107.3.36.203/tcp/30343/ws/p2p/12D3KooWEky53mfJXdBLjWYxi68h4RyaopNLw8Se6Z5qQYFE8cDa    
2022-07-22 19:44:27 [Relaychain] Received msg before first active leaves update. This is not expected - message will be dropped. msg=ActiveDisputes(Sender { complete: false })
2022-07-22 19:44:27 [Relaychain] error=Sender(AskActiveDisputesCanceled) ctx="on FromOrchestra"
2022-07-22 19:44:30 [Relaychain] ⚙️  Syncing, target=#11280144 (16 peers), best: #4522 (0x2b24…1cbf), finalized #4096 (0x13e9…9e70), ⬇ 636.4kiB/s ⬆ 43.5kiB/s    
2022-07-22 19:44:30 [Parachain] 💤 Idle (0 peers), best: #0 (0x5b21…5593), finalized #0 (0x5b21…5593), ⬇ 0.3kiB/s ⬆ 0.3kiB/s