1.23.2.4656 update makes PMS inaccessible until restart

Plex Media Server NAS & Devices
1

Server Version#: 1.23.2.4656
Player Version#: N/A

I’m using GitHub - mrworf/plexupdate: Plex Update script to simplify the life of Linux Plex Media Server users. to auto-update two PMS servers. Both are Debian 10 boxes. One in a custom-made box with an ASRock board and another in an Intel NUC 10.

Both were updated today but the PMS in the Intel NUC 10 was inaccessible afterwards. I checked the service and it was up and running. I then checked /var/log/syslog and here’s what a snippet of what I saw during the update process:

Jun 6 06:25:01 nuc CRON[24267]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Jun 6 06:25:01 nuc cracklib: no dictionary update necessary.
Jun 6 06:25:03 nuc plexupdate: Retrieving list of available distributions
Jun 6 06:25:04 nuc plexupdate: Downloading release “plexmediaserver_1.23.2.4656-85f0adf5b_amd64.deb”
Jun 6 06:25:06 nuc plexupdate: File downloaded
Jun 6 06:25:07 nuc plexupdate: (Reading database … 80882 files and directories currently installed.)
Jun 6 06:25:07 nuc plexupdate: Preparing to unpack …/plexmediaserver_1.23.2.4656-85f0adf5b_amd64.deb …
Jun 6 06:25:07 nuc systemd[1]: Stopping Plex Media Server…
Jun 6 06:25:07 nuc systemd[1]: plexmediaserver.service: Succeeded.
Jun 6 06:25:07 nuc systemd[1]: Stopped Plex Media Server.
Jun 6 06:25:07 nuc plexupdate: PlexMediaServer install: Pre-installation Validation.
Jun 6 06:25:07 nuc root: PlexMediaServer install: Pre-installation Validation.
Jun 6 06:25:07 nuc plexupdate: PlexMediaServer install: Pre-installation Validation complete.
Jun 6 06:25:07 nuc logger[24657]: PlexMediaServer install: Pre-installation Validation complete.
Jun 6 06:25:07 nuc plexupdate: Unpacking plexmediaserver (1.23.2.4656-85f0adf5b) over (1.23.2.4625-a83d2d0f9) …
Jun 6 06:25:12 nuc plexupdate: Setting up plexmediaserver (1.23.2.4656-85f0adf5b) …
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: PlexMediaServer-1.23.2.4656-85f0adf5b - Installation starting.
Jun 6 06:25:12 nuc logger[24841]: PlexMediaServer install: PlexMediaServer-1.23.2.4656-85f0adf5b - Installation starting.
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install:
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Now installing based on:
Jun 6 06:25:12 nuc logger[24843]: PlexMediaServer install: Now installing based on:
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Installation Type: Update
Jun 6 06:25:12 nuc logger[24850]: PlexMediaServer install: Installation Type: Update
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Process Control: systemd
Jun 6 06:25:12 nuc logger[24852]: PlexMediaServer install: Process Control: systemd
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Plex User: plex
Jun 6 06:25:12 nuc logger[24854]: PlexMediaServer install: Plex User: plex
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Plex Group: plex
Jun 6 06:25:12 nuc logger[24856]: PlexMediaServer install: Plex Group: plex
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Video Group: render
Jun 6 06:25:12 nuc logger[24858]: PlexMediaServer install: Video Group: render
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Metadata Dir: /home/plex/Library/Application Support
Jun 6 06:25:12 nuc logger[24860]: PlexMediaServer install: Metadata Dir: /home/plex/Library/Application Support
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Temp Directory: /home/plex/Transcode
Jun 6 06:25:12 nuc logger[24862]: PlexMediaServer install: Temp Directory: /home/plex/Transcode
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Lang Encoding: en_US.UTF-8
Jun 6 06:25:12 nuc logger[24864]: PlexMediaServer install: Lang Encoding: en_US.UTF-8
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Config file used: /etc/systemd/system/plexmediaserver.service.d/override.conf
Jun 6 06:25:12 nuc logger[24876]: PlexMediaServer install: Config file used: /etc/systemd/system/plexmediaserver.service.d/override.conf
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel i915 Hardware: Found
Jun 6 06:25:12 nuc logger[24878]: PlexMediaServer install: Intel i915 Hardware: Found
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Nvidia GPU card: Not Found
Jun 6 06:25:12 nuc logger[24880]: PlexMediaServer install: Nvidia GPU card: Not Found
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install:
Jun 6 06:25:12 nuc logger[24882]: PlexMediaServer install:
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: OpenCL: Installed
Jun 6 06:25:12 nuc logger[24884]: PlexMediaServer install: OpenCL: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel Gmmlib: Installed
Jun 6 06:25:12 nuc logger[24886]: PlexMediaServer install: Intel Gmmlib: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel IGC Core: Installed
Jun 6 06:25:12 nuc logger[24888]: PlexMediaServer install: Intel IGC Core: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel IGC OpenCL: Installed
Jun 6 06:25:12 nuc logger[24890]: PlexMediaServer install: Intel IGC OpenCL: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel OpenCL: Installed
Jun 6 06:25:12 nuc logger[24892]: PlexMediaServer install: Intel OpenCL: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel OCLoc: Installed
Jun 6 06:25:12 nuc logger[24894]: PlexMediaServer install: Intel OCLoc: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Intel Zero GPU: Installed
Jun 6 06:25:12 nuc logger[24896]: PlexMediaServer install: Intel Zero GPU: Installed
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install:
Jun 6 06:25:12 nuc logger[24898]: PlexMediaServer install:
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Completing final configuration.
Jun 6 06:25:12 nuc logger[24900]: PlexMediaServer install: Completing final configuration.
Jun 6 06:25:12 nuc systemd[1]: Reloading.
Jun 6 06:25:12 nuc systemd-udevd[24937]: Using default interface naming scheme ‘v240’.
Jun 6 06:25:12 nuc systemd-udevd[24951]: Using default interface naming scheme ‘v240’.
Jun 6 06:25:12 nuc systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.
Jun 6 06:25:12 nuc systemd[1]: /etc/systemd/system/plexmediaserver.service.d/override.conf:4: Failed to parse mode value, ignoring: 0002 # this must be octal - See warning below
Jun 6 06:25:12 nuc systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.
Jun 6 06:25:12 nuc systemd[1]: /lib/systemd/system/rpc-statd.service:13: PIDFile= references path below legacy directory /var/run/, updating /var/run/rpc.statd.pid → /run/rpc.statd.pid; please update the unit file accordingly.
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: Starting Plex Media Server.
Jun 6 06:25:12 nuc logger[25029]: PlexMediaServer install: Starting Plex Media Server.
Jun 6 06:25:12 nuc systemd[1]: Starting Plex Media Server…
Jun 6 06:25:12 nuc systemd[1]: Started Plex Media Server.
Jun 6 06:25:12 nuc plexupdate: PlexMediaServer install: PlexMediaServer-1.23.2.4656-85f0adf5b - Installation successful. Errors: 0, Warnings: 0
Jun 6 06:25:12 nuc logger[25047]: PlexMediaServer install: PlexMediaServer-1.23.2.4656-85f0adf5b - Installation successful. Errors: 0, Warnings: 0
Jun 6 06:25:12 nuc plexupdate: Processing triggers for mime-support (3.62) …

