Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sometimes sync from DSN stops making progress #2192

Closed
nazar-pc opened this issue Nov 2, 2023 · 6 comments
Closed

Sometimes sync from DSN stops making progress #2192

nazar-pc opened this issue Nov 2, 2023 · 6 comments
Assignees
@nazar-pc @shamil-gadelshin
Labels
bug Something isn't working networking Subspace networking (DSN) node Node (service library/node app)

Comments

@nazar-pc
Copy link
Member

nazar-pc commented Nov 2, 2023 •
edited

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 <https://subspace.network>, 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 nazar-pc added bug Something isn't working networking Subspace networking (DSN) labels Nov 2, 2023
@nazar-pc nazar-pc added the node Node (service library/node app) label Nov 2, 2023
@nazar-pc
Copy link
Member Author

nazar-pc commented Nov 6, 2023

@shamil-gadelshin any updates here?

@nazar-pc nazar-pc mentioned this issue Nov 10, 2023
Merged
1 task
@erdnapa
Copy link

erdnapa commented Nov 18, 2023

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
Copy link
Member Author

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

@nazar-pc
Copy link
Member Author

I think #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
Copy link
Member Author

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
Copy link
Member Author

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

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

  • we initiate download of multiple pieces
  • each of the pieces requires search for closest peers that take a long time if peers are unreachable due to errors and timeouts
  • this results in retries that take a long time as well
  • all this multiplied by little to no connected peers, which in turn limits concurrency on requests we're making

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.

@nazar-pc nazar-pc closed this as not planned Won't fix, can't repro, duplicate, stale Nov 22, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nazar-pc nazar-pc

@shamil-gadelshin shamil-gadelshin

Labels
bug Something isn't working networking Subspace networking (DSN) node Node (service library/node app)
Projects
Subspace core (node, farmer, etc.)
Status: Closed
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nazar-pc @shamil-gadelshin @erdnapa