This is the 2nd Sunday in a row where all of my recordings are "Failed: program missed"
Everything seems to record fine on all other days. What gives?
Logs have been submitted as 915a9ca9-7b45-440c-ae48-6f28b4638a72.
Looks like the dvr was restarted last night at 2am. Unfortunately that caused the state to be reset so the diagnostics don't show me why things failed.
If it happens again please submit before restarting.
Ok will do. Yes there is a nightly 2am reboot however these programs were schedule to record and finish many hours before 2am. Any other thoughts in the meantime?
My thoughts in the meantime are: why is your server rebooting every night at 2AM? And secondly, can you disable that automatic reboot before Sunday, to be able to properly test what's happening?
Reboot is intentional. 2 parts as to why. Part 1 in the event I fall asleep Channels/Plex are not running all night long. Part 2 I travel for work a lot and am not always home should the server have any issue and I am unable to remote log in the reboot at 2am would resolve any hang ups. (Learned that one the hard way)
Yes I can temporarily disable the reboot and see come Sunday.
Are archived logs not kept anywhere prior to my nightly reboot? Anyway to have logs saved daily?
2021/10/24 12:19:45.526189 http: TLS handshake error from 172.58.168.192:53685: EOF
2021/10/24 12:20:27.040474 [HLS] Stopping inactive session file367-1d94051f9101
2021/10/24 12:20:27.113603 [ENC] Stopped encoder for College GameDay 2021-10-23-0900.mpg in V:\ProBox 4 TV HDD (ChannelsDVR)\Streaming\file367-1d94051f9101-3710220315\encoder-0-31729901 after encoding 0 to 1453
2021/10/24 12:22:46.102058 http: TLS handshake error from 172.58.168.192:24809: read tcp 192.168.0.57:8089->172.58.168.192:24809: wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
2021/10/24 12:22:47.616047 http: TLS handshake error from 172.58.168.192:46227: read tcp 192.168.0.57:8089->172.58.168.192:46227: wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
2021/10/24 12:22:47.951120 http: TLS handshake error from 172.58.168.192:28366: read tcp 192.168.0.57:8089->172.58.168.192:28366: wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
2021/10/24 12:23:01.100333 http: TLS handshake error from 172.58.168.192:64413: read tcp 192.168.0.57:8089->172.58.168.192:64413: wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
2021/10/24 12:26:23.541704 http: TLS handshake error from 172.58.168.192:59293: read tcp 192.168.0.57:8089->172.58.168.192:59293: wsarecv: An existing connection was forcibly closed by the remote host.
2021/10/24 12:28:18.637178 http: TLS handshake error from 172.58.168.192:36800: EOF
2021/10/24 12:36:41.750125 AdditionalCachedPlaylists: existingPlaylists=map[https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/b.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc0034208c0 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/c.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc0034207e0 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/d.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc003420700 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/e.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc003420540 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/f.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc003420460 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/g.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc0034202a0 https://content-ause2-up-1.uplynk.com/channel/4c6446157b9b48c891e83bee9913e944/h.m3u8?pbs=b54cabeda6b34f91be770d1a015f1159:0xc003420380] cachedPlaylist=map[] codec=mp4a.40.5,avc1.42001e
2021/10/24 12:36:41.969024 [TVE] stream timestamps: fox: start_at=2021-10-24T12:35:42-04:00 current_at=2021-10-24T12:36:02-04:00 end_at=2021-10-24T12:36:10-04:00
2021/10/24 12:36:41.969024 [TNR] Opened connection to TVE-ATT for ch6002 WTVT
2021/10/24 13:03:50.336569 [TNR] Closed connection to TVE-ATT for ch6002 WTVT
2021/10/24 13:04:24.470386 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 14:04:24.620445 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 15:04:24.646537 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 15:07:25.645710 [DVR] Fetched guide data for XMLTV-PlutoTV in 1s
2021/10/24 15:07:29.728064 [DVR] Indexed 4368 airings into XMLTV-PlutoTV (318 channels over 16h0m0s) + 1151 skipped [3s index]
2021/10/24 15:07:29.750349 [DVR] pruned 1139 replaced airings in 0s.
2021/10/24 15:07:30.669952 [DVR] Reindexed 803 airings into XMLTV-DizqueTV (2 channels over 328h0m0s) + 22 skipped [0s index]
2021/10/24 15:07:30.674092 [DVR] pruned 3 replaced airings in 0s.
2021/10/24 15:07:30.678728 [IDX] Pruned 224 expired groups from XMLTV-PlutoTV in 4.636ms.
2021/10/24 15:07:30.690678 [DBG] Scheduling wake timer for guide data in 18h22m59.3093216s
2021/10/24 15:07:30.690678 [DBG] Scheduling wake timer for xmltv guide data in 2h58m30s
2021/10/24 15:07:30.835100 [DVR] Rule 'College Football' (5) found 3 new airings
2021/10/24 15:07:30.844415 [DVR] queued recording job for EP029941835940 @ Sat Oct 30 3:00:00PM on ch=[6197] (1635620400-5)
2021/10/24 15:07:30.850195 [DVR] queued recording job for EP029941836008 @ Sat Oct 30 4:00:00PM on ch=[6198] (1635624000-5)
2021/10/24 15:07:30.855522 [DVR] queued recording job for EP029941835994 @ Sat Oct 30 10:30:00PM on ch=[6140] (1635647400-5)
2021/10/24 15:07:30.913301 [DVR] Rule 'NFL Football' (11) found 1 new airings
2021/10/24 15:07:30.916017 [DVR] queued recording job for EP000031282989 @ Sun Oct 24 1:00:00PM on ch=[6002] (1635094800-11)
2021/10/24 16:04:24.696500 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 17:04:24.714038 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 18:04:24.769149 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 18:07:31.714667 [DVR] Fetched guide data for XMLTV-PlutoTV in 1s
2021/10/24 18:07:35.842678 [DVR] Indexed 4384 airings into XMLTV-PlutoTV (318 channels over 15h45m0s) + 1150 skipped [3s index]
2021/10/24 18:07:35.865440 [DVR] pruned 1137 replaced airings in 0s.
2021/10/24 18:07:36.772053 [DVR] Reindexed 796 airings into XMLTV-DizqueTV (2 channels over 325h30m0s) + 29 skipped [0s index]
2021/10/24 18:07:36.776164 [DVR] pruned 4 replaced airings in 0s.
2021/10/24 18:07:36.781602 [IDX] Pruned 244 expired groups from XMLTV-PlutoTV in 4.8955ms.
2021/10/24 18:07:36.801192 [DBG] Scheduling wake timer for guide data in 15h44m53.1988071s
2021/10/24 18:07:36.801192 [DBG] Scheduling wake timer for xmltv guide data in 2h58m30s
2021/10/24 18:07:36.945181 [DVR] Rule 'College Football' (5) found 3 new airings
2021/10/24 18:07:36.955336 [DVR] queued recording job for EP029941835983 @ Sat Oct 30 3:00:00PM on ch=[6144] (1635620400-5)
2021/10/24 18:07:36.961948 [DVR] queued recording job for EP029941835998 @ Sat Oct 30 4:00:00PM on ch=[6147] (1635624000-5)
2021/10/24 18:07:36.967483 [DVR] queued recording job for EP029941835964 @ Sat Oct 30 10:30:00PM on ch=[6197] (1635647400-5)
2021/10/24 19:04:24.792364 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 20:04:24.838731 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 21:04:24.848276 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 21:07:37.733294 [DVR] Fetched guide data for XMLTV-PlutoTV in 0s
2021/10/24 21:07:41.838262 [DVR] Indexed 4406 airings into XMLTV-PlutoTV (318 channels over 18h30m0s) + 1148 skipped [3s index]
2021/10/24 21:07:41.864933 [DVR] pruned 1133 replaced airings in 0s.
2021/10/24 21:07:42.808693 [DVR] Reindexed 789 airings into XMLTV-DizqueTV (2 channels over 323h30m0s) + 36 skipped [0s index]
2021/10/24 21:07:42.812852 [DVR] pruned 6 replaced airings in 0s.
2021/10/24 21:07:42.817713 [IDX] Pruned 223 expired groups from XMLTV-PlutoTV in 4.8613ms.
2021/10/24 21:07:42.830242 [DBG] Scheduling wake timer for guide data in 12h27m47.1697575s
2021/10/24 21:07:42.830242 [DBG] Scheduling wake timer for xmltv guide data in 2h58m30s
2021/10/24 21:07:42.977804 [DVR] Rule 'College Football' (5) found 3 new airings
2021/10/24 21:07:42.983998 [DVR] queued recording job for EP029941835940 @ Sat Oct 30 3:00:00PM on ch=[6197] (1635620400-5)
2021/10/24 21:07:42.990009 [DVR] queued recording job for EP029941836008 @ Sat Oct 30 4:00:00PM on ch=[6198] (1635624000-5)
2021/10/24 21:07:42.999376 [DVR] queued recording job for EP029941835994 @ Sat Oct 30 10:30:00PM on ch=[6140] (1635647400-5)
2021/10/24 22:04:24.875558 [NAT] Successfully mapped port 8089 using upnp
2021/10/24 23:04:24.901118 [NAT] Successfully mapped port 8089 using upnp
2021/10/25 00:04:24.904941 [NAT] Successfully mapped port 8089 using upnp
2021/10/25 00:07:45.880591 [DVR] Reindexed 3259 airings into XMLTV-PlutoTV (318 channels over 13h15m0s) + 2295 skipped [3s index]
2021/10/25 00:07:45.913119 [DVR] pruned 1132 replaced airings in 0s.
2021/10/25 00:07:45.937473 [DVR] Fetched guide data for XMLTV-DizqueTV in 0s
2021/10/25 00:07:46.973720 [DVR] Indexed 821 airings into XMLTV-DizqueTV (2 channels over 335h32m20s) + 5 skipped [0s index]
2021/10/25 00:07:46.977555 [DVR] pruned 2 replaced airings in 0s.
2021/10/25 00:07:46.977555 [IDX] Pruned 0 expired groups from XMLTV-DizqueTV in 0s.
2021/10/25 00:07:46.990981 [DBG] Scheduling wake timer for guide data in 9h11m43.0090189s
2021/10/25 00:07:46.990981 [DBG] Scheduling wake timer for xmltv guide data in 2h58m30s
2021/10/25 00:07:47.143051 [DVR] Rule 'College Football' (5) found 3 new airings
2021/10/25 00:07:47.153245 [DVR] queued recording job for EP029941835983 @ Sat Oct 30 3:00:00PM on ch=[6144] (1635620400-5)
2021/10/25 00:07:47.153245 [DVR] queued recording job for EP029941835998 @ Sat Oct 30 4:00:00PM on ch=[6147] (1635624000-5)
2021/10/25 00:07:47.174952 [DVR] queued recording job for EP029941835964 @ Sat Oct 30 10:30:00PM on ch=[6197] (1635647400-5)
2021/10/25 00:20:48.641979 http: TLS handshake error from 128.14.133.58:37498: local error: tls: bad record MAC
2021/10/25 01:04:24.931167 [NAT] Successfully mapped port 8089 using upnp
2021/10/25 02:01:07.453073 [SYS] Shutting down...
2021/10/25 02:01:07.543988 [SYS] Bonjour service stopped.
2021/10/25 02:01:07.666971 [DVR] Recording engine stopped.
2021/10/25 02:01:07.667610 [SYS] Goodbye.This line stands out: it says its queueing a recording for Oct 24 at 1pm, but it wasn't scheduled until 3:07pm. (The scheduled time, indicated by 1635094800 converts to Oct 24, 2021 5:00pm UTC. I don't know your timezone, but I figure you can do the math yourself.)
Timezone is ET, Recording should have taken place at 1PM ET. No clue why it was queued
What I'm saying is the logs show that while it was supposed to take place at 1, the DVR didn't schedule it to record until after 3pm, two hours after it was due to start.
Also, at the start of the logs is this:
2021/10/24 12:36:41.969024 [TNR] Opened connection to TVE-ATT for ch6002 WTVT
2021/10/24 13:03:50.336569 [TNR] Closed connection to TVE-ATT for ch6002 WTVT
It shows that connection was opened at 12:36, but then closed at 1:03. There are no [DVR] entries around that time, so the DVR did not try to record anything ... probably because the recording for 1pm on 6002 wasn't created until after 3pm.
It is set as a Pass for "NFL Football" not manually set. Something is broken with the pass recording hit and miss. Seems like it is postponing live tv recordings for whatever reason.
3 Recordings were scheduled via the Pass 1PM 4:05PM and 8:20PM and all got "postponed" by the log
I guess you'll have to wait until next weekend then, and submit diagnostic logs, as what you've provided here only shows that the channel was tuned for 30 minutes prior, and your recording was scheduled 2 hours after.
I imagine if there are any issues with your setup, DVR, system, or something else, then those would only be shown in the diagnostic logs. I wish you luck.
Agreed, Wish I could archive daily relevant logs. Some days everything records fine other times it does not or completely misses a recording that was clearly scheduled all together
I already looked at your logs and they don't explain what happened. We need a full diagnostics that's taken while its still in the stuck state before any sort of reboot.
Understood, if the recording is scheduled at 1PM ET and is missed at what point is it considered "stuck state"? and what time should logs be pulled and submitted?
Any plans to add an option to email ourselves Troubleshooting logs at X time of a day? Rather than generating and only able to "Submit them"?
The log I have dates back to 2021/10/23 20:32:50.962256, is the submitted log not going back prior to the 2AM reboot?
You can submit as soon as something that was listed on the schedule fails to start recording.
You will see in the log messages like "[DVR] Waiting 1h32s until next job" and then after that amount of time it should show "[DVR] Starting job"
You're only allowed one question per post.
Just kidding.
https://getchannels.com/docs/getting-started/faqs/channels-plus/#how-can-i-view-more-of-the-channels-dvr-server-log
I took a look at the older logs and was able to figure out what happened. There's a rare race condition on boot which is getting triggered by your scheduled reboots. There will be a fix in the next prerelease.
4 Likes
Another recording just missed.
Logs have been submitted as da59d244-f24d-4055-bcfb-a5ffa8fc0969.
Which recording at what time on what channel?