Channels DVR v2022.08.26.2245 Silently Failing to Record

After upgrading to pre-release v2022.08.26.2245, something I've never experienced before is happening: recording is failing silently, recordings shown in the Schedule are not starting, and nothing I'm seeing in the DVR Server logs directly indicates why.

I also checked against the guide data on zap2it, and these airings are all still as originally scheduled, yet somehow the recordings never started. No errors, just a gap. Namely, "How Do They Do It?," which is using a pass that has been working fine until today displays as "Queued", yet nothing was recorded. The pass' only condition is SeriesID == 404110.

Screenshot taken at 10:45 PM EST:

Log snippet:

2022/08/26 19:25:20.135150 [SYS] Starting Channels DVR v2022.08.26.2245 (linux-x86_64 pid:12453) in /var/packages/ChannelsDVR/target/channels-dvr/data
2022/08/26 19:25:20.297400 [SYS] Started HTTP Server
2022/08/26 19:25:20.752507 [HDR] Found 1 devices
2022/08/26 19:25:21.134026 [TVE] action=cbs_station err=unavailable in location
2022/08/26 19:25:21.450761 [M3U] Refreshed lineup for Stirr with 107 channels
2022/08/26 19:25:21.509575 [M3U] Refreshed lineup for Pluto with 338 channels
2022/08/26 19:25:22.525493 [DVR] Recording engine started in /volume1/DVR
2022/08/26 19:25:22.526837 [DVR] Waiting 1h34m27.473168475s until next job 1661561990-159 How Do They Do It?
2022/08/26 19:25:22.528124 [SYS] Removing old update 2022.08.19.0326
2022/08/26 19:25:26.960225 [SYS] Created database snapshot: backup-20220826.192526
2022/08/26 19:25:26.960472 [SYS] Removing old backup backup-20220809.182328
2022/08/26 19:25:32.748521 [IDX] Pruned 44 expired airings from XMLTV-Pluto in 213.463462ms.
2022/08/26 19:25:32.803555 [IDX] Pruned 20 expired airings from XMLTV-Stirr in 54.977869ms.
2022/08/26 19:25:32.803688 [IDX] Pruned 0 expired airings from X-M3U in 100.703µs.
2022/08/26 19:25:32.803925 [IDX] Pruned 0 expired airings from X-VIRTUAL in 219.79µs.
2022/08/26 19:25:33.063773 [IDX] Pruned 78 expired airings from X-TVE in 259.82131ms.
2022/08/26 19:25:33.193153 [IDX] Pruned 4 expired airings from USA-OTA***** in 129.335919ms.
2022/08/26 19:36:51.252734 [M3U] Refreshed lineup for Pluto with 338 channels
2022/08/26 19:36:52.807924 [M3U] Refreshed lineup for Stirr with 107 channels
2022/08/26 20:59:50.005630 [DVR] Starting job 1661561990-159 How Do They Do It? on ch=[6110]
2022/08/26 20:59:50.005734 [DVR] Waiting 29m59.994270119s until next job 1661563790-159 How Do They Do It?
2022/08/26 22:25:33.201900 [DVR] Fetched guide data for XMLTV-Pluto in 0s
2022/08/26 22:25:36.172534 [DVR] Indexed 1129 airings into XMLTV-Pluto (72 channels over 28h15m0s) + 74 skipped [2s index]
2022/08/26 22:25:36.476133 [DVR]   pruned 238 replaced airings in 0s.
2022/08/26 22:25:36.708900 [DVR] Fetched guide data for XMLTV-Stirr in 0s
2022/08/26 22:25:37.996841 [DVR] Indexed 606 airings into XMLTV-Stirr (22 channels over 26h36m0s) + 17 skipped [1s index]
2022/08/26 22:25:38.229503 [DVR]   pruned 41 replaced airings in 0s.

Note the lack of the expected [DVR] Recording for job xxx [...] line at 20:59:50 (the pass was padded by 10 seconds).

