joystream-node: Investigate why Syncing hangs #2999

traumschule · 2022-01-09T15:47:21Z

As you can read in the #validators channel many operators have this issue at least once during a full sync run:

Jan 09 15:24:35 host joystream-node[479138]: Jan 09 15:24:35.432  INFO ⚙️  Syncing  0.0 bps, target=#3951362 (55 peers), best: #3743339 (0xc4a9…85aa), finalized #3743232 (0x44db…ab21), ⬇ 17.2kiB/s ⬆ 4.3kiB/s

From my memory this did not happen / much less on the Babylon testnet.

┆Issue is synchronized with this Asana task by Unito

The text was updated successfully, but these errors were encountered:

mnaamani · 2022-01-10T08:54:25Z

Could you perhaps share a few additional logs lines before the one above. Do you see any "Invalid justification provided" messages?

If you were to restart the node does log output reach line:

👶 Starting BABE Authorship worker

And at this point you see high CPU usage?

I have experienced this on some validators. If you leave it running for some time it will eventually come back to life. I suspect it is scanning the database for integrity.

In the case of this node it took approx 5h..

Jan 03 14:32:12 localhost joystream-node[608]: Jan 03 14:32:12.726 INFO 👶 Starting BABE Authorship worker
Jan 03 19:48:23 localhost joystream-node[608]: Jan 03 19:48:23.886 INFO 💤 Idle (0 peers), best: #3865501 (0x1eae…4418), finalized #3765457 (0x04ab…3dbd), ⬇ 0 ⬆ 0
Jan 03 19:48:24 localhost joystream-node[608]: Jan 03 19:48:24.334 INFO 🔍 Discovered new external address for our node: /ip4/109.74.197.139/tcp/30333/p2p/12D3KooWSjh3tdH36932YmMozBxb4cuPmWaT1vThwpxgXPRvbLLu
Jan 03 19:48:24 localhost joystream-node[608]: Jan 03 19:48:24.405 INFO 🔍 Discovered new external address for our node: /dns4/rome-node-2.joystream.org/tcp/30333/p2p/12D3KooWSjh3tdH36932YmMozBxb4cuPmWaT1vThw>
Jan 03 19:48:24 localhost joystream-node[608]: Jan 03 19:48:24.629 INFO 🔍 Discovered new external address for our node: /ip6/2a01:7e00::f03c:92ff:fe1d:508e/tcp/30333/p2p/12D3KooWSjh3tdH36932YmMozBxb4cuPmWaT1>
Jan 03 19:48:25 localhost joystream-node[608]: Jan 03 19:48:25.010 TRACE execute_block: Batch-verification: 0 pending tasks, 0 sr25519 signatures {block}
Jan 03 19:48:25 localhost joystream-node[608]: Jan 03 19:48:25.010 TRACE execute_block: Finalization of batch verification took 0 ms {block}
Jan 03 19:48:25 localhost joystream-node[608]: Jan 03 19:48:25.353 TRACE execute_block: Batch-verification: 0 pending tasks, 0 sr25519 signatures {block}

This behavior is of course a little buggy and we know that the current version of substrate we are using for the testnet is a bit outdated and there have been some bugs related to syncing fixes in newer version. such as paritytech/substrate#8698

traumschule · 2022-01-10T22:24:14Z

Checked logs of recently synced endpoints and found two nodes with occasional zero syncs and one that got stuck. From what i saw reasons could be

temporary connection / routing issues
low resource VPS (1 CPU, 2GB RAM) and competing services (cron, snapd)
possibly related?
- WARN Low open file descriptor limit configured for the process. Current value: 8192, recommended value: 10000.
- incoming tcp connections

Do you see any "Invalid justification provided" messages?

Never experiencesd that one.

If you were to restart the node does log output reach line:

👶 Starting BABE Authorship worker

And at this point you see high CPU usage?

This always goes through without issues and syncing picks up immediately after the restart without the need to check CPU usage.

Sorry for the formatting, wish there was a way to log into a separate file with stripped color codes.

stuck

Sync rate suddenly drops to zero, node had to be restarted manually which usualy fixes the issue.

The curious question is why despite non-zero peers the node gets into a state where suddenly no more blocks are imported indefinitely.

