PMS loses connection everytime at around 10am

Plex Media Server
,
1

The last week my Plex server keeps losing connection at around 10:00am every day. It is usually up and running 2 minutes later.
Looking at my network logs, I can see that no packet is being dropped, and all of the services on my server works fine. All other connected devices work fine as well.
Only Plex Media Server is losing connection.

I have provided the logs that occured around the time PMS went down today, but it looks like it perhaps gets stuck on the database optimization? Which is also weird, because maintence window is between 00:00 am and 03:00 am…

Server Version#: Version 1.41.1.9057
Player Version#:

Oct 30, 2024 10:09:04.648 [127893956193080] WARN - [Req#6445f/Database optimization/com.plexapp.plugins.library.db/DatabaseFixups] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/DatabaseFixups.cpp:363): 0.230000 seconds
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db/DatabaseFixups] Running database fix-ups completed in 0.8 seconds.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 0.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 1.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 2.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 3.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 4.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 5.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 6.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 7.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 8.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 9.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 10.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 11.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 12.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 13.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 14.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 15.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 16.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 17.
Oct 30, 2024 10:09:04.695 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 18.
Oct 30, 2024 10:09:06.771 [127894223231800] DEBUG - Auth: authenticated user 71675212 as xxx
Oct 30, 2024 10:09:13.263 [127894221122360] DEBUG - Auth: authenticated user 20688234 as xxx
Oct 30, 2024 10:09:50.472 [127894011235128] DEBUG - [Req#63f38] BPQ: onConsiderProcessing: Idle (true)
Oct 30, 2024 10:09:50.472 [127894011235128] DEBUG - [Req#63f38] BPQ: [Idle] -> [Processing]
Oct 30, 2024 10:10:20.046 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Captured session 19.
Oct 30, 2024 10:10:20.046 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Rebuilding full text search tables.
Oct 30, 2024 10:10:20.047 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Activity: updated activity 08470f86-d653-49b0-b3fc-901e54bf7caa - completed 40.0% - Optimizing database
Oct 30, 2024 10:10:20.047 [127893958302520] DEBUG - Activity: updated activity d55f38a3-50b4-42ec-875c-5a7122a3a3ec - completed 25.0% - Cleaning bundles
Oct 30, 2024 10:10:20.047 [127893958302520] DEBUG - Activity: updated activity d55f38a3-50b4-42ec-875c-5a7122a3a3ec - completed 50.0% - Cleaning bundles
Oct 30, 2024 10:10:25.287 [127893956193080] WARN - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:58): 2.520000 seconds
Oct 30, 2024 10:10:31.802 [127893956193080] WARN - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:71): 1.040000 seconds
Oct 30, 2024 10:10:48.176 [127893956193080] WARN - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:81): 5.810000 seconds
Oct 30, 2024 10:10:56.773 [127893956193080] WARN - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Held transaction for too long (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Library/FullTextSearch.cpp:94): 3.470000 seconds
Oct 30, 2024 10:10:57.481 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Database optimization: starting.
Oct 30, 2024 10:10:57.481 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Activity: updated activity 08470f86-d653-49b0-b3fc-901e54bf7caa - completed 60.0% - Optimizing database
Oct 30, 2024 10:11:41.484 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Database optimization: complete.
Oct 30, 2024 10:11:41.488 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.492 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.496 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.499 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.502 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.504 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.509 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.514 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.519 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.523 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.528 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.532 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.537 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.541 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.545 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.548 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.551 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.555 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.558 [127893956193080] INFO - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] SQLITE3:0x80000001, 17, statement aborts at 60: [select * from metadata_items limit 1] database schema has changed
Oct 30, 2024 10:11:41.560 [127893958302520] DEBUG - Deleted 0 metadata bundles.
Oct 30, 2024 10:11:41.560 [127893958302520] DEBUG - Activity: updated activity d55f38a3-50b4-42ec-875c-5a7122a3a3ec - completed 50.0% - Cleaning bundles
Oct 30, 2024 10:11:41.562 [127893988338488] DEBUG - Request: [192.168.1.54:61075 (Allowed Network (Subnet))] GET /:/timeline?bufferedTime=232&col=6&context=preplay&duration=3099604&key=%2Flibrary%2Fmetadata%2F535689&location=lan&playQueueItemID=488303&playbackTime=125298&ratingKey=535689&row=0&state=playing&time=1556480 (9 live) #64478 TLS GZIP Signed-in Token (xxx)
Oct 30, 2024 10:11:41.562 [127894223231800] DEBUG - Failed to stream media, client probably disconnected after 233979904 bytes: 32 - Broken pipe
Oct 30, 2024 10:11:41.562 [127894223231800] DEBUG - Completed after connection close: [192.168.1.54:51714] 206 GET /library/parts/247555/1727468410/file.mkv (9 live) #6360d TLS 393353ms 233979904 bytes (range: bytes=918831398-) 
Oct 30, 2024 10:11:41.562 [127893996710712] DEBUG - Request: [79.136.16.118:40108 (WAN)] GET /:/timeline?audioStreamID=839357&bufferedTime=309104&context=source%3Acontent.watchlist.all&duration=2424064&guid=local%3A%2F%2F481034&key=%2Flibrary%2Fmetadata%2F481034&playbackTime=427851&playQueueItemID=488264&ratingKey=481034&state=playing&time=2114960&token=xxxxxxxxxxxxxxxxxxxx (9 live) #64475 TLS GZIP Signed-in Token (xxx)
Oct 30, 2024 10:11:41.562 [127894221122360] DEBUG - WebSocket: client initiated close
Oct 30, 2024 10:11:41.563 [127894223231800] DEBUG - handleStreamRead code 1: stream truncated
Oct 30, 2024 10:11:41.563 [127894223231800] DEBUG - NotificationStream: Removing because of error
Oct 30, 2024 10:11:41.563 [127894011235128] DEBUG - [Req#63f38] BPQ: generating queue items from 0 generator(s)
Oct 30, 2024 10:11:41.563 [127894011235128] DEBUG - [Req#63f38] BPQ: generated 0 item(s) for queue
Oct 30, 2024 10:11:41.563 [127894223231800] DEBUG - Completed after connection close: [172.18.0.4:36206] -3 GET /:/websockets/notifications (10 live) #1a TLS 127483574ms 16987357 bytes
Oct 30, 2024 10:11:41.563 [127894221122360] DEBUG - [EventSourceClient/pubsub/172.104.145.70:443] Failure: 9 - Bad file descriptor.
Oct 30, 2024 10:11:41.564 [127894221122360] DEBUG - [EventSourceClient/pubsub/172.104.145.70:443] MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Oct 30, 2024 10:11:41.564 [127893988338488] DEBUG - [Req#64478] Client [5699EB89-F93D-4309-BEA8-82C17CFFCC8F] reporting timeline state playing, progress of 1556480/3099604ms for guid=, playbackTime=125298ms ratingKey=535689 url=, key=/library/metadata/535689, containerKey=, metadataId=535689, source=
Oct 30, 2024 10:11:41.564 [127893996710712] DEBUG - [Req#64475] Client [e94d99a70969ea85-com-plexapp-android] reporting timeline state playing, progress of 2114960/2424064ms for guid=local://481034, playbackTime=427851ms ratingKey=481034 url=, key=/library/metadata/481034, containerKey=, metadataId=481034, source=
Oct 30, 2024 10:11:41.565 [127894221122360] ERROR - [EventSourceClient/pubsub/172.104.145.70:443] Retrying in 15 seconds.
2

This is definitely a symptom of database optimization. I’m just not sure why it’s running at that time. I have database optimization turned off because of the same symptoms. I just perform it manually when no one is watching. You probably have a big database just like me, or maybe your server is slow?

3

Brand new server with Plex on SSD. Running i5-13500 with 32GB DDR4 ram. Upgraded it one year ago, and has been running without issues - so server is definitaly not slow.

However, the database optimization is running off schedule, and obviously crashing …
I have not disabled database optimization just to see if it stops this from happening tomorrow.

My databases files are not big, most are about 250MB in size.

-rw-r--r--+ 1 abc  1000 2.8M Nov 10  2019 com.plexapp.dlna.db                                                                             -rw-r--r--+ 1 abc  1000  32K Nov 10  2019 com.plexapp.dlna.db-shm                                                                         -rw-r--r--+ 1 abc  1000 4.1M Nov 10  2019 com.plexapp.dlna.db-wal                                                                         -rw-rw-r--+ 1 abc users  41M Oct 30 09:45 com.plexapp.plugins.library.blobs.db                                                            -rw-r--r--+ 1 abc users  15M Oct 21 00:02 com.plexapp.plugins.library.blobs.db-2024-10-21                                                 -rw-r--r--+ 1 abc users  31M Oct 24 00:04 com.plexapp.plugins.library.blobs.db-2024-10-24                                                 -rw-r--r--+ 1 abc users  34M Oct 27 00:02 com.plexapp.plugins.library.blobs.db-2024-10-27                                                 -rw-r--r--+ 1 abc users  39M Oct 30 00:02 com.plexapp.plugins.library.blobs.db-2024-10-30                                                 -rw-rw-r--+ 1 abc users  32K Oct 30 09:58 com.plexapp.plugins.library.blobs.db-shm                                                        -rw-rw-r--+ 1 abc users 1.1M Oct 30 09:55 com.plexapp.plugins.library.blobs.db-wal
-rw-r--r--+ 1 abc  1000 261M Oct 30 11:17 com.plexapp.plugins.library.db
-rw-r--r--+ 1 abc users    0 Aug 16 00:00 com.plexapp.plugins.library.db-2024-08-16-tmp
-rw-r--r--+ 1 abc users 258M Oct 21 00:02 com.plexapp.plugins.library.db-2024-10-21
-rw-r--r--+ 1 abc users 260M Oct 24 00:04 com.plexapp.plugins.library.db-2024-10-24
-rw-r--r--+ 1 abc users 261M Oct 27 00:02 com.plexapp.plugins.library.db-2024-10-27
-rw-r--r--+ 1 abc users 261M Oct 30 00:02 com.plexapp.plugins.library.db-2024-10-30
-rw-r--r--+ 1 abc users 2.1M Oct 30 11:43 com.plexapp.plugins.library.db-shm
-rw-r--r--+ 1 abc users 268M Oct 30 11:43 com.plexapp.plugins.library.db-wal
-rw-r--r--+ 1 abc users  13K Apr 14  2024 media_provider_resources.tsv
-rw-rw-r--+ 1 abc users 1.1M Dec 18  2023 tv.plex.providers.epg.xmltv-5ce2f39b-672f-495b-8c2f-160da3daf999.db
-rw-rw-r--+ 1 abc users  32K Dec 18  2023 tv.plex.providers.epg.xmltv-5ce2f39b-672f-495b-8c2f-160da3daf999.db-shm
-rw-rw-r--+ 1 abc users 1.1M Dec 18  2023 tv.plex.providers.epg.xmltv-5ce2f39b-672f-495b-8c2f-160da3daf999.db-wal
-rw-r--r--+ 1 abc  1000 4.0K Dec 18  2020 tv.plex.providers.epg.xmltv-81bb4ee2-63c7-471f-869b-262106048557.db
-rw-r--r--+ 1 abc  1000  32K Apr 14  2024 tv.plex.providers.epg.xmltv-81bb4ee2-63c7-471f-869b-262106048557.db-shm
-rw-r--r--+ 1 abc  1000    0 Dec 18  2020 tv.plex.providers.epg.xmltv-81bb4ee2-63c7-471f-869b-262106048557.db-wal
4

DB optimizations are also made automatically after extensive DB updates. e.g. adding a whole bunch of titles or refreshing metadata of a lot of items.

I’d check whether there are external tools which could trigger a library scan.
For example if there are automatic library scan activated, they can be triggered by external tools making changes in the media folder(s).
One common example, which is easily avoidable, is a crontab script which resets all access permissions in the media folders, by bluntly overwriting each and every file’s access perms.

Or maybe other apps from the *arr-family.

5

Yeah, that DB is way too small to cause a short 2-minute hang. Unless lots of changes are being made constantly to your DB. Btw it’s not actually crashing, PMS is just unresponsive during heavy DB optimization. If you look at the start and end of the optimization:

Oct 30, 2024 10:10:57.481 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Database optimization: starting.
Oct 30, 2024 10:10:57.481 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Activity: updated activity 08470f86-d653-49b0-b3fc-901e54bf7caa - completed 60.0% - Optimizing database
Oct 30, 2024 10:11:41.484 [127893956193080] DEBUG - [Req#6445f/Database optimization/com.plexapp.plugins.library.db] Database optimization: complete.

That’s about 2 minutes.

For troubleshooting purposes, disable the auto database optimization and that’ll indicate if some third-party is requesting it. The other thing is that this PMS auto db optimization only runs once a week, so if you’ve been experiencing this problem every day, then that should narrow it down to other apps causing this.

Another thing you can try is to disable Auto Empty Trash. Maybe your media drive is disappearing and then coming back, so Plex removes them and re-adds them again constantly. If Auto Empty Trash is turned off, it doesn’t remove items from the DB when your files disappear.

This is interesting… and it makes sense from my experience.

6

Thanks for the information. I have disabled the automatic database optimization to see if it happens again tomorrow.

I have not changed anything in my container stack, so it would be weird that any 3rd party app is doing stuff - but definitely it is a possibility.

I will get back to you tomorrow :slight_smile:

7

So, the automatic database optimization is not running anymore.

So I will now stop all my Docker containers that is integrating with Plex, and see which one is faulty.

I think Kometa - but at the same time, it has been running without issues for almost one year…