Help Reading Deep Analysis Log

Server Version#: 1.23.0.4438
Player Version#: n/aPlex Media Server Logs_2021-05-10_03-36-53.zip (5.5 MB)

As can be seen from the attached logs, while running volume analysis, there is a clearly a problem with a file that Plex finds, but it just prints:

May 10, 2021 03:26:39.277 [0x7fa4a473bb38] ERROR - Analysis: Format error 'Invalid data found when processing input'.

…over and over again in Deep Analysis.log. I cannot find in any of the logs (even with Debug turned on) which file is causing the problem. Could anyone help me find the offending file? Thanks!

You need to turn DEBUG logging on (keeping it on is best because it doesn’t change the amount of disk space used but we do get more info)

Download the ZIP set.

(The whole ZIP set is needed to back trace – by time stamp – to find the offending file )

Reading logs now.

I think DEBUG logging is already on for that set - at least the checkmark is on. If I’m mistaken, let me know and I’ll upload another set of logs. Thanks.

May 10, 2021 03:26:33.574 [0x7f69114a2b38] DEBUG - Activity: registered new activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - "Generating video preview thumbnails"
May 10, 2021 03:26:33.574 [0x7f69114a2b38] DEBUG - [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/fa235d6-3855-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxP' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:v' 'hevc' '-skip_frame:v' 'nokey' '-i' '/storage/tv/Gilmore Girls/Season 02/Gilmore Girls - S02E04 - The Road Trip to Harvard.mkv' '-threads' '0' '-nostats' '-q' '3' '-loglevel' 'quiet' '-filter_complex' '[0:V:0] fps=fps=0.500000:round=up,scale=w=320:h=240:force_original_aspect_ratio=decrease [out]' '-map' '[out]' '/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Media/localhost/2/03a46be0c1db073cbfbbc1419135452ca14c1cd.bundle/Contents/Indexes/tmp/img-%06d.jpg' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress'
May 10, 2021 03:26:33.574 [0x7f69114a2b38] DEBUG - [JobRunner] Jobs: Starting child process with pid 3312996
May 10, 2021 03:26:33.578 [0x7f69034a5b38] DEBUG - Request: [127.0.0.1:37918 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=startup (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.578 [0x7f69951beb38] DEBUG - Completed: [127.0.0.1:37918] 206 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=startup (13 live) 0ms 371 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.582 [0x7f6903356b38] DEBUG - Request: [127.0.0.1:37918 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=startup (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.583 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37918] 206 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=startup (13 live) 0ms 371 bytes (pipelined: 2) (range: bytes=0-) 
May 10, 2021 03:26:33.583 [0x7f6903bcab38] DEBUG - Request: [127.0.0.1:37918 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=opening (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.583 [0x7f69951beb38] DEBUG - Completed: [127.0.0.1:37918] 206 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=opening (13 live) 0ms 371 bytes (pipelined: 3) (range: bytes=0-) 
May 10, 2021 03:26:33.628 [0x7f6903c52b38] DEBUG - Request: [127.0.0.1:37918 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=opened (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.628 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37918] 206 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?status=opened (13 live) 0ms 371 bytes (pipelined: 4) (range: bytes=0-) 
May 10, 2021 03:26:33.628 [0x7f6903c2fb38] DEBUG - Request: [127.0.0.1:37918 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=0&id=0&codec=hevc&type=video (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.629 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37918] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=0&id=0&codec=hevc&type=video (13 live) 0ms 288 bytes (pipelined: 5) (range: bytes=0-) 
May 10, 2021 03:26:33.629 [0x7f690b9d0b38] DEBUG - Request: [127.0.0.1:37924 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=0&id=0&codec=hevc&type=video (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.629 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37924] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=0&id=0&codec=hevc&type=video (13 live) 0ms 288 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.630 [0x7f690478ab38] DEBUG - Request: [127.0.0.1:37926 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=1&id=0&codec=ac3&type=audio (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.630 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37926] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/stream?index=1&id=0&codec=ac3&type=audio (13 live) 0ms 288 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.631 [0x7f69034a5b38] DEBUG - Request: [127.0.0.1:37928 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main&language=eng&width=1920&height=1080&interlaced=0&sar=1:1&level=120&frameRate=23.976&disp_default=1 (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.631 [0x7f69951beb38] DEBUG - Completed: [127.0.0.1:37928] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main&language=eng&width=1920&height=1080&interlaced=0&sar=1:1&level=120&frameRate=23.976&disp_default=1 (13 live) 0ms 288 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.631 [0x7f6903356b38] DEBUG - Request: [127.0.0.1:37930 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=1&id=0&codec=ac3&type=audio&bitrate=256000&language=eng&channels=2&layout=stereo&sampleRate=48000&disp_default=1 (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.631 [0x7f699519bb38] DEBUG - Completed: [127.0.0.1:37930] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=1&id=0&codec=ac3&type=audio&bitrate=256000&language=eng&channels=2&layout=stereo&sampleRate=48000&disp_default=1 (13 live) 0ms 288 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.632 [0x7f6903bcab38] DEBUG - Request: [127.0.0.1:37932 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.632 [0x7f69951beb38] DEBUG - Completed: [127.0.0.1:37932] 404 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (13 live) 0ms 288 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:33.632 [0x7f6903c52b38] DEBUG - Request: [127.0.0.1:37934 (Loopback)] PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?duration=2594.139000 (13 live) Signed-in Token (benzo8) (range: bytes=0-) 
May 10, 2021 03:26:33.633 [0x7f69951beb38] DEBUG - Completed: [127.0.0.1:37934] 206 PUT /video/:/transcode/session/bif/59eeccd4-bd35-473f-9262-ea2fc630e0af/progress?duration=2594.139000 (13 live) 0ms 371 bytes (pipelined: 1) (range: bytes=0-) 
May 10, 2021 03:26:34.135 [0x7f6903c2fb38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 2.0% - Generating video preview thumbnails
May 10, 2021 03:26:34.645 [0x7f69034a5b38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 4.8% - Generating video preview thumbnails
May 10, 2021 03:26:35.147 [0x7f6903c2fb38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 7.9% - Generating video preview thumbnails
May 10, 2021 03:26:35.663 [0x7f6903c2fb38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 11.2% - Generating video preview thumbnails
May 10, 2021 03:26:36.180 [0x7f6903bcab38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 14.0% - Generating video preview thumbnails
May 10, 2021 03:26:36.679 [0x7f6903c2fb38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 17.3% - Generating video preview thumbnails
May 10, 2021 03:26:37.194 [0x7f690478ab38] DEBUG - [Transcode] Activity: updated activity 59eeccd4-bd35-473f-9262-ea2fc630e0af - completed 20.0% - Generating video preview thumbnails

Look here ( Plex Media Server.1.log )

Scroll down to the time stamp.

This will be a proximity search but think I found it. – As it processed “S02E04” of “Gilmore Girls”.

Thanks for looking Chuck. Unfortunately, I’m 99% convinced it’s an issue with loudness analysis when music is added (or when the night-time scheduled processing takes place), not with a video file - for a number of reasons:

  1. I’ve had GG for years, without any problems. This problem started a few weeks ago now.
  2. When this happens, it uses my entire RAM and then takes down my server completely. For that reason, it’s been tough to troubleshoot even this far, but setting “Analyze audio tracks for loudness” in Library to “Never” stopped it for a week.
  3. Tonight I had some time so I tried to force the issue by setting “Analyze audio tracks for loudness” back to “…and when media is added” and then added some music files.

I raised this on the forums a week ago where I uploaded a different set of logs, which might help further.

(Also, it’s a difficult one to instigate as there seems to be no way of manually starting the loudness analysis process without adding new music or changing the scheduling. The “Analyse” menu option on media in my library doesn’t launch the loudness analysis process, no matter what the settings say.)

Thanks again your time on this so far; I’d love to get to the bottom of this so I can start using volume levelling again without my server crashing every night!

If you feel that’s the case, Take the album it’s processing out of the library. and rerun it.

This is the first you’r mentioning any system impact. Knowing such things does help me in diagnosing but I’m still going by timestamp for now.

Loudness analysis is done during scheduled maintenance .
PMS does a few at a time to minimize impact.

You can conduct basic analysis as you remove-add the media and check the logs again.

Also, forcing it to transcode to a lower quality will expose file corruption

Were it that easy! I add a lot of music, all the time. This problem first reared it’s head some weeks ago and I initially ignored it (restarted the server, moved on) but when it happened regularly I started to look into it and narrowed it down to Plex. Long story short - whatever the album is that’s causing problems, it’s now buried relatively deep in my collection, hence trying to find from the logs which particular file it’s barfing on.

If removing all the music I’ve added over perhaps the last two months and then adding it back, album by album, is the only way forward, I guess I have to do it, but I’m trying to avoid that being the only option!

(BTW, if you look at the htop screenshot in the previous thread - yeah, I’m pretty sure where the issue lies!)

This is not good.

“You had a simple bug bite but now we need amputate”

Yep, you need to start unwinding.

I hope you’re good with listing by date created (or using find) and some shell scripting.

If you have a known time frame, you can probably be somewhat surgical and move only those from Date X through Date Y.

Thanks for looking at this, trumpy. I still think it’s to do with music, partly because it’s reproducible by forcing a loudness analysis to run, and didn’t occur for the whole week while loudness analysis was disabled. And also partly because of this image:

When this happens, the Deep Analysis logs fill up so fast that all five are completely filled with that same message nigh-on instantaneously and the moment where the issue first occurred is quickly lost to log rotation. Yes there is a coincident time stamp with something else the server is doing, but it’s not the Zero Point.

Right now I’m in the process of “unwinding”, as Chuck put it. I can already confirm that removing two weeks of new albums running up to where I can confirm by date the issue began has allowed the loudness analysis to complete without that error flooding the logs - which it would not do earlier this morning. So I think we’re on the right track; I just have to find out which of these 137 albums contains the tainted file (or files)!

And… after over 8 hours, I’ve found it/them… If I had started my search with “esoteric” file types, I’d have found them much more quickly, as they’re .dsf files. I have other .dsf files in my collection, and Plex recognises them (and these) perfectly but these particular ones make Plex’s loudness analysis process enter into an infinite loop until all the available memory is swallowed up and the server needs to be restarted.

On discovering these, I couldn’t kill the process fast enough to have any useful logs (all 5 full of the usual message by the time I got to them). @ChuckPa - would you like me to make one (or more) of them available to you to do some further investigating? (They are each approx. 300MB but I have the bandwidth to move them around as required.)

@benzo8

If you can make one of them available to me , I would greatly appreciate it.

I know PRECISELY to whom this should go for followup investigation and work. :smiling_imp:

@ChuckPa

Thanks. Can I pm you a link?

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