Jan  5 16:25:01 frankfurt CRON[527161]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan  5 16:25:02 frankfurt joystream-node[479138]: Jan 05 16:25:02.589  INFO ⚙️  #033[1;37mSyncing  2.3 bps#033[0m, target=#3895069 (#033[1;37m43#033[0m peers), 
best: ##033[1;37m3743066#033[0m (0xab4e…58cc), finalized ##033[1;37m3742973#033[0m (0x4e01…7fc0), #033[32m⬇ 6.7kiB/s#033[0m #033[31m⬆ 99.5kiB/s#033[0m
...
Jan  5 16:25:57 frankfurt joystream-node[479138]: Jan 05 16:25:57.030  INFO ⚙️  #033[1;37mSyncing  2.4 bps#033[0m, target=#3895078 (#033[1;37m42#033[0m peers), 
best: ##033[1;37m3743186#033[0m (0xcb9c…05a9), finalized ##033[1;37m3742973#033[0m (0x4e01…7fc0), #033[32m⬇ 8.4kiB/s#033[0m #033[31m⬆ 89.6kiB/s#033[0m
Jan  5 16:25:59 frankfurt joystream-node[479138]: Jan 05 16:25:59.366  INFO Accepted a new tcp connection from 127.0.0.1:40378.
Jan  5 16:25:59 frankfurt joystream-node[479138]: Jan 05 16:25:59.368  WARN Blocked connection to WebSockets server from untrusted origin: Some("https://joystr
eamstats.live")
Jan  5 16:26:02 frankfurt joystream-node[479138]: Jan 05 16:26:02.668  INFO ⚙️  #033[1;37mSyncing  2.3 bps#033[0m, target=#3895079 (#033[1;37m42#033[0m peers), 
best: ##033[1;37m3743199#033[0m (0x8459…8a39), finalized ##033[1;37m3742973#033[0m (0x4e01…7fc0), #033[32m⬇ 10.2kiB/s#033[0m #033[31m⬆ 101.1kiB/s#033[0m
Jan  5 16:26:07 frankfurt joystream-node[479138]: Jan 05 16:26:07.669  INFO ⚙️  #033[1;37mSyncing  2.6 bps#033[0m, target=#3895080 (#033[1;37m42#033[0m peers), 
best: ##033[1;37m3743212#033[0m (0x6332…d957), finalized ##033[1;37m3742973#033[0m (0x4e01…7fc0), #033[32m⬇ 7.1kiB/s#033[0m #033[31m⬆ 94.2kiB/s#033[0m
Jan  5 16:26:12 frankfurt joystream-node[479138]: Jan 05 16:26:12.669  INFO ⚙️  #033[1;37mSyncing  3.6 bps#033[0m, target=#3895081 (#033[1;37m41#033[0m peers), 
best: ##033[1;37m3743230#033[0m (0x2335…479c), finalized ##033[1;37m3742973#033[0m (0x4e01…7fc0), #033[32m⬇ 8.4kiB/s#033[0m #033[31m⬆ 20.0kiB/s#033[0m
Jan  5 16:26:17 frankfurt joystream-node[479138]: Jan 05 16:26:17.670  INFO ⚙️  #033[1;37mSyncing  4.3 bps#033[0m, target=#3895081 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743252#033[0m (0x3f69…89c7), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 9.1kiB/s#033[0m #033[31m⬆ 2.9kiB/s#033[0m
Jan  5 16:26:22 frankfurt joystream-node[479138]: Jan 05 16:26:22.670  INFO ⚙️  #033[1;37mSyncing  3.4 bps#033[0m, target=#3895082 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743269#033[0m (0xb28a…0dcc), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 8.1kiB/s#033[0m #033[31m⬆ 5.6kiB/s#033[0m
Jan  5 16:26:27 frankfurt joystream-node[479138]: Jan 05 16:26:27.670  INFO ⚙️  #033[1;37mSyncing  4.0 bps#033[0m, target=#3895083 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743289#033[0m (0xdd74…cbe4), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 10.0kiB/s#033[0m #033[31m⬆ 4.8kiB/s#033[0m
Jan  5 16:26:32 frankfurt joystream-node[479138]: Jan 05 16:26:32.671  INFO ⚙️  #033[1;37mSyncing  4.4 bps#033[0m, target=#3895084 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743311#033[0m (0x513a…0bb7), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 7.2kiB/s#033[0m #033[31m⬆ 4.3kiB/s#033[0m
Jan  5 16:26:37 frankfurt joystream-node[479138]: Jan 05 16:26:37.671  INFO ⚙️  #033[1;37mSyncing  4.0 bps#033[0m, target=#3895085 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743331#033[0m (0xf574…b978), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 7.5kiB/s#033[0m #033[31m⬆ 5.8kiB/s#033[0m
Jan  5 16:26:42 frankfurt joystream-node[479138]: Jan 05 16:26:42.671  INFO ⚙️  #033[1;37mSyncing  1.6 bps#033[0m, target=#3895086 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 7.5kiB/s#033[0m #033[31m⬆ 5.6kiB/s#033[0m
Jan  5 16:26:47 frankfurt joystream-node[479138]: Jan 05 16:26:47.672  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3895086 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 5.4kiB/s#033[0m #033[31m⬆ 2.3kiB/s#033[0m
Jan  5 16:26:52 frankfurt joystream-node[479138]: Jan 05 16:26:52.673  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3895087 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 6.5kiB/s#033[0m #033[31m⬆ 4.4kiB/s#033[0m
Jan  5 16:26:57 frankfurt joystream-node[479138]: Jan 05 16:26:57.674  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3895088 (#033[1;37m41#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 5.8kiB/s#033[0m #033[31m⬆ 3.5kiB/s#033[0m
... stuck from here
Jan  8 00:00:40 frankfurt systemd[1]: logrotate.service: Succeeded.
Jan  8 00:00:40 frankfurt systemd[1]: Finished Rotate log files.
Jan  8 00:00:40 frankfurt systemd[1]: man-db.service: Succeeded.
Jan  8 00:00:40 frankfurt systemd[1]: Finished Daily man-db regeneration.
Jan  8 00:00:41 frankfurt joystream-node[479138]: Jan 08 00:00:41.195  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3927981 (#033[1;37m55#033[0m peers), 
best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 11.5kiB/s#033[0m #033[31m⬆ 5.5kiB/s#033[0m
...
Jan  9 00:00:35 frankfurt joystream-node[479138]: Jan 09 00:00:35.735  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3942219 (#033[1;37m55#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 12.1kiB/s#033[0m #033[31m⬆ 4.1kiB/s#033[0m
Jan  9 00:00:40 frankfurt systemd[1]: Starting Rotate log files...
Jan  9 00:00:40 frankfurt systemd[1]: Starting Daily man-db regeneration...
--- new log file
Jan  9 00:00:40 frankfurt joystream-node[479138]: Jan 09 00:00:40.869  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3942220 (#033[1;37m56#033[0m peers), 
best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 13.4kiB/s#033[0m #033[31m⬆ 134.8kiB/s#033[0m
Jan  9 00:00:40 frankfurt systemd[1]: logrotate.service: Succeeded.
Jan  9 00:00:40 frankfurt systemd[1]: Finished Rotate log files.
Jan  9 00:00:45 frankfurt joystream-node[479138]: Jan 09 00:00:45.869  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3942221 (#033[1;37m56#033[0m peers), 
best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 24.4kiB/s#033[0m #033[31m⬆ 247.4kiB/s#033[0m
...
Jan  9 00:04:57 frankfurt joystream-node[479138]: Jan 09 00:04:57.321  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3942261 (#033[1;37m56#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 12.7kiB/s#033[0m #033[31m⬆ 183.2kiB/s#033[0m
Jan  9 00:05:01 frankfurt CRON[558064]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan  9 00:05:02 frankfurt joystream-node[479138]: Jan 09 00:05:02.406  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3942261 (#033[1;37m56#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 10.9kiB/s#033[0m #033[31m⬆ 194.9kiB/s#033[0m
...
Jan  9 20:31:03 frankfurt joystream-node[479138]: Jan 09 20:31:03.103  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3954389 (#033[1;37m55#033[0m peers), best: ##033[1;37m3743339#033[0m (0xc4a9…85aa), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 53.4kiB/s#033[0m #033[31m⬆ 14.2kiB/s#033[0m
Jan  9 20:31:07 frankfurt systemd[1]: Stopping Joystream Node...
Jan  9 20:31:08 frankfurt systemd[1]: joystream-node.service: Succeeded.
Jan  9 20:31:08 frankfurt systemd[1]: Stopped Joystream Node.
Jan  9 20:31:08 frankfurt systemd[1]: Started Joystream Node.
Jan  9 20:31:08 frankfurt joystream-node[568460]: Jan 09 20:31:08.420  WARN Low open file descriptor limit configured for the process. Current value: 8192, recommended value: 10000.
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.774  INFO Joystream Node
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.774  INFO ✌️  version 5.1.0-9d9e77751-x86_64-linux-gnu
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO ❤️  by Joystream contributors, 2019-2022
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO 📋 Chain specification: Joystream
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO 🏷  Node name: low-effect-2032
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO 👤 Role: AUTHORITY
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO 💾 Database: RocksDb at /home/joystream/chains/joy_testnet_5/db
Jan  9 20:31:17 frankfurt joystream-node[568460]: Jan 09 20:31:17.775  INFO ⛓  Native runtime: joystream-node-3 (joystream-node-0.tx1.au9)
Jan  9 20:31:18 frankfurt joystream-node[568460]: Jan 09 20:31:18.674  INFO 🏷  Local node identity is: 12D3KooWDc8SzrEsPqsPVgLBqJXGAUoHbrLjEiQWB6LLDEGqGPi4 (legacy representation: 12D3KooWDc8SzrEsPqsPVgLBqJXGAUoHbrLjEiQWB6LLDEGqGPi4)
Jan  9 20:31:18 frankfurt joystream-node[568460]: Jan 09 20:31:18.687  INFO 📦 Highest known block at #3743339
Jan  9 20:31:18 frankfurt joystream-node[568460]: Jan 09 20:31:18.690  INFO 〽️ Prometheus server started at 127.0.0.1:9615
Jan  9 20:31:18 frankfurt joystream-node[568460]: Jan 09 20:31:18.704  INFO Listening for new connections on 127.0.0.1:9944.
Jan  9 20:31:18 frankfurt joystream-node[568460]: Jan 09 20:31:18.713  INFO 👶 Starting BABE Authorship worker
Jan  9 20:31:19 frankfurt joystream-node[568460]: Jan 09 20:31:19.439  INFO 🔍 Discovered new external address for our node: /ip4/51.75.66.98/tcp/30333/p2p/12D3KooWDc8SzrEsPqsPVgLBqJXGAUoHbrLjEiQWB6LLDEGqGPi4
Jan  9 20:31:23 frankfurt joystream-node[568460]: Jan 09 20:31:23.920  INFO ⚙️  #033[1;37mSyncing#033[0m, target=#3954392 (#033[1;37m12#033[0m peers), best: ##033[1;37m3743340#033[0m (0x8591…19c0), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 327.8kiB/s#033[0m #033[31m⬆ 71.1kiB/s#033[0m
Jan  9 20:31:29 frankfurt joystream-node[568460]: Jan 09 20:31:29.517  INFO ⚙️  #033[1;37mSyncing  1.7 bps#033[0m, target=#3954393 (#033[1;37m18#033[0m peers), best: ##033[1;37m3743350#033[0m (0x8bc6…7d6d), finalized ##033[1;37m3743232#033[0m (0x44db…ab21), #033[32m⬇ 82.4kiB/s#033[0m #033[31m⬆ 185.3kiB/s#033[0m

temporary issues

Jan  7 04:01:07 us joystream-node[263852]: Jan 07 04:01:07.496  INFO ⚙️  #033[1;37mSyncing  1.1 bps#033[0m, target=#3916146 (#033[1;37m49#033[0m peers), best: #
#033[1;37m3897393#033[0m (0xe78f…3247), finalized ##033[1;37m3897344#033[0m (0xbbf6…de69), #033[32m⬇ 11.8kiB/s#033[0m #033[31m⬆ 5.7kiB/s#033[0m
Jan  7 04:02:59 us joystream-node[263852]: Jan 07 04:02:59.254 ERROR Handler initialization process is too long with PeerId("12D3KooWSjh3tdH36932YmMozBxb4cuPmWaT1vThwpxgXPRvbLLu")
Jan  7 04:02:59 us joystream-node[263852]: Jan 07 04:02:59.588 ERROR Handler initialization process is too long with PeerId("12D3KooWBs694iyMT6br5DMDLfekRwhYxZdqG75xSAsHpxdetkLW")
Jan  7 04:02:59 us joystream-node[263852]: Jan 07 04:02:59.915 ERROR Handler initialization process is too long with PeerId("12D3KooWPX3batNSMT3WKbjQjDBKX9pRtUukoVh8suvDWYZFfffa")
Jan  7 04:03:06 us joystream-node[263852]: Jan 07 04:03:06.845 ERROR Handler initialization process is too long with PeerId("12D3KooWLJS46a66hjQ9MkeC6uZSH7m2fGfuyK3obSYWQsTC6vry")
Jan  7 04:03:08 us joystream-node[263852]: Jan 07 04:03:08.031 ERROR Handler initialization process is too long with PeerId("12D3KooWE9SYj4aA56agbSoJgAyogEVPKkQ9uAnXJFQdJVw5EKRA")
Jan  7 04:03:10 us joystream-node[263852]: Jan 07 04:03:10.461  WARN Polling the telemetry took more than 200ms
Jan  7 04:03:10 us joystream-node[263852]: Jan 07 04:03:10.914 ERROR Handler initialization process is too long with PeerId("12D3KooWGr6i9oSfPtQgzAoJfqSyuitH6BiaEfy43ZgaGK9KVJHp")
Jan  7 04:03:11 us joystream-node[263852]: Jan 07 04:03:11.411  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3916161 (#033[1;37m6#033[0m peers), best: ##033[1;37m3897397#033[0m (0xab8f…00d0), finalized ##033[1;37m3897344#033[0m (0xbbf6…de69), #033[32m⬇ 3.8kiB/s#033[0m #033[31m⬆ 1.5kiB/s#033[0m

...
Jan  7 04:06:51 us joystream-node[263852]: Jan 07 04:06:51.550  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3916200 (#033[1;37m19#033[0m peers), best: ##033[1;37m3897412#033[0m (0x769c…f288), finalized ##033[1;37m3897344#033[0m (0xbbf6…de69), #033[32m⬇ 6.7kiB/s#033[0m #033[31m⬆ 4.2kiB/s#033[0m
Jan  7 04:07:23 us joystream-node[263852]: Jan 07 04:07:23.773  WARN Libp2p => Failed to get record: Timeout { key: Key(b"\x12 \xb4\rF\xf4374\x8ew5P\x1b\xe6\x88\x80\\@\xa2\xf8\x9fK\xb2n\xf2\xc0HI\xc7\x8e\xaaH}"), records: [], quorum: 1 }
Jan  7 04:07:50 us joystream-node[263852]: Jan 07 04:07:50.473 ERROR Handler initialization process is too long with PeerId("12D3KooWDtwZkvi1LJLWSw3vrF45eiszZaoH2zqW263ioGiBsGAK")
Jan  7 04:07:55 us joystream-node[263852]: Jan 07 04:07:55.799 ERROR Handler initialization process is too long with PeerId("12D3KooWNbwbHufcqQbikYfSAFRgpkVJrogwgKvt3GuephUggujM")
Jan  7 04:08:18 us joystream-node[263852]: Jan 07 04:08:18.587  WARN Polling the telemetry took more than 200ms
Jan  7 04:08:20 us joystream-node[263852]: Jan 07 04:08:20.248 ERROR Handler initialization process is too long with PeerId("12D3KooWDkj4oXSYptELcPD392RmNtQxJTH6KPeMo51s3iYg3qcx")
Jan  7 04:08:42 us joystream-node[263852]: Jan 07 04:08:42.282 ERROR Handler initialization process is too long with PeerId("12D3KooWDcGzws2Nbo3fe6fZujC7QArop6PyBeQVrUCLh4fY9Hb5")
Jan  7 04:09:06 us joystream-node[263852]: Jan 07 04:09:06.557  WARN Polling the telemetry took more than 200ms
Jan  7 04:09:12 us joystream-node[263852]: Jan 07 04:09:12.749  WARN Libp2p => Failed to get record: Timeout { key: Key(b"\x12 &\xac8\x8f\x96\xd6\x03\x8a9\x82\x07\x98N\x8c\xed4GK!<Y \x18\xf7J\xb5\xcae\xc235("), records: [], quorum: 1 }
Jan  7 04:09:13 us joystream-node[263852]: Jan 07 04:09:13.383 ERROR Handler initialization process is too long with PeerId("12D3KooWPhbxsftanD9buzAHhgxJqmNzKcAbdzJW4p8R3zuUNSB6")
Jan  7 04:09:18 us joystream-node[263852]: Jan 07 04:09:18.632 ERROR Handler initialization process is too long with PeerId("12D3KooWDc8SzrEsPqsPVgLBqJXGAUoHbrLjEiQWB6LLDEGqGPi4")
Jan  7 04:09:34 us joystream-node[263852]: Jan 07 04:09:34.739  WARN Polling the telemetry took more than 200ms
Jan  7 04:09:51 us joystream-node[263852]: Jan 07 04:09:51.576  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3916227 (#033[1;37m20#033[0m peers), best: #
...
Jan  5 11:09:36 us joystream-node[263852]: Jan 05 11:09:36.451  INFO ⚙️  #033[1;37mSyncing  5.8 bps#033[0m, target=#3891949 (#033[1;37m16#033[0m peers), best: #
#033[1;37m3394114#033[0m (0x168f…ff6b), finalized ##033[1;37m3394048#033[0m (0x3a97…7c4e), #033[32m⬇ 24 B/s#033[0m #033[31m⬆ 49 B/s#033[0m
Jan  5 11:09:41 us joystream-node[263852]: Jan 05 11:09:41.454  INFO ⚙️  #033[1;37mSyncing  3.9 bps#033[0m, target=#3891951 (#033[1;37m15#033[0m peers), best: #
#033[1;37m3394134#033[0m (0xc706…b1bb), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 13.0kiB/s#033[0m #033[31m⬆ 8.6kiB/s#033[0m
Jan  5 11:09:46 us joystream-node[263852]: Jan 05 11:09:46.454  INFO ⚙️  #033[1;37mSyncing  1.2 bps#033[0m, target=#3891952 (#033[1;37m15#033[0m peers), best: #
#033[1;37m3394140#033[0m (0x3fdf…e81d), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 8.0kiB/s#033[0m #033[31m⬆ 6.3kiB/s#033[0m
Jan  5 11:09:51 us joystream-node[263852]: Jan 05 11:09:51.455  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3891953 (#033[1;37m15#033[0m peers), best: ##033[1;37m3394140#033[0m (0x3fdf…e81d), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 91 B/s#033[0m #033[31m⬆ 33 B/s#033[0m
Jan  5 11:09:56 us joystream-node[263852]: Jan 05 11:09:56.458  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3891954 (#033[1;37m16#033[0m peers), best: ##033[1;37m3394140#033[0m (0x3fdf…e81d), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 126.0kiB/s#033[0m #033[31m⬆ 8.5kiB/s#033[0m
Jan  5 11:10:01 us joystream-node[263852]: Jan 05 11:10:01.459  INFO ⚙️  #033[1;37mSyncing  1.4 bps#033[0m, target=#3891954 (#033[1;37m18#033[0m peers), best: ##033[1;37m3394147#033[0m (0x5878…29de), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 46.6kiB/s#033[0m #033[31m⬆ 10.6kiB/s#033[0m
Jan  5 11:10:03 us joystream-node[263852]: Jan 05 11:10:03.495  WARN ⚠️  Rejected log entry because queue is full for "/dns/telemetry.polkadot.io/tcp/443/x-parity-wss/%2Fsubmit%2F"
(last message repeated 30 times)
Jan  5 11:10:09 us joystream-node[263852]: Jan 05 11:10:09.050  WARN ⚠️  Disconnected from /dns/telemetry.polkadot.io/tcp/443/x-parity-wss/%2Fsubmit%2F: Timeout
Jan  5 11:10:11 us joystream-node[263852]: Jan 05 11:10:11.459  INFO ⚙️  #033[1;37mSyncing  5.0 bps#033[0m, target=#3891955 (#033[1;37m15#033[0m peers), best: ##033[1;37m3394194#033[0m (0x8e82…9956), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 0.1kiB/s#033[0m #033[31m⬆ 0.3kiB/s#033[0m
Jan  5 11:10:16 us joystream-node[263852]: Jan 05 11:10:16.459  INFO ⚙️  #033[1;37mSyncing  4.2 bps#033[0m, target=#3891955 (#033[1;37m16#033[0m peers), best: ##033[1;37m3394215#033[0m (0x78c6…1d85), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 24 B/s#033[0m #033[31m⬆ 99 B/s#033[0m
Jan  5 11:10:21 us joystream-node[263852]: Jan 05 11:10:21.459  INFO ⚙️  #033[1;37mSyncing  5.4 bps#033[0m, target=#3891955 (#033[1;37m15#033[0m peers), best: ##033[1;37m3394242#033[0m (0x6a0b…2562), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 0#033[0m #033[31m⬆ 0#033[0m
Jan  5 11:10:26 us joystream-node[263852]: Jan 05 11:10:26.459  INFO ⚙️  #033[1;37mSyncing  5.0 bps#033[0m, target=#3891959 (#033[1;37m14#033[0m peers), best: ##033[1;37m3394267#033[0m (0xf1dc…4cbb), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 13.1kiB/s#033[0m #033[31m⬆ 8.8kiB/s#033[0m
Jan  5 11:10:31 us joystream-node[263852]: Jan 05 11:10:31.460  INFO ⚙️  #033[1;37mSyncing  2.0 bps#033[0m, target=#3891960 (#033[1;37m17#033[0m peers), best: ##033[1;37m3394277#033[0m (0xc4ff…c434), finalized ##033[1;37m3394120#033[0m (0xd9a7…8da5), #033[32m⬇ 89.3kiB/s#033[0m #033[31m⬆ 13.7kiB/s#033[0m
Jan  5 11:10:31 us joystream-node[263852]: Jan 05 11:10:31.561  WARN ⚠️  Rejected log entry because queue is full for "/dns/telemetry.joystream.org/tcp/443/x-parity-wss/%2Fsubmit%2F"
...
Jan  5 11:33:18 us joystream-node[263852]: Jan 05 11:33:18.301  INFO ⚙️  #033[1;37mSyncing  1.2 bps#033[0m, target=#3892178 (#033[1;37m26#033[0m peers), best: #
#033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 64 B/s#033[0m
Jan  5 11:33:23 us joystream-node[263852]: Jan 05 11:33:23.302  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3892178 (#033[1;37m26#033[0m peers), best: #
#033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 14 B/s#033[0m
Jan  5 11:33:28 us joystream-node[263852]: Jan 05 11:33:28.303  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3892178 (#033[1;37m26#033[0m peers), best: ##033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 0#033[0m
Jan  5 11:33:33 us joystream-node[263852]: Jan 05 11:33:33.305  INFO ⚙️  #033[1;37mSyncing  0.0 bps#033[0m, target=#3892178 (#033[1;37m1#033[0m peers), best: ##033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 77 B/s#033[0m #033[31m⬆ 0.2kiB/s#033[0m
Jan  5 11:33:38 us joystream-node[263852]: Jan 05 11:33:38.306  INFO 💤 #033[1;37mIdle#033[0m (#033[1;37m0#033[0m peers), best: ##033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 0#033[0m
Jan  5 11:33:38 us joystream-node[263852]: Jan 05 11:33:38.719  WARN ❌ Error while dialing /dns/telemetry.polkadot.io/tcp/443/x-parity-wss/%2Fsubmit%2F: Custom { kind: Other, error: Timeout }
Jan  5 11:33:40 us joystream-node[263852]: Jan 05 11:33:40.072  WARN ❌ Error while dialing /dns/telemetry.joystream.org/tcp/443/x-parity-wss/%2Fsubmit%2F: Custom { kind: Other, error: Timeout }
Jan  5 11:33:43 us joystream-node[263852]: Jan 05 11:33:43.307  INFO 💤 #033[1;37mIdle#033[0m (#033[1;37m0#033[0m peers), best: ##033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 0#033[0m
Jan  5 11:33:48 us joystream-node[263852]: Jan 05 11:33:48.308  INFO 💤 #033[1;37mIdle#033[0m (#033[1;37m0#033[0m peers), best: ##033[1;37m3399900#033[0m (0x8ed0…c9af), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 0#033[0m #033[31m⬆ 0#033[0m
Jan  5 11:33:53 us joystream-node[263852]: Jan 05 11:33:53.309  INFO ⚙️  #033[1;37mSyncing  1.7 bps#033[0m, target=#3892188 (#033[1;37m6#033[0m peers), best: ##033[1;37m3399909#033[0m (0x783b…fef8), finalized ##033[1;37m3399680#033[0m (0xc504…a5ed), #033[32m⬇ 106.6kiB/s#033[0m #033[31m⬆ 29.4kiB/s#033[0m

unrelated

Network with single bootnode dies because background compilation delays block production.

Jan 10 02:02:23.078  INFO 💤 Idle (0 peers), best: #1959 (0x30fe…04fd), finalized #1956 (0x1dd0…81d5), ⬇ 0.8kiB/s ⬆ 1.0kiB/s                                   
Jan 10 02:02:24.702  WARN Writing a telemetry log took more than 50ms                                                                                         
Jan 10 02:02:24.719  INFO 🙌 Starting consensus session on top of parent 0x30fe22c3d8d0e9852cffcc6031dc5df3ae80d120554d28e4d2b0ccd551dd04fd                    
Jan 10 02:02:28.578  INFO 💤 Idle (0 peers), best: #1959 (0x30fe…04fd), finalized #1957 (0x03af…f862), ⬇ 0.8kiB/s ⬆ 1.3kiB/s               
Jan 10 02:02:29.343  INFO 🎁 Prepared block for proposing at 1960 [hash: 0xdd8a109cb03188f8a4255f2432bd2983a97514be7d00baead76993e93c78e33e; parent_hash: 0x30f
e…04fd; extrinsics (2): [0xf76c…8200, 0xcc14…2813]]
Jan 10 02:02:29.614  INFO 🔖 Pre-sealed block for proposal at 1960. Hash now 0x4084584a4efe8d45f822a9c04b7b23915d9abff9a2b13b36bdf603fd1e826608, previously 0xdd8a109cb03188f8a4255f2432bd2983a97514be7d00baead76993e93c78e33e.
Jan 10 02:02:31.051  INFO ✨ Imported #1960 (0x4084…6608)
Jan 10 02:02:31.242  INFO 🙌 Starting consensus session on top of parent 0x4084584a4efe8d45f822a9c04b7b23915d9abff9a2b13b36bdf603fd1e826608
Jan 10 02:02:35.800  WARN Writing a telemetry log took more than 50ms
Jan 10 02:02:36.529  INFO ⌛️ Discarding proposal for slot 273630025; block production took too long
Jan 10 02:02:37.047  WARN Writing a telemetry log took more than 50ms
Jan 10 02:02:37.389  WARN Encountered consensus error: ClientImport("Timeout in the Slots proposer")
Jan 10 02:02:41.582  WARN Writing a telemetry log took more than 50ms
Jan 10 02:02:50.976  WARN Polling the telemetry took more than 200ms
Jan 10 02:07:05.899  WARN ⚠️  Disconnected from /dns/telemetry.joystream.org/tcp/443/x-parity-wss/%2Fsubmit%2F: Closed
Jan 10 02:09:35.901  INFO 🎁 Prepared block for proposing at 1961 [hash: 0x513de33bbabe708803d27f0566f05bfa3ebb3a0732cea7f5d2457700fc92760c; parent_hash: 0x4084…6608; extrinsics (1): [0x38a5…3844]] 
Jan 10 02:19:27.960  INFO Accepted a new tcp connection from 127.0.0.1:34338.
Jan 10 02:19:27.996  INFO 🙌 Starting consensus session on top of parent 0x4084584a4efe8d45f822a9c04b7b23915d9abff9a2b13b36bdf603fd1e826608
Jan 10 02:19:28.128  INFO 🎁 Prepared block for proposing at 1961 [hash: 0xe552dc01fd79839ea4e612663afb9d264a9701c4c201bb4b139d1f884989c059; parent_hash: 0x408
4…6608; extrinsics (2): [0x917a…3a2c, 0x60d4…3a83]]                  
Jan 10 02:19:28.131  INFO 🔖 Pre-sealed block for proposal at 1961. Hash now 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221, previously 0xe
552dc01fd79839ea4e612663afb9d264a9701c4c201bb4b139d1f884989c059.     
Jan 10 02:19:28.131  INFO 👶 New epoch 20 launching at block 0xda6a…c221 (block slot 273630194 >= start slot 273630050).
Jan 10 02:19:28.132  INFO 👶 Next epoch starts at slot 273630150     
Jan 10 02:19:28.134  INFO ✨ Imported #1961 (0xda6a…c221)            
Jan 10 02:19:28.174  INFO 💤 Idle (0 peers), best: #1961 (0xda6a…c221), finalized #1958 (0xc29e…a76f), ⬇ 20 B/s ⬆ 18 B/s
Jan 10 02:19:30.019  INFO 🙌 Starting consensus session on top of parent 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221
Jan 10 02:19:30.045  INFO 🎁 Prepared block for proposing at 1962 [hash: 0x34aef3b796f8423cdfc117811a664e8c70d9735de809609d9c6d36662ed2d3f8; parent_hash: 0xda6
a…c221; extrinsics (2): [0x65e5…8498, 0xdafa…7346]]                  
Jan 10 02:19:30.049  INFO 🔖 Pre-sealed block for proposal at 1962. Hash now 0xe2439ad256adccc8cf920bf8e9ea779944fa280fbc30ace6fbbd245bc0b79497, previously 0x3
4aef3b796f8423cdfc117811a664e8c70d9735de809609d9c6d36662ed2d3f8.
Jan 10 02:19:30.050  WARN Error with block built on 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221: ClientImport("Unexpected epoch change")
Jan 10 02:19:33.174  INFO 💤 Idle (0 peers), best: #1961 (0xda6a…c221), finalized #1959 (0x30fe…04fd), ⬇ 2.6kiB/s ⬆ 5.7kiB/s
Jan 10 02:19:30.019  INFO 🙌 Starting consensus session on top of parent 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221                    
Jan 10 02:19:30.045  INFO 🎁 Prepared block for proposing at 1962 [hash: 0x34aef3b796f8423cdfc117811a664e8c70d9735de809609d9c6d36662ed2d3f8; parent_hash: 0xda6
a…c221; extrinsics (2): [0x65e5…8498, 0xdafa…7346]]                                                                                                           
Jan 10 02:19:30.049  INFO 🔖 Pre-sealed block for proposal at 1962. Hash now 0xe2439ad256adccc8cf920bf8e9ea779944fa280fbc30ace6fbbd245bc0b79497, previously 0x3
4aef3b796f8423cdfc117811a664e8c70d9735de809609d9c6d36662ed2d3f8.                                                                                              
Jan 10 02:19:30.050  WARN Error with block built on 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221: ClientImport("Unexpected epoch change")                                                                                                                                                       
Jan 10 02:19:33.174  INFO 💤 Idle (0 peers), best: #1961 (0xda6a…c221), finalized #1959 (0x30fe…04fd), ⬇ 2.6kiB/s ⬆ 5.7kiB/s
--- after restart:
Jan 10 02:26:47.838  INFO 👶 Starting BABE Authorship worker    
Jan 10 02:26:48.207  INFO 🙌 Starting consensus session on top of parent 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221    
Jan 10 02:26:48.779  WARN Timeout fired waiting for transaction pool at block #1961. Proceeding with production.    
Jan 10 02:26:48.798  INFO 🎁 Prepared block for proposing at 1962 [hash: 0xf0cfc5b4a9fbc9de554ecbdee9ccb0f360e7b551bf51c2016a145defa6ef81a2; parent_hash: 0xda6a…c221; extrinsics (2): [0x0c69…dc98, 0xdafa…7346]]    
Jan 10 02:26:48.802  INFO 🔖 Pre-sealed block for proposal at 1962. Hash now 0x2a7a87f3119f7ac75d65d4d4f0e4313620a63594b0c2330b94ba85bf8b4f4446, previously 0xf0cfc5b4a9fbc9de554ecbdee9ccb0f360e7b551bf51c2016a145defa6ef81a2.    
Jan 10 02:26:48.802  WARN Error with block built on 0xda6a5ec6060d60df248690d1d2468c3edc3149add7d11e2bb4a568832e4ec221: ClientImport("Unexpected epoch change")    
Jan 10 02:26:52.839  INFO 💤 Idle (0 peers), best: #1961 (0xda6a…c221), finalized #1959 (0x30fe…04fd), ⬇ 0.8kiB/s ⬆ 1.8kiB/s

bedeho closed this as completed Dec 12, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

joystream-node: Investigate why Syncing hangs #2999

joystream-node: Investigate why Syncing hangs #2999

traumschule commented Jan 9, 2022 •

edited by sync-by-unito bot

Loading

mnaamani commented Jan 10, 2022

traumschule commented Jan 10, 2022

joystream-node: Investigate why Syncing hangs #2999

joystream-node: Investigate why Syncing hangs #2999

Comments

traumschule commented Jan 9, 2022 • edited by sync-by-unito bot Loading

mnaamani commented Jan 10, 2022

traumschule commented Jan 10, 2022

stuck

temporary issues

unrelated

traumschule commented Jan 9, 2022 •

edited by sync-by-unito bot

Loading