Official PLEX app on SCALE crash, but not crashed? Not Found by devices and no web UI mid stream.

asdpyro

Cadet
Joined
May 26, 2022
Messages
5
TrueNAS-22.02.4-MASTER-20220805-041141
PLEX app Version: 1.28.0.5999_1.7.16
Server Hardware in Signature

Mid stream while watching a show the stream ended with the error "connection to server not fast enough" shown on the client. I'm hard-wired to all my devices and hadn't had this issue before. I backed out and tried starting it again and was prompted with "server unavailable". I popped open a browser and went to the PLEX web address and got a browser error of "ERR_EMPTY_RESPONSE".

Opened up TrueNAS Scale interface and saw that PLEX was running, checked the PLEX pod logs and they looked as usual. Tried accessing the web browser via the button in the apps interface to the same "ERR_EMPTY_RESPONSE" error.
Stopped and restarted the pod. Same result.
Reboot entire server. Same result.
Attempt roll-back of PLEX app. Same result.
Updated back to current PLEX app. Same result.

Basically I tried everything I could think of that was simple other than deleting and re-installing the PLEX app.

2022-08-09 21:52:04
Startup probe failed:
2022-08-09 21:51:53
Started container plex
2022-08-09 21:51:53
Created container plex
2022-08-09 21:51:53
Container image "plexinc/pms-docker:plexpass" already present on machine
2022-08-09 21:51:53
Add eth0 [172.16.0.46/16] from ix-net

Successfully assigned ix-server-plex/server-plex-8458f9cf9c-k49mb to ix-truenas
2022-08-09 21:50:37
Stopping container plex
2022-08-09 21:50:36
Started container plex
2022-08-09 21:50:34
Created container plex
2022-08-09 21:50:34
Container image "plexinc/pms-docker:plexpass" already present on machine
2022-08-09 21:50:21
network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:docker: network plugin is not ready: cni config uninitialized
2022-08-09 21:50:31
Marking for deletion Pod ix-server-plex/server-plex-8458f9cf9c-wc5wk
2022-08-09 21:50:31
Cancelling deletion of Pod ix-server-plex/server-plex-8458f9cf9c-wc5wk
2022-08-09 21:50:34
Add eth0 [172.16.0.18/16] from ix-net
2022-08-09 21:50:31
Created pod: server-plex-8458f9cf9c-k49mb

0/1 nodes are available: 1 node(s) had taint {ix-svc-start: }, that the pod didn't tolerate.
2022-08-09 21:42:24
Failed to create pod sandbox: rpc error: code = Unknown desc = failed to create a sandbox for pod "server-plex-8458f9cf9c-wc5wk": operation timeout: context deadline exceeded
2022-08-09 21:40:22
Created pod: server-plex-8458f9cf9c-wc5wk