So I really don’t see any errors but why isn’t it accessible and why did the issue happen only on the Intel NUC 10 box? I restarted the service and everything seems to be working again.

@ChuckPa any idea? It looks to be the same issue as the one from a few beta versions ago.

2

In case you need the PMS logs:

3

FWIW, here’s the output of systemctl status plexmediaserver.service before I restarted the service:

image
image848×350 13.8 KB

Here’s the one after the restart:

image
image1649×474 51.1 KB

4

@kevindd992002

The ZIP would have been easier for you.
Most important, I need the Plex Media Server.log from right after it starts…

Please do the following:

  1. Restart that PMS
  2. Let it sit 2 minutes
  3. Stop PMS
  4. Make a tar.gz of the “Logs” directory
  5. Attach that tar.gz here
5

So I do this even though everything seems to be working now?

6

mine was inaccessible as well after the update (using ubuntu 20.04) for a period of around 10 minutes - couldn’t log on via app or website, it was reporting my libraries had no media assigned, i couldn’t swap users they were no other users and that i could access as it requires secure connection even though it is.

my plex is setup so only used internally and not externally, so i should never have issues accessing the system when at home

7

@ChuckPa here you go:

8

Mine was not accessible at all after the update

9

@kevindd992002

Next time you have any problems like this, please grab that instantaneous snapshot so we can track it down.

PMS software package installation stops PMS first, installs the software, then restarts the server.

I’m uncertain if your system was delayed in starting (which did happen starting a few versions ago with the ICU upgrades). This ICU support required PMS to upgrade the database during first restart and did leave it inaccessible.

This could have been perceived as a failure even though the server was running normally.

What I would be careful of & concerned about is if that was the case and a now-partial upgraded DB exists.

10

Ok, got it. So I guess the Logs.zip I provided is not useful for troubleshooting.

How can I confirm if my current DB is a partially upgraded DB? That seems to be a legitimate concern, yes.

11

There’s no way of knowing the current DB state.

It may not even be a concern if it’s partial. I would expect the DB to write new records with the ICU table entries as well.

ICU is something I don’t know a lot about in this DB context. I should probably learn more.

Unless you see internationalization issues, I think it’s safe to not worry about it

12

I see. Would forcefully updating PMS again be recommended though?

13

no… nothing to gain at this point except disturbing a working system.

1 Like
14

The problem happened again today because there was a new PMS release. Same exact thing happened. After the update, PMS was inaccessible. After I noticed this, I did the steps in your post here.

Here is the Logs directory:

Logs.zip (3.3 MB)

15

@ChuckPa

16

You had something seriously bog things down,

Look at how bad the database abruptly got?

