Deep analysis not working, transcoder failture (1.32.4.7195)

Plex Media Server
1

Server Version#: 1.32.4.7195 on linux debian 11

Hi,

i have the problem that the deep analysis seems to crash after adding aproximated 3700 items to the deep analysis queue and after starting the transcoder fails and all 3700 jobs get the following error

Jun 23, 2023 01:15:32.291 [140540255755064] ERROR - [Req#14110/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] Error while decoding stream #0:1: Invalid data found when processing input
Jun 23, 2023 01:15:32.291 [140540276591416] ERROR - [Req#14111/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] [mp3 @ 0x7ff19844dac0] Header missing

This happens every time the background tasks start.

I have attached all server logs and tried to extract the relevant portion of the logs.
If im wrong, please correct me. But what i can interpret here is the Plex Media Scanner job successes and (besides some Intro detection) then all files are listed with that errors (3 per millisecound) till all 3700 job requests are printed out as error.

Here the part which is relevant, i think:

Jun 23, 2023 01:15:30.370 [140540370000696] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=24862&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e23 GZIP 0ms 195 bytes (pipelined: 24)
Jun 23, 2023 01:15:30.459 [140540261391160] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e24 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.459 [140540370000696] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e24 GZIP 0ms 195 bytes (pipelined: 25)
Jun 23, 2023 01:15:30.459 [140540246903608] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e37 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.459 [140540372110136] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e37 GZIP 0ms 195 bytes (pipelined: 26)
Jun 23, 2023 01:15:30.460 [140540287941432] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e38 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.460 [140540370000696] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=15130&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e38 GZIP 0ms 195 bytes (pipelined: 27)
Jun 23, 2023 01:15:30.549 [140540282616632] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e39 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.549 [140540372110136] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e39 GZIP 0ms 195 bytes (pipelined: 28)
Jun 23, 2023 01:15:30.549 [140540274481976] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e4c GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.549 [140540370000696] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e4c GZIP 0ms 195 bytes (pipelined: 29)
Jun 23, 2023 01:15:30.550 [140540255755064] DEBUG - Request: [127.0.0.1:45910 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e4d GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.550 [140540372110136] DEBUG - Completed: [127.0.0.1:45910] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=10135&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e4d GZIP 0ms 195 bytes (pipelined: 30)
Jun 23, 2023 01:15:30.554 [140540374674232] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 3112 is 0 (success)
Jun 23, 2023 01:15:30.554 [140540338588472] DEBUG - Activity: ended sub-activity a2c9d2b5-3108-40bc-8320-c9fa076c0c74 parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 100.0% (370/370)
Jun 23, 2023 01:15:30.554 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks
Jun 23, 2023 01:15:30.554 [140540338588472] DEBUG - Activity: registered new sub-activity 8c03560d-594e-4128-bad9-3cc9e9ebab7e - "UpgradeMediaAnalysis" parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 99.7% (370/371)
Jun 23, 2023 01:15:30.554 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:30.690 [140540338588472] DEBUG - [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/8217c1c-4565-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --analy
ze --item 9676,16852,26303 --log-file-suffix " Analysis"
Jun 23, 2023 01:15:30.691 [140540338588472] DEBUG - [JobRunner] Jobs: Starting child process with pid 3118
Jun 23, 2023 01:15:30.845 [140540276591416] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13d8e GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.845 [140540370000696] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13d8e GZIP 0ms 195 bytes (pipelined: 1)
Jun 23, 2023 01:15:30.846 [140540292258616] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e6f GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.846 [140540370000696] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e6f GZIP 0ms 195 bytes (pipelined: 2)
Jun 23, 2023 01:15:30.846 [140540261391160] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e70 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.846 [140540372110136] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=9676&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e70 GZIP 0ms 195 bytes (pipelined: 3)
Jun 23, 2023 01:15:30.938 [140540246903608] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e71 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.939 [140540372110136] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e71 GZIP 0ms 195 bytes (pipelined: 4)
Jun 23, 2023 01:15:30.939 [140540287941432] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e84 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.939 [140540370000696] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e84 GZIP 0ms 195 bytes (pipelined: 5)
Jun 23, 2023 01:15:30.940 [140540282616632] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e85 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:30.940 [140540370000696] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=1&metadataItemID=16852&metadataType=4&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13e85 GZIP 0ms 195 bytes (pipelined: 6)
Jun 23, 2023 01:15:31.080 [140540274481976] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e8c GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:31.080 [140540372110136] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=analyzing (5 live) #13e8c GZIP 0ms 195 bytes (pipelined: 7)
Jun 23, 2023 01:15:31.081 [140540255755064] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e99 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:31.081 [140540370000696] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=thumbnailing (5 live) #13e99 GZIP 0ms 195 bytes (pipelined: 8)
Jun 23, 2023 01:15:31.081 [140540276591416] DEBUG - Request: [127.0.0.1:45914 (Loopback)] GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13ea0 GZIP Signed-in Token (retro1982)
Jun 23, 2023 01:15:31.081 [140540372110136] DEBUG - Completed: [127.0.0.1:45914] 200 GET /:/metadata/notify/changeItemState?librarySectionID=2&metadataItemID=26303&metadataType=1&state=-1&parentID=-1&rootID=-1&mediaState=idle (5 live) #13ea0 GZIP 0ms 195 bytes (pipelined: 9)
Jun 23, 2023 01:15:31.091 [140540374674232] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 3118 is 0 (success)
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: ended sub-activity 8c03560d-594e-4128-bad9-3cc9e9ebab7e parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 100.0% (371/371)
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - The butler analyzed 3553 items.
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: registered new sub-activity 7edb2a3a-f1ad-4fa1-af92-b04407a2d156 - "CleanOldBundles" parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 99.7% (371/372)
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: ended sub-activity 7edb2a3a-f1ad-4fa1-af92-b04407a2d156 parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 100.0% (372/372)
Jun 23, 2023 01:15:31.092 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks
Jun 23, 2023 01:15:31.093 [140540338588472] DEBUG - Activity: registered new sub-activity 48781001-69cc-47ba-8954-c896d9fd5926 - "ButlerTaskGenerateIntroMarkers" parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 99.7% (372/373)
Jun 23, 2023 01:15:31.093 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:31.093 [140540338588472] DEBUG - Butler: Scheduling intro marker creation for: 7014
Jun 23, 2023 01:15:31.094 [140540338588472] DEBUG - IntroDetector: Running intro detection for [7014] [Disney Animated Shorts] [1925]
Jun 23, 2023 01:15:31.096 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E01 - Alice Cans the Cannibals.mpg" (7015)
Jun 23, 2023 01:15:31.096 [140540338588472] DEBUG - Downloading document http://127.0.0.1:32400/library/metadata/7015
Jun 23, 2023 01:15:31.118 [140540338588472] WARN - MDE: unable to find a working transcode profile for video stream
Jun 23, 2023 01:15:31.118 [140540338588472] WARN - MDE: unable to find a working transcode profile for video stream
Jun 23, 2023 01:15:31.118 [140540338588472] DEBUG - Cleaning directory for session de8bccc1-69cd-40d6-99b4-6a8ee1d343b1 ()
Jun 23, 2023 01:15:31.119 [140540338588472] DEBUG - Starting a transcode session de8bccc1-69cd-40d6-99b4-6a8ee1d343b1 at offset -1.0 (state=3)
Jun 23, 2023 01:15:31.119 [140540338588472] DEBUG - Streaming Resource: Added session 0x7fd218d2a4e8:de8bccc1-69cd-40d6-99b4-6a8ee1d343b1
Jun 23, 2023 01:15:31.119 [140540338588472] DEBUG - [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/8217c1c-4565-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Transcoder" -f  -map_m
etadata -1 -map_chapters -1 -t 600 /tmp/Transcode/Detection/195a4049-2361-4ff7-8f23-f89c7d7aab5b -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2/progress
Jun 23, 2023 01:15:31.119 [140540338588472] DEBUG - [JobRunner] In directory: "/tmp/Transcode/Sessions/plex-transcode-de8bccc1-69cd-40d6-99b4-6a8ee1d343b1-10f956cb-2fcf-4784-b4e8-90f2fc0dede2"
Jun 23, 2023 01:15:31.119 [140540338588472] DEBUG - [JobRunner] Jobs: Starting child process with pid 3124
Jun 23, 2023 01:15:31.122 [140540292258616] DEBUG - Request: [127.0.0.1:45922 (Loopback)] PUT /video/:/transcode/session/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2/progress?status=startup (5 live) #13e6e Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.122 [140540370000696] DEBUG - Completed: [127.0.0.1:45922] 204 PUT /video/:/transcode/session/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2/progress?status=startup (5 live) #13e6e 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
Jun 23, 2023 01:15:31.124 [140540261391160] DEBUG - Request: [127.0.0.1:45922 (Loopback)] PUT /video/:/transcode/session/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2/progress?status=startup (5 live) #13ed4 Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.124 [140540372110136] DEBUG - Completed: [127.0.0.1:45922] 204 PUT /video/:/transcode/session/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2/progress?status=startup (5 live) #13ed4 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
Jun 23, 2023 01:15:31.124 [140540246903608] ERROR - [Req#13ed5/Transcode/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2] [NULL @ 0x7fcdc6b2f8c0] Requested output format '' is not a suitable output format
Jun 23, 2023 01:15:31.124 [140540287941432] ERROR - [Req#13ed6/Transcode/de8bccc1-69cd-40d6-99b4-6a8ee1d343b1/10f956cb-2fcf-4784-b4e8-90f2fc0dede2] /tmp/Transcode/Detection/195a4049-2361-4ff7-8f23-f89c7d7aab5b: Invalid argument
Jun 23, 2023 01:15:31.125 [140540374674232] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 3124 is 1 (failure)
Jun 23, 2023 01:15:31.125 [140540338588472] DEBUG - Using default transcode duration of 120 minutes
Jun 23, 2023 01:15:31.125 [140540338588472] DEBUG - Using default transcode duration of 120 minutes
Jun 23, 2023 01:15:31.125 [140540338588472] DEBUG - Started session successfully: de8bccc1-69cd-40d6-99b4-6a8ee1d343b1
Jun 23, 2023 01:15:31.125 [140540335266616] DEBUG - Streaming Resource: Terminated session 0x7fd218d2a4e8:de8bccc1-69cd-40d6-99b4-6a8ee1d343b1 with reason Conversion failed. The transcoder exited due to an error.
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Killing job.
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Signalling job ID 3124 with 9
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Job was already killed, not killing again.
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Stopping transcode session de8bccc1-69cd-40d6-99b4-6a8ee1d343b1
Jun 23, 2023 01:15:31.125 [140540338588472] ERROR - IntroDetector: Failed to transcode file (1): /mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E01 - Alice Cans the Cannibals.mpg
Jun 23, 2023 01:15:31.125 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Streaming Resource: Removing session 0x7fd218d2a4e8:de8bccc1-69cd-40d6-99b4-6a8ee1d343b1
Jun 23, 2023 01:15:31.125 [140540326619960] DEBUG - Transcoder: Cleaning old transcode directories.
Jun 23, 2023 01:15:31.126 [140540326619960] DEBUG - Transcoder: Cleaning old transcode directory: "/tmp/Transcode/Sessions/plex-transcode-de8bccc1-69cd-40d6-99b4-6a8ee1d343b1-10f956cb-2fcf-4784-b4e8-90f2fc0dede2"
Jun 23, 2023 01:15:31.126 [140540326619960] DEBUG - Whacked session de8bccc1-69cd-40d6-99b4-6a8ee1d343b1, 0 remaining.
Jun 23, 2023 01:15:31.126 [140540326619960] DEBUG - Cleaning directory for session de8bccc1-69cd-40d6-99b4-6a8ee1d343b1 (/tmp/Transcode/Sessions/plex-transcode-de8bccc1-69cd-40d6-99b4-6a8ee1d343b1-10f956cb-2fcf-4784-b4e8-90f2fc0dede2)
Jun 23, 2023 01:15:31.127 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E02 - Alice the Toreador.mpg" (7016)
Jun 23, 2023 01:15:31.128 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.129 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E03 - Alice Gets Stung.avi" (7017)
Jun 23, 2023 01:15:31.131 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.132 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E04 - Alice Solves the Puzzle.mpg" (7018)
Jun 23, 2023 01:15:31.134 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.135 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E05 - Alice's Egg Plant.mpg" (7019)
Jun 23, 2023 01:15:31.136 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.138 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E06 - Alice is Stage Struck.mpg" (7020)
Jun 23, 2023 01:15:31.139 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.140 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E07 - Alice Loses Out.mpg" (7021)
Jun 23, 2023 01:15:31.142 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.143 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E09 - Alice Picks the Champ.mpg" (7022)
Jun 23, 2023 01:15:31.143 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.145 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E10 - Alice the Jail Bird.mpg" (7023)
Jun 23, 2023 01:15:31.145 [140540282616632] DEBUG - Request: [192.168.0.2:34594 (Subnet)] GET /status/sessions/background (5 live) #13ed3 TLS GZIP Signed-in Token (retro1982) (Firefox)
Jun 23, 2023 01:15:31.146 [140540370000696] DEBUG - Completed: [192.168.0.2:34594] 200 GET /status/sessions/background (5 live) #13ed3 TLS GZIP 0ms 529 bytes (pipelined: 1)
Jun 23, 2023 01:15:31.147 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.148 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E11 - Alice's Tin Pony.mpg" (7024)
Jun 23, 2023 01:15:31.149 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.150 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E12 - Alice Chops the Suey.mpg" (7025)
Jun 23, 2023 01:15:31.152 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.153 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E14 - Alice Rattled by Rats.mpg" (7026)
Jun 23, 2023 01:15:31.154 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.9% - Butler tasks
Jun 23, 2023 01:15:31.155 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E15 - Alice in the Jungle.mpg" (7027)
Jun 23, 2023 01:15:31.157 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks

Jun 23, 2023 01:15:31.183 [140540274481976] DEBUG - Request: [192.168.0.199:49416 (Subnet)] GET /status/sessions/background (6 live) #13f13 TLS GZIP Signed-in Token (retro1982) (Chrome)
Jun 23, 2023 01:15:31.184 [140540370000696] DEBUG - Completed: [192.168.0.199:49416] 200 GET /status/sessions/background (6 live) #13f13 TLS GZIP 0ms 532 bytes (pipelined: 1)
Jun 23, 2023 01:15:31.185 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks
Jun 23, 2023 01:15:31.313 [140540338588472] DEBUG - IntroDetector: Less than half of episodes have an intro. Clearing intros for [7014]
Jun 23, 2023 01:15:31.315 [140540338588472] DEBUG - Updating part with ID=6492 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E02 - Alice the Toreador.mpg]
Jun 23, 2023 01:15:31.318 [140540338588472] DEBUG - Updating part with ID=6493 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E03 - Alice Gets Stung.avi]
Jun 23, 2023 01:15:31.321 [140540338588472] DEBUG - Updating part with ID=6494 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E04 - Alice Solves the Puzzle.mpg]
Jun 23, 2023 01:15:31.324 [140540338588472] DEBUG - Updating part with ID=6495 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E05 - Alice's Egg Plant.mpg]
Jun 23, 2023 01:15:31.327 [140540338588472] DEBUG - Updating part with ID=6496 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E06 - Alice is Stage Struck.mpg]
Jun 23, 2023 01:15:31.330 [140540338588472] DEBUG - Updating part with ID=6497 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E07 - Alice Loses Out.mpg]
Jun 23, 2023 01:15:31.333 [140540338588472] DEBUG - Updating part with ID=6498 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E09 - Alice Picks the Champ.mpg]
Jun 23, 2023 01:15:31.336 [140540338588472] DEBUG - Updating part with ID=6499 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E10 - Alice the Jail Bird.mpg]
Jun 23, 2023 01:15:31.339 [140540338588472] DEBUG - Updating part with ID=6500 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E11 - Alice's Tin Pony.mpg]
Jun 23, 2023 01:15:31.341 [140540338588472] DEBUG - Updating part with ID=6501 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E12 - Alice Chops the Suey.mpg]
Jun 23, 2023 01:15:31.344 [140540338588472] DEBUG - Updating part with ID=6502 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E14 - Alice Rattled by Rats.mpg]
Jun 23, 2023 01:15:31.347 [140540338588472] DEBUG - Updating part with ID=6503 [/mnt/data/Video/Serien/Disney Animated Shorts/S1925/Disney Animated Shorts - S1925E15 - Alice in the Jungle.mpg]
Jun 23, 2023 01:15:31.349 [140540338588472] DEBUG - Activity: ended sub-activity 48781001-69cc-47ba-8954-c896d9fd5926 parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 100.0% (373/373)
Jun 23, 2023 01:15:31.349 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 100.0% - Butler tasks
Jun 23, 2023 01:15:31.349 [140540338588472] DEBUG - Activity: registered new sub-activity 8116296a-edd7-4168-9bca-128cc50ab092 - "ButlerTaskGenerateIntroMarkers" parent: 16e79d04-af52-424b-b3d0-6420508b6a91 overall progress: 99.7% (373/374)
Jun 23, 2023 01:15:31.349 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:31.349 [140540338588472] DEBUG - Butler: Scheduling intro marker creation for: 17267
Jun 23, 2023 01:15:31.351 [140540338588472] DEBUG - IntroDetector: Running intro detection for [17267] [The Simpsons] [16]
Jun 23, 2023 01:15:31.352 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E01.Treehouse of Horror XV.avi" (17268)
Jun 23, 2023 01:15:31.354 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.7% - Butler tasks
Jun 23, 2023 01:15:31.355 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E02.All's Fair in Oven War.avi" (17269)
Jun 23, 2023 01:15:31.357 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.358 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E03.Sleeping With the Enemy.avi" (17270)
Jun 23, 2023 01:15:31.360 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.361 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E04.She Used to Be My Girl.avi" (17271)
Jun 23, 2023 01:15:31.363 [140540338588472] DEBUG - Activity: updated activity 16e79d04-af52-424b-b3d0-6420508b6a91 - completed 99.8% - Butler tasks
Jun 23, 2023 01:15:31.365 [140540338588472] DEBUG - IntroDetector: Initializing for "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E05.Fat Man and Little Boy.avi" (17272)
Jun 23, 2023 01:15:31.365 [140540338588472] DEBUG - Downloading document http://127.0.0.1:32400/library/metadata/17272
Jun 23, 2023 01:15:31.397 [140540338588472] DEBUG - [Req#140f7] We're going to try to auto-select an audio stream for account 1.
Jun 23, 2023 01:15:31.397 [140540338588472] DEBUG - [Req#140f7] Selecting best audio stream for part ID 15939 (language: )
Jun 23, 2023 01:15:31.397 [140540338588472] DEBUG - [Req#140f7] Audio Stream: 61333, Subtitle Stream: -1
Jun 23, 2023 01:15:31.398 [140540338588472] WARN - MDE: unable to find a working transcode profile for video stream
Jun 23, 2023 01:15:31.398 [140540338588472] WARN - MDE: unable to find a working transcode profile for video stream
Jun 23, 2023 01:15:31.398 [140540338588472] DEBUG - Cleaning directory for session 5707ba3e-85f8-4f3d-98da-90d991fcaa44 ()
Jun 23, 2023 01:15:31.398 [140540338588472] DEBUG - Starting a transcode session 5707ba3e-85f8-4f3d-98da-90d991fcaa44 at offset -1.0 (state=3)
Jun 23, 2023 01:15:31.398 [140540338588472] DEBUG - Streaming Resource: Added session 0x7fd21a5db518:5707ba3e-85f8-4f3d-98da-90d991fcaa44
Jun 23, 2023 01:15:31.444 [140540338588472] DEBUG - [Universal] Using local file path instead of URL: /mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E05.Fat Man and Little Boy.avi
Jun 23, 2023 01:15:31.445 [140540338588472] DEBUG - [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/8217c1c-4565-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Transcoder" "-codec:#0
x01" mp3 -analyzeduration 20000000 -probesize 20000000 -i "/mnt/data/Video/Serien/Simpsons/Season 16/The Simpsons.S16E05.Fat Man and Little Boy.avi" -filter_complex "[0:#0x01] aresample=async=1:ochl='stereo':rematrix_maxval=0.000000dB:osr=48000[0]" -map "[0]" -codec:0 flac -b:0 4096k -f flac -map_metadata -1 -map_ch
apters -1 -t 653.90350000000001 /tmp/Transcode/Detection/c7b5f896-8a23-418e-99a7-3cfebe5f73ab -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress
Jun 23, 2023 01:15:31.445 [140540338588472] DEBUG - [JobRunner] In directory: "/tmp/Transcode/Sessions/plex-transcode-5707ba3e-85f8-4f3d-98da-90d991fcaa44-db2cf65c-00ae-449a-8e30-4592c9ef7827"
Jun 23, 2023 01:15:31.445 [140540338588472] DEBUG - [JobRunner] Jobs: Starting child process with pid 3125
Jun 23, 2023 01:15:31.448 [140540255755064] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=startup (7 live) #13f7b Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.448 [140540370000696] DEBUG - Completed: [127.0.0.1:45926] 204 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=startup (7 live) #13f7b 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
Jun 23, 2023 01:15:31.450 [140540276591416] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=startup (7 live) #140fb Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.450 [140540370000696] DEBUG - Completed: [127.0.0.1:45926] 204 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=startup (7 live) #140fb 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
Jun 23, 2023 01:15:31.450 [140540292258616] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=opening (7 live) #140fc Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.450 [140540370000696] DEBUG - Completed: [127.0.0.1:45926] 204 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=opening (7 live) #140fc 0ms 203 bytes (pipelined: 3) (range: bytes=0-)
Jun 23, 2023 01:15:31.525 [140540261391160] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=opened (7 live) #140fd Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.526 [140540372110136] DEBUG - Completed: [127.0.0.1:45926] 204 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?status=opened (7 live) #140fd 0ms 203 bytes (pipelined: 4) (range: bytes=0-)
Jun 23, 2023 01:15:31.526 [140540246903608] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/stream?index=0&id=0&codec=mpeg4&type=video (7 live) #140fe Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.526 [140540372110136] DEBUG - Completed: [127.0.0.1:45926] 200 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/stream?index=0&id=0&codec=mpeg4&type=video (7 live) #140fe 0ms 195 bytes (pipelined: 5) (range: bytes=0-)
Jun 23, 2023 01:15:31.526 [140540287941432] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/stream?index=1&id=1&codec=mp3&type=audio (7 live) #140ff Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.526 [140540372110136] DEBUG - Completed: [127.0.0.1:45926] 200 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/stream?index=1&id=1&codec=mp3&type=audio (7 live) #140ff 0ms 195 bytes (pipelined: 6) (range: bytes=0-)
Jun 23, 2023 01:15:31.528 [140540282616632] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/streamDetail?index=0&id=0&codec=mpeg4&type=video&bitrate=975162&profile=Advanced%20Simple%20Profile&width=512&hei
ght=384&interlaced=0&sar=1:1&level=5&frameRate=23.976 (7 live) #14100 Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.529 [140540372110136] DEBUG - Completed: [127.0.0.1:45926] 200 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/streamDetail?index=0&id=0&codec=mpeg4&type=video&bitrate=975162&profile=Advanced%20Simple%20Profile&width=512&height=3
84&interlaced=0&sar=1:1&level=5&frameRate=23.976 (7 live) #14100 0ms 195 bytes (pipelined: 7) (range: bytes=0-)
Jun 23, 2023 01:15:31.529 [140540274481976] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/streamDetail?index=1&id=1&codec=mp3&type=audio&bitrate=138704&channels=2&layout=stereo&sampleRate=48000 (7 live)
#14101 Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.529 [140540372110136] DEBUG - Completed: [127.0.0.1:45926] 200 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress/streamDetail?index=1&id=1&codec=mp3&type=audio&bitrate=138704&channels=2&layout=stereo&sampleRate=48000 (7 live) #1410
1 0ms 195 bytes (pipelined: 8) (range: bytes=0-)
Jun 23, 2023 01:15:31.532 [140540255755064] DEBUG - Request: [127.0.0.1:45926 (Loopback)] PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?duration=1307.806500 (7 live) #14102 Signed-in Token (retro1982) (range: bytes=0-)
Jun 23, 2023 01:15:31.533 [140540370000696] DEBUG - Completed: [127.0.0.1:45926] 204 PUT /video/:/transcode/session/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827/progress?duration=1307.806500 (7 live) #14102 0ms 203 bytes (pipelined: 9) (range: bytes=0-)
Jun 23, 2023 01:15:31.533 [140540338588472] DEBUG - Using default transcode duration of 120 minutes
Jun 23, 2023 01:15:31.533 [140540338588472] DEBUG - Started session successfully: 5707ba3e-85f8-4f3d-98da-90d991fcaa44
Jun 23, 2023 01:15:31.535 [140540276591416] DEBUG - [Req#14103/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] Streaming Resource: Unthrottling session 0x7fd21a5db518:5707ba3e-85f8-4f3d-98da-90d991fcaa44 which is using static transcoder slot.  Used slots is now 1
Jun 23, 2023 01:15:31.536 [140540292258616] DEBUG - Request: [192.168.0.2:34594 (Subnet)] GET /status/sessions/background (7 live) #13f1a TLS GZIP Signed-in Token (retro1982) (Firefox)
Jun 23, 2023 01:15:31.536 [140540372110136] DEBUG - Completed: [192.168.0.2:34594] 200 GET /status/sessions/background (7 live) #13f1a TLS GZIP 0ms 529 bytes (pipelined: 2)
Jun 23, 2023 01:15:31.543 [140540261391160] DEBUG - Request: [192.168.0.199:49416 (Subnet)] GET /status/sessions/background (7 live) #13f82 TLS GZIP Signed-in Token (retro1982) (Chrome)
Jun 23, 2023 01:15:31.543 [140540370000696] DEBUG - Completed: [192.168.0.199:49416] 200 GET /status/sessions/background (7 live) #13f82 TLS GZIP 0ms 532 bytes (pipelined: 2)
Jun 23, 2023 01:15:32.290 [140540287941432] ERROR - [Req#1410d/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] [mp3 @ 0x7ff19844dac0] Header missing
Jun 23, 2023 01:15:32.290 [140540282616632] ERROR - [Req#1410e/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] Error while decoding stream #0:1: Invalid data found when processing input
Jun 23, 2023 01:15:32.291 [140540274481976] ERROR - [Req#1410f/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] [mp3 @ 0x7ff19844dac0] Header missing
Jun 23, 2023 01:15:32.291 [140540255755064] ERROR - [Req#14110/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] Error while decoding stream #0:1: Invalid data found when processing input
Jun 23, 2023 01:15:32.291 [140540276591416] ERROR - [Req#14111/Transcode/5707ba3e-85f8-4f3d-98da-90d991fcaa44/db2cf65c-00ae-449a-8e30-4592c9ef7827] [mp3 @ 0x7ff19844dac0] Header missing

Here are the full logs:

Plex Media Server Logs_2023-06-23_01-26-50.zip (3.6 MB)

Anyone any idea, some help or some direction ?

Nice Regards,
Hoping for some help,
Martin

2

I started over with a new and empty database, the only thing maybe not so standard is that i use a ramdrive mountet to /tmp to reduce the ssd wearout. The ramdisk is 10GB big and had never more than 2GB data on it. But may that can cause the problem and causes the deep analyse fail for all items at once ?

3

Hi,

this problem persists! (Any of the devs reading here too ?)

Today again tens of thousands of this entries! Can anyone have a look please and point me in the right direction?


Jun 24, 2023 01:12:05.846 [140540218772280] ERROR - [Req#94fe4/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 01:12:05.846 [140540230753080] ERROR - [Req#94fe5/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] [mp3 @ 0x7ffa92db15c0] Header missing
Jun 24, 2023 01:12:05.847 [140540227210040] ERROR - [Req#94fe6/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 01:12:05.847 [140540218772280] ERROR - [Req#94fe7/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] [mp3 @ 0x7ffa92db15c0] Header missing
Jun 24, 2023 01:12:05.847 [140540230753080] ERROR - [Req#94fe8/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 01:12:05.847 [140540227210040] ERROR - [Req#94fe9/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] [mp3 @ 0x7ffa92db15c0] Header missing
Jun 24, 2023 01:12:05.847 [140540218772280] ERROR - [Req#94fea/Transcode/58ba508b-da80-413f-99cc-89c507d08ddb/53853d61-c920-41b4-a9d4-dc143d272fd7] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 01:12:05.858 [140540374674232] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 141940 is 69 (failure)

Plex Media Server Logs_2023-06-24_09-23-51.zip (3.2 MB)

Or anyone an idea where/what to look?

Update: Run with verbose logging on:

Jun 24, 2023 10:22:39.234 [139823699335992] DEBUG - Request: [127.0.0.1:35922 (Loopback)] POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=Error%20while%20decoding%20stream%20%230%3A1%3A%20Invalid%20data%20found%20when%20processing%20input (3 live) #1c0ea Signed-in Token (retro1982) (range: bytes=0-)  / Accept => */* / Connection => keep-alive / Host => 127.0.0.1:32400 / Icy-MetaData => 1 / Range => bytes=0- / User-Agent => Lavf/LIBAVFORMAT_VERSION / X-Plex-Http-Pipeline => infinite / X-Plex-Token => xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
Jun 24, 2023 10:22:39.234 [139823699335992] ERROR - [Req#1c0ea/Transcode/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 10:22:39.234 [139823754357560] DEBUG - Completed: [127.0.0.1:35922] 200 POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=Error%20while%20decoding%20stream%20%230%3A1%3A%20Invalid%20data%20found%20when%20processing%20input (3 live) #1c0ea 0ms 195 bytes (pipelined: 32341) (range: bytes=0-)
Jun 24, 2023 10:22:39.234 [139823699335992] DEBUG - Request: [127.0.0.1:35922 (Loopback)] POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=%5Bmp3%20%40%200x7ff1970545c0%5D%20Header%20missing (3 live) #1c0eb Signed-in Token (retro1982) (range: bytes=0-)  / Accept => */* / Connection => keep-alive / Host => 127.0.0.1:32400 / Icy-MetaData => 1 / Range => bytes=0- / User-Agent => Lavf/LIBAVFORMAT_VERSION / X-Plex-Http-Pipeline => infinite / X-Plex-Token => xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
Jun 24, 2023 10:22:39.234 [139823699335992] ERROR - [Req#1c0eb/Transcode/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f] [mp3 @ 0x7ff1970545c0] Header missing
Jun 24, 2023 10:22:39.234 [139823752248120] DEBUG - Completed: [127.0.0.1:35922] 200 POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=%5Bmp3%20%40%200x7ff1970545c0%5D%20Header%20missing (3 live) #1c0eb 0ms 195 bytes (pipelined: 32342) (range: bytes=0-)
Jun 24, 2023 10:22:39.235 [139823699335992] DEBUG - Request: [127.0.0.1:35922 (Loopback)] POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=Error%20while%20decoding%20stream%20%230%3A1%3A%20Invalid%20data%20found%20when%20processing%20input (3 live) #1c0ec Signed-in Token (retro1982) (range: bytes=0-)  / Accept => */* / Connection => keep-alive / Host => 127.0.0.1:32400 / Icy-MetaData => 1 / Range => bytes=0- / User-Agent => Lavf/LIBAVFORMAT_VERSION / X-Plex-Http-Pipeline => infinite / X-Plex-Token => xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
Jun 24, 2023 10:22:39.235 [139823699335992] ERROR - [Req#1c0ec/Transcode/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f] Error while decoding stream #0:1: Invalid data found when processing input
Jun 24, 2023 10:22:39.235 [139823754357560] DEBUG - Completed: [127.0.0.1:35922] 200 POST /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress/log?level=0&message=Error%20while%20decoding%20stream%20%230%3A1%3A%20Invalid%20data%20found%20when%20processing%20input (3 live) #1c0ec 0ms 195 bytes (pipelined: 32343) (range: bytes=0-)
Jun 24, 2023 10:22:39.235 [139823699335992] DEBUG - Request: [127.0.0.1:35922 (Loopback)] PUT /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress?progress=50.0&size=17542268&remaining=12&speed=34.1 (3 live) #1c0ed Signed-in Token (retro1982) (range: bytes=0-)  / Accept => */* / Connection => keep-alive / Host => 127.0.0.1:32400 / Icy-MetaData => 1 / Range => bytes=0- / User-Agent => Lavf/LIBAVFORMAT_VERSION / X-Plex-Http-Pipeline => infinite / X-Plex-Token => xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
Jun 24, 2023 10:22:39.235 [139823699335992] VERBOSE - [Req#1c0ed/Transcode/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f] It took 0.0 sec to serialize a list with 0 elements.
Jun 24, 2023 10:22:39.235 [139823752248120] DEBUG - Completed: [127.0.0.1:35922] 206 PUT /video/:/transcode/session/167b8c28-f7b0-4fca-b662-e077414fa51e/69bbf205-af20-4109-93c7-c85a6026b64f/progress?progress=50.0&size=17542268&remaining=12&speed=34.1 (3 live) #1c0ed 0ms 355 bytes (pipelined: 32344) (range: bytes=0-)
Jun 24, 2023 10:22:39.246 [139823754357560] VERBOSE - Didn't receive a request from 127.0.0.1:35922: End of file
Jun 24, 2023 10:22:39.246 [139823756917560] VERBOSE - JobManager: child process with handle 147344 exited
Jun 24, 2023 10:22:39.246 [139823756917560] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 147344 is 69 (failure)
Jun 24, 2023 10:22:39.246 [139823663078200] DEBUG - Streaming Resource: Terminating session 0x7f2b40bfe9a8:167b8c28-f7b0-4fca-b662-e077414fa51e which is using static transcoder slot.  Used slots is now 0
Jun 24, 2023 10:22:39.246 [139823644052280] DEBUG - Killing job.

And log files with verbose logging on
Plex Media Server Logs_2023-06-24_10-26-19.zip (1.6 MB)

I hope that can also help …

Thx,
Martin

4

@retro1982

You turned off DEBUG Logging.

It’s impossible to see which file it’s getting hung up on from the information posted.

Please turn DEBUG Logging on again and recreate (let it happen).

From what I am seeing, based on experience, I think there’s a bad MP3 file it’s tripping over.

DEBUG logging should allow that filename to be discovered.

5

Hi @ChuckPa

thx for taking the time and looking into the log files. Now i have cleared out the Log direcotry and ensured DEBUG is on and VERBOSE is off. I restarted the server with these settings and let it happen again.

Here are the logs:

Plex Media Server Logs_2023-06-25_09-13-37.zip (745.1 KB)

Thank you for your help,
If we need Verbose logs, i will create them.

Nice Regards,
Martin

6

After moving out one album which was mentioned in the logs, after another, 35 Albums later i got all damaged files out, now its working like it should.

Thx

7

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