Bug with pass?

[bpoe]

I’ve run into the issue twice now. For one reason or another, my DVR doesn’t record an episode and it shows in the Schedule as “Program had already started”. I see that another airing of that episode in the guide later. I would assume that the DVR would try to record that one. But it doesn’t show up in the recording schedule. And if I try to manually tell it to record the episode, nothing happens. Is this a bug? Or is my DVR I’m some bad state?

This happened with 2 different passes, The Walking Dead and His Dark Materials. Both in the past 3 weeks. My confidence in this usually rock solid DVR is beginning to waver. Any thoughts?

[tmm1]

What does the log show at the time the original recording was supposed to happen?

[bpoe]

2019/12/07 12:35:52 [DVR] Rule 'His Dark Materials' (44) found 2 new airings
2019/12/07 12:35:52 [DVR] queued recording job for EP032341330015 @ Mon Dec 9 5:57:00PM (1575943020-44)
2019/12/07 12:35:52 [DVR] queued recording job for EP032341330007 @ Mon Dec 16 5:57:00PM (1576547820-44)
2019/12/07 12:36:45 [DVR] Rule 'His Dark Materials' (44) found 7 new airings
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330005 @ Sat Dec 7 12:27:00PM (1575750420-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330001 @ Sun Dec 8 5:57:00AM (1575813420-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330002 @ Sun Dec 8 6:57:00AM (1575817020-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330003 @ Sun Dec 8 7:57:00AM (1575820620-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330004 @ Sun Dec 8 8:57:00AM (1575824220-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330015 @ Mon Dec 9 5:57:00PM (1575943020-44)
2019/12/07 12:36:45 [DVR] queued recording job for EP032341330007 @ Mon Dec 16 5:57:00PM (1576547820-44)
2019/12/07 12:36:45 [DVR] Skipping job because program already started 1575750420-44 His Dark Materials
2019/12/07 12:36:45 [DVR] Waiting 17h20m14.2169718s until next job 1575813420-44 His Dark Materials
2019/12/07 12:45:04 [NAT] Successfully mapped port 8089 using upnp
2019/12/07 12:51:20 [DVR] Skipping job because program already started 1575750420-44 His Dark Materials

I’m fine with it skipping the occurrence if it already started. My concern is that it didn’t record the next occurrence of the missed episode and that it won’t let me manually schedule it either. Seems like that episode has some kind of unreleased lock.

[tmm1]

Looks like the pass is set to record All?

Can you pull logs for the Walking Dead failure too?

[bpoe]

2019/11/24 17:57:00 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:57:00 [DVR] Waiting 1h19m59.9758637s until next job 1574651820-4 Talking Dead
2019/11/24 17:57:03 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:57:03 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:57:33 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:57:33 [DVR] Waiting 1h19m26.9361122s until next job 1574651820-4 Talking Dead
2019/11/24 17:57:34 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:57:34 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:58:04 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:58:04 [DVR] Waiting 1h18m55.8392694s until next job 1574651820-4 Talking Dead
2019/11/24 17:58:05 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:58:05 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:58:35 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:58:35 [DVR] Waiting 1h18m24.7792861s until next job 1574651820-4 Talking Dead
2019/11/24 17:58:36 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:58:36 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:59:06 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:59:06 [DVR] Waiting 1h17m53.7081061s until next job 1574651820-4 Talking Dead
2019/11/24 17:59:07 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:59:07 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:59:37 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 17:59:37 [DVR] Waiting 1h17m22.6029752s until next job 1574651820-4 Talking Dead
2019/11/24 17:59:38 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 17:59:38 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:00:08 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:00:08 [DVR] Waiting 1h16m51.5022428s until next job 1574651820-4 Talking Dead
2019/11/24 18:00:09 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:00:09 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:00:39 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:00:39 [DVR] Waiting 1h16m20.4170651s until next job 1574651820-4 Talking Dead
2019/11/24 18:00:40 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:00:40 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:01:10 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:01:10 [DVR] Waiting 1h15m49.3350942s until next job 1574651820-4 Talking Dead
2019/11/24 18:01:11 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:01:11 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:01:41 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:01:41 [DVR] Waiting 1h15m18.2651212s until next job 1574651820-4 Talking Dead
2019/11/24 18:01:42 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:01:42 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:02:13 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:02:13 [DVR] Waiting 1h14m46.7089729s until next job 1574651820-4 Talking Dead
2019/11/24 18:02:14 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:02:14 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:02:44 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:02:44 [DVR] Waiting 1h14m15.621083s until next job 1574651820-4 Talking Dead
2019/11/24 18:02:45 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:02:45 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:03:15 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:03:15 [DVR] Waiting 1h13m44.5204633s until next job 1574651820-4 Talking Dead
2019/11/24 18:03:16 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:03:16 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:03:46 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:03:46 [DVR] Waiting 1h13m13.4441772s until next job 1574651820-4 Talking Dead
2019/11/24 18:03:47 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:03:47 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:04:17 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:04:17 [DVR] Waiting 1h12m42.3693792s until next job 1574651820-4 Talking Dead
2019/11/24 18:04:18 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:04:18 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:04:48 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:04:48 [DVR] Waiting 1h12m11.2918877s until next job 1574651820-4 Talking Dead
2019/11/24 18:04:49 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:04:49 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:05:19 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:05:19 [DVR] Waiting 1h11m40.2102447s until next job 1574651820-4 Talking Dead
2019/11/24 18:05:20 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:05:20 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:05:50 [DVR] Starting job 1574647020-2 The Walking Dead on ch=[731]
2019/11/24 18:05:50 [DVR] Waiting 1h11m9.1453016s until next job 1574651820-4 Talking Dead
2019/11/24 18:05:51 [ERR] Failed to start stream on channel 731 via 1325ADF9: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:05:51 [DVR] Error running job 1574647020-2 The Walking Dead: could not start stream on channels=[731]: Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.
2019/11/24 18:06:21 [DVR] Skipping job because program already started 1574647020-2 The Walking Dead
2019/11/24 18:06:21 [DVR] Waiting 1h10m38.0650033s until next job 1574651820-4 Talking Dead
2019/11/24 19:17:00 [DVR] Skipping job because program already started 1574647020-2 The Walking Dead
2019/11/24 19:17:00 [DVR] Starting job 1574651820-4 Talking Dead on ch=[731]
2019/11/24 19:17:00 [DVR] Waiting 1h39m59.9753243s until next job 1574657820-16 NCIS: Los Angeles

[tmm1]

Get http://10.0.1.19:5004/auto/v731?: dial tcp 10.0.1.19:5004: connectex: No connection could be made because the target machine actively refused it.

Hmm the dvr was unable to connect to your HDHR for some reason. It might be worth adding a dhcp reservation on your router so the IP of the HDHR stays the same.

As far as not recording the next airing automatically- I will take a look.

[bpoe]

That’s a good suggestion, I just did that.

So in the case of The Walking Dead, someone had unplugged the HDHR. That’s why it couldn’t connect. I got it plugged back in and it reconnected successfully and it was able to record the next show, Talking Dead. However, the missed episode of The Walking Dead aired again right after Talking Dead. Like I mentioned, the DVR didn’t try to automatically record the missed episode and it wouldn’t let me manually schedule it either.

It looks like I’m in this same state with His Dark Materials right now. S01E05 was missed and I’m not even able to manually schedule it. So if there is anything you want me to collect or try out while I’m in this state, let me know.

[tmm1]

Where are you trying to manually schedule and what happens when you try?

[bpoe]

I’ve tried from the iPad app and the Apple TV app. I enable HTTP logging and I see this in the log:

[GIN] 2019/12/09 - 12:04:24 | 200 | 15.7068ms | 10.0.1.33 | PUT /dvr/jobs/1575750420-44
2019/12/09 12:04:24 [DVR] Waiting 5h52m35.1109084s until next job 1575943020-44 His Dark Materials

But when I go back to the scheduled recordings, it’s not listed.

[tmm1]

Can you try from the web UI

[bpoe]

If I look at the upcoming episodes on the web UI, it says that it is queued

[tmm1]

Does it show on the Schedule?

[bpoe]

No. Only the failed attempt and the next episode.

[tmm1]

On the previous screen if you click the Queued drop down what does it say?

[bpoe]

I’m not sure which screen you meant, so here is both

[tmm1]

Okay I see what's going on. It thinks it's still scheduled in the past.

If you delete from the Schedule, does it then get rid of the Queued state in search?

[bpoe]

Yep! I can try to manually schedule it again, but should I wait to see if the engine will pick it up?

[tmm1]

Great. You can pause/resume the pass and it should reschedule.

I will fix the bug where it gets stuck as Queued after a failure.

[bpoe]

Pause/Resume trigger the job to record the episode. Thanks for the help and thanks for looking into the bug! The awesome support from you guys always restores my faith

[tmm1]

Thanks for reporting this issue and for helping us narrow down the root cause.

The bug with the stuck Queued state has been fixed for the next DVR build.