Successfully assigned ix-server-plex/server-plex-8458f9cf9c-wc5wk to ix-truenas
2022-08-09 21:40:21
Scaled up replica set server-plex-8458f9cf9c to 1
2022-08-09 21:35:16
Stopping container plex
2022-08-09 21:39:16
error killing pod: [failed to "KillContainer" for "plex" with KillContainerError: "rpc error: code = Unknown desc = operation timeout: context deadline exceeded", failed to "KillPodSandbox" for "435aeaf4-18d2-423d-b259-275c992aa9c6" with KillPodSandboxError: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"]
2022-08-09 21:35:16
Deleted pod: server-plex-557b6886c5-mfmkd
2022-08-09 21:35:14
Scaled down replica set server-plex-557b6886c5 to 0
2022-08-09 21:19:33
Startup probe failed:
2022-08-09 21:19:23
Started container plex
2022-08-09 21:19:23
Created container plex
2022-08-09 21:19:22
Container image "plexinc/pms-docker:plexpass" already present on machine
2022-08-09 21:19:22
Add eth0 [172.16.0.119/16] from ix-net

Successfully assigned ix-server-plex/server-plex-557b6886c5-mfmkd to ix-truenas
2022-08-09 21:18:04
Readiness probe failed:
2022-08-09 21:18:02
Stopping container plex
2022-08-09 21:18:01
Started container plex
2022-08-09 21:17:59
Created container plex
2022-08-09 21:17:56
Container image "plexinc/pms-docker:plexpass" already present on machine
2022-08-09 21:17:54
Pod sandbox changed, it will be killed and re-created.
2022-08-09 21:17:59
Marking for deletion Pod ix-server-plex/server-plex-557b6886c5-9844r
2022-08-09 21:17:59
Cancelling deletion of Pod ix-server-plex/server-plex-557b6886c5-9844r
2022-08-09 21:17:49
network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:docker: network plugin is not ready: cni config uninitialized
2022-08-09 21:17:59
Created pod: server-plex-557b6886c5-mfmkd

0/1 nodes are available: 1 node(s) had taint {ix-svc-start: }, that the pod didn't tolerate.
2022-08-09 21:17:56
Add eth0 [172.16.0.75/16] from ix-net
2022-08-09 21:08:29
Startup probe failed:
2022-08-09 21:08:18
Started container plex
2022-08-09 21:08:18
Created container plex
2022-08-09 21:08:16
Container image "plexinc/pms-docker:plexpass" already present on machine
2022-08-09 21:08:16
Add eth0 [172.16.0.74/16] from ix-net

Successfully assigned ix-server-plex/server-plex-557b6886c5-9844r to ix-truenas
2022-08-09 21:08:13
Created pod: server-plex-557b6886c5-9844r
2022-08-09 21:08:13
Scaled up replica set server-plex-557b6886c5 to 1
2022-08-09 21:07:55
Stopping container plex
2022-08-10 04:51:53.784074+00:00[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
2022-08-10 04:51:53.814848+00:00[s6-init] ensuring user provided files have correct perms...exited 0.
2022-08-10 04:51:53.815779+00:00[fix-attrs.d] applying ownership & permissions fixes...
2022-08-10 04:51:53.816706+00:00[fix-attrs.d] done.
2022-08-10 04:51:53.817378+00:00[cont-init.d] executing container initialization scripts...
2022-08-10 04:51:53.818403+00:00[cont-init.d] 40-plex-first-run: executing...
2022-08-10 04:51:53.851008+00:00Plex Media Server first run setup complete
2022-08-10 04:51:53.851533+00:00[cont-init.d] 40-plex-first-run: exited 0.
2022-08-10 04:51:53.852084+00:00[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: executing...
2022-08-10 04:51:53.855158+00:00[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: exited 0.
2022-08-10 04:51:53.855596+00:00[cont-init.d] 50-plex-update: executing...
2022-08-10 04:51:54.540059+00:00Attempting to upgrade to: 1.28.1.6041-738907df3
2022-08-10 04:51:54.548977+00:00% Total % Received % Xferd Average Speed Time Time Time Current
2022-08-10 04:51:54.549060+00:00Dload Upload Total Spent Left Speed
2022-08-10 04:51:55.203775+00:000 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 190 0 190 0 0 290 0 --:--:-- --:--:-- --:--:-- 290
2022-08-10 04:51:58.334029+00:001 81.3M 1 1582k 0 0 1415k 0 0:00:58 0:00:01 0:00:57 1415k 38 81.3M 38 31.0M 0 0 14.4M 0 0:00:05 0:00:02 0:00:03 28.7M 76 81.3M 76 61.9M 0 0 19.8M 0 0:00:04 0:00:03 0:00:01 30.1M 100 81.3M 100 81.3M 0 0 21.5M 0 0:00:03 0:00:03 --:--:-- 29.9M
2022-08-10 04:51:58.393277+00:00Selecting previously unselected package plexmediaserver.
2022-08-10 04:51:58.453373+00:00(Reading database ... 7274 files and directories currently installed.)
2022-08-10 04:51:58.454147+00:00Preparing to unpack /tmp/plexmediaserver.deb ...
2022-08-10 04:51:58.478051+00:00PlexMediaServer install: Pre-installation Validation.
2022-08-10 04:51:58.494417+00:00PlexMediaServer install: Docker detected. Preinstallation validation not required.
2022-08-10 04:51:58.499880+00:00Unpacking plexmediaserver (1.28.1.6041-738907df3) ...
2022-08-10 04:52:07.046091+00:00Setting up plexmediaserver (1.28.1.6041-738907df3) ...
2022-08-10 04:52:07.056444+00:00PlexMediaServer install: Docker detected. Postinstallation tasks not required. Continuing.
2022-08-10 04:52:07.076906+00:00[cont-init.d] 50-plex-update: exited 0.
2022-08-10 04:52:07.078471+00:00[cont-init.d] done.
2022-08-10 04:52:07.080200+00:00[services.d] starting services
2022-08-10 04:52:07.089775+00:00Starting Plex Media Server.
2022-08-10 04:52:07.091622+00:00[services.d] done.
2022-08-10 04:52:19.959431+00:00Critical: libusb_init failed

Many other apps from TrueCharts and native iX apps still running and accessible as expected after and before each test.

Anyone have any suggestions or thing I can check?
 

asdpyro

Cadet
Joined
May 26, 2022
Messages
5
After a few days I happened to notice that streaming to devices is still working as long as the device already had seen the server in the past. Web interface still unresponsive and new devices don't auto-find the server.
 

homer27081990

Patron
Joined
Aug 9, 2022
Messages
321
Sounds like an IPv6 thing... Do you happen to have DHCPv6-PD on your router set up? Streaming services, witch dabble in UDP heavily usually get thrown out of whack if they are configured for IPv6 and something router-side goes wrong (ie, the occasional prefix change).
 

homer27081990

Patron
Joined
Aug 9, 2022
Messages
321
Just in case, check your boot logs. See if middlewared exited abnormally (or any other USB errors).
 

asdpyro

Cadet
Joined
May 26, 2022
Messages
5
Could you point me to where I could find the boot logs in the debug files? Or any other logs that might be relevant to this issue.

I'm running a pfSense router and hadn't changed any settings in the last year or so. IPv6 is disabled.

No new jails or usb devices in a least a few months.
 

homer27081990

Patron
Joined
Aug 9, 2022
Messages
321
Could you point me to where I could find the boot logs in the debug files? Or any other logs that might be relevant to this issue.

I'm running a pfSense router and hadn't changed any settings in the last year or so. IPv6 is disabled.

No new jails or usb devices in a least a few months.
Boot logs are here. Check PfSense for anything abnormal, I know its far-fetched, but it is good practise to do anyway.
 

Thenand

Cadet
Joined
Apr 14, 2023
Messages
6
Did you ever figure this out? I have this same exact issue. Using this thread I narrowed it down to the kube-bridge port entering blocking state. I disabled IPV6 with sysctl and I also have IPV6 disabled on my PfSense box but it is still happening. The errors below stop because I restarted the app. The libusb_init failed error is a plex error and can be ignored. I am running TrueNAS-SCALE-22.12.1

Code:
root@snorlax:~# dmesg  -T
...
[Thu Apr 13 18:36:37 2023]  ret_from_fork+0x1f/0x30
[Thu Apr 13 18:36:37 2023]  </TASK>
...
[Thu Apr 13 22:06:05 2023] kube-bridge: port 3(veth610878a1) entered disabled state
[Thu Apr 13 22:06:05 2023] device veth610878a1 left promiscuous mode
[Thu Apr 13 22:06:05 2023] kube-bridge: port 3(veth610878a1) entered disabled state
[Thu Apr 13 22:06:27 2023] net_ratelimit: 21 callbacks suppressed
[Thu Apr 13 22:06:27 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:28 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:29 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:29 2023] kube-bridge: port 3(vethb0f743fa) entered blocking state
[Thu Apr 13 22:06:29 2023] kube-bridge: port 3(vethb0f743fa) entered disabled state
[Thu Apr 13 22:06:29 2023] device vethb0f743fa entered promiscuous mode
[Thu Apr 13 22:06:29 2023] kube-bridge: port 3(vethb0f743fa) entered blocking state
[Thu Apr 13 22:06:29 2023] kube-bridge: port 3(vethb0f743fa) entered forwarding state
[Thu Apr 13 22:06:29 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:29 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:32 2023] net_ratelimit: 7 callbacks suppressed
[Thu Apr 13 22:06:32 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:33 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:34 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:34 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:34 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:34 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:35 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:35 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:35 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:36 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:38 2023] net_ratelimit: 1 callbacks suppressed
[Thu Apr 13 22:06:38 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:38 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:39 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:39 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:39 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:39 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:40 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:40 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:40 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:40 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:43 2023] net_ratelimit: 12 callbacks suppressed
[Thu Apr 13 22:06:43 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:43 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:44 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:44 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:44 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:44 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:44 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:45 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:45 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:45 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:50 2023] net_ratelimit: 14 callbacks suppressed
[Thu Apr 13 22:06:50 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:51 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:52 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:52 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:52 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:53 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:53 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:54 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:54 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:54 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] net_ratelimit: 6 callbacks suppressed
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:55 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:56 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:56 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
[Thu Apr 13 22:06:56 2023] IPVS: rr: TCP 192.168.10.10:32400 - no destination available
 
Top