DVR stops recording shows after failed scheduled recording

[jpsb]

Hello,

I have an issue where the DVR stopped recording everything on the schedule after a recording fails.

This happened to me a few weeks back too and I just shrugged and rebooted the DVR on my server (FreeNAS) which fixed the issue & the schedule started working again. Now that it's happened again, I thought I'd reach out.

Everything seems to work (watching live TV, recordings, etc., just scheduled recordings have stopped).

There is plenty of space on the hard drive, the DVR runs on a server so it never sleeps.

Logs:

2020/01/04 05:00:00 [DVR] Starting job 1578135600-75 Dolly! on ch=[25.6]
2020/01/04 05:00:00 [DVR] Waiting 4h59m59.99551686s until next job 1578153600-77 Earth Odyssey With Dylan Dreyer
2020/01/04 09:14:00 [DVR] Fetching guide data for 34 stations in USA-OTA55437 @ 2020-01-04 9:00AM
2020/01/04 09:14:01 [DVR]   indexed 257 airings (34 channels) [0s fetch, 0s index]
2020/01/04 09:14:01 [DVR]   indexed 12 movies (6 channels) [0s fetch, 0s index]
2020/01/04 09:14:01 [DVR]   pruned 31 replaced airings in 0s.

-- snip 1 --

2020/01/04 09:17:53 [DVR] Rule 'Batwoman' (73) found 1 new airings
2020/01/04 09:17:53 [DVR]   queued recording job for EP032311020010 @ Sun Jan 19 7:00:00PM (1579482000-73)
2020/01/04 09:17:54 [DVR] Deleting job with expired serial: 1578798000-35 Saturday Night Live (EP000037101175)
2020/01/04 09:17:54 [DVR] Marking expired job 1578135600-75 Dolly!
2020/01/04 09:17:54 [DVR] Waiting 42m5.630700349s until next job 1578153600-77 Earth Odyssey With Dylan Dreyer
2020/01/04 09:17:56 [DVR] Waiting 42m3.742550113s until next job 1578153600-77 Earth Odyssey With Dylan Dreyer
2020/01/04 14:04:11 [SYS] Created database snapshot: backup-20200104.140411
2020/01/04 14:04:11 [SYS] Removing old backup backup-20191205.220740

-- snip 2 [ capturing dvr service reboot mentioned in next post ] -- 

