Analysis: PMS (Linux) became inaccessible, logs contain critical entries

Plex Media Server
1

Server Version#: 1.32.6.7371
Player Version#: 4.112.0

Could someone have a look at my logs to see what had gone wrong with the server?

2

@triks_melb

Do you have DEBUG logging enabled or ERROR/INFO only?

If you have DEBUG logging enabled, then I can look at them and try to figure out what’s happening.

A tar.gz or the ZIP of the “Logs” directory is what I need.

3

Plex Media Server Logs_2023-08-09_19-19-29.zip (5.2 MB)

4

@triks_melb

When’s the last time you did a good DB optimize (either Plex or my tool) ?

Your logs are showing PMS getting hung up waiting on the DB and then actually timing out (which I will speak to Engineering about).

Aug 09, 2023 18:55:18.243 [139937094794040] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137a8] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:18.254 [139937578433336] DEBUG - [HttpClient/HCl#137a8] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:18.645 [139937100372792] ERROR - [Req#37b7e7] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:19.315 [139937008020280] ERROR - [Req#37bf06] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:19.532 [139937109404472] ERROR - [Req#37bac1] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:21.274 [139937140714296] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137a9] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:21.276 [139937578433336] DEBUG - [HttpClient/HCl#137a9] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:21.277 [139937140714296] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137aa] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:21.288 [139937578433336] DEBUG - [HttpClient/HCl#137aa] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:24.309 [139936962673464] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137ab] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:24.310 [139937578433336] DEBUG - [HttpClient/HCl#137ab] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:24.310 [139936962673464] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137ac] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:24.322 [139937578433336] DEBUG - [HttpClient/HCl#137ac] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:24.500 [139937107295032] ERROR - [Req#37bb45] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:25.426 [139937138604856] ERROR - [Req#37bf05] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:27.342 [139937149676344] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137ad] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:27.344 [139937578433336] DEBUG - [HttpClient/HCl#137ad] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:27.344 [139937149676344] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137ae] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:27.356 [139937578433336] DEBUG - [HttpClient/HCl#137ae] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:27.684 [139937027742520] DEBUG - Grabber: Plex Tuner Service not running; retrying in 10 seconds.
Aug 09, 2023 18:55:28.853 [139937100372792] ERROR - [Req#37b7e7] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:29.532 [139937008020280] ERROR - [Req#37bf06] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:29.739 [139937109404472] ERROR - [Req#37bac1] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:30.376 [139937621949240] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137af] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:30.378 [139937578433336] DEBUG - [HttpClient/HCl#137af] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:30.379 [139937621949240] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b0] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:30.390 [139937578433336] DEBUG - [HttpClient/HCl#137b0] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:33.410 [139937621949240] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b1] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:33.412 [139937578433336] DEBUG - [HttpClient/HCl#137b1] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:33.412 [139937621949240] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b2] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:33.423 [139937578433336] DEBUG - [HttpClient/HCl#137b2] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:34.717 [139937107295032] ERROR - [Req#37bb45] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:35.634 [139937138604856] ERROR - [Req#37bf05] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:36.443 [139937027742520] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b3] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:36.445 [139937578433336] DEBUG - [HttpClient/HCl#137b3] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:36.445 [139937027742520] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b4] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:36.457 [139937578433336] DEBUG - [HttpClient/HCl#137b4] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:37.685 [139937617730360] DEBUG - Grabber: Plex Tuner Service not running; retrying in 10 seconds.
Aug 09, 2023 18:55:39.074 [139937100372792] ERROR - [Req#37b7e7] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:39.275 [139937100372792] ERROR - Got exception from request handler: sqlite3_statement_backend::loadOne: database is locked
Aug 09, 2023 18:55:39.477 [139937619839800] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b5] HTTP requesting GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:39.479 [139937578433336] DEBUG - [HttpClient/HCl#137b5] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/discover.json
Aug 09, 2023 18:55:39.480 [139937619839800] DEBUG - [Grabber/77e266a7634acbed59e485473a085f8174e39cd9/HCl#137b6] HTTP requesting GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:39.491 [139937578433336] DEBUG - [HttpClient/HCl#137b6] HTTP/1.1 (0.0s) 200 response from GET http://10.0.1.140:80/lineup_status.json
Aug 09, 2023 18:55:39.741 [139937008020280] ERROR - [Req#37bf06] Waited over 10 seconds for a busy database; giving up.
Aug 09, 2023 18:55:39.947 [139937109404472] ERROR - [Req#37bac1] Waited over 10 seconds for a busy database; giving up.

How many media items (approx) are in the DB (movies, episodes, tracks, and photos)

5

I’d say I optimise and clean bundles on average 2 times per week but can’t say exactly when I did it on this server. Wouldn’t there be entries of that in the logs? DB contains approximately 5000 episodes, 2200 movies, 3000 general videos and 80 Albums.

6

May I be a bit bold and suggest you give my tool a shot ?

The Waited over 10 seconds for a busy database; giving up. is harsh.

Either HDD is thrashing or Index chains have grown crazy long

My tool will export the DB and then reimport it in perfect order along with recreating the indexes to match

The usual place folks notice the speedup is

  1. page load
  2. searching (it often finishes as you type)
7

thanks - I have used your tool previously but will go back to it. Would be nice if the process could be automated perhaps via Cron. Any instructions for this would be appreciated. Additionally which options do you recommend and in which order?

8

Instructions are on Github in the README.

you can launch it via cron. It will process the commands on the command line until done.

ex: DBRepair.sh stop auto start exit

9

thanks - I’ll create a Cronjob to run every 2 weeks.

Ran tool items 1,2 and 4 - hopefully that will clean up the DB or it was just a once off issue.

1 - ‘stop’ - Stop PMS
2 - ‘automatic’ - database check, repair/optimize, and reindex in one step.
4 - ‘vacuum’ - Remove empty space from database

10

@triks_melb

Vacuum provides nothing here after running “Auto” (which does a full rebuild)
There is no empty space to remove.

As I suggested: Stop. Auto, Start. Exit are all you need.

If you look at the log files, you can see the DB size changes.

11

OK great, I’ve already executed the ‘stop,’ ‘automatic,’ and ‘start’ steps (items 1, 2, and 4). Your clarification on ‘vacuum’ is noted and yes the DB size had decreased and performance somewhat increased.

12

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