search

autonomys / subspace

Subspace Network reference implementation
https://subspace.network
370 stars 242 forks source link

Sometimes sync from DSN stops making progress #2192

Closed nazar-pc closed 10 months ago

nazar-pc commented 11 months ago

Turns out sometimes DSN sync hangs and stops making any progress:

``` 2023-11-02T04:08:36.496531Z INFO main sc_cli::runner: Subspace 2023-11-02T04:08:36.496671Z INFO main sc_cli::runner: ✌ version 0.1.0-24712853776 2023-11-02T04:08:36.496711Z INFO main sc_cli::runner: ❤ by Subspace Labs , 2021-2023 2023-11-02T04:08:36.496714Z INFO main sc_cli::runner: 📋 Chain specification: Subspace Gemini 3g 2023-11-02T04:08:36.496716Z INFO main sc_cli::runner: 🏷 Node name: anke_subtrx 2023-11-02T04:08:36.496718Z INFO main sc_cli::runner: 👤 Role: AUTHORITY 2023-11-02T04:08:36.496720Z INFO main sc_cli::runner: 💾 Database: ParityDb at /home/bruno/.subspace/chains/subspace_gemini_3g/paritydb/full 2023-11-02T04:08:38.642289Z DEBUG main subspace_service: [Consensus] Setting DSN protocol version... chain_type=Custom("Subspace Gemini 3g") genesis_hash=418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b 2023-11-02T04:08:38.642358Z TRACE main subspace_service::dsn: [Consensus] Subspace networking starting. 2023-11-02T04:08:38.643182Z INFO main subspace_networking::constructor: [Consensus] DSN instance configured. allow_non_global_addresses_in_dht=false peer_id=12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu protocol_version=/subspace/418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b 2023-11-02T04:08:38.643626Z INFO main subspace_service: [Consensus] Subspace networking initialized: Node ID is 12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.643825Z INFO tokio-runtime-worker block_relay: [Consensus] relay::consensus block server: starting 2023-11-02T04:08:38.643919Z INFO main sub-libp2p: [Consensus] 🏷 Local node identity is: 12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.644060Z INFO tokio-runtime-worker subspace_service: [Consensus] DSN listening on /ip4/127.0.0.1/udp/30433/quic-v1/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.644102Z INFO tokio-runtime-worker subspace_service: [Consensus] DSN listening on /ip4/192.168.40.25/udp/30433/quic-v1/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.644137Z INFO tokio-runtime-worker subspace_service: [Consensus] DSN listening on /ip4/127.0.0.1/tcp/30433/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.644144Z INFO tokio-runtime-worker subspace_service: [Consensus] DSN listening on /ip4/192.168.40.25/tcp/30433/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:38.645146Z INFO main subspace: [Consensus] Last archived block 21722 2023-11-02T04:08:38.645174Z INFO main subspace: [Consensus] Archiving already produced blocks 21723..=30322 2023-11-02T04:08:38.694074Z INFO tokio-runtime-worker subspace_networking::node_runner: [Consensus] Added observed address as external: /ip4/a.b.c.d/tcp/30433 2023-11-02T04:08:40.659153Z INFO main subspace: [Consensus] 🧑‍🌾tarting Subspace Authorship worker 2023-11-02T04:08:40.659308Z INFO main subspace_metrics: [Consensus] Metrics server started. endpoints=[127.0.0.1:9615] 2023-11-02T04:08:40.659313Z INFO main actix_server::builder: [Consensus] starting 48 workers 2023-11-02T04:08:40.659371Z INFO tokio-runtime-worker actix_server::server: [Consensus] Tokio runtime found; starting in existing Tokio runtime 2023-11-02T04:08:40.692078Z INFO main sc_sysinfo: [Consensus] 💻 Operating system: linux 2023-11-02T04:08:40.692082Z INFO main sc_sysinfo: [Consensus] 💻 CPU architecture: x86_64 2023-11-02T04:08:40.692084Z INFO main sc_sysinfo: [Consensus] 💻 Target environment: gnu 2023-11-02T04:08:40.692085Z INFO main sc_sysinfo: [Consensus] 💻 CPU: AMD Ryzen Threadripper 3960X 24-Core Processor 2023-11-02T04:08:40.692086Z INFO main sc_sysinfo: [Consensus] 💻 CPU cores: 24 2023-11-02T04:08:40.692087Z INFO main sc_sysinfo: [Consensus] 💻 Memory: 257597MB 2023-11-02T04:08:40.692089Z INFO main sc_sysinfo: [Consensus] 💻 Kernel: 5.15.0-88-generic 2023-11-02T04:08:40.692090Z INFO main sc_sysinfo: [Consensus] 💻 Linux distribution: Ubuntu 22.04.3 LTS 2023-11-02T04:08:40.692091Z INFO main sc_sysinfo: [Consensus] 💻 Virtual machine: no 2023-11-02T04:08:40.692123Z INFO main sc_service::builder: [Consensus] 📦 Highest known block at #30422 2023-11-02T04:08:40.692286Z INFO main sc_rpc_server: [Consensus] Running JSON-RPC server: addr=0.0.0.0:9944, allowed origins=["*"] 2023-11-02T04:08:40.694773Z INFO tokio-runtime-worker libp2p_mdns::behaviour: [Consensus] discovered: 12D3KooWJBAjasBGrnqW12j1AAzDJKKQB9Sztgkpbp3WpAjkrMaz /ip4/192.168.40.130/tcp/31333 2023-11-02T04:08:40.709004Z INFO tokio-runtime-worker subspace_service::sync_from_dsn: [Consensus] Received notification to sync from DSN reason=WentOnlineSubspace 2023-11-02T04:08:40.709039Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Searching for latest segment header last_known_segment_index=1 2023-11-02T04:08:40.709043Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=1 2023-11-02T04:08:41.271809Z INFO tokio-runtime-worker sub-libp2p: [Consensus] 🔍 Discovered new external address for our node: /ip4/a.b.c.d/tcp/30333/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu 2023-11-02T04:08:45.692581Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing, target=#30538 (17 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 64.6kiB/s ⬆ 26.9kiB/s 2023-11-02T04:08:50.692868Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30538 (23 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 27.3kiB/s ⬆ 6.3kiB/s 2023-11-02T04:08:55.693081Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30539 (27 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 45.9kiB/s ⬆ 9.0kiB/s 2023-11-02T04:09:00.693952Z WARN tokio-runtime-worker telemetry: [Consensus] ❌ Error while dialing /dns/telemetry.subspace.network/tcp/443/x-parity-wss/%2Fsubmit%2F: Custom { kind: Other, error: Timeout } 2023-11-02T04:09:00.693993Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30540 (28 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 35.6kiB/s ⬆ 2.6kiB/s 2023-11-02T04:09:05.694144Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30540 (28 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 29.4kiB/s ⬆ 1.1kiB/s 2023-11-02T04:09:10.694302Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30542 (31 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 34.4kiB/s ⬆ 2.0kiB/s 2023-11-02T04:09:15.694495Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30544 (32 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 40.8kiB/s ⬆ 1.7kiB/s 2023-11-02T04:09:20.694697Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30545 (33 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 30.3kiB/s ⬆ 0.8kiB/s 2023-11-02T04:09:25.694880Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30546 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 37.2kiB/s ⬆ 1.3kiB/s 2023-11-02T04:09:30.695059Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30546 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 22.6kiB/s ⬆ 1.4kiB/s 2023-11-02T04:09:35.695213Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30547 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 20.1kiB/s ⬆ 1.6kiB/s 2023-11-02T04:09:40.695359Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30548 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 40.0kiB/s ⬆ 5.5kiB/s 2023-11-02T04:09:45.695509Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30548 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 44.9kiB/s ⬆ 5.3kiB/s 2023-11-02T04:09:50.695644Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30549 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 25.0kiB/s ⬆ 1.9kiB/s 2023-11-02T04:09:55.695799Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30550 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.7kiB/s ⬆ 2.8kiB/s 2023-11-02T04:10:00.695951Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (33 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 50.3kiB/s ⬆ 2.0kiB/s 2023-11-02T04:10:00.862362Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:00.895041Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:00.895070Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, will retry peer_count=0 required_peers=20 retry_attempt=1 2023-11-02T04:10:00.895075Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=2 2023-11-02T04:10:05.696109Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (34 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 41.9kiB/s ⬆ 0.7kiB/s 2023-11-02T04:10:10.696263Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (36 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 35.9kiB/s ⬆ 2.0kiB/s 2023-11-02T04:10:15.696400Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (36 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.1kiB/s ⬆ 1.9kiB/s 2023-11-02T04:10:19.747788Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:19.799591Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:19.799604Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, will retry peer_count=0 required_peers=19 retry_attempt=2 2023-11-02T04:10:19.799609Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=3 2023-11-02T04:10:20.696550Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (37 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 27.9kiB/s ⬆ 1.7kiB/s 2023-11-02T04:10:23.998877Z INFO tokio-runtime-worker subspace_networking::node_runner: [Consensus] Public address status changed. old=Unknown new=Private 2023-11-02T04:10:25.696704Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (38 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 45.1kiB/s ⬆ 1.2kiB/s 2023-11-02T04:10:30.696847Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 31.2kiB/s ⬆ 1.5kiB/s 2023-11-02T04:10:35.696985Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30552 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 57.2kiB/s ⬆ 12.4kiB/s 2023-11-02T04:10:37.236645Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRPZkzGa72gL9y1F42RPKQnNTaMuWXjbUku8X6XynCJbw segment_headers_number=2 2023-11-02T04:10:37.374414Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWE6EfTk6jj8KATQEuHnDQ5Li5DbWhLrvKYqpfKeHmCgyv segment_headers_number=2 2023-11-02T04:10:38.788964Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWHMWxwUgnphqQXPFG7eQBw7o9jssEvLWdWVRHB4qT25Sg segment_headers_number=2 2023-11-02T04:10:38.836234Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:38.864134Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:38.864162Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, will retry peer_count=3 required_peers=18 retry_attempt=3 2023-11-02T04:10:38.864168Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=4 2023-11-02T04:10:40.697143Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30554 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 47.7kiB/s ⬆ 11.1kiB/s 2023-11-02T04:10:45.697312Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30555 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 25.8kiB/s ⬆ 3.3kiB/s 2023-11-02T04:10:50.697465Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30555 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 32.0kiB/s ⬆ 1.7kiB/s 2023-11-02T04:10:55.697600Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30555 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 36.6kiB/s ⬆ 2.3kiB/s 2023-11-02T04:10:57.245334Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWE6EfTk6jj8KATQEuHnDQ5Li5DbWhLrvKYqpfKeHmCgyv segment_headers_number=2 2023-11-02T04:10:57.504736Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRPZkzGa72gL9y1F42RPKQnNTaMuWXjbUku8X6XynCJbw segment_headers_number=2 2023-11-02T04:10:58.069840Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWHMWxwUgnphqQXPFG7eQBw7o9jssEvLWdWVRHB4qT25Sg segment_headers_number=2 2023-11-02T04:10:58.092824Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:58.130049Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:10:58.130081Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, but result is the same as last time, so continue with what we've got peer_count=3 required_peers=17 retry_attempt=4 2023-11-02T04:10:58.130095Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment header matches last known segment header, nothing to download last_known_segment_index=1 2023-11-02T04:10:58.130100Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::import_blocks: [Consensus] Found 0 new segment headers 2023-11-02T04:10:58.130145Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::import_blocks: [Consensus] Processing segment segment_index=1 2023-11-02T04:10:58.130149Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::import_blocks: [Consensus] Checking segment header segment_index=1 last_archived_block_number=21722 last_archived_block_progress=Partial(2161) 2023-11-02T04:10:58.130188Z INFO tokio-runtime-worker subspace_service::sync_from_dsn: [Consensus] Received notification to sync from DSN reason=WentOnlineSubstrate 2023-11-02T04:10:58.130193Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Searching for latest segment header last_known_segment_index=1 2023-11-02T04:10:58.130196Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=1 2023-11-02T04:11:00.697738Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30555 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.1kiB/s ⬆ 1.9kiB/s 2023-11-02T04:11:05.697893Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30556 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.3kiB/s ⬆ 1.7kiB/s 2023-11-02T04:11:10.698057Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30556 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.7kiB/s ⬆ 1.8kiB/s 2023-11-02T04:11:15.698155Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30557 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.5kiB/s ⬆ 1.2kiB/s 2023-11-02T04:11:20.447905Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:11:20.698384Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30557 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 23.0kiB/s ⬆ 2.0kiB/s 2023-11-02T04:11:23.772326Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWBf16qkGKX2SWB5xSp8weVnsTFQ1poFMZtpW2S6d3daos segment_headers_number=2 2023-11-02T04:11:24.083147Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWKVUiJ6qjeAq9wocXiZ8VRraDs9v8vydwRCGUGKfGbmD7 segment_headers_number=2 2023-11-02T04:11:24.139936Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:11:24.444067Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRKjEKSEGHybR3GE2J6ecH2iqESiMt5QhyGwE9bomeT5z segment_headers_number=2 2023-11-02T04:11:25.040745Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWED1Bat2xbJZnmm5PoUN4puJiBf4B6K4sEp5NuxGtukcc error=ProtocolFailure(Network(ConnectionClosed)) 2023-11-02T04:11:25.124070Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWE6EfTk6jj8KATQEuHnDQ5Li5DbWhLrvKYqpfKeHmCgyv segment_headers_number=2 2023-11-02T04:11:25.413537Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRPZkzGa72gL9y1F42RPKQnNTaMuWXjbUku8X6XynCJbw segment_headers_number=2 2023-11-02T04:11:25.698568Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30557 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 24.6kiB/s ⬆ 2.0kiB/s 2023-11-02T04:11:30.698686Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30558 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 42.4kiB/s ⬆ 1.7kiB/s 2023-11-02T04:11:32.722219Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWHMWxwUgnphqQXPFG7eQBw7o9jssEvLWdWVRHB4qT25Sg segment_headers_number=2 2023-11-02T04:11:32.722246Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, will retry peer_count=6 required_peers=20 retry_attempt=1 2023-11-02T04:11:32.722250Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=2 2023-11-02T04:11:35.698938Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30558 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 29.0kiB/s ⬆ 1.8kiB/s 2023-11-02T04:11:40.700014Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30560 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 38.6kiB/s ⬆ 2.0kiB/s 2023-11-02T04:11:45.700159Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30560 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 19.5kiB/s ⬆ 1.9kiB/s 2023-11-02T04:11:48.978948Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWCUUWEBe1bWUXhcjarYgNh7LvCHmmxSFfFkXuzRGDEpMW segment_headers_number=2 2023-11-02T04:11:49.546150Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWHMWxwUgnphqQXPFG7eQBw7o9jssEvLWdWVRHB4qT25Sg segment_headers_number=2 2023-11-02T04:11:49.816929Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRPZkzGa72gL9y1F42RPKQnNTaMuWXjbUku8X6XynCJbw segment_headers_number=2 2023-11-02T04:11:50.143274Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWE6EfTk6jj8KATQEuHnDQ5Li5DbWhLrvKYqpfKeHmCgyv segment_headers_number=2 2023-11-02T04:11:50.452546Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWRKjEKSEGHybR3GE2J6ecH2iqESiMt5QhyGwE9bomeT5z segment_headers_number=2 2023-11-02T04:11:50.478134Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWPTtJXa8Pfx9NfTxQdLoatVGyidybfg5t3ASmD1F1aMzF error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:11:50.700382Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30561 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 29.1kiB/s ⬆ 4.4kiB/s 2023-11-02T04:11:50.749633Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWKVUiJ6qjeAq9wocXiZ8VRraDs9v8vydwRCGUGKfGbmD7 segment_headers_number=2 2023-11-02T04:11:54.794463Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request succeeded peer_id=12D3KooWBf16qkGKX2SWB5xSp8weVnsTFQ1poFMZtpW2S6d3daos segment_headers_number=2 2023-11-02T04:11:54.816700Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Last segment headers request failed peer_id=12D3KooWQkJUqsc27Vx8Hvc9nSQzv2DezPxFKtozNKz61mVrB7f8 error=ProtocolFailure(Network(UnsupportedProtocols)) 2023-11-02T04:11:54.816717Z DEBUG tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Segment headers consensus requires more peers, will retry peer_count=7 required_peers=19 retry_attempt=2 2023-11-02T04:11:54.816723Z TRACE tokio-runtime-worker subspace_service::sync_from_dsn::segment_header_downloader: [Consensus] Downloading last segment headers retry_attempt=3 2023-11-02T04:11:55.700527Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30561 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.3kiB/s ⬆ 3.2kiB/s 2023-11-02T04:11:57.747348Z INFO tokio-runtime-worker subspace_networking::node_runner: [Consensus] Public address status changed. old=Private new=Public("/ip4/a.b.c.d/udp/30433/quic-v1/p2p/12D3KooWCFpVKxgiuHxW4MyX1Rw3Fg7J678oHAm86v6NtQ99DvUu") 2023-11-02T04:12:00.700643Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30564 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 30.4kiB/s ⬆ 2.0kiB/s 2023-11-02T04:12:05.700783Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30566 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.8kiB/s ⬆ 1.2kiB/s 2023-11-02T04:12:10.700913Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30566 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 37.5kiB/s ⬆ 1.1kiB/s 2023-11-02T04:12:15.701104Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30568 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 34.0kiB/s ⬆ 1.6kiB/s 2023-11-02T04:12:20.701268Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30570 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 32.4kiB/s ⬆ 2.3kiB/s 2023-11-02T04:12:25.701432Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30570 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 30.4kiB/s ⬆ 2.2kiB/s 2023-11-02T04:12:30.701649Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30571 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 41.7kiB/s ⬆ 1.5kiB/s 2023-11-02T04:12:35.701812Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30572 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 34.2kiB/s ⬆ 1.0kiB/s 2023-11-02T04:12:40.701970Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30575 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 41.6kiB/s ⬆ 2.6kiB/s 2023-11-02T04:12:45.702155Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30575 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.4kiB/s ⬆ 2.4kiB/s 2023-11-02T04:12:50.702449Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30577 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 32.8kiB/s ⬆ 2.5kiB/s 2023-11-02T04:12:55.702621Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30577 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 42.9kiB/s ⬆ 2.4kiB/s 2023-11-02T04:13:00.702829Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30578 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 33.1kiB/s ⬆ 2.8kiB/s 2023-11-02T04:13:05.703142Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30580 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 40.5kiB/s ⬆ 1.7kiB/s 2023-11-02T04:13:10.703343Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30581 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 32.9kiB/s ⬆ 1.3kiB/s 2023-11-02T04:13:15.703487Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30582 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 36.2kiB/s ⬆ 1.1kiB/s 2023-11-02T04:13:20.703630Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30583 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.2kiB/s ⬆ 1.1kiB/s 2023-11-02T04:13:25.703774Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30584 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 28.2kiB/s ⬆ 1.4kiB/s 2023-11-02T04:13:30.703881Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30585 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 31.5kiB/s ⬆ 1.5kiB/s 2023-11-02T04:13:35.704047Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30585 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 31.4kiB/s ⬆ 2.2kiB/s 2023-11-02T04:13:40.704201Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30586 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 34.0kiB/s ⬆ 2.2kiB/s 2023-11-02T04:13:45.704432Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30586 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 49.4kiB/s ⬆ 9.4kiB/s 2023-11-02T04:13:50.704588Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30587 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 44.7kiB/s ⬆ 3.0kiB/s 2023-11-02T04:13:55.704781Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30587 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 34.0kiB/s ⬆ 3.2kiB/s 2023-11-02T04:14:00.705001Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30589 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 35.2kiB/s ⬆ 2.6kiB/s 2023-11-02T04:14:05.705380Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30589 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 44.9kiB/s ⬆ 3.1kiB/s 2023-11-02T04:14:10.705504Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30590 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 41.6kiB/s ⬆ 3.1kiB/s 2023-11-02T04:14:15.705679Z INFO tokio-runtime-worker substrate: [Consensus] ⚙ Syncing 0.0 bps, target=#30590 (40 peers), best: #30422 (0xfc23…0538), finalized #0 (0x4180…180b), ⬇ 41.7kiB/s ⬆ 1.3kiB/s ```

