Intro Detection Crashing During Analyze: Plex won't let its Media Fingerprinter finish!

Plex Media Server NAS & Devices
, ,
1

Server Version#: 1.29.2.6364
Player Version#: 1.58.1.3380-ea159c52

I upgraded to a lifetime Plex Pass just a few days ago, and wanted to try the Intro Detection feature. So I went ahead and started analyzing one of my TV shows, just to test.
After the analysis process was complete, I never saw the “skip intro” button, so I was getting a bit worried of not doing things correctly.
My server is a Synology DS120J NAS, a cheap popular 1-bay NAS with a dual-core CPU, absolutely NOT a powerhouse, but fine for my usage (I only use direct play).
However, I am a bit of a tech nerd, so I turned on the logs to check what was happening.
I saw that the process of generating the “intro skip” marker is made of at least two parts:

  1. Plex Transcoder: it generates an “audio only” file from the video episode.
  2. Plex Media Fingerprinter: it creates an audio fingerprint from the transcoded audio, to then compare it with the others of the same season and find the matching audio to mark.

The (probable) bug that I found, is that Plex won’t let the Media Fingerprinter finish! My NAS is not fast enough to finish in time, so Plex kills it with a -9 signal while its Fingerprinter it’s working (probably it finds that it could be stuck when it’s not!). The Fingerprinter gets killed after exactly 60 seconds.

This happens with EVERY TV show on my NAS, so it’s not a file issue.

To crosscheck that my theory was correct, here’s what I did:

  1. Clicked “analyze” on the Web App
  2. Waited to let the Plex Transcoder create the audio file
  3. “Stole” the transcoded file, by copying it to another folder
  4. Ran the Plex Media Fingerprinter by myself on a shell (with the same parameters, taken from the logs), and, after 120 good seconds, it finished correctly, and generated the fingerprint!
  5. Checked the logs and yup, Plex killed the instance, while mine completed successfully (exit code: 0).

So, this seems an easy fix to implement: just increase the killing timer by a truly unrealistic amount for today’s CPUs (eg. 5 minutes, not just 60 seconds), so that Plex won’t kill the Fingerprinter on slower NAS CPUs, while still timing out if it gets stuck!

I’ll leave the logs here, one of the offending line is:

