PMS unreachable on Synology NAS after update to 1.22.3.4392 (edit: failed DB upgrade?)

theirongiant · April 25, 2021, 2:47am

Server Version#: 1.22.3.4392-6000
Player Version#: n/a
Synology Model: DS918+

Updated Plex Media Server to 1.22.3.4392 this morning and now the web portal won’t launch, and the Plex online service thinks the PMS on the NAS is not available. Cannot reach it from Plex for iOS or Apple TV.

The Plex Media Server process is running, but doesn’t appear to be doing anything particularly useful:

$ ps -efj | grep Plex

plex     11925     1 11902 11902  1 19:37 ?        00:00:10 /var/packages/Plex Media Server/target/Plex Media Server

edit: I think the database upgrade failed somehow. See below…

theirongiant · April 25, 2021, 2:55am

Yeah, I think you’re just replying to gain points / reputation on this forum without diving into the problem…

I think there’s something wrong with the underlying database.

On closer inspection, the logs show some alteration that occurred during upgrade, and it fell on its face.

admin@librarycore:/volume1/Plex/Library/Application Support/Plex Media Server/Logs$ cat "Plex Media Server.1.log"
Apr 24, 2021 19:13:11.603 [0x7f3dee1d9700] INFO - Plex Media Server v1.22.3.4392-d7c624def - Synology DS918+ x86_64 - build: linux-x86_64 synology - GMT -07:00
Apr 24, 2021 19:13:11.603 [0x7f3dee1d9700] INFO - Linux version: DSM 6.2.3.25423-0, language: en-US
Apr 24, 2021 19:13:11.603 [0x7f3dee1d9700] INFO - Processor Intel(R) Celeron(R) CPU J3455 @ 1.50GHz
Apr 24, 2021 19:13:11.603 [0x7f3dee1d9700] INFO - /var/packages/Plex Media Server/target/Plex Media Server
Apr 24, 2021 19:13:11.946 [0x7f3df8a61780] INFO - SQLITE3:(nil), 283, recovered 1385 frames from WAL file /volume1/Plex/Library/Application Support/Plex Media Server/Plug-in Support/Databases/com.plexapp.plugins.library.db-wal
Apr 24, 2021 19:13:18.930 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/DatabaseMigrations.cpp:231): 1.030000 seconds
Apr 24, 2021 19:14:23.908 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.911 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.915 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.918 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.922 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.926 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.930 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.933 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.937 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.941 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.945 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.949 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.953 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.957 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.961 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.966 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.970 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.974 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:23.978 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed
Apr 24, 2021 19:14:27.775 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 22: [SELECT (SELECT max(idx) FROM 'main'.'fts4_tag_titles_segdir' WHERE level = ?) + 1] database schema has changed
Apr 24, 2021 19:14:27.775 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 20: [SELECT coalesce((SELECT max(blockid) FROM 'main'.'fts4_tag_titles_segments') + 1, 1)] database schema has changed
Apr 24, 2021 19:14:27.775 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 13: [REPLACE INTO 'main'.'fts4_tag_titles_segments'(blockid, block) VALUES(?, ?)] database schema has changed
Apr 24, 2021 19:14:27.779 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 25: [REPLACE INTO 'main'.'fts4_tag_titles_segdir' VALUES(?,?,?,?,?,?)] database schema has changed
Apr 24, 2021 19:14:27.779 [0x7f3df8a61780] INFO - SQLITE3:(nil), 17, statement aborts at 22: [SELECT level, idx, end_block FROM 'main'.'fts4_tag_titles_segdir' WHERE level BETWEEN ? AND ? ORDER BY level DESC, idx ASC] database schema has changed
Apr 24, 2021 19:18:21.268 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:59): 26.440000 seconds
Apr 24, 2021 19:18:56.144 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:69): 5.240000 seconds
Apr 24, 2021 19:19:27.043 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:80): 4.390000 seconds
Apr 24, 2021 19:19:43.312 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/FullTextSearch.cpp:90): 2.540000 seconds
Apr 24, 2021 19:19:43.313 [0x7f3df8a61780] WARN - Held transaction for too long (../Library/DatabaseMigrations.cpp:231): 40.970000 seconds