To me this looks like a deadlock somewhere in the networking stack that prevents sync from making progress.

The next step after "Downloading last segment headers" is to get closest peers to a random key and send SegmentHeaderRequest::LastSegmentHeaders request. Not sure if get_closest_peers doesn't resolve or send_generic_request hangs, but we do not get response to the request in the end.

Forum thread: https://forum.subspace.network/t/gemini-3g-nodes-not-syncing-on-linux/2090

nazar-pc commented 10 months ago

@shamil-gadelshin any updates here?

erdnapa commented 10 months ago

I had the sync issue again on one node with Nov-17. I did run the debug again, and it synced. Full log until sync at https://pastebin.com/zuMUEWb0 (will self destruct in 4 weeks) To me it seems it tries the same two non-responding nodes over and over.

nazar-pc commented 10 months ago

According to logs you have synced successfully, so this is not the same issue

nazar-pc commented 10 months ago

I think https://github.com/subspace/subspace/issues/2237 is related to this one too. It appears that not having (enough?) connections just prevents it from making any progress at all even though I don't think we have infinite number of retries (or maybe we do due to a bug somewhere?).

nazar-pc commented 10 months ago

Users in Discord report that latest release that fixed QUIC address translation now prints errors during piece retrieval, which further indicates that networking issues result in requests being stuck, in this case I guess piece retrieval specifically, but probably others.

nazar-pc commented 10 months ago

I'm concluding that while unfortunate, this works as expected.

Essentially with both node sync from DSN and piece cache sync the following happens:

So all of the above means that the progress is being made, but extremely slowly. And without backpressure in libp2p we can't really push it further or put additional timeout externally because internally queries/requests will continue progressing.

I'm closing this for now, but it doesn't mean we will not be making improvements that will indirectly help here.