Recordings Interrupted by HDHomeRun I/O Timeouts


#1

Found a strange issue that affected my recordings tonight. I had 3 shows queued to record simultaneously with Channels DVR. First time I’ve tried that, I think.
All of them started successfully, but they were all interrupted with what appears to be a loss of connection to the HDHomeRun Prime.
The logs show the jobs all restart 30 seconds later only to have the same thing happen again 5 minutes later. The recordings still played fine in the end, but were missing two 30 second chucks. (Caused me to miss a goal in the hockey game :anguished:

I don’t recall the HDHR ever having trouble with 3 simultaneous recordings when I used to use Windows Media Center. Neither has it happened with Channels ATV or iOS apps pre-DVR.
I checked the CPU Disk and Network utilization of my Synology DS916+, and it shows nothing out of the ordinary. Nothing else crazy was going on with the network at the time. In fact no one was home.

Any ideas what could be causing these i/o timeouts?

Logs below:

2017/01/24 18:02:59 [DVR] Waiting 27m0.655750543s until next job 1485300600-ch1530
2017/01/24 18:03:07 [DVR] Waiting 26m52.569325439s until next job 1485300600-ch1530
2017/01/24 18:30:00 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 18:30:00 [DVR] Waiting 29m59.984970818s until next job 1485302400-12
2017/01/24 18:30:00 [DVR] Recording for job 1485300600-ch1530 from 131037AA ch1530 into “Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg” for 2h2m59.982883302s
2017/01/24 19:00:00 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:00:00 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:00:00 [DVR] Recording for job 1485302400-4 from 131037AA ch201 into “TV/NHL Hockey/2017-01-24-1900 NHL Hockey 2017-01-24 Detroit Red Wings at Boston Bruins.mpg” for 3h29m59.996082405s
2017/01/24 19:00:00 [DVR] Recording for job 1485302400-12 from 131037AA ch214 into “TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg” for 1h2m59.995986654s
2017/01/24 19:42:29 [DVR] Job 1485302400-4 ended prematurely: 2h47m30.209160442s
2017/01/24 19:42:29 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:42:29 [DVR] Job 1485302400-12 ended prematurely: 20m30.198182163s
2017/01/24 19:42:29 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:42:29 [DVR] Job 1485300600-ch1530 ended prematurely: 50m30.188431476s
2017/01/24 19:42:29 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:42:34 [ERR] Failed to start stream on channel 201 via 131037AA: Get http://192.168.15.204:5004/auto/v201?duration=10051: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:42:34 [DVR] Error running job 1485302400-4: could not start stream on channels=[201]: Get http://192.168.15.204:5004/auto/v201?duration=10051: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:42:34 [ERR] Failed to start stream on channel 214 via 131037AA: Get http://192.168.15.204:5004/auto/v214?duration=1231: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:42:34 [DVR] Error running job 1485302400-12: could not start stream on channels=[214]: Get http://192.168.15.204:5004/auto/v214?duration=1231: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:42:34 [ERR] Failed to start stream on channel 1530 via 131037AA: Get http://192.168.15.204:5004/auto/v1530?duration=3031: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:42:34 [DVR] Error running job 1485300600-ch1530: could not start stream on channels=[1530]: Get http://192.168.15.204:5004/auto/v1530?duration=3031: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:04 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:43:04 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:43:04 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:43:09 [ERR] Failed to start stream on channel 214 via 131037AA: Get http://192.168.15.204:5004/auto/v214?duration=1196: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:09 [DVR] Error running job 1485302400-12: could not start stream on channels=[214]: Get http://192.168.15.204:5004/auto/v214?duration=1196: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:09 [ERR] Failed to start stream on channel 1530 via 131037AA: Get http://192.168.15.204:5004/auto/v1530?duration=2996: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:09 [DVR] Error running job 1485300600-ch1530: could not start stream on channels=[1530]: Get http://192.168.15.204:5004/auto/v1530?duration=2996: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:09 [ERR] Failed to start stream on channel 201 via 131037AA: Get http://192.168.15.204:5004/auto/v201?duration=10016: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:09 [DVR] Error running job 1485302400-4: could not start stream on channels=[201]: Get http://192.168.15.204:5004/auto/v201?duration=10016: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:43:39 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:43:39 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:43:39 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:43:40 [DVR] Recording for job 1485302400-12 from 131037AA ch214 into “TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg” for 19m20.193687681s
2017/01/24 19:43:40 [DVR] Recording for job 1485300600-ch1530 from 131037AA ch1530 into “Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg” for 49m20.194598043s
2017/01/24 19:43:40 [DVR] Recording for job 1485302400-4 from 131037AA ch201 into “TV/NHL Hockey/2017-01-24-1900 NHL Hockey 2017-01-24 Detroit Red Wings at Boston Bruins.mpg” for 2h46m20.192987008s
2017/01/24 19:48:40 [DVR] Job 1485302400-12 ended prematurely: 14m19.541837609s
2017/01/24 19:48:40 [DVR] Job 1485302400-4 ended prematurely: 2h41m19.540227674s
2017/01/24 19:48:40 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:48:40 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:48:40 [DVR] Job 1485300600-ch1530 ended prematurely: 44m19.484181082s
2017/01/24 19:48:40 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:48:45 [ERR] Failed to start stream on channel 201 via 131037AA: Get http://192.168.15.204:5004/auto/v201?duration=9680: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:48:45 [DVR] Error running job 1485302400-4: could not start stream on channels=[201]: Get http://192.168.15.204:5004/auto/v201?duration=9680: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:48:45 [ERR] Failed to start stream on channel 214 via 131037AA: Get http://192.168.15.204:5004/auto/v214?duration=860: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:48:45 [DVR] Error running job 1485302400-12: could not start stream on channels=[214]: Get http://192.168.15.204:5004/auto/v214?duration=860: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:48:45 [ERR] Failed to start stream on channel 1530 via 131037AA: Get http://192.168.15.204:5004/auto/v1530?duration=2660: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:48:45 [DVR] Error running job 1485300600-ch1530: could not start stream on channels=[1530]: Get http://192.168.15.204:5004/auto/v1530?duration=2660: dial tcp 192.168.15.204:5004: i/o timeout
2017/01/24 19:49:15 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:49:15 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:49:15 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:49:15 [DVR] Recording for job 1485302400-4 from 131037AA ch201 into “TV/NHL Hockey/2017-01-24-1900 NHL Hockey 2017-01-24 Detroit Red Wings at Boston Bruins.mpg” for 2h40m44.530763109s
2017/01/24 19:49:15 [DVR] Recording for job 1485302400-12 from 131037AA ch214 into “TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg” for 13m44.531775773s
2017/01/24 19:49:16 [DVR] Recording for job 1485300600-ch1530 from 131037AA ch1530 into “Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg” for 43m44.529821733s
2017/01/24 19:53:13 [DVR] Job 1485302400-12 ended prematurely: 9m46.594817978s
2017/01/24 19:53:13 [DVR] Starting job 1485302400-12 The First 100 Days on ch=[1105 214 66]
2017/01/24 19:53:13 [DVR] Job 1485302400-4 ended prematurely: 2h36m46.589990609s
2017/01/24 19:53:13 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:53:13 [DVR] Job 1485300600-ch1530 ended prematurely: 39m46.538535093s
2017/01/24 19:53:13 [DVR] Starting job 1485300600-ch1530 Paul Blart: Mall Cop (2009) on ch=[1530]
2017/01/24 19:53:16 [ERR] Failed to start stream on channel 201 via 131037AA: got http response code 503
2017/01/24 19:53:16 [DVR] Error running job 1485302400-4: could not start stream on channels=[201]: got http response code 503
2017/01/24 19:53:16 [DVR] Recording for job 1485302400-12 from 131037AA ch214 into “TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg” for 9m46.59094196s
2017/01/24 19:53:17 [DVR] Recording for job 1485300600-ch1530 from 131037AA ch1530 into “Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg” for 39m46.534686804s
2017/01/24 19:53:46 [DVR] Starting job 1485302400-4 NHL Hockey on ch=[1650 201 30]
2017/01/24 19:53:46 [DVR] Recording for job 1485302400-4 from 131037AA ch201 into “TV/NHL Hockey/2017-01-24-1900 NHL Hockey 2017-01-24 Detroit Red Wings at Boston Bruins.mpg” for 2h36m13.572269672s
2017/01/24 20:03:04 [DVR] Finished job 1485302400-12 The First 100 Days
2017/01/24 20:03:04 [DVR] Processing file-74: TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg
2017/01/24 20:03:04 [DVR] Running commercial detection on file 74 (TV/The First 100 Days/2017-01-24-1900 The First 100 Days 2017-01-24.mpg)
2017/01/24 20:15:10 [DVR] Commercial detection finished with 12 markers.
2017/01/24 20:33:04 [DVR] Finished job 1485300600-ch1530 Paul Blart: Mall Cop (2009)
2017/01/24 20:33:04 [DVR] Processing file-72: Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg
2017/01/24 20:33:05 [DVR] Running commercial detection on file 72 (Movies/Paul Blart: Mall Cop (2009) 2017-01-24-1830.mpg)


#2

Looks like the DVR lost network access to the HDHR. No clue why… could be a network issue, or the HDHR itself died or lost ethernet or something.


#3

I have the same problem. Here is a snippet from my logs:

2019/04/03 07:51:23 [ERR] Failed to start stream on channel 4.1 via 1064EBC1: Get http://192.168.7.141:5004/auto/v4.1?: dial tcp 192.168.7.141:5004: i/o timeout

2019/04/03 07:51:23 [DVR] Error running job 1554289200-1 Today: could not start stream on channels=[4.1]: Get http://192.168.7.141:5004/auto/v4.1?: dial tcp 192.168.7.141:5004: i/o timeout

2019/04/03 07:51:54 [DVR] Starting job 1554289200-1 Today on ch=[4.1]

2019/04/03 07:51:54 [DVR] Waiting 11h8m5.949472979s until next job 1554332400-3 NBC Nightly News With Lester Holt

2019/04/03 07:51:56 [ERR] Failed to start stream on channel 4.1 via 1064EBC1: Get http://192.168.7.141:5004/auto/v4.1?: dial tcp 192.168.7.141:5004: i/o timeout


I watch shows via the $20 Channels app on my Apple TV and I know there is a problem because the DVR menu option disappears. The only remedy seems to be to REBOOT the box running the Channels DVR software. Can you guys put in a check on the logs periodically to detect this and reboot the box automatically (or at least provide that as an option in settings). Here is the info about my box from your settings page:

OS

Freebsd
11.2-release (kernel: 11.2-release)

CPU

2 cores / Intel(R) Core(TM)2 CPU T7600 @ 2.33GHz

load averages: 0.32 0.25 0.19

RAM

2.89 GB
92.4% free

---- all running on a Mac Mini -----

Any suggestions? This happens about one a month and is what keeps me from recommending your product to anyone (especially someone not tech savvy).

Bart


#4

This means the DVR is trying to connect to your HDHR and it is not able to make a connection. Either the IP of your HDHR is changing (in which case you should setup a static DHCP reservation on your router), or something is broken on your network.

This also indicates a network problem, since the ATV is unable to talk to the DVR all of a sudden. Maybe you are experiencing hardware failure or there are bugs on your router.

Are all the devices connected to the same physical switch?