Recording to HDHomeRun EXTEND intermittently fails

General Discussions
1

I am running Plex on Ubuntu 18.04 LTS on a 6-core Intel Broadwell Xeon 3.6 GHz (4.0 turbo) based system with 64 GBs of ECC RAM and hardware RAID 5 for storage.
Plex version: 1.14.1.5488

I am seeing Plex intermittently fail to record a show or fail somewhere in the middle of recording. However it seems every time I check the tuner (HDHomeRun EXTEND), it always tunes into the channel when done in a more manual fashion or even watching through Plex live. I am wondering why Plex does not retry when a failure occurs and also if something else is going on? I did some digging through the logs and first right before I see failures in the log where it looks to be recording on the same channel the next show before stopping the recording of the previous show even though I don’t tell it to go over and I can’t find a way to tell it to go under:

Jan 15, 2019 16:00:00.930 [0x7f350c7ff700] DEBUG - DVR:Grabber: Starting operation for ‘Eyewitness News 4:00PM - Episode 01-15’ on channel 7.1.
Jan 15, 2019 16:00:00.931 [0x7f350c7ff700] DEBUG - Activity: registered new activity 936bf345-1305-4d01-baad-47e5b0c0933c - Recording
Jan 15, 2019 16:00:00.931 [0x7f350c7ff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/10583C70 (Silicondust HDHomeRun EXTEND, supported) tuner 0.
Jan 15, 2019 16:00:00.931 [0x7f34dbfff700] DEBUG - Activity: updated activity 519f362e-2906-49bd-ab41-3f2020672096 - completed 100% - Recording
Jan 15, 2019 16:00:00.934 [0x7f350c7ff700] DEBUG - DVR:Subscription: Resolved subscription to library item ‘Eyewitness News 4:00PM’ (39984)
Jan 15, 2019 16:00:01.011 [0x7f350c7ff700] DEBUG - There were 1 top-level paths for Eyewitness News 4:00PM.
Jan 15, 2019 16:00:01.012 [0x7f350c7ff700] DEBUG - DVR:Grabber: Saving recording to “/pub/Videos/Plex/.grab/060bceb7f98975e3fc8ad4db1db6f004307ae296”
Jan 15, 2019 16:00:01.013 [0x7f350c7ff700] DEBUG - HTTP requesting GET http://192.168.1.211:80/lineup.json
Jan 15, 2019 16:00:01.310 [0x7f34d6bff700] DEBUG - EPG[onconnect]: Next thing to start/end is at 2019-01-16 00:20:00 GMT (in 1200 seconds)
Jan 15, 2019 16:00:01.670 [0x7f353bfff700] DEBUG - buildLiveM3U8: min 0 max 876 ended 0
Jan 15, 2019 16:00:01.671 [0x7f353bfff700] DEBUG - buildLiveM3U8: ended due to segment 1796.612044 past end time 2019-01-16 00:00:00.000000000 +0000
Jan 15, 2019 16:00:01.673 [0x7f350d7ff700] DEBUG - Request: [::ffff:127.0.0.1:40320 (Loopback)] GET /livetv/sessions/e1ac7eb1-cf27-440c-b0e6-04e64cfc507d/6ce47a4d-e69a-4b56-851e-4b32b697ab64/00876.ts (13 live) Signed-in
Jan 15, 2019 16:00:01.674 [0x7f350d7ff700] DEBUG - Content-Length of /tmp/plex_transcode/Transcode/Sessions/plex-transcode-e1ac7eb1-cf27-440c-b0e6-04e64cfc507d/media-00876.ts is 1623756.
Jan 15, 2019 16:00:01.677 [0x7f353a7fe700] DEBUG - Completed: [::ffff:127.0.0.1:40320] 200 GET /livetv/sessions/e1ac7eb1-cf27-440c-b0e6-04e64cfc507d/6ce47a4d-e69a-4b56-851e-4b32b697ab64/00876.ts (13 live) 3ms 1623756 bytes (pipelined: 23)
Jan 15, 2019 16:00:01.685 [0x7f353cfff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 20429 is 0 (success)
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - DVR:Recorder: No more consumers, stopping.
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - DVR:Recorder: Asked to stop recording ‘ABC World News Tonight With David Muir - E15 - Episode 15’ on channel 7.1.
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - DVR:Recorder: Stopping transcode session.
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - Killing job.
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - Signalling job ID 20424 with 9
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - Job was already killed, not killing again.
Jan 15, 2019 16:00:01.686 [0x7f34c53f8700] DEBUG - Stopping transcode session e1ac7eb1-cf27-440c-b0e6-04e64cfc507d
Jan 15, 2019 16:00:01.686 [0x7f34dd7fb700] DEBUG - Cleaning directory for session e1ac7eb1-cf27-440c-b0e6-04e64cfc507d (/tmp/plex_transcode/Transcode/Sessions/plex-transcode-e1ac7eb1-cf27-440c-b0e6-04e64cfc507d)
Jan 15, 2019 16:00:01.689 [0x7f353cfff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 20424 is -9 (signal: Killed)
Jan 15, 2019 16:00:01.705 [0x7f34c53f8700] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jan 15, 2019 16:00:01.705 [0x7f34c53f8700] DEBUG - DVR:Grabber: Recording for ‘ABC World News Tonight With David Muir - E15 - Episode 15’ on channel 7.1 stopped with status complete.
Jan 15, 2019 16:00:01.705 [0x7f34c53f8700] DEBUG - DVR:Grabber: Using recording status.
Jan 15, 2019 16:00:01.705 [0x7f34c53f8700] DEBUG - Activity: updated activity 519f362e-2906-49bd-ab41-3f2020672096 - completed 100% - Recording
Jan 15, 2019 16:00:01.706 [0x7f34c53f8700] DEBUG - [MI] Opening input file: “/pub/Videos/Plex/.grab/24a1bc4b8a16ca5fb3ba93217869365c14679cad/ABC World News Tonight With David Muir (2014) - S2019E15 - Episode 15.ts”
Jan 15, 2019 16:00:01.706 [0x7f34c53f8700] DEBUG - [FFMPEG] - Opening ‘/pub/Videos/Plex/.grab/24a1bc4b8a16ca5fb3ba93217869365c14679cad/ABC World News Tonight With David Muir (2014) - S2019E15 - Episode 15.ts’ for reading

Then 29 seconds into recording a show where I see the failure:

Jan 15, 2019 16:00:29.340 [0x7f34ddffc700] DEBUG - DVR:Device: Discovering and refreshing devices with identifier tv.plex.grabbers.hdhomerun
Jan 15, 2019 16:00:29.341 [0x7f34ddffc700] DEBUG - DVR:Grabber: HDHomerun discovered 0 compatible devices.
Jan 15, 2019 16:00:29.341 [0x7f34ddffc700] DEBUG - DVR:Device: Testing grabber HDHomerun device device://tv.plex.grabbers.hdhomerun/10583C70 at http://192.168.1.211:80
Jan 15, 2019 16:00:29.341 [0x7f34ddffc700] DEBUG - DVR:Device: Device device://tv.plex.grabbers.hdhomerun/10583C70 was already known, refreshing database info
Jan 15, 2019 16:00:34.348 [0x7f34ddffc700] ERROR - DVR:Device: Error refreshing existing device device://tv.plex.grabbers.hdhomerun/10583C70, marking as dead.
Jan 15, 2019 16:00:35.010 [0x7f34c4bf7700] DEBUG - Activity: updated activity 9f94c961-f47f-419b-84bb-a549332b1d1d - completed 32% - Generating video preview thumbnails
Jan 15, 2019 16:00:35.510 [0x7f34d63fe700] DEBUG - Activity: updated activity 9f94c961-f47f-419b-84bb-a549332b1d1d - completed 33% - Generating video preview thumbnails
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] DEBUG - TranscodeSession: timed out waiting to find duration for live session
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] ERROR - Failed to start session.
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] DEBUG - Streaming Resource: Terminated session 0x7f350ac39160:3072d361-9484-469e-93df-99ec1237fadd with reason Recording failed. Please check your tuner or antenna.
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] ERROR - DVR:Recorder: Unable to create transcode session or session failed to start.
Jan 15, 2019 16:00:36.065 [0x7f34cc3ff700] DEBUG - Killing job.
Jan 15, 2019 16:00:36.065 [0x7f34cc3ff700] DEBUG - Signalling job ID 25515 with 9
Jan 15, 2019 16:00:36.065 [0x7f34cc3ff700] DEBUG - Job was already killed, not killing again.
Jan 15, 2019 16:00:36.065 [0x7f34cc3ff700] DEBUG - Stopping transcode session 3072d361-9484-469e-93df-99ec1237fadd
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] DEBUG - Job was already killed, not killing again.
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] ERROR - DVR:Recorder: Error 16 (Recording failed. Please check your tuner or antenna.) starting the record, shutting things down.
Jan 15, 2019 16:00:36.065 [0x7f35137ff700] DEBUG - Cleaning directory for session 3072d361-9484-469e-93df-99ec1237fadd (/tmp/plex_transcode/Transcode/Sessions/plex-transcode-3072d361-9484-469e-93df-99ec1237fadd)
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] DEBUG - MediaRecorderVirtual: setting stop time to 2019-01-15 16:00:36
Jan 15, 2019 16:00:36.065 [0x7f350c7ff700] DEBUG - DVR:Recorder: Asked to stop recording ‘Eyewitness News 4:00PM - Episode 01-15’ on channel 7.1.
Jan 15, 2019 16:00:36.068 [0x7f353cfff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 25515 is -9 (signal: Killed)
Jan 15, 2019 16:00:36.068 [0x7f350c7ff700] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jan 15, 2019 16:00:36.068 [0x7f350c7ff700] ERROR - DVR:Recorder: Error 16 (Recording failed. Please check your tuner or antenna.) starting the record, shutting things down.
Jan 15, 2019 16:00:36.068 [0x7f350c7ff700] DEBUG - MediaRecorderVirtual: setting stop time to 2019-01-15 16:00:36
Jan 15, 2019 16:00:36.068 [0x7f350c7ff700] DEBUG - DVR:Recorder: No more consumers, stopping.
Jan 15, 2019 16:00:36.068 [0x7f350c7ff700] DEBUG - DVR:Grabber: Operation for ‘Eyewitness News 4:00PM - Episode 01-15’ on channel 7.1 completed with status error (Recording failed. Please check your tuner or antenna.)
Jan 15, 2019 16:00:36.069 [0x7f350c7ff700] DEBUG - Activity: Ended activity 936bf345-1305-4d01-baad-47e5b0c0933c.
Jan 15, 2019 16:00:36.069 [0x7f350c7ff700] ERROR - DVR:Grabber: Starting media grab failed.

2

One thing I have done since this post is setup a new antenna. While the original antenna worked at first, there was getting to be a lot of breakup on some channels intermittently as in most recordings would be fine, some would not be and recording failures seemed to be focused at points of heavy breakup. With the new antenna this signal breaking up issue has completely resolved, however sometimes a recording abruptly fails, so there is still a problem. When I go into the logs, now there are just way too many things being logged for the allowed log file size and the problem time scrolls off the logs before I get a chance to download and examine them. I am only getting about an hour or so of the “Plex Media Server” log before log #5 scrolls off. I really need at least a whole day of logs so I have a reasonable chance of catching one of these recording failures as they are highly intermittent and it is not reasonably to hover over Plex 7x24 trying to catch the instant one of the recordings fail.

3

I had a drop out while in live mode. From the Roku it says it exited after too many errors. From the logs though, it looks like it just quit. I have a direct fiber link between rooms and it seems to be a very reliable link. Here are the logs I found of relevance:

Feb 02, 2019 14:26:45.306 [0x7f9054bf7700] DEBUG - Asked for segment 4079 from session.
Feb 02, 2019 14:26:45.306 [0x7f9054bf7700] DEBUG - Returning segment 4079 from session: “/tmp/plex_transcode/Transcode/Sessions/plex-transcode-22b66f2b-1313-453a-99e5-93b94c1ae9d9_1-51381e93-5bf5-4d0c-8263-9408c0a2af68/media-04079.ts”
Feb 02, 2019 14:26:45.306 [0x7f9054bf7700] DEBUG - Content-Length of /tmp/plex_transcode/Transcode/Sessions/plex-transcode-22b66f2b-1313-453a-99e5-93b94c1ae9d9_1-51381e93-5bf5-4d0c-8263-9408c0a2af68/media-04079.ts is 900708.
Feb 02, 2019 14:26:45.359 [0x7f90c37fe700] DEBUG - Completed: [::ffff:192.168.1.128:34775] 200 GET /video/:/transcode/universal/session/22b66f2b-1313-453a-99e5-93b94c1ae9d9_1/base/04079.ts?protocol=hls&mediaIndex=0&waitForSegments=1 (18 live) TLS 52ms 900708 bytes (pipelined: 4080)
Feb 02, 2019 14:26:45.445 [0x7f9053bf5700] DEBUG - Asked for segment 4080 from session.
Feb 02, 2019 14:26:45.445 [0x7f9053bf5700] DEBUG - Returning segment 4080 from session: “/tmp/plex_transcode/Transcode/Sessions/plex-transcode-22b66f2b-1313-453a-99e5-93b94c1ae9d9_1-51381e93-5bf5-4d0c-8263-9408c0a2af68/media-04080.ts”
Feb 02, 2019 14:26:45.445 [0x7f9053bf5700] DEBUG - Content-Length of /tmp/plex_transcode/Transcode/Sessions/plex-transcode-22b66f2b-1313-453a-99e5-93b94c1ae9d9_1-51381e93-5bf5-4d0c-8263-9408c0a2af68/media-04080.ts is 467556.
Feb 02, 2019 14:26:45.449 [0x7f90c37fe700] DEBUG - Completed: [::ffff:192.168.1.128:34775] 200 GET /video/:/transcode/universal/session/22b66f2b-1313-453a-99e5-93b94c1ae9d9_1/base/04080.ts?protocol=hls&mediaIndex=0&waitForSegments=1 (18 live) TLS 4ms 467556 bytes (pipelined: 4081)
Feb 02, 2019 14:26:45.585 [0x7f905ffff700] DEBUG - Transcoder segment range: 0 - 1993
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Grabber: Cancelling operation for ‘Live TV - Session’ on channel 7.1 with status complete.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Grabber: Cleaning up rolling grab for channel 7.1.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Recorder: No more consumers, stopping.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Recorder: Asked to stop recording ‘Live TV - Session’ on channel 7.1.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - DVR:Recorder: Stopping transcode session.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - Killing job.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - Signalling job ID 17346 with 9
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - Job was already killed, not killing again.
Feb 02, 2019 14:26:45.913 [0x7f9058bff700] DEBUG - Stopping transcode session 11249b6a-8269-40ac-af27-8d56099d495b
Feb 02, 2019 14:26:45.913 [0x7f90c4fff700] DEBUG - Cleaning directory for session 11249b6a-8269-40ac-af27-8d56099d495b (/tmp/plex_transcode/Transcode/Sessions/plex-transcode-11249b6a-8269-40ac-af27-8d56099d495b)
Feb 02, 2019 14:26:45.917 [0x7f90bb3ff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 17346 is -9 (signal: Killed)
Feb 02, 2019 14:26:45.921 [0x7f90c3fff700] DEBUG - Completed: [::ffff:192.168.1.10:47440] 200 GET /status/sessions/background (17 live) TLS GZIP 2ms 470 bytes (pipelined: 4)
Feb 02, 2019 14:26:45.923 [0x7f90c3fff700] DEBUG - Completed: [::ffff:192.168.1.10:47296] 200 GET /status/sessions/background (17 live) TLS GZIP 1ms 470 bytes (pipelined: 8)
Feb 02, 2019 14:26:45.941 [0x7f9058bff700] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Grabber: Recording for ‘Live TV - Session’ on channel 7.1 stopped with status complete.
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Grabber: This was a rolling sub, not assimilating.
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Grabber: Operation for ‘Live TV - Session’ on channel 7.1 completed with status complete (Success)
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - Activity: Ended activity d0323d91-866c-4303-a7f4-8fae509cf865.
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Grabber: Cleaning up rolling grab for channel 7.1.
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Recorder: No more consumers, stopping.
Feb 02, 2019 14:26:45.941 [0x7f905dffe700] DEBUG - DVR:Subscription: Cancelling grab for subscription 211: ‘Live TV - Session’ on channel 7.1
Feb 02, 2019 14:26:45.943 [0x7f905dffe700] DEBUG - Activity: registered new activity b4b0b8d1-86d2-447f-85de-fd4533a8e65c - Processing subscriptions

4

Had another failed recording. I managed to get the logs this time and it looks like what happens is the recording gets rescheduled at the 1 hour mark and soon after the recording is issued a stop command.

Here are logs of interest:
Feb 03, 2019 07:00:02.539 [0x7f9044ff4700] DEBUG - DVR:NewSchedule: Scheduled an operation ‘CBS News Sunday Morning - Episode 02-03’ on channel 2.1 on tuner 0 between 2019-02-03 06:00:00 and 2019-02-03 07:30:00
Feb 03, 2019 07:00:02.539 [0x7f9044ff4700] DEBUG - MediaRecorderVirtual: setting stop time to 2019-02-03 07:30:00

Note that the recording has been going for an hour now and the scheduler is scheduling a ‘new’ operation now. Next how the logs show the recording has stopped:
Feb 03, 2019 07:00:32.895 [0x7f90bb3ff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 17913 is 0 (success)
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Recorder: No more consumers, stopping.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Recorder: Asked to stop recording ‘CBS News Sunday Morning - Episode 02-03’ on channel 2.1.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Recorder: Stopping transcode session.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - Job was already killed, not killing again.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - Job was already killed, not killing again.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Grabber: Recording for ‘CBS News Sunday Morning - Episode 02-03’ on channel 2.1 stopped with status error.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - DVR:Grabber: Using recording status.
Feb 03, 2019 07:00:32.895 [0x7f905cfff700] DEBUG - Activity: updated activity c466af99-4b5c-4747-bd77-e2967c38a23c - completed 100% - Recording
Feb 03, 2019 07:00:32.896 [0x7f905cfff700] DEBUG - Activity: updated activity c466af99-4b5c-4747-bd77-e2967c38a23c - completed 100% - Recording
Feb 03, 2019 07:00:32.896 [0x7f905cfff700] DEBUG - [MI] Opening input file: “/pub/Videos/Plex/.grab/1a9de215d7d4711346abe2bd75a7767af4468959/CBS News Sunday Morning (1979) - 2019-02-03 06 00 00 - Episode 02-03.ts”
Feb 03, 2019 07:00:32.896 [0x7f905cfff700] DEBUG - [FFMPEG] - Opening ‘/pub/Videos/Plex/.grab/1a9de215d7d4711346abe2bd75a7767af4468959/CBS News Sunday Morning (1979) - 2019-02-03 06 00 00 - Episode 02-03.ts’ for reading

For some extra notes:

  1. The recording duration shows up as 59:56 recorded out of 1:30:00 total.
  2. This is not the first time it has failed this far into a recording (as in almost exactly 1 hour in).
  3. The video quality is perfect all the way up to the ‘failure’.
5

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