admin@librarycore:/volume1/Plex/Library/Application Support/Plex Media Server/Logs$ cat "Plex Media Server.log"
Apr 24, 2021 19:37:09.231 [0x7f6834cf1700] INFO - Plex Media Server v1.22.3.4392-d7c624def - Synology DS918+ x86_64 - build: linux-x86_64 synology - GMT -07:00
Apr 24, 2021 19:37:09.231 [0x7f6834cf1700] INFO - Linux version: DSM 6.2.3.25423-0, language: en-US
Apr 24, 2021 19:37:09.231 [0x7f6834cf1700] INFO - Processor Intel(R) Celeron(R) CPU J3455 @ 1.50GHz
Apr 24, 2021 19:37:09.231 [0x7f6834cf1700] INFO - /var/packages/Plex Media Server/target/Plex Media Server
Apr 24, 2021 19:37:09.374 [0x7f683f579780] INFO - SQLITE3:(nil), 283, recovered 11 frames from WAL file /volume1/Plex/Library/Application Support/Plex Media Server/Plug-in Support/Databases/com.plexapp.plugins.library.db-wal
Apr 24, 2021 19:37:10.303 [0x7f683f579780] INFO - SQLITE3:(nil), 283, recovered 377 frames from WAL file /volume1/Plex/Library/Application Support/Plex Media Server/Plug-in Support/Databases/com.plexapp.plugins.library.blobs.db-wal
Apr 24, 2021 19:37:10.800 [0x7f683f579780] INFO - SQLITE3:(nil), 17, statement aborts at 57: [select * from metadata_items limit 1] database schema has changed

theirongiant · April 25, 2021, 2:58am

My NAS has never reported any disk errors, and there is more than 50GB free on volume1 right now.

ChuckPa · April 25, 2021, 3:14am

May we please have DEBUG (not INFO or VERBOSE) log files ZIP;

Change log settings - SAVE changes
Restart PMS
Let start for 60 seconds
Attempt to connect
Stop Plex
Manually create a ZIP file of the Logs directory in the Plex share.
Attach said ZIP file here.

theirongiant · April 25, 2021, 3:18am

Service wasn’t even starting to the point where I could change the log settings.

Letting Plex regenerate the Preferences file allowed Plex to relaunch and sign in, but it still says the library is “unavailable.”

ChuckPa · April 25, 2021, 3:20am

Be advised,

When it comes to log files, plus several other settings, we don’t need the GUI.

We can effect settings changes via the Synology Text Editor and the Preferences.xml file.

In the case of logging. the addtion of logDebug="1" inside the XML structure is all it takes to enable DEBUG logging.

fuchshei_chello_at · April 25, 2021, 5:18am

Hello,
same problem here:
Server: 1.22.3.4392-6000
Synology 1621+

The steps from [trumpy81] doesn´t help.

-Heimo

fuchshei_chello_at · April 25, 2021, 5:30am

Hello,
same problem. Please find attached the log files.

Log files

-Heimo

theirongiant · April 25, 2021, 6:27am

Here is the debug log. This is the first ~20 minutes from the most recent startup, without media scan activity.

In the local Plex console, I am seeing orange exclamation marks next to every library (movies, tv, music).

PS: I don’t think it’s a good idea to upload the entire log folder to a publicly accessible forum, since it includes media scan activity and potentially every title in your library.

ChuckPa · April 25, 2021, 2:31pm

@fuchshei_chello_at

I attempted to retrieve the logs. Nothing was available at that URL

fuchshei_chello_at · April 25, 2021, 7:49pm

Link is back … sorry

fuchshei_chello_at · April 26, 2021, 3:11pm

So far my problem is solved. My pihole DNS filter has blocked a domain …

Thank you,

Heimo

theirongiant · April 26, 2021, 4:14pm

Hey @fuchshei_chello_at , can you please share the domain(s) that were blocked? I’m also using a PiHole but there was no issue until the recent upgrade. Maybe Plex added something new.

fuchshei_chello_at · April 26, 2021, 4:34pm

hxxp://r3.o.lencr.org … seems to be a domain from lets encrypt

-Heimo

theirongiant · April 28, 2021, 5:45pm

I just checked my DNS filter configuration and it looks like the PiHole isn’t serving DNS queries to the NAS. So that’s ruled out. The NAS is using my router’s default DNS lookup, which just goes upstream to the ISP, and I can resolve the same domain on other machines on my network.

What else could it be?

theirongiant · April 28, 2021, 5:48pm

Well the end of this saga is that there were duplicate entries for my NAS in the Library section. Three in total. Two were offline. When I deleted the second one, my ‘pinned’ sources disappeared. I think my library is still there. Currently checking…

theirongiant · April 28, 2021, 8:29pm

@fuchshei_chello_at @ChuckPa @trumpy81 :

This is resolved. Thank you.

Have there been other reports of this happening to Plex Media Server users updating to this version, or is it random and unpredictable during routine upgrades?

system · July 27, 2021, 8:30pm

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Upgraded PMS from 1.2.7 to 1.3.0 now Plex is broken (had to reboot NAS) General Discussions	1	74	January 7, 2020
Unable to connect to Plex after upgrade NAS & Devices server-synology	11	280	August 9, 2022
Can't reach PMS on Synology 916+ NAS & Devices server-synology	27	943	February 15, 2020
Unable to connect after update to 1.30.2.6563 NAS & Devices server-qnap	17	347	April 28, 2023
Plex only sporadically reachable after installing PMS-1.18.1.1973-0f4abfbcc-x86_64 NAS & Devices server-synology	56	1042	February 19, 2020

PMS unreachable on Synology NAS after update to 1.22.3.4392 (edit: failed DB upgrade?)

Related topics