PLEX movie issue - CPU death spiral

I’ve already provided debug logging, a copy of my database and reliable steps to recreate the issue multiple times. We had many DM’s back and forth last year up to October.

The taggings table that I mentioned then and multiple times since is the cause of the issue, I’ve asked why they’re being added but never heard anything.

Clearing the excess garbage rows that are generated when movie posters are changed 100% resolves the issue, and I’ve been doing daily ever since.

@carrousel5301

To whom did you give/send your logs?

Asking because the ONLY logs I see here are from either 2023 or with INFO/ERROR only.

This same issue is in multiple threads that I’ve posted in, and the logs I’ve posted from 2023 are still relevant from today. Including the copy of the database and the steps I provided to replicate the issue.

Really, the only thing that needs to happen is to ask why so many junk entries are being added to the taggings table when a movie item has it’s poster set manually. It’s crazy. With a large library there are millions of excess rows.

may I ask for this info?

Sqlite from com.plexapp.plugins.library.db

select count(*) from media_parts;
select count(*) from media_items;
select count(*) from metadata_items;
select count(*) from metadata_relations;

This will tell me if your database has the programmed number of alternatives or has gotten bloated to all heck.

@freezegunn47 can you please enable debugging, reproduce the issue, and share your debug logs?

I was not able to reproduce with the steps you’ve provided with similar media.

@carrousel5301 I wasn’t able to quickly find any previous posts with complete logs or a DB. Can you provide fresh debug logs and a copy of your DB? I’m not expecting @ChuckPa to have held anything from 2023. Lets work with what’s current.

@Atomatth & @ChuckPa

Debug Logs, my friend reproduced the issue on their Samsung device and I did it as well on my Apple TV.

DEBUG - Plex Media Server Logs_2024-05-10_17-09-51.zip (938.4 KB)

Thank you for taking the time to look into this

@freezegunn47

Is this one of the failures?

