tv show failed today with there was a transcoding error. also having issues with recordings hanging.
I have been using this for sometime with limited issues until this.
Windows 10
Version 1.7.5.4035
HD Homerun extend.
all storage internal
Logs attached, any insight would be appreciated.
What show, what time did it start/end. Would be helpful to know more information instead of just dumping the zip file of logs. I and others don’t mind reviewing logs but would be nice to know what we are looking for or a general time frame so we can narrow the scope of searching.
It would be the absolute only thing that happened this am. Should be 10am if I remember correctly. Matlock
I see the following log entries for Matlock:
Jul 11, 2017 09:59:00.276 [15824] DEBUG - DVR:Grabber: Starting operation for ‘Matlock - E2 - The Vacation’.
Jul 11, 2017 09:59:00.276 [15824] DEBUG - Activity: registered new activity 2d996389-1195-45b4-8e2d-394fe7eac6a4 - Recording
Jul 11, 2017 09:59:00.276 [15824] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10532295 tuner 0.
Jul 11, 2017 09:59:00.292 [15824] DEBUG - DVR:Subscription: Resolved subscription to library item ‘Matlock’ (179770)
Jul 11, 2017 09:59:00.292 [15824] DEBUG - There were 1 top-level paths for Matlock.
Jul 11, 2017 09:59:00.292 [15824] DEBUG - DVR:Grabber: Saving recording to W:\TV-Shows.grab\14ff690496369945265400b92bbcd07e1014c8b2
Jul 11, 2017 09:59:00.292 [15824] DEBUG - DVR:Grabber: Going to record for 3720 seconds, final URL is http://192.168.10.111:5004/auto/v12.2?transcode=none
Jul 11, 2017 09:59:00.292 [15824] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘Matlock - E2 - The Vacation’ in 3720 seconds.
Jul 11, 2017 09:59:00.292 [15824] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.10.111:5004/auto/v12.2?transcode=none.
Jul 11, 2017 09:59:00.761 [15824] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Jul 11, 2017 09:59:00.761 [15824] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
Jul 11, 2017 09:59:00.924 [15824] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Jul 11, 2017 09:59:00.924 [15824] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 1 language: en)
Jul 11, 2017 09:59:00.924 [15824] DEBUG - Falling back to picking the first audio stream 1.
Jul 11, 2017 09:59:00.924 [15824] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Jul 11, 2017 09:59:00.924 [15824] ERROR - Unable to find title for item of type 5
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: analyzing media item -1
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: : codec is unavailable for analysis
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: : codec is unavailable for analysis
Jul 11, 2017 09:59:00.924 [15824] ERROR - Unable to find title for item of type 5
Jul 11, 2017 09:59:00.924 [15824] DEBUG - MDE: : selected media 0 / -1
Jul 11, 2017 09:59:00.924 [15824] DEBUG - Cleaning directory for session 87bf1915-da78-4121-8ff9-75fdb4f816c4 ()
Jul 11, 2017 09:59:00.993 [15824] DEBUG - Starting a transcode session 87bf1915-da78-4121-8ff9-75fdb4f816c4 at offset -1.0 (state=3)
Jul 11, 2017 09:59:00.993 [15824] DEBUG - Streaming Resource: Added session 077EC558:87bf1915-da78-4121-8ff9-75fdb4f816c4
Jul 11, 2017 09:59:04.080 [15824] DEBUG - Job running: EAE_ROOT=’\?\C:\Users\Ray\AppData\Local\Plex-Server-data\Plex Media Server\Cache\Transcode\Sessions\EasyAudioEncoder’ FFMPEG_EXTERNAL_LIBS=’\\?\C:\Users\Ray\AppData\Local\Plex-Server-data\Plex\ Media\ Server\Codecs\46b03cf-1241-windows-i386\’ XDG_CACHE_HOME=‘C:\Users\Ray\AppData\Local\Plex-Server-data\Plex Media Server\Cache’ XDG_DATA_HOME=‘C:\Program Files (x86)\Plex\Plex Media Server\Resources’ X_PLEX_TOKEN=‘xxxxxxxxxxxxxxxxxxxx’ C:\Program Files (x86)\Plex\Plex Media Server\PlexTranscoder.exe -noaccurate_seek -ignore_unknown -scan_all_pmts -1 -i http://192.168.10.111:5004/auto/v12.2?transcode=none -map 0:V? -codec:V copy -map 0:a? -codec:a copy -copypriorss:a 0 -map 0:s? -codec:s copy -segment_format mpegts -f ssegment -individual_header_trailer 0 -segment_time 1 -segment_start_number 0 -segment_copyts 1 -segment_time_delta 0.0625 -segment_list http://127.0.0.1:32400/video/:/transcode/session/87bf1915-da78-4121-8ff9-75fdb4f816c4/3cf4698e-801d-4015-90fa-254c27151869/seglist -segment_list_type csv -segment_list_size 2147483647 -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 media-%05d.ts -start_at_zero -copyts -vsync cfr -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/87bf1915-da78-4121-8ff9-75fdb4f816c4/3cf4698e-801d-4015-90fa-254c27151869/progress
Jul 11, 2017 09:59:35.403 [15824] DEBUG - Using default transcode duration of 120 minutes
Jul 11, 2017 09:59:35.403 [15824] DEBUG - Started session successfully: 87bf1915-da78-4121-8ff9-75fdb4f816c4
Jul 11, 2017 09:59:35.403 [15824] DEBUG - DVR:Recorder: It took 34.5 sec to start the session for http://192.168.10.111:5004/auto/v12.2?transcode=none
Jul 11, 2017 09:59:35.619 [15824] ERROR - DVR:Recorder: No part because session isn’t reporting one.
Jul 11, 2017 09:59:35.619 [15824] ERROR - DVR:Recorder: Couldn’t obtain a part, something went wrong.
Jul 11, 2017 09:59:35.619 [15824] ERROR - DVR:Recorder: Error 12 starting the record, shutting things down.
Jul 11, 2017 09:59:35.619 [15824] DEBUG - DVR:Recorder: Asked to stop recording ‘Matlock - E2 - The Vacation’.
Jul 11, 2017 09:59:35.619 [15824] DEBUG - DVR:Recorder: Stopping transcode session.
Jul 11, 2017 09:59:35.619 [15824] DEBUG - Killing job.
Jul 11, 2017 09:59:37.389 [15824] DEBUG - Job was already killed, not killing again.
Jul 11, 2017 09:59:37.389 [15824] DEBUG - Stopping transcode session 87bf1915-da78-4121-8ff9-75fdb4f816c4
Jul 11, 2017 09:59:37.389 [15824] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jul 11, 2017 09:59:37.389 [15824] DEBUG - DVR:Grabber: Operation for Matlock - E2 - The Vacation completed with status error (There was a transcoder error)
Jul 11, 2017 09:59:37.389 [4396] DEBUG - DVR:Recorder: Asked to stop recording ‘Matlock - E2 - The Vacation’.
Jul 11, 2017 09:59:37.389 [15824] DEBUG - Activity: Ended activity 2d996389-1195-45b4-8e2d-394fe7eac6a4.
Jul 11, 2017 09:59:37.389 [15824] ERROR - DVR:Grabber: Starting media grab failed.
Is your HDHR tuner 192.168.10.111?
Is the W: drive an internal drive? Guessing it is a network drive. Any access issues with the drive around that time?
I am not sure what an Error 12 indicates in Plex. Perhaps a Plex Employee @keithah can chime in and provide some insight.
Yes that is the Ip address for my tuner.
W: is an internal drive dedicated to plex Tv-Shows. No issues accessing it.
now the second show that should have recorded (Remington Steele 11am) looks like it completed but is in a hung state 30 mins after completion and never handed it off to MCE buddy for the post-processing script. I have had no issues with recording apart from what seems like the normal hiccups with the beta until today. I checked to see if I had a windows upate and nothing new has been added to the system since yesterday.
I would suggest a reboot of the server. If you are getting transcoder issues and hung recordings wouldn’t want to keep having problems today. I reverted back to 1.6.1 because I started having issues like this and couldn’t record more than one HDHR device tuners available. I have 9 total tuners from 4 HDHR devices and could only record using on HDHR Connect.
i went ahead and rebooted.
rebooted, updated to the latest release this AM. Version 1.7.6.4058, restarted - tested a single program and everything was fine. I reluctantly thought all might be well again. Then at 10-11am it tried to record matlock followed by remington steele on the same channel from 11am-12. I watched and I guess since it is the same channel it never used more than 1 tuner but both jobs just hung as if they were recording fine, but never stopped and passed it off to the post processing script for MCEbuddy. logs attached. by the way signal seemed good the entire time watching the HDhomerun config app.
There is a lot of data in your logs. Logs only cover about 3 hours of time. Unfortunately I have no clue why your show does not show in your library. I see where it started recording and got to 100% and request was made to stop the recording, then nothing that I saw until over an hour later when I see it destroying the metadata so guess it was deleted for some reason but I don’t see why in the logs. Perhaps a Plex Employee can chime in here and look @keithah @BigWheel. Pasting log entries I found related to the Matlock show below.
Jul 12, 2017 09:59:00.894 [11120] DEBUG - DVR:Grabber: Starting operation for ‘Matlock - E3 - The Legacy’.
Jul 12, 2017 09:59:00.895 [11120] DEBUG - Activity: registered new activity 131b43a3-1342-4ea4-9541-85dfcafac258 - Recording
Jul 12, 2017 09:59:00.895 [11120] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10532295 tuner 0.
Jul 12, 2017 09:59:00.896 [11120] DEBUG - DVR:Subscription: Resolved subscription to library item ‘Matlock’ (179770)
Jul 12, 2017 09:59:00.914 [11120] DEBUG - There were 1 top-level paths for Matlock.
Jul 12, 2017 09:59:00.915 [11120] DEBUG - DVR:Grabber: Saving recording to W:\TV-Shows.grab\894f5daa98f9fd9616ec222d8b36034aa9452e93
Jul 12, 2017 09:59:00.915 [11120] DEBUG - HTTP requesting GET http://192.168.10.111:80/lineup.json
Jul 12, 2017 09:59:00.946 [11120] DEBUG - HTTP 200 response from GET http://192.168.10.111:80/lineup.json
Jul 12, 2017 09:59:00.947 [11120] DEBUG - DVR:Grabber: Going to record for 3720 seconds, final URL is http://192.168.10.111:5004/auto/v12.2?transcode=none
Jul 12, 2017 09:59:00.947 [11120] DEBUG - DVR:Grabber: Setting timer to stop grab of ‘Matlock - E3 - The Legacy’ in 3720 seconds.
Jul 12, 2017 09:59:00.948 [11120] DEBUG - DVR:Segmenter: Creating a new recorder for http://192.168.10.111:5004/auto/v12.2?transcode=none.
Jul 12, 2017 09:59:00.963 [11120] DEBUG - DVR:Grabber: Waiting for a tuner (2 available).
Jul 12, 2017 09:59:00.963 [11120] DEBUG - DVR:Grabber: Allocated a tuner (1 left)
Jul 12, 2017 09:59:00.993 [11120] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Jul 12, 2017 09:59:00.993 [11120] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 1 language: en)
Jul 12, 2017 09:59:00.993 [11120] DEBUG - Falling back to picking the first audio stream 1.
Jul 12, 2017 09:59:00.993 [11120] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Jul 12, 2017 09:59:00.993 [11120] ERROR - Unable to find title for item of type 5
Jul 12, 2017 09:59:00.994 [11120] DEBUG - MDE: analyzing media item -1
Jul 12, 2017 09:59:00.994 [11120] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Jul 12, 2017 09:59:00.994 [11120] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Jul 12, 2017 09:59:00.994 [11120] DEBUG - MDE: : codec is unavailable for analysis
Jul 12, 2017 09:59:00.994 [11120] DEBUG - MDE: : codec is unavailable for analysis
Jul 12, 2017 09:59:00.995 [11120] ERROR - Unable to find title for item of type 5
Jul 12, 2017 09:59:00.995 [11120] DEBUG - MDE: : selected media 0 / -1
Jul 12, 2017 09:59:00.996 [11120] DEBUG - Cleaning directory for session 29c0843e-dabf-4919-8a1a-929149cc0f92 ()
Jul 12, 2017 09:59:00.996 [11120] DEBUG - Starting a transcode session 29c0843e-dabf-4919-8a1a-929149cc0f92 at offset -1.0 (state=3)
Jul 12, 2017 09:59:00.996 [11120] DEBUG - Streaming Resource: Added session 09690340:29c0843e-dabf-4919-8a1a-929149cc0f92
Jul 12, 2017 09:59:01.018 [11120] DEBUG - Job running: EAE_ROOT=’\?\C:\Users\Ray\AppData\Local\Plex-Server-data\Plex Media Server\Cache\Transcode\Sessions\EasyAudioEncoder’ FFMPEG_EXTERNAL_LIBS=’\\?\C:\Users\Ray\AppData\Local\Plex-Server-data\Plex\ Media\ Server\Codecs\46b03cf-1241-windows-i386\’ XDG_CACHE_HOME=‘C:\Users\Ray\AppData\Local\Plex-Server-data\Plex Media Server\Cache’ XDG_DATA_HOME=‘C:\Program Files (x86)\Plex\Plex Media Server\Resources’ X_PLEX_TOKEN=‘xxxxxxxxxxxxxxxxxxxx’ C:\Program Files (x86)\Plex\Plex Media Server\PlexTranscoder.exe -noaccurate_seek -ignore_unknown -scan_all_pmts -1 -i http://192.168.10.111:5004/auto/v12.2?transcode=none -map 0:V? -codec:V copy -map 0:a? -codec:a copy -copypriorss:a 0 -map 0:s? -codec:s copy -segment_format mpegts -f ssegment -individual_header_trailer 0 -segment_time 1 -segment_start_number 0 -segment_copyts 1 -segment_time_delta 0.0625 -segment_list http://127.0.0.1:32400/video/:/transcode/session/29c0843e-dabf-4919-8a1a-929149cc0f92/20cef493-36d9-490c-8ebb-1ca3426245a1/seglist -segment_list_type csv -segment_list_size 2147483647 -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 media-%05d.ts -start_at_zero -copyts -vsync cfr -y -nostats -loglevel quiet -loglevel_plex error -progressurl http://127.0.0.1:32400/video/:/transcode/session/29c0843e-dabf-4919-8a1a-929149cc0f92/20cef493-36d9-490c-8ebb-1ca3426245a1/progress
Jul 12, 2017 11:01:00.874 [11584] DEBUG - Activity: updated activity 131b43a3-1342-4ea4-9541-85dfcafac258 - completed 100% - Recording
Jul 12, 2017 11:01:00.949 [11120] DEBUG - DVR:Grabber: Cancelling operation for ‘Matlock - E3 - The Legacy’ with status complete.
Jul 12, 2017 11:01:00.949 [11120] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Jul 12, 2017 12:08:09.895 [16332] DEBUG - DVR:Recorder: Asked to stop recording ‘Matlock - E3 - The Legacy’.
Jul 12, 2017 12:08:09.895 [16332] DEBUG - DVR:Recorder: Stopping transcode session.
Jul 12, 2017 12:08:09.895 [16332] DEBUG - Job was already killed, not killing again.
Jul 12, 2017 12:08:09.896 [16332] DEBUG - Job was already killed, not killing again.
Jul 12, 2017 12:08:09.896 [16332] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jul 12, 2017 12:08:09.964 [16112] DEBUG - DVR:Recorder: Asked to stop recording ‘Matlock - E3 - The Legacy’.
Jul 12, 2017 12:08:09.969 [10176] DEBUG - JobRunner: exec of C:\ComskipDonator\plex script\MCEBuddyScriptv2.bat cancelled. In shutdown state.
Jul 12, 2017 12:08:09.970 [10176] ERROR - DVR:Recorder: Postprocessing script ‘C:\ComskipDonator\plex script\MCEBuddyScriptv2.bat’ didn’t start up.
Jul 12, 2017 12:08:09.970 [16332] DEBUG - JobRunner: exec of C:\ComskipDonator\plex script\MCEBuddyScriptv2.bat cancelled. In shutdown state.
Jul 12, 2017 12:08:09.970 [10176] DEBUG - Killing job.
Jul 12, 2017 12:08:09.970 [16332] ERROR - DVR:Recorder: Postprocessing script ‘C:\ComskipDonator\plex script\MCEBuddyScriptv2.bat’ didn’t start up.
Jul 12, 2017 12:08:09.970 [16332] DEBUG - DVR:Grabber: Scheduling ‘Matlock - E3 - The Legacy’ for assimilation.
Jul 12, 2017 12:08:09.972 [11120] DEBUG - DVR:Subscription: Resolved subscription to library item ‘Matlock’ (179770)
Jul 12, 2017 12:08:10.004 [11120] DEBUG - DVR:Grabber: Postprocessing, we’re going to put Matlock - E3 - The Legacy in W:\TV-Shows\Matlock (1986)\Season 07\Matlock (1986) - S07E03 - The Legacy.ts
Jul 12, 2017 12:08:10.041 [11120] DEBUG - DVR:Grabber: Moving W:\TV-Shows.grab\894f5daa98f9fd9616ec222d8b36034aa9452e93\Matlock (1986) - S07E03 - The Legacy.ts to W:\TV-Shows\Matlock (1986)\Season 07\Matlock (1986) - S07E03 - The Legacy.ts
Jul 12, 2017 12:08:10.045 [12528] INFO - Library section 3 (TV Shows) will be updated because of a change in W:\TV-Shows\Matlock (1986)\Season 07
Jul 12, 2017 12:08:43.001 [15992] DEBUG - EPG[onconnect]: Purging 2 airings which completed in the past.
Jul 12, 2017 12:08:43.002 [15992] DEBUG - Destroying metadata item 460 (The Legacy)
it did get killed eventually, I waited for about 35 mins after the second show and it never passed off any of the jobs so I had to stop the plex server to de-hang them.
