Server Version#: 1.40.4.8679-424562606
Player Version#:
Logs.tar.gz (7.1 MB)
Hi,
After a power outage, my Plex server refuses to start. I run Plex in Docker on a NUC. My media resides on a NAS, which is mounted as a CIFS volume in Docker. I’m fairly certain that this is not the cause of the issue.
The contents of my /config folder is backed up off-site, so I restored a backup from the day before the power outage, but I still get the same error message. The logs provided are from this attempt. Could it be perhaps that the incorrect data was stored sometime before the power outage? It had run continuously for a couple of months before.
When the server starts up, the following is being output, before I shut down the server:
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 40-plex-first-run: executing...
Plex Media Server first run setup complete
[cont-init.d] 40-plex-first-run: exited 0.
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: executing...
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: exited 0.
[cont-init.d] 50-plex-update: executing...
Attempting to upgrade to: 1.40.4.8679-424562606
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
22 77.9M 22 17.2M 0 0 22.4M 0 0:00:03 --:--:-- 0:00:03 22.4M
64 77.9M 64 50.3M 0 0 28.3M 0 0:00:02 0:00:01 0:00:01 32.9M
100 77.9M 100 77.9M 0 0 29.7M 0 0:00:02 0:00:02 --:--:-- 32.7M
Selecting previously unselected package plexmediaserver.
(Reading database ... 7274 files and directories currently installed.)
Preparing to unpack /tmp/plexmediaserver.deb ...
PlexMediaServer install: Pre-installation Validation.
PlexMediaServer install: Docker detected. Preinstallation validation not required.
Unpacking plexmediaserver (1.40.4.8679-424562606) ...
Setting up plexmediaserver (1.40.4.8679-424562606) ...
PlexMediaServer install: Docker detected. Postinstallation tasks not required. Continuing.
[cont-init.d] 50-plex-update: exited 0.
[cont-init.d] done.
[services.d] starting services
Starting Plex Media Server.
[services.d] done.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
I would assume that the interesting part of my logs are these rows:
Jul 26, 2024 09:33:19.585 [139714466204304] INFO - Running migrations. (EPG 0)
Jul 26, 2024 09:33:19.586 [139714466204304] INFO - Running forward migration 202406050800.
Jul 26, 2024 09:33:19.588 [139714466204304] ERROR - SQLITE3:0x80000001, 1, statement aborts at 4: [SELECT `id` FROM metadata_item_settings WHERE extra_data -> 'pv:SyncedViewAt' IS NOT NULL or extra_data -> 'pv:SyncedRatedAt' IS NOT NULL] malformed JSON
Jul 26, 2024 09:33:19.588 [139714466204304] ERROR - Exception inside transaction (inside=1) (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseMigrations.cpp:342): sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 09:33:19.589 [139714466204304] ERROR - Exception thrown during migrations, aborting: sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 09:33:19.589 [139714466204304] ERROR - Database corruption: sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 09:33:19.589 [139714466204304] ERROR - Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Hi,
Sorry, I should have mentioned that in my post. I have already tried this, and the integrity test returns Ok. I have also tried recreating the database by expiring it as SQL and then reading from that.
Hi,
I have restored a backup. I have also tried to repair the restored DB, but the integrity check returns ok.
Also the PlexDBRepair tools says that everything looks good (also on the restored DB).
How is forward migration 202406050800 defined? My Plex installation is quite old (12 years or so). Could it be that this migration makes assumptions that do not hold in my DB?
Doesn’t matter as long as you have successfully updated the server software. Which you appear to have done (Server version 1.40.4.8679-424562606).
Or did you update from a 12 year old sererver version to 1.40.4.8679-424562606?
Probably not, it would have failed, I think.
Are you still seeing the error from your first post above in your server logs?
I’m using the plexinc/pms-docker:public Docker image, so the server version before my power outage was around three months old. However, my DB was created many years ago, and may thus contain (or miss) data in an unexpected way.
Since the same error occurs even after I have restored my whole /config folder, I’m beginning to suspect that a write that was aborted at exactly the wrong time may not be the culprit here after all.
Yes, I do:
Jul 26, 2024 15:01:25.616 [139649042971280] INFO - Running migrations. (EPG 0)
Jul 26, 2024 15:01:25.618 [139649042971280] INFO - Running forward migration 202406050800.
Jul 26, 2024 15:01:25.619 [139649042971280] ERROR - SQLITE3:0x80000001, 1, statement aborts at 4: [SELECT `id` FROM metadata_item_settings WHERE extra_data -> 'pv:SyncedViewAt' IS NOT NULL or extra_data -> 'pv:SyncedRatedAt' IS NOT NULL] malformed JSON
Jul 26, 2024 15:01:25.619 [139649042971280] ERROR - Exception inside transaction (inside=1) (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseMigrations.cpp:342): sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 15:01:25.620 [139649042971280] ERROR - Exception thrown during migrations, aborting: sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 15:01:25.620 [139649042971280] ERROR - Database corruption: sqlite3_statement_backend::loadRS: malformed JSON
Jul 26, 2024 15:01:25.620 [139649042971280] ERROR - Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
If I recreate the query from the error log, I get the same error message:
sqlite> SELECT `id` FROM metadata_item_settings WHERE extra_data -> 'pv:SyncedViewAt' IS NOT NULL or extra_data -> 'pv:SyncedRatedAt' IS NOT NULL;
Runtime error: malformed JSON
sqlite> SELECT `id`, `extra_data` FROM metadata_item_settings LIMIT 10;
1|
2|
3|
4|
5|
6|
7|
8|
9|
10|
Try downgrading to an earlier server version, if you can.
Then repair again and try the upgrade.
Great idea. As I said, the DB tool says that there is nothing to repair.
plexinc/pms-docker:1.40.2.8395-c67dce28e: Starts
plexinc/pms-docker:1.40.3.8555-fef15d30c: Starts
plexinc/pms-docker:1.40.4.8679-424562606: Error
Console output from plexinc/pms-docker:1.40.3.8555-fef15d30c:
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 40-plex-first-run: executing...
Plex Media Server first run setup complete
[cont-init.d] 40-plex-first-run: exited 0.
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: executing...
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: exited 0.
[cont-init.d] 50-plex-update: executing...
[cont-init.d] 50-plex-update: exited 0.
[cont-init.d] done.
[services.d] starting services
Starting Plex Media Server.
[services.d] done.
Critical: libusb_init failed
Console output from plexinc/pms-docker:1.40.4.8679-424562606:
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 40-plex-first-run: executing...
Plex Media Server first run setup complete
[cont-init.d] 40-plex-first-run: exited 0.
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: executing...
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: exited 0.
[cont-init.d] 50-plex-update: executing...
[cont-init.d] 50-plex-update: exited 0.
[cont-init.d] done.
[services.d] starting services
Starting Plex Media Server.
[services.d] done.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
Perform the repair anyway, this check is not infallible.
I performed a repair using the PlexDBRepair tool and updated my Docker image to plexinc/pms-docker:1.40.4.8679-424562606 and got the same result.
PlexDBRepair:
stolpe@Flitwick:~/apa/plexdbrepair/PlexDBRepair-1.07.00$ sudo ./DBRepair.sh --sqlite /home/stolpe/apa/plexmediaserver/ -
-databases /home/stolpe/Plex/config/Library/Application\ Support/Plex\ Media\ Server/Plug-in\ Support/Databases/
Plex Media Server Database Repair Utility (User Defined)
Version v1.07.00
PlexSQLite = '/home/stolpe/apa/plexmediaserver//Plex SQLite'
Databases = '/home/stolpe/Plex/config/Library/Application Support/Plex Media Server/Plug-in Support/Databases/'
Select
1 - 'stop' - (Not available. Stop manually.)
2 - 'automatic' - Check, Repair/Optimize, and Reindex Database in one step.
3 - 'check' - Perform integrity check of database.
4 - 'vacuum' - Remove empty space from database without optimizing.
5 - 'repair' - Repair/Optimize databases.
6 - 'reindex' - Rebuild database database indexes.
7 - 'start' - (Not available. Start manually)
8 - 'import' - Import watch history from another database independent of Plex. (risky).
9 - 'replace' - Replace current databases with newest usable backup copy (interactive).
10 - 'show' - Show logfile.
11 - 'status' - Report status of PMS (run-state and databases).
12 - 'undo' - Undo last successful command.
21 - 'prune' - Prune (remove) old image files (jpeg,jpg,png) from PhotoTranscoder cache.
42 - 'ignore' - Ignore duplicate/constraint errors.
88 - 'update' - Check for updates.
99 - 'quit' - Quit immediately. Keep all temporary files.
'exit' - Exit with cleanup options.
Enter command # -or- command name (4 char min) : 5
Exporting current databases using timestamp: 2024-07-26_15.54.07
Exporting Main DB
Exporting Blobs DB
Successfully exported the main and blobs databases.
Start importing into new databases.
Importing Main DB.
Importing Blobs DB.
Successfully imported databases.
Verifying databases integrity after importing.
Verification complete. PMS main database is OK.
Verification complete. PMS blobs database is OK.
Saving current databases with '-BACKUP-2024-07-26_15.54.07'
Making repaired databases active
Repair complete. Please check your library settings and contents for completeness.
Recommend: Scan Files and Refresh all metadata for each library section.
Select
1 - 'stop' - (Not available. Stop manually.)
2 - 'automatic' - Check, Repair/Optimize, and Reindex Database in one step.
3 - 'check' - Perform integrity check of database.
4 - 'vacuum' - Remove empty space from database without optimizing.
5 - 'repair' - Repair/Optimize databases.
6 - 'reindex' - Rebuild database database indexes.
7 - 'start' - (Not available. Start manually)
8 - 'import' - Import watch history from another database independent of Plex. (risky).
9 - 'replace' - Replace current databases with newest usable backup copy (interactive).
10 - 'show' - Show logfile.
11 - 'status' - Report status of PMS (run-state and databases).
12 - 'undo' - Undo last successful command.
21 - 'prune' - Prune (remove) old image files (jpeg,jpg,png) from PhotoTranscoder cache.
42 - 'ignore' - Ignore duplicate/constraint errors.
88 - 'update' - Check for updates.
99 - 'quit' - Quit immediately. Keep all temporary files.
'exit' - Exit with cleanup options.
Enter command # -or- command name (4 char min) : exit
Ok to remove temporary databases/workfiles for this session? (Y/N) ? y
Deleting all temporary work files.
Console output:
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 40-plex-first-run: executing...
Plex Media Server first run setup complete
[cont-init.d] 40-plex-first-run: exited 0.
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: executing...
[cont-init.d] 45-plex-hw-transcode-and-connected-tuner: exited 0.
[cont-init.d] 50-plex-update: executing...
[cont-init.d] 50-plex-update: exited 0.
[cont-init.d] done.
[services.d] starting services
Starting Plex Media Server.
[services.d] done.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
Starting Plex Media Server.
Error: Unable to set up server: sqlite3_statement_backend::loadRS: malformed JSON (N4soci10soci_errorE)
Stopping Plex Media Server.
kill: usage: kill [-s sigspec | -n signum | -sigspec] pid | jobspec ... or kill -l [sigspec]
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.
Did you perform the repair on a freshly restored database? i.e. one that wasn’t touched by an unsuccessful upgrade attempt?
Yes I did. To be absolutely sure, I redid it again, with the same results. What does work (also after this restore) is to downgrade to 1.40.3.8555-fef15d30c, where this migration is not applied. I feel increasingly convinced that there is something wrong with this migration, something that is apparently quite rarely triggered.
Can you perform this query on your database?
It should find invalid data, which would cause the migration to fail:
SELECT `id`, `extra_data` FROM metadata_item_settings where NOT json_valid(extra_data)
Depending on their number, you could attempt to repair them.
You could probably be able to figure it out looking at the other entries (you seem to understand these things) but if it’s a URL encoded string, transform that into a JSON object for the key/values and put the URL encoded string in the url key in the JSON object. Other entries should give a good pattern for this. Hopefully it’s just a few entries.
If you can’t repair them, deleting is an option too, but this would remove the “watched” state of the connected media title from the DB.
It looks like every row has invalid JSON data in extra_data (it appears to be empty). And to clarify, Plex does keep track of what I’ve watched. Now that I am able to start the server using version 1.40.3, I can verify that the correct media is marked as watched.
sqlite> SELECT `id`, `extra_data` FROM metadata_item_settings where NOT json_valid(extra_data);
1|
2|
3|
...
201875|
201876|
201878|
201879|
201880|
201883|
201884|
201885|
201886|
Here is another tip from a developer:
SQLite sees the empty string as invalid json. I expect that’s what is happening here. The question is why are these empty strings because a previous migration explicitly sets empty extra_data to null to handle exactly this situation.
Setting every instance of the empty string to null should fix at least the ones that he pasted. So
SELECT `id`, `extra_data` FROM metadata_item_settings where length(extra_data) = 0;
should yield nothing. If it’s not and all those really are empty, then a
UPDATE metadata_item_settings `extra_data` = NULL WHERE length(extra_data) = 0;
should correct those.