DEBUG - [Req#685] Killing job.
[Req#685] Signalling job ID 19823 with 9
DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter' exit code for process 19823 is -9 (signal: Killed)

Plex Media Server.1.log (1.4 MB)

2

Plex Media Server.3.log (3.0 MB)

Here’s another file where you can better see what’s happening (in the file I uploaded the first topic you can only see this one time: here, it happens maaaany more times).

3

Sorry to bother, but can anybody from Plex follow up on this? Currently, I have a Plex Pass but cannot use the Intro Skip feature due to this, on any of my shows. Furthermore, low-end NASes are super popular, so I’m sure I’m not the only one affected by this. It’s also very easy to reproduce, so I’d be super happy if this could get filed as a bug report, and get fixed in the upcoming versions of PMS!

4

From the log you provided (I would really like to see the ZIP file with all of them AND with VERBOSE turned OFF)

The CPU you have is a dual-core ARMv8 (NOT fast at all)

I see, what looks like, concurrent – VERBOSE is making it really messy / difficult

  1. Playback with transcode to Safari
Nov 29, 2022 22:23:32.013 [0x7f76fa9aa0] DEBUG - Request: [127.0.0.1:50156 (Loopback)] PUT /video/:/transcode/session/246e8f1e-d50b-49ff-8df8-a0307eb48cca/851f2fb7-f170-4284-b983-887ac8cc8b2b/progress?progress=6.8&size=78905344&remaining=382&speed=8.1 (9 live) #1b69 Signed-in Token (belgio99) (range: bytes=0-)  / Accept => */* / Connection => keep-alive / Host => 127.0.0.1:32400 / Icy-MetaData => 1 / Range => bytes=0- / User-Agent => Lavf/58.65.101 / X-Plex-Http-Pipeline => infinite / X-Plex-Token => xxxxxxxxxxxxxxxxxxxx43ee-bedb-7c0870ad8c82
Nov 29, 2022 22:23:32.030 [0x7f76fa9aa0] VERBOSE - [Req#1b69/Transcode/246e8f1e-d50b-49ff-8df8-a0307eb48cca/851f2fb7-f170-4284-b983-887ac8cc8b2b] It took 0.0 sec to serialize a list with 0 elements.
Nov 29, 2022 22:23:32.031 [0x7f7d886aa0] DEBUG - Completed: [127.0.0.1:50156] 206 PUT /video/:/transcode/session/246e8f1e-d50b-49ff-8df8-a0307eb48cca/851f2fb7-f170-4284-b983-887ac8cc8b2b/progress?progress=6.8&size=78905344&remaining=382&speed=8.1 (9 live) 18ms 355 bytes (pipelined: 93) (range: bytes=0-) 
Nov 29, 2022 22:23:32.040 [0x7f7da89aa0] VERBOSE - Didn't receive a request from 192.168.1.25:51829: Connection reset by peer

---
Nov 29, 2022 22:23:41.219 [0x7f82976590] DEBUG - Signalling job ID 20085 with 9
Nov 29, 2022 22:23:41.219 [0x7f82976590] DEBUG - Job was already killed, not killing again.
Nov 29, 2022 22:23:41.219 [0x7f82976590] DEBUG - Stopping transcode session 246e8f1e-d50b-49ff-8df8-a0307eb48cca
Nov 29, 2022 22:23:41.224 [0x7f7dccbaa0] VERBOSE - JobManager: child process with handle 20085 exited
Nov 29, 2022 22:23:41.224 [0x7f7dccbaa0] DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Transcoder' exit code for process 20085 is -9 (signal: Killed)
Nov 29, 2022 22:23:41.224 [0x7f793dfaa0] ERROR - [Req#685] IntroDetector: Failed to transcode file (-9): /volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E02 - Chapter Two - The Weirdo on Maple Street Bluray-2160p.mkv
Nov 29, 2022 22:23:41.406 [0x7f793dfaa0] DEBUG - [Req#685] Activity: updated activity 0c5f6524-b20f-4bdc-bd07-62d23bc10707 - completed 7.1% - Detecting intros
Nov 29, 2022 22:23:41.519 [0x7f82976590] DEBUG - Streaming Resource: Terminating session 0x7f7d4d27a8:246e8f1e-d50b-49ff-8df8-a0307eb48cca which is using static transcoder slot.  Used slots is now 0
Nov 29, 2022 22:23:41.519 [0x7f771acaa0] DEBUG - Job was already killed, not killing again.
Nov 29, 2022 22:23:41.519 [0x7f771acaa0] DEBUG - Job was already killed, not killing again.
Nov 29, 2022 22:23:41.519 [0x7f82976590] DEBUG - Streaming Resource: Terminated session 0x7f7d4d27a8:246e8f1e-d50b-49ff-8df8-a0307eb48cca with reason Client stopped playback.
Nov 29, 2022 22:23:41.520 [0x7f82976590] DEBUG - Streaming Resource: Removing session 0x7f7d4d27a8:246e8f1e-d50b-49ff-8df8-a0307eb48cca
Nov 29, 2022 22:23:41.520 [0x7f82976590] DEBUG - Transcoder: Cleaning old transcode directories.
  1. Intro detection - which is finally able to start but can’t with the server shutting down
Nov 29, 2022 22:23:41.752 [0x7f793dfaa0] DEBUG - [Req#685] It took 90.000000 ms to retrieve 1 items.
Nov 29, 2022 22:23:41.828 [0x7f793dfaa0] DEBUG - [Req#685] It took 60.000000 ms to retrieve 29 items.
Nov 29, 2022 22:23:41.839 [0x7f793dfaa0] DEBUG - [Req#685] IntroDetector: Initializing for "/volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E03 - Chapter Three - Holly, Jolly Bluray-2160p.mkv" (258)
Nov 29, 2022 22:23:41.853 [0x7f82976590] DEBUG - [com.plexapp.agents.imdb] Killing.
Nov 29, 2022 22:23:41.865 [0x7f7dccbaa0] WARN - JobManager: Could not find job for handle 16909

Not seeing a bug here yet.
I am seeing a very overloaded CPU.

You have 2160p HEVC HDR media. In software, on that ARM CPU – it will be slow and painful.

You have to wait.

To confirm there isn’t a bug, may I get a sample of the file ?

/volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E02 - Chapter Two - The Weirdo on Maple Street Bluray-2160p.mkv
5

Understood. I am so sorry that the logs are messy, and I completely understand that the CPU is slow. What I am seeing in the log I posted (not the first one, try checking the one I posted in the reply above), the lines that I want to point out are:

Plex Media Fingerprinter starts generating the fingerprint for the transcoded audio…

Nov 29, 2022 19:39:35.393 [0x7f72f95aa0] DEBUG - [Req#4765/JobRunner] Job running: "/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter" -raw -length 1529.509 "/var/packages/PlexMediaServer/shares/PlexMediaServer/AppData/Plex Media Server/Cache/Transcode/Detection/82749067-4367-4e09-8a1a-43bc656d38d0"

And then, after EXACTLY 60 seconds, with absolutely no input on my end in the meanwhile:

Nov 29, 2022 19:40:35.458 [0x7f72f95aa0] DEBUG - [Req#4765] Killing job.
Nov 29, 2022 19:40:35.458 [0x7f72f95aa0] DEBUG - [Req#4765] Signalling job ID 23673 with 9
Nov 29, 2022 19:40:35.459 [0x7f72f95aa0] DEBUG - [Req#4765] Activity: updated activity a2f11afe-bf04-4aa2-b2f4-4991ecaaa376 - completed 55.3% - Detecting intros
Nov 29, 2022 19:40:35.461 [0x7f7a1e9aa0] DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter' exit code for process 23673 is -9 (signal: Killed)

It gets killed, but it didn’t finish yet!
Then, the progress circle on the UI moves forward, as if it completed successfully (when it’s not!), and the same thing happens again with the following episode:

Nov 29, 2022 19:42:58.790 [0x7f72f95aa0] DEBUG - [Req#4765/JobRunner] Job running: "/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter" -raw -length 1271.4614999999999 "/var/packages/PlexMediaServer/shares/PlexMediaServer/AppData/Plex Media Server/Cache/Transcode/Detection/651fdfe1-516a-444c-a5db-9e6002cb68f1"
Nov 29, 2022 19:42:58.800 [0x7f72f95aa0] DEBUG - [Req#4765/JobRunner] Jobs: Starting child process with pid 23973

After 60 seconds:

Nov 29, 2022 19:43:58.861 [0x7f72f95aa0] DEBUG - [Req#4765] Killing job.
Nov 29, 2022 19:43:58.861 [0x7f72f95aa0] DEBUG - [Req#4765] Signalling job ID 23973 with 9
Nov 29, 2022 19:43:58.862 [0x7f72f95aa0] DEBUG - [Req#4765] Activity: updated activity a2f11afe-bf04-4aa2-b2f4-4991ecaaa376 - completed 60.6% - Detecting intros
Nov 29, 2022 19:43:58.864 [0x7f7a1e9aa0] DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter' exit code for process 23973 is -9 (signal: Killed)

The same thing goes on for the rest of the season…and here, the server was NOT shutting down.
I ran the Fingerprinter by myself on a shell, and on average, I saw that it takes about 120 seconds to fully complete. Here, Plex only gives it 60 seconds, and then it straight up kills it and starts transcoding the following episode.
Then, when the process is fully “complete”, or at least Plex says it is, no Intro Skip markers are generated (there are none in the XML file, and the Skip Intro button does not appear).

About the logs: I just turned off the verbose option, and I’ll generate new logs ASAP. In the meanwhile, can you tell me if my explanation was clearer? I completely understand that it’s not a super straightforward thing to see, and the fact that it happens only on low-end CPUs make it even harder to see.

About the file: how can I send it to you? It’s pretty big (more than 1 GB)

6

@ChuckPa
Here are the full logs!

This time, they are much more readable. In the newest file, “Plex Media Server.log”, I started a new and clean job on detecting intros. No other processes were going on. If you wanna search for it, the starting line of when I clicked “analyze” in the UI is:

Dec 01, 2022 22:43:57.879 [0x7f737ecaa0] DEBUG - [Req#24b] BackgroundTaskQueue: creating activity container for "media.generate.intros"

The problem occurred, even this time:

Dec 01, 2022 22:48:18.927 [0x7f71641aa0] DEBUG - [Req#24b] Killing job.
Dec 01, 2022 22:48:18.938 [0x7f71641aa0] DEBUG - [Req#24b] Signalling job ID 23182 with 9
Dec 01, 2022 22:48:18.940 [0x7f758bdaa0] DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Media Fingerprinter' exit code for process 23182 is -9 (signal: Killed)
Dec 01, 2022 22:48:19.370 [0x7f71641aa0] DEBUG - [Req#24b] Activity: updated activity c8509ba0-af02-4ce8-9289-a8d1dc0e5c92 - completed 10.6% - Detecting intros

And as you can see, I let it complete to 100% anyway:

Dec 01, 2022 23:18:29.387 [0x7f71641aa0] DEBUG - [Req#24b] Activity: updated activity c8509ba0-af02-4ce8-9289-a8d1dc0e5c92 - completed 100.0% - Detecting intros

but nothing, no Intro Skip markers generated. Each time, the Fingerprinter got killed at exactly 60 seconds, well short of the 140/160 seconds it needs to generate the fingerprint on slower CPUs…

As you can see, it does the exact same thing I wrote in the reply just above this one (that was a previous run), so the issue is easily reproducible on my end. It happens even with all the other TV shows, so I don’t think it’s a file issue, but let me know if you want the file anyway.

Hope to hear you back soon, and thank you so much for your support.

Plex Media Server Logs_2022-12-01_23-19-04.zip (3.6 MB)

7 
Dec 01, 2022 22:43:57.879 [0x7f737ecaa0] DEBUG - [Req#24b] Scheduling an intro detection job for 255
Dec 01, 2022 22:43:57.879 [0x7f737ecaa0] DEBUG - [Req#24b] BackgroundTaskQueue: creating activity container for "media.generate.intros"
Dec 01, 2022 22:43:57.894 [0x7f737ecaa0] DEBUG - [Req#24b] Activity: registered new activity c8509ba0-af02-4ce8-9289-a8d1dc0e5c92 - "Detecting intros"
Dec 01, 2022 22:43:57.927 [0x7f6ecb4aa0] DEBUG - [Req#19a] Selected a foreign audio track: en
Dec 01, 2022 22:43:57.927 [0x7f6ecb4aa0] DEBUG - [Req#19a] Subtitles: Found a candidate subtitle language [en] for a foreign film
Dec 01, 2022 22:43:57.927 [0x7f6ecb4aa0] DEBUG - [Req#19a] Audio Stream: 3200, Subtitle Stream: 3201
Dec 01, 2022 22:43:58.001 [0x7f737ecaa0] DEBUG - [Req#24b] Activity: registered new sub-activity 85aa471f-6494-4968-8947-d10bf4dab46f - "Stranger Things S1" parent: c8509ba0-af02-4ce8-9289-a8d1dc0e5c92 overall progress: 0.0% (0/1)
Dec 01, 2022 22:43:58.002 [0x7f7567aaa0] DEBUG - Completed: [127.0.0.1:50992] 200 PUT /library/metadata/255/intro?force=0 (14 live) GZIP 271ms 195 bytes (pipelined: 25)
Dec 01, 2022 22:43:58.017 [0x7f758bdaa0] DEBUG - Jobs: '/volume1/@appstore/PlexMediaServer/Plex Media Scanner' exit code for process 21900 is 0 (success)
Dec 01, 2022 22:43:58.019 [0x7f7567aaa0] DEBUG - Completed: [192.168.1.6:53463] 200 PUT /library/metadata/255/analyze (14 live) TLS GZIP 8025ms 195 bytes (pipelined: 10)
Dec 01, 2022 22:43:58.046 [0x7f71641aa0] DEBUG - [Req#24b] Activity: updated activity c8509ba0-af02-4ce8-9289-a8d1dc0e5c92 - completed 0.0% - Detecting intros
Dec 01, 2022 22:43:58.060 [0x7f71641aa0] DEBUG - [Req#24b] IntroDetector: Running intro detection for [255] [Stranger Things] [1]
Dec 01, 2022 22:43:58.140 [0x7f7567aaa0] DEBUG - Completed: [192.168.1.6:53460] 200 GET /library/metadata/263?skipRefresh=1 (13 live) TLS GZIP 442ms 2653 bytes (pipelined: 13)
Dec 01, 2022 22:43:58.152 [0x7f71641aa0] DEBUG - [Req#24b] IntroDetector: Initializing for "/volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E01 - Chapter One - The Vanishing of Will Byers Bluray-2160p.mkv" (256)
Dec 01, 2022 22:43:58.174 [0x7f70b0daa0] DEBUG - Request: [192.168.1.6:53383 (Subnet)] GET /statistics/bandwidth?timespan=6 (13 live) #225 TLS GZIP Signed-in Token (belgio99) (Safari)
Dec 01, 2022 22:43:58.182 [0x7f7567aaa0] DEBUG - Completed: [192.168.1.6:53383] 200 GET /statistics/bandwidth?timespan=6 (13 live) TLS GZIP 8ms 1266 bytes (pipelined: 53)
Dec 01, 2022 22:43:58.410 [0x7f71641aa0] DEBUG - [Req#24b] Downloading document http://127.0.0.1:32400/library/metadata/256
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] We're going to try to auto-select an audio stream for account 1.
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] Selecting best audio stream for part ID 878 (autoselect: 0 language: xn)
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] We're going to try to auto-select a subtitle.
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] Selected a foreign audio track: en
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] Subtitles: Found a candidate subtitle language [en] for a foreign film
Dec 01, 2022 22:43:58.467 [0x7f71641aa0] DEBUG - [Req#24b/Req#271] Audio Stream: 3179, Subtitle Stream: 3180
Dec 01, 2022 22:43:58.522 [0x7f71641aa0] WARN - [Req#24b] MDE: unable to find a working transcode profile for video stream
Dec 01, 2022 22:43:58.523 [0x7f71641aa0] WARN - [Req#24b] MDE: unable to find a working transcode profile for video stream
Dec 01, 2022 22:43:58.524 [0x7f71641aa0] DEBUG - [Req#24b] Cleaning directory for session d6f8864a-a600-4600-941f-5e8856d7f2ee ()
Dec 01, 2022 22:43:58.579 [0x7f71641aa0] DEBUG - [Req#24b] Starting a transcode session d6f8864a-a600-4600-941f-5e8856d7f2ee at offset -1.0 (state=3)
Dec 01, 2022 22:43:58.580 [0x7f71641aa0] DEBUG - [Req#24b] Streaming Resource: Added session 0x7f74900378:d6f8864a-a600-4600-941f-5e8856d7f2ee
Dec 01, 2022 22:43:58.636 [0x7f71641aa0] DEBUG - [Req#24b] [Universal] Using local file path instead of URL: /volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E01 - Chapter One - The Vanishing of Will Byers Bluray-2160p.mkv
Dec 01, 2022 22:43:58.636 [0x7f71641aa0] DEBUG - [Req#24b] TPU: hardware transcoding: final decoder: , final encoder: 
Dec 01, 2022 22:43:58.638 [0x7f71641aa0] DEBUG - [Req#24b/JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/var/packages/PlexMediaServer/shares/PlexMediaServer/AppData/Plex\ Media\ Server/Codecs/c4efa15-4387-linux-aarch64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx4dca-a129-6271aceed946 "/volume1/@appstore/PlexMediaServer/Plex Transcoder" -codec:1 ac3 -analyzeduration 20000000 -probesize 20000000 -i "/volume1/video/TV Shows/Stranger Things/Season 1/Stranger Things - S01E01 - Chapter One - The Vanishing of Will Byers Bluray-2160p.mkv" -filter_complex "[0:1] aresample=async=1:ocl='5.1':rematrix_maxval=0.000000dB:osr=48000[0]" -map "[0]" -metadata:s:0 language=eng -codec:0 flac -b:0 4096k -f flac -map_metadata -1 -map_chapters -1 -t 1426.432 "/var/packages/PlexMediaServer/shares/PlexMediaServer/AppData/Plex Media Server/Cache/Transcode/Detection/06e6f386-984c-4788-bfd9-fb32dc826397" -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress
Dec 01, 2022 22:43:58.644 [0x7f71641aa0] DEBUG - [Req#24b/JobRunner] Jobs: Starting child process with pid 21935
Dec 01, 2022 22:43:58.865 [0x7f737ecaa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=startup (14 live) #17a Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:58.870 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 204 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=startup (14 live) 5ms 203 bytes (pipelined: 1) (range: bytes=0-) 
Dec 01, 2022 22:43:59.181 [0x7f70b0daa0] DEBUG - Request: [192.168.1.6:53383 (Subnet)] GET /statistics/bandwidth?timespan=6 (14 live) #270 TLS GZIP Signed-in Token (belgio99) (Safari)
Dec 01, 2022 22:43:59.188 [0x7f6e8aeaa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=startup (14 live) #275 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.189 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 204 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=startup (14 live) 1ms 203 bytes (pipelined: 2) (range: bytes=0-) 
Dec 01, 2022 22:43:59.191 [0x7f6e2a5aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=opening (14 live) #276 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.194 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 204 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=opening (14 live) 3ms 203 bytes (pipelined: 3) (range: bytes=0-) 
Dec 01, 2022 22:43:59.200 [0x7f737ecaa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=opened (14 live) #277 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.202 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 204 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?status=opened (14 live) 2ms 203 bytes (pipelined: 4) (range: bytes=0-) 
Dec 01, 2022 22:43:59.204 [0x7f6e4a8aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/stream?index=0&id=0&codec=hevc&type=video (14 live) #278 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.205 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 200 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/stream?index=0&id=0&codec=hevc&type=video (14 live) 1ms 195 bytes (pipelined: 5) (range: bytes=0-) 
Dec 01, 2022 22:43:59.208 [0x7f75477aa0] DEBUG - Completed: [192.168.1.6:53383] 200 GET /statistics/bandwidth?timespan=6 (14 live) TLS GZIP 27ms 1274 bytes (pipelined: 54)
Dec 01, 2022 22:43:59.213 [0x7f6ecb4aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/stream?index=1&id=0&codec=ac3&type=audio (14 live) #279 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.215 [0x7f7567aaa0] DEBUG - Completed: [127.0.0.1:50994] 200 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/stream?index=1&id=0&codec=ac3&type=audio (14 live) 2ms 195 bytes (pipelined: 6) (range: bytes=0-) 
Dec 01, 2022 22:43:59.419 [0x7f6e8aeaa0] DEBUG - Request: [192.168.1.6:53460 (Subnet)] GET /library/metadata/255/children?excludeAllLeaves=1&includeUserState=1 (13 live) #26f TLS Page 0-7 GZIP Signed-in Token (belgio99) (MACBOOKPRO-7FC8.station)
Dec 01, 2022 22:43:59.441 [0x7f6e8aeaa0] DEBUG - [Req#26f] Setting container serialization range to [0, 7] (total=-1)
Dec 01, 2022 22:43:59.470 [0x7f6e8aeaa0] DEBUG - [Req#26f] Setting container serialization range to [0, 7] (total=8)
Dec 01, 2022 22:43:59.481 [0x7f75477aa0] DEBUG - Completed: [192.168.1.6:53460] 200 GET /library/metadata/255/children?excludeAllLeaves=1&includeUserState=1 (13 live) TLS GZIP Page 0-7 61ms 3333 bytes (pipelined: 14)
Dec 01, 2022 22:43:59.520 [0x7f6e2a5aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main%2010&width=3840&height=1920&interlaced=0&sar=1:1&level=153&frameRate=23.976&disp_default=1 (13 live) #27b Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.521 [0x7f7567aaa0] DEBUG - Completed: [127.0.0.1:50994] 200 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main%2010&width=3840&height=1920&interlaced=0&sar=1:1&level=153&frameRate=23.976&disp_default=1 (13 live) 1ms 195 bytes (pipelined: 7) (range: bytes=0-) 
Dec 01, 2022 22:43:59.523 [0x7f737ecaa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=1&id=0&codec=ac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (13 live) #282 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.524 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 200 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=1&id=0&codec=ac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (13 live) 1ms 195 bytes (pipelined: 8) (range: bytes=0-) 
Dec 01, 2022 22:43:59.525 [0x7f6e4a8aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=2&id=0&codec=hdmv_pgs_subtitle&type=subtitle&language=eng (13 live) #283 Signed-in Token (belgio99) (range: bytes=0-) 
Dec 01, 2022 22:43:59.526 [0x7f75477aa0] DEBUG - Completed: [127.0.0.1:50994] 200 PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress/streamDetail?index=2&id=0&codec=hdmv_pgs_subtitle&type=subtitle&language=eng (13 live) 1ms 195 bytes (pipelined: 9) (range: bytes=0-) 
Dec 01, 2022 22:43:59.563 [0x7f6ecb4aa0] DEBUG - Request: [127.0.0.1:50994 (Loopback)] PUT /video/:/transcode/session/d6f8864a-a600-4600-941f-5e8856d7f2ee/d45f55f2-b8fb-4c43-a3aa-524a176411cb/progress?duration=2852.864000 (13 live) #284 Signed-in Token (belgio99) (range: bytes=0-)

I think I see something . Please confirm for me?

  1. The default language track of the video isn’t what you want
  2. You want PMS to find the intro marker (audio) for your selected language
  3. That language is code xn ???
Dec 01, 2022 22:46:40.412 [0x7f6e4a8aa0] DEBUG - We're going to try to auto-select an audio stream for account 1.
Dec 01, 2022 22:46:40.414 [0x7f6e4a8aa0] DEBUG - Selecting best audio stream for part ID 492 (autoselect: 0 language: xn)
Dec 01, 2022 22:46:40.415 [0x7f6e4a8aa0] DEBUG - We're going to try to auto-select a subtitle.
Dec 01, 2022 22:46:40.416 [0x7f6e4a8aa0] DEBUG - Selected a foreign audio track: 
Dec 01, 2022 22:46:40.418 [0x7f6e4a8aa0] DEBUG - Subtitles: Found a candidate subtitle language [] for a foreign film
Dec 01, 2022 22:46:40.419 [0x7f6e4a8aa0] DEBUG - Audio Stream: 1504, Subtitle Stream: 1503
Dec 01, 2022 22:46:40.425 [0x7f6e4a8aa0] DEBUG - We're going to try to auto-select an audio stream for account 1.
Dec 01, 2022 22:46:40.427 [0x7f6e4a8aa0] DEBUG - Selecting best audio stream for part ID 491 (autoselect: 0 language: xn)
Dec 01, 2022 22:46:40.428 [0x7f6e4a8aa0] DEBUG - We're going to try to auto-select a subtitle.
Dec 01, 2022 22:46:40.430 [0x7f6e4a8aa0] DEBUG - Selected a foreign audio track: en

If I’m reading it right, then it’ll never resolve (not handling the resolution is a problem) because there is no ISO language listed for ‘xn’ .

8

xn should be the code for “no preferred languages”, that’s how I have it set up in Plex. However, I don’t think this is related because I literally changed to this like two days ago just to try exactly if I could fix this issue. Before, it was set to English, but it didn’t do any difference.
Furthermore, all my TV shows only have one language track, so even if I set it to a different preferred one, in the end it would still select that track.

9

I need to check with the engineers on the XN vs Default track.

I’d like to ask how these shows open?

Do they have audio the instant they begin then pause only slightly (or not at all) before the main program begins?

I am asking because if the audio gap is too short - I know it won’t detect it.
( I will also find out what that minimum window is )

10

Nope, the intro is like 1 or 2 minutes into the show, so it should be easily detectable.

However, If you want more info on this:
The language selection is done right. I copied one of the transcoded files on my PC, before the fingerprinter got killed, renamed to .ac3, and tried to open it with VLC. The file is valid, and it contains the English audio track, so the selection, even if set to xn in the preferences, in the end is en. The problem is just Plex killing the Fingerprinter while generating the fingerprint (probably, exceeding some timeout set a bit too tight: 1 minute is not enough on slow CPUs, in fact, the problem does not appear on fast CPUs: they take less than a minute to generate the fingerprint).

11

Thanks.

Having dug deeper into this, there does appear to be a problem with how failures (can’t find intro in time) is handled.

I’m writing it up now for Engineering to review and work on.

For now, what if you turn off intro detection?

Does PMS recover?

If so, I’d like you to continue this way while Engineering works on this.

12

Yes, for now, I turned off intro detection, that’s the only thing I could do. PMS recovered normally.

May I ask you to link this thread in what you’re writing to Engineering? Maybe the explanation I gave in the first post, and the log explaining I did in the reply, could be useful for them, to better identify the timeout issue!

Also, if the engineers want to follow up to me with any questions or tests, you can let them know that they can contact me by replying on this topic, or on DMs! I’d be happy to have Intro Skip working! And, with me, I’m sure that lots of low-end NAS owners would want as well!

13

I’ve linked this thread and also linked your log files (please leave them here) for Engineering to see what’s happening. ( I always link the threads & logs )

If they have any questions, they will reach out to you

1 Like
14

Found another post talking about the same issue, so I wanted to link it here, but the proposed workaround does not work on 1-track TV shows, and this bug can happen even of fast CPUs if the show is long enough. On slower CPUs it can happen even on shorter shows.

I have had the same exact behaviour yesterday, while trying to analyze intros on a Raspberry Pi. It times out at 60 seconds, but the Pi needs more time to generate the fingerprint!

The fix is really super easy (just change the timeout to 5 or 10 minutes instead of just 60 seconds).

Intro detection is an offline process so it’s not a problem if it takes more time on slow CPUs. And, if it gets stuck, timing out after 5 minutes is reasonable.

15

Thanks for linking it.

I checked today and Engineering has now assigned an engineer to work on it.

2 Likes
16

@ChuckPa Any news on this? I am experiencing this issue on a DS1821+ NAS which has a AMD Ryzen Embedded V1500B using PMS 1.30.2.6563.

17

I bought a much faster server (DS720+) so I’m not experiencing it anymore, but it should just have been fixed in the latest public version of PMS!

https://forums.plex.tv/t/plex-media-server/30447/554

Marking this as solved, thanks @ChuckPa!!

1 Like
18

Still happening here with 1.31.1.6716. Worth noting the CPU doesn’t seem to have any graphics but surely it should be done in software? I also don’t seem to be able to transcode anything.

Feb 17, 2023 13:39:54.000 [0x7f66a9965b38] Error — [Req#449/Transcode/8bc753ab-34ec-4b35-bedc-3b24af9d46c0/0cfa8443-b2f4-4dfe-b674-2c1d74f0a17c] [eac3_eae @ 0x7f75f7c24740] EAE timeout! EAE not running, or wrong folder? Could not read '/tmp/pms-5f85a1c0-d888-4f64-8d0e-621971ee47eb/EasyAudioEncoder/Convert to WAV (to 8ch or less)/8bc753ab-34ec-4b35-bedc-3b24af9d46c0_380-0-1.wav'
Feb 17, 2023 13:39:54.001 [0x7f66ac94fb38] Error — [Req#45d/Transcode/8bc753ab-34ec-4b35-bedc-3b24af9d46c0/0cfa8443-b2f4-4dfe-b674-2c1d74f0a17c] [eac3_eae @ 0x7f75f7c24740] error reading output: -5 (I/O error)
19

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