Closed traumschule closed 1 year ago
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 https://github.com/paritytech/substrate/pull/8698
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
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.
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
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
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
As you can read in the #validators channel many operators have this issue at least once during a full sync run:
From my memory this did not happen / much less on the Babylon testnet.
┆Issue is synchronized with this Asana task by Unito