Next, I tried to manually record something from the Web UI, but it just showed as "Scheduled" (not "Recording" like it should), nothing was added to the log at all, and the recording did not start. Finally, I stopped and started the Channels DVR Synology package and recording started working again... something is rather amiss here!

This screenshot was taken after restarting the Channels DVR Synology package:

I would very much like to help get to the bottom of this! I submitted diagnostics:

  1. Sent when I first noticed the issue:
    2107d267-ede1-4868-bc03-9d8d32ff5d47
  2. Sent after delete & recreate guide database (issue persisted):
    d9043aaf-b995-4919-95ca-b0be306932c1
  3. Sent after restarting the Channels DVR Synology package:
    5fbead7f-a272-4d42-a1ee-d9371741211f

Thank you for capturing the diagnostics.

Fix is uploading now.

1 Like

2245 is breaking mpeg ts m3u’s as well. Diagnostics sent
139ef7e3-39ed-42f5-9465-3cb6870ae5af

Breaking what and how?

Okay I see it

Not sure it’s like it’s overriding MPEG ts to HLS. M3u-OTA Channel 4.1

Possible fix uploading now

Trying again

It will actually play the channel now but still some runtime panic errors

9bd3bb1a-71da-46f0-a258-e74dacaf211b

Submitted

Try new build

Looks fixed. Nice work. Thanks

2 Likes

Recording continues to work on v2022.08.27.0519, thanks for the super quick fix!

However, one recording from this morning is still marked as "Recording" even though it has finished (and I cleared it from the Schedule view), and the details show the index is "out of date." Playing it in the web player required remuxing at first, until I ran "Regenerate Video Index," after which it plays fine without remuxing.

In the logs, there is an "unexpected end of file" error. Another recording on the same channel overlapped with the end of this one.

2022/08/27 12:33:27.279735 [SNR] Buffer statistics for "Movies/X-Men First Class (2011) 2022-08-27-0929.mpg": buf=0% drop=0%
2022/08/27 12:33:27.360001 [MTS] Statistics for "Movies/X-Men First Class (2011) 2022-08-27-0929.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=23 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=true saw_pmt=true highest_pts=11024.341878
2022/08/27 12:33:27.369057 [DVR] Error running job 1661606990-161 X-Men: First Class (2011): unexpected EOF

Diagnostics: 1774b6e3-83c2-450f-be47-590098554eec

Seeing the same thing here. Recording completed but marked as failed.
Status in manage shows says it's still recording.

2022/08/27 12:58:00.005698 [DVR] Starting job 1661630280-107 Yellowstone on ch=[9368]
2022/08/27 12:58:03.227903 [TNR] Opened connection to M3U-Pluto for ch9368 More TV Drama
2022/08/27 12:58:03.228370 [DVR] Recording for job 1661630280-107 from M3U-Pluto ch9368 into "TV/Yellowstone/Yellowstone S02E201 2019-06-19 A Thundering 2022-08-27-1258.mpg" for 1h3m59.993986533s
2022/08/27 12:58:03.962331 [IDX] Generating video index for job 1661630280-107
2022/08/27 14:02:15.003158 [SNR] Buffer statistics for "TV/Yellowstone/Yellowstone S02E201 2019-06-19 A Thundering 2022-08-27-1258.mpg": buf=0% drop=0%
2022/08/27 14:02:15.109602 [MTS] Statistics for "TV/Yellowstone/Yellowstone S02E201 2019-06-19 A Thundering 2022-08-27-1258.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=32 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=true saw_pmt=true highest_pts=3876.726667
2022/08/27 14:02:15.149002 [ADS] Detected 14 commercial markers in file-998: TV/Yellowstone/Yellowstone S02E201 2019-06-19 A Thundering 2022-08-27-1258.mpg
2022/08/27 14:02:15.278564 [DVR] Error running job 1661630280-107 Yellowstone: unexpected EOF

Logs have been submitted as 9ebd8e76-8777-4bdf-a9f6-33b48db9bdfb

Thanks for the reports. Checking them out.

2 Likes

Another DVR server same issue.