2020/01/05 20:23:00 [SYS] Shutting down...
2020/01/05 20:23:00 [TVE] action=screenshot_err err=context canceled
2020/01/05 20:23:00 [TVE] action=script_error err=&runtime.ExceptionDetails{ExceptionID:1, Text:"Uncaught", LineNumber:5, ColumnNumber:5, ScriptID:"15", URL:"", StackTrace:(*runtime.StackTrace)(0xc000eb4f40), Exception:(*runtime.RemoteObject)(0xc000c80090), ExecutionContextID:0} exp=&runtime.RemoteObject{Type:"string", Subtype:"", ClassName:"", Value:easyjson.RawMessage{0x22, 0x6e, 0x6f, 0x20, 0x6c, 0x6f, 0x67, 0x69, 0x6e, 0x20, 0x66, 0x6f, 0x72, 0x6d, 0x20, 0x66, 0x6f, 0x75, 0x6e, 0x64, 0x22}, UnserializableValue:"", Description:"", ObjectID:"", Preview:(*runtime.ObjectPreview)(nil), CustomPreview:(*runtime.CustomPreview)(nil)} exp_value="no login form found"
2020/01/05 20:23:00 [ERR] Could not start stream for TVE-Mediacom ch6030 CNN: TVE: encountered exception 'Uncaught' (5:5)
2020/01/05 20:23:00 [ERR] Failed to start stream on channel 25.6 via 107505AC: Get http://192.168.1.106:5004/auto/v25.6?: dial tcp 192.168.1.106:5004: connect: network is unreachable
2020/01/05 20:23:00 [DVR] Error running job 1578135600-75 Dolly!: could not start stream on channels=[25.6]: Get http://192.168.1.106:5004/auto/v25.6?: dial tcp 192.168.1.106:5004: connect: network is unreachable
2020/01/05 20:23:00 [DVR] Starting job 1578153600-77 Earth Odyssey With Dylan Dreyer on ch=[11.1]
2020/01/05 20:23:00 [DVR] Marking expired job 1578155400-77 Earth Odyssey With Dylan Dreyer
2020/01/05 20:23:00 [DVR] Error running job 1578153600-77 Earth Odyssey With Dylan Dreyer: no time left: -33h53m0.380553981s
2020/01/05 20:23:00 [DVR] Marking expired job 1578160800-23 MotorWeek
2020/01/05 20:23:00 [DVR] Marking expired job 1578245400-23 MotorWeek
2020/01/05 20:23:00 [DVR] Waiting 22h6m59.396154298s until next job 1578357000-59 Infinity Train
2020/01/05 20:23:01 [DVR] Waiting 22h6m58.497144713s until next job 1578357000-59 Infinity Train
2020/01/05 20:23:01 [DVR] Waiting 22h6m58.44542372s until next job 1578357000-59 Infinity Train
2020/01/05 20:23:03 [SYS] Bonjour service stopped.
2020/01/05 20:23:03 [DVR] Recording engine stopped.
2020/01/05 20:23:04 [SYS] Goodbye.
2020/01/05 20:23:07 [SYS] Starting Channels DVR v2019.12.05.0128 (freebsd-x86_64 pid:44061) in /usr/local/channels-dvr/data
2020/01/05 20:23:08 [HDR] Found 1 devices
2020/01/05 20:23:14 [SYS] Started HTTP Server
2020/01/05 20:23:14 [DVR] Recording engine started in /mnt/media/channels-dvr
2020/01/05 20:23:14 [SYS] Bonjour service running for dvr-channelsdvr.local. [192.168.1.152]
2020/01/05 20:23:14 [DVR] Waiting 22h6m45.061273764s until next job 1578357000-59 Infinity Train
2020/01/05 20:23:15 [SYS] Created database snapshot: backup-20200105.202315
2020/01/05 20:23:15 [SYS] Removing old backup backup-20191207.220742
2020/01/05 20:23:25 [IDX] Pruned 1249 expired airings from X-TVE in 126.545327ms.
2020/01/05 20:23:25 [IDX] Pruned 452 expired airings from USA-OTA55437 in 77.064582ms.

[jpsb]

After rebooting the DVR, and this is what I am seeing in the scheduled recordings UI now:

I just cleared out these stale recordings (after taking the screen shot). If this behaves like last time, the scheduled recordings will start working again.

[tmm1]

The logs you posted don't show any recording attempts. Please search for the log messages from the time of a scheduled recording and only post those.

It seems like maybe your server is not keeping time correctly. I would check the RTC settings in the bios and make sure you have NTP enabled on the OS

[jpsb]

Sorry, my log posting got a little messy above.

The first log does have this, which corresponds to the "Dolly!" recording that got stuck (including correct date & time):

2020/01/04 05:00:00 [DVR] Starting job 1578135600-75 Dolly! on ch=[25.6]
2020/01/04 05:00:00 [DVR] Waiting 4h59m59.99551686s until next job 1578153600-77 Earth Odyssey With Dylan Dreyer

[tmm1]

That one shows "network unreachable" in your screenshot which points to a network issue with the dvr being unable to access your HDHR

[jpsb]

I cleaned up the logs. Sorry I posted way too much! Just the relevant logs should be in my original post now.

That detailed error message didn't show up until after a service reboot. It was in a weird state though, so that could just be why it wasn't showing in the UI.

My network was acting up the last few days (fixed with a router reboot), so that could definitely be the issue. I'm concerned though that one transient connection issue was able to freeze up all future scheduled recordings (twice now).