May 10, 2024 17:00:52.788 [10484] DEBUG - Auth: authenticated user 276612012 as Haley L
May 10, 2024 17:00:52.788 [12608] DEBUG - Request: [98.204.254.155:52496 (WAN)] GET /video/:/transcode/universal/session/08f781ac-5633-4903-88be-0d57e4e24175-26/base/00135.ts?protocol=hls&mediaIndex=0&waitForSegments=1&videoQuality=60&session=08f781ac-5633-4903-88be-0d57e4e24175-26&maxVideoBitrate=1500&mediaBufferSize=50000&offset=629&partIndex=0&videoResolution=720x480&directPlay=0&path=%2Flibrary%2Fmetadata%2F418157&directStream=1&subtitles=auto (47 live) #95a TLS Signed-in Token (Haley L)
May 10, 2024 17:00:52.788 [12608] DEBUG - [Req#95a/Transcode/08f781ac-5633-4903-88be-0d57e4e24175-26] Asked for segment 135 from session.
May 10, 2024 17:00:52.788 [12608] DEBUG - [Req#95a/Transcode/08f781ac-5633-4903-88be-0d57e4e24175-26] Returning segment 135 from session
May 10, 2024 17:00:52.788 [12608] DEBUG - Content-Length of G:\PLEX\Transcode\Sessions\plex-transcode-08f781ac-5633-4903-88be-0d57e4e24175-26-f17d463a-6494-4d9e-8c81-a6bb5d587c37\media-00135.ts is 1210720 (of total: 1210720).
May 10, 2024 17:00:52.788 [10484] DEBUG - Auth: authenticated user 276612012 as Haley L
May 10, 2024 17:00:52.788 [12616] DEBUG - Request: [98.204.254.155:52497 (WAN)] GET /video/:/transcode/universal/session/08f781ac-5633-4903-88be-0d57e4e24175-26/base/00135.ts?protocol=hls&mediaIndex=0&waitForSegments=1&videoQuality=60&session=08f781ac-5633-4903-88be-0d57e4e24175-26&maxVideoBitrate=1500&mediaBufferSize=50000&offset=629&partIndex=0&videoResolution=720x480&directPlay=0&path=%2Flibrary%2Fmetadata%2F418157&directStream=1&subtitles=auto (47 live) #90f TLS Signed-in Token (Haley L)
May 10, 2024 17:00:52.788 [12616] DEBUG - [Req#90f/Transcode/08f781ac-5633-4903-88be-0d57e4e24175-26] Asked for segment 135 from session.
May 10, 2024 17:00:52.788 [12616] DEBUG - [Req#90f/Transcode/08f781ac-5633-4903-88be-0d57e4e24175-26] Returning segment 135 from session
May 10, 2024 17:00:52.788 [10484] DEBUG - Completed: [192.168.47.200:50382] 200 POST /playQueues?continuous=0&extrasPrefixCount=0&includeExternalMedia=1&includeLoudnessRamps=1&recursive=0&shuffle=0&type=video&uri=server%3A%2F%2F7430e7503a6c9a9f7b5e9217■■■3bce58ad0f9f4%2Fcom.plexapp.plugins.library%2Flibrary%2Fmetadata%2F32187 (47 live) #5e0 TLS GZIP 207668ms 551 bytes (pipelined: 4)
May 10, 2024 17:00:52.788 [12616] DEBUG - Content-Length of G:\PLEX\Transcode\Sessions\plex-transcode-08f781ac-5633-4903-88be-0d57e4e24175-26-f17d463a-6494-4d9e-8c81-a6bb5d587c37\media-00135.ts is 1210720 (of total: 1210720).
May 10, 2024 17:00:52.788 [10484] DEBUG - handleStreamWrite code 10054: An existing connection was forcibly closed by the remote host
May 10, 2024 17:00:52.788 [10484] DEBUG - NotificationStream: Removing because of error
May 10, 2024 17:00:52.788 [10484] DEBUG - Completed after connection close: [74.139.24.90:57339] 200 GET /:/eventsource/notifications (48 live) #266 TLS 241158ms 198 bytes
May 10, 2024 17:00:52.789 [10484] DEBUG - handleStreamWrite code 10054: An existing connection was forcibly closed by the remote host
May 10, 2024 17:00:52.789 [4524] DEBUG - BPQ: generating queue items from 0 generator(s)
May 10, 2024 17:00:52.789 [4524] DEBUG - BPQ: generated 0 item(s) for queue
May 10, 2024 17:00:52.789 [10484] DEBUG - NotificationStream: Removing because of error
May 10, 2024 17:00:52.789 [10484] DEBUG - Completed after connection close: [192.168.47.200:50377] 200 GET /:/eventsource/notifications (47 live) #192 TLS GZIP 246271ms 45470 bytes (pipelined: 1)
May 10, 2024 17:00:52.789 [10484] DEBUG - handleStreamWrite code 10054: An existing connection was forcibly closed by the remote host
May 10, 2024 17:00:52.789 [10484] DEBUG - NotificationStream: Removing because of error
May 10, 2024 17:00:52.789 [10484] DEBUG - Completed after connection close: [96.244.233.117:60526] 200 GET /:/eventsource/notifications (46 live) #262 TLS 241366ms 220 bytes
May 10, 2024 17:00:52.789 [12616] DEBUG - Request: [127.0.0.1:61241 (Loopback)] GET /servers (42 live) #955 GZIP Signed-in Token (freezegunn)
May 10, 2024 17:00:52.789 [12608] DEBUG - [Req#98b/Transcode/08f781ac-5633-4903-88be-0d57e4e24175-26/f17d463a-6494-4d9e-8c81-a6bb5d587c37] Throttle - Getting back to work.
May 10, 2024 17:00:52.791 [10484] DEBUG - [EventSourceClient/pubsub/172.104.213.234:443] Failure: 10009 - The file handle supplied is not valid.
May 10, 2024 17:00:52.791 [10484] DEBUG - [EventSourceClient/pubsub/172.104.213.234:443] MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
May 10, 2024 17:00:52.791 [10484] ERROR - [EventSourceClient/pubsub/172.104.213.234:443] Retrying in 15 seconds.
May 10, 2024 17:00:52.791 [10484] DEBUG - Failed to stream media, client probably disconnected after 16384 bytes: 167772367 - protocol is shutdown (SSL routines)
May 10, 2024 17:00:52.791 [10484] DEBUG - Completed after connection close: [98.204.254.155:52496] 200 GET /video/:/transcode/universal/session/08f781ac-5633-4903-88be-0d57e4e24175-26/base/00135.ts?protocol=hls&mediaIndex=0&waitForSegments=1&videoQuality=60&session=08f781ac-5633-4903-88be-0d57e4e24175-26&maxVideoBitrate=1500&mediaBufferSize=50000&offset=629&partIndex=0&videoResolution=720x480&directPlay=0&path=%2Flibrary%2Fmetadata%2F418157&directStream=1&subtitles=auto (38 live) #95a TLS 3ms 16384 bytes (pipelined: 5)
May 10, 2024 17:00:52.791 [10484] DEBUG - Failed to stream media, client probably disconnected after 16384 bytes: 167772367 - protocol is shutdown (SSL routines)
May 10, 2024 17:00:52.791 [10484] DEBUG - Completed after connection close: [98.204.254.155:52497] 200 GET /video/:/transcode/universal/session/08f781ac-5633-4903-88be-0d57e4e24175-26/base/00135.ts?protocol=hls&mediaIndex=0&waitForSegments=1&videoQuality=60&session=08f781ac-5633-4903-88be-0d57e4e24175-26&maxVideoBitrate=1500&mediaBufferSize=50000&offset=629&partIndex=0&videoResolution=720x480&directPlay=0&path=%2Flibrary%2Fmetadata%2F418157&directStream=1&subtitles=auto (38 live) #90f TLS 3ms 16384 bytes (pipelined: 3)
May 10, 2024 17:00:52.791 [10484] DEBUG - Completed: [127.0.0.1:61241] 200 GET /servers (39 live) #955 GZIP 2ms 495 bytes
May 10, 2024 17:00:52.791 [10484] DEBUG - Completed: [192.168.47.200:50383] 200 GET /hubs/metadata/32187/related?includeAugmentations=1&includeExternalMetadata=1&includeMeta=1 (39 live) #5b9 TLS GZIP 208709ms 11562 bytes (pipelined: 2)
May 10, 2024 17:00:52.792 [10484] DEBUG - Removed transcode data consumer, active count 2 => 1
May 10, 2024 17:00:52.792 [10484] DEBUG - Removed transcode data consumer, active count 1 => 0
May 10, 2024 17:00:52.792 [10484] DEBUG - CERT: incomplete TLS handshake from 192.168.47.200:50407: An established connection was aborted by the software in your host machine
May 10, 2024 17:00:52.793 [10484] DEBUG - CERT: incomplete TLS handshake from 98.204.254.155:52498: stream truncated
May 10, 2024 17:00:52.793 [10484] DEBUG - CERT: incomplete TLS handshake from 174.24.74.203:48615: stream truncated

The Haley Stream no, but way down where it says the IP addresses the .200 was my Apple TV attempt which did crash/not play.

How come every time someone from PLEX actually looks into this issue they just stop responding…

Right? Absolutely amazing that a fairly common bug that literally breaks their entire service is pretty much ignored. It’s been how long since we first reported the issue? I’m literally up and replying right now because I just tried playing a movie on the AppleTV in my bedroom and it caused my server to crash. Nothing I love more than having to get up out of bed and triage my Plex server because I had the audacity to try and play one of the movies in my collection…

1 Like

I ended up running this process. I had over 250k entries from the 1st line of the script and now have purged them all. So far PLEX is running faster than it’s run in a while and I no movie playing crashes. Will test more today.

1 Like

I’ve also been running carrousel5301’s script daily for the last couple months, and have no longer encountered this issue. (Thanks carrousel!)

Is there a way to run this if our install is not in docker? Mine is just a native Windows 10 install. Not familiar enough to know how to modify it myself.

Use the instructions here to open your PLEX database with the PLEX SQLite tool:
https://support.plex.tv/articles/repair-a-corrupted-database/

Then run the database command mentioned above:
"DELETE FROM taggings WHERE tag_id IN (SELECT tag_id FROM taggings WHERE text LIKE '%image.tmdb.org%' OR text LIKE '%artworks.thetvdb.com%' OR text LIKE '%metadata-static.plex.tv%');"

crickets

Why is the only solution here a user made SQL script that requires advanced understanding of what you’re doing so that your server doesn’t crash.

Or, never change movie posters EVER from the weird ugly ones the agent picks now.

2 Likes

@mkplx @carrousel5301 Is there a specific reason for running it daily? If you didn’t run it daily would the issue of failure to start playback return?

It sounds like, at one point there was an issue that has since been resolved, where the taggings field was collecting too much data. So I’m thinking that the collection portion of the issue is resolved but older entries were not cleaned up, so then running this DELETE command once should be sufficient. I don’t know enough of the history around this issue but I’m still digging.

One problem going forward is that if you did run the DELETE command then it will make our troubleshooting the root cause more difficult. So now asking for logs or DBs for anyone how has ran this won’t be helpful unless the issue returns.

@freezegunn47 What does your case look like now? You’ve ran the DELETE command, now what? Are you continuously running it on a schedule or one and done? Can you hold off on running it again to see if the issue returns? If the issue does return can you please have Debugging enabled and reproduce the issue?

@jonnyatlas Have you not been able to run the SQL commands still? If not, could you please enable Debugging, reproduce the issue, download your logs and DB and share them with me?

@Atomatth - Everything works perfectly smoothy. I only run the script when I add a bunch of movies and change the posters from the default ones the movie agent pics. If i only add 1-2 movies and change them I do things the old manual tedious way.

After I ran this script the 1st time it “fixed” every movie that had the issue in the past until now.

Manual fix for this issue:

  • Add movie, hate poster
  • Change Poster
  • Manually “fix match”
  • Analyze data

@freezegunn47 If you do not run the script do you observe the issue of failure to start playback?

Not sure why you’d need to manually “fix match” or run an analyze. Was the movie not matched initially?

@Atomatth That’s kind of the point of this entire thread…

Some people are having this weird issue where you add a movie (always a movie, never series), that’s x265 to PLEX, and then change the default poster it picks to something not ugly and covered with text. Once you do that simple thing, the movie will randomly never play and in fact bring down your entire server with long stale SQL queries whenever a user tries to play the movie. The only known fix, after users working on this issue for a year now on their own, is to manually “fix match” and then analyze the movie afterwards which most of the time makes the movie playable again.

A while back @carrousel5301 discovered the issue is due to bad metadata these movies have there’s a post far up in the thread where they explain in detail what specifically is wrong. The short version is : “many junk entries are being added to the taggings table when a movie item has it’s poster set”

Now when I add a movie, if I change the poster I have to do the manual fix mentioned above or it’s likely the movie will never play and become a time bomb waiting for a user to play and bring down my server. If I add a bunch of movies and fix their posters I use the script because it’s faster than refreshing every changed poster movie by hand.

@freezegunn47 now that you have ran that script and cleared out any old “junk”, when you add something new and:

  1. do not change the poster, does it play?
  2. change the poster, does it play?

As I mentioned above, I’m not able to reproduce this issue so I need to rely on anyone who is observing the issue for troubleshooting. This script is potentially a band-aid at best while the root cause is still unknown. If you are able to still reproduce the issue, please enable debug logging and share your server logs and DB after capturing the issue.

Also, if you are willing can you please provide the output from the commands in @ChuckPa post or I can if you share your DB :grin:?