2022/08/27 15:30:01.000615 [DVR] Starting job 1661639401-ch6085 Canary SUNDANCE Recording on ch=[6085]
2022/08/27 15:30:02.961121 [TNR] Opened connection to TVE-Comcast_SSO for ch6085 SUNDANCE
2022/08/27 15:30:02.961404 [DVR] Recording for job 1661639401-ch6085 from TVE-Comcast_SSO ch6085 into "TV/Canary SUNDANCE Recording/Canary SUNDANCE Recording 2022-08-27-1530.mpg" for 9m59.999216775s
2022/08/27 15:30:03.297211 [IDX] Generating video index for job 1661639401-ch6085
2022/08/27 15:40:13.510335 [SNR] Buffer statistics for "TV/Canary SUNDANCE Recording/Canary SUNDANCE Recording 2022-08-27-1530.mpg": buf=0% drop=0%
2022/08/27 15:40:13.513387 [TNR] Closed connection to TVE-Comcast_SSO for ch6085 SUNDANCE
2022/08/27 15:40:13.740989 [MTS] Statistics for "TV/Canary SUNDANCE Recording/Canary SUNDANCE Recording 2022-08-27-1530.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=0 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=true saw_pmt=true highest_pts=627.492000
2022/08/27 15:40:13.744767 [DVR] Error running job 1661639401-ch6085 Canary SUNDANCE Recording: unexpected EOF

Logs have been submitted as df7190e6-f4dc-4bb3-ad58-65096201f25a

@chDVRuser Could you upload the recording.log for 998 to the dropbox?

Uploaded as 998-recording.log

Let's see if this helps out:

Fingers crossed :crossed_fingers:
My last recording before I updated ended strangely with the error Could not fetch playlist after the connection was closed.

2022/08/27 18:02:15.039200 [SNR] Buffer statistics for "TV/Yellowstone/Yellowstone S02E205 2019-07-24 Touching Your Enemy 2022-08-27-1658.mpg": buf=0% drop=0%
2022/08/27 18:02:15.046448 [TNR] Closed connection to M3U-Pluto for ch9368 More TV Drama
2022/08/27 18:02:15.308379 [MTS] Statistics for "TV/Yellowstone/Yellowstone S02E205 2019-07-24 Touching Your Enemy 2022-08-27-1658.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=25 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=true saw_pmt=true highest_pts=3876.954667
2022/08/27 18:02:15.381711 [ADS] Detected 12 commercial markers in file-1002: TV/Yellowstone/Yellowstone S02E205 2019-07-24 Touching Your Enemy 2022-08-27-1658.mpg
2022/08/27 18:02:15.521799 [DVR] Error running job 1661644680-107 Yellowstone: Could not fetch playlist: https://service-stitcher-ipv4.clusters.pluto.tv/stitch/hls/channel/613260e4bdb71c00070d63fa/3063648/playlist.m3u8?terminate=false&embedPartner=&serverSideAds=true&paln=&includeExtendedEvents=false&architecture=&deviceId=8d620d78-2642-11ed-994d-0242ac120004&deviceVersion=unknown&appVersion=unknown&deviceType=web&deviceMake=Chrome&sid=4c2a7f7f-1624-4bc1-a1d5-3b1fa8603bb6&advertisingId=&deviceLat=0&deviceLon=0&deviceDNT=0&deviceModel=web&userId=&appName=web: Get "https://service-stitcher-ipv4.clusters.pluto.tv/stitch/hls/channel/613260e4bdb71c00070d63fa/3063648/playlist.m3u8?terminate=false&embedPartner=&serverSideAds=true&paln=&includeExtendedEvents=false&architecture=&deviceId=8d620d78-2642-11ed-994d-0242ac120004&deviceVersion=unknown&appVersion=unknown&deviceType=web&deviceMake=Chrome&sid=4c2a7f7f-1624-4bc1-a1d5-3b1fa8603bb6&advertisingId=&deviceLat=0&deviceLon=0&deviceDNT=0&deviceModel=web&userId=&appName=web": context canceled