Jul 06, 2021 05:35:00.162 [0x7f43260ceb38] DEBUG - Auth: authenticated user 1 as Kevin Ong
Jul 06, 2021 05:35:00.162 [0x7f43260abb38] DEBUG - Auth: authenticated user 1 as Kevin Ong
Jul 06, 2021 05:35:00.163 [0x7f4324387b38] DEBUG - Request: [192.168.10.10:41459 (Subnet)] GET /library/metadata/33838 (30 live) GZIP Signed-in Token (Kevin Ong)
Jul 06, 2021 05:35:00.163 [0x7f43243fdb38] DEBUG - Request: [192.168.10.10:41458 (Subnet)] GET /library/metadata/33875 (30 live) GZIP Signed-in Token (Kevin Ong)
Jul 06, 2021 05:35:00.163 [0x7f4324205b38] DEBUG - Request: [192.168.10.10:41460 (Subnet)] GET /library/metadata/33835 (30 live) GZIP Signed-in Token (Kevin Ong)
Jul 06, 2021 05:35:00.164 [0x7f43240ccb38] DEBUG - Request: [192.168.10.10:41461 (Subnet)] GET /library/metadata/33836 (30 live) GZIP Signed-in Token (Kevin Ong)
Jul 06, 2021 05:35:00.180 [0x7f4326cf6b38] DEBUG - It took 150.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.184 [0x7f4324e28b38] DEBUG - It took 140.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.184 [0x7f4324f94b38] DEBUG - It took 130.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.184 [0x7f43247d1b38] DEBUG - It took 160.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.185 [0x7f43258a0b38] DEBUG - It took 190.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.186 [0x7f432558eb38] DEBUG - It took 170.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.187 [0x7f4324f68b38] DEBUG - It took 200.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.188 [0x7f43243fdb38] DEBUG - It took 120.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.190 [0x7f43258cbb38] WARN - SLOW QUERY: It took 230.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.190 [0x7f432483bb38] DEBUG - It took 170.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.190 [0x7f432474bb38] DEBUG - It took 140.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.194 [0x7f4324e28b38] DEBUG - It took 80.000000 ms to retrieve 82 items.
Jul 06, 2021 05:35:00.194 [0x7f43258a0b38] DEBUG - It took 70.000000 ms to retrieve 64 items.
Jul 06, 2021 05:35:00.196 [0x7f43240ccb38] DEBUG - It took 180.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.197 [0x7f4324f68b38] DEBUG - It took 100.000000 ms to retrieve 90 items.
Jul 06, 2021 05:35:00.197 [0x7f43243fdb38] DEBUG - It took 90.000000 ms to retrieve 77 items.
Jul 06, 2021 05:35:00.198 [0x7f43258cbb38] DEBUG - It took 80.000000 ms to retrieve 62 items.
Jul 06, 2021 05:35:00.198 [0x7f4324dd8b38] WARN - SLOW QUERY: It took 270.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.199 [0x7f43248a6b38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.199 [0x7f4324205b38] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.201 [0x7f4324961b38] WARN - SLOW QUERY: It took 310.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.202 [0x7f4326cf6b38] DEBUG - It took 90.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.203 [0x7f432474bb38] DEBUG - It took 130.000000 ms to retrieve 71 items.
Jul 06, 2021 05:35:00.205 [0x7f43244c0b38] WARN - SLOW QUERY: It took 310.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.209 [0x7f43248a6b38] DEBUG - It took 100.000000 ms to retrieve 60 items.
Jul 06, 2021 05:35:00.210 [0x7f43240ccb38] DEBUG - It took 140.000000 ms to retrieve 101 items.
Jul 06, 2021 05:35:00.210 [0x7f4326cf6b38] DEBUG - It took 80.000000 ms to retrieve 61 items.
Jul 06, 2021 05:35:00.211 [0x7f4324912b38] WARN - SLOW QUERY: It took 410.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.211 [0x7f432558eb38] DEBUG - It took 150.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.212 [0x7f4324ed8b38] WARN - SLOW QUERY: It took 420.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.212 [0x7f43244c0b38] DEBUG - It took 60.000000 ms to retrieve 48 items.
Jul 06, 2021 05:35:00.213 [0x7f4324dd8b38] DEBUG - It took 130.000000 ms to retrieve 102 items.
Jul 06, 2021 05:35:00.214 [0x7f4324f94b38] DEBUG - It took 140.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.216 [0x7f4324961b38] DEBUG - It took 150.000000 ms to retrieve 100 items.
Jul 06, 2021 05:35:00.217 [0x7f4324205b38] DEBUG - It took 170.000000 ms to retrieve 95 items.
Jul 06, 2021 05:35:00.217 [0x7f4324e28b38] DEBUG - It took 110.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.219 [0x7f43247d1b38] DEBUG - It took 180.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.220 [0x7f43258a0b38] DEBUG - It took 120.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.222 [0x7f4324ed8b38] DEBUG - It took 90.000000 ms to retrieve 93 items.
Jul 06, 2021 05:35:00.223 [0x7f43243fdb38] DEBUG - It took 140.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.224 [0x7f4324387b38] WARN - SLOW QUERY: It took 540.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.224 [0x7f4324912b38] DEBUG - It took 130.000000 ms to retrieve 108 items.
Jul 06, 2021 05:35:00.225 [0x7f43258cbb38] DEBUG - It took 150.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.228 [0x7f4324e28b38] DEBUG - It took 100.000000 ms to retrieve 82 items.
Jul 06, 2021 05:35:00.228 [0x7f432474bb38] DEBUG - It took 120.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.229 [0x7f43247d1b38] DEBUG - It took 90.000000 ms to retrieve 62 items.
Jul 06, 2021 05:35:00.231 [0x7f43258cbb38] DEBUG - It took 60.000000 ms to retrieve 62 items.
Jul 06, 2021 05:35:00.231 [0x7f4324f68b38] WARN - SLOW QUERY: It took 220.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.232 [0x7f43258a0b38] DEBUG - It took 110.000000 ms to retrieve 64 items.
Jul 06, 2021 05:35:00.233 [0x7f43243fdb38] DEBUG - It took 90.000000 ms to retrieve 77 items.
Jul 06, 2021 05:35:00.233 [0x7f4324dd8b38] DEBUG - It took 110.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.234 [0x7f43240ccb38] DEBUG - It took 110.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.234 [0x7f4324387b38] DEBUG - It took 110.000000 ms to retrieve 109 items.
Jul 06, 2021 05:35:00.234 [0x7f432474bb38] DEBUG - It took 60.000000 ms to retrieve 71 items.
Jul 06, 2021 05:35:00.234 [0x7f432483bb38] WARN - SLOW QUERY: It took 260.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.236 [0x7f43248a6b38] DEBUG - It took 200.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.236 [0x7f43244c0b38] DEBUG - It took 160.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.237 [0x7f4324961b38] DEBUG - It took 100.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.238 [0x7f4324f68b38] DEBUG - It took 60.000000 ms to retrieve 90 items.
Jul 06, 2021 05:35:00.239 [0x7f4324205b38] DEBUG - It took 100.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.240 [0x7f4324dd8b38] DEBUG - It took 50.000000 ms to retrieve 102 items.
Jul 06, 2021 05:35:00.241 [0x7f43240ccb38] DEBUG - It took 50.000000 ms to retrieve 101 items.
Jul 06, 2021 05:35:00.242 [0x7f4324ed8b38] DEBUG - It took 90.000000 ms to retrieve 1 items.
Jul 06, 2021 05:35:00.244 [0x7f4324912b38] DEBUG - It took 10.000000 ms to retrieve 108 items.
Jul 06, 2021 05:35:00.247 [0x7f4324387b38] DEBUG - It took 0.000000 ms to retrieve 109 items.
Jul 06, 2021 05:35:00.398 [0x7f4326cf6b38] DEBUG - We're going to try to auto-select an audio stream for account 1.
Jul 06, 2021 05:35:00.398 [0x7f4326cf6b38] DEBUG - Selecting best audio stream for part ID 122757 (autoselect: 1 language: en)

It’s behaving as if it were having ICU updates performed.

What can you tell me about where the DB istored ? (/var/lib/plexmediaserver)

17

I do see those SLOW QUERY’s all over the place and I don’t know how to fix them because when I search about it I see a lot of people also having them and ignoring them.

No, the DB is stored at /home/plex on both the NUC and the custom-made box. I see those SLOW QUERY errors on the logs of both PMS servers but the update issue only happens on the NUC box.

18

Optimize Database will take care of the database.

EDIT: If using a NUC, which is a SSD, AND the DB is slow? WoW. That’s NVMe. It definitely needs cleaning up.

19

I’ll optimize the database now for both boxes. Is this the cause of the update issue for the NUC though?

And yes, the NUC is running off of an NVMe for the OS and the plex DB so I’m not sure why the DB isn’t optimized in the first place. Also, the DB is for 981 movies and 132 shows only. That is not a lot and I did a Plex dance for this PMS just about two months ago. Can that amount of media in that timeframe really mess up the DB?

20

Also, there’s an optimize database every week scheduled task. Why did this not have any effect?

I just did an optimize database on both boxes and it took less than 15 seconds to finish. Is that normal?