Bug: recordings interrupted by a pending upgrade

I apologize in advance for the lengthy post but this deserves some context because this is a very particular situation. I would say this is a case where "all the stars have to align" for something to happen.

Server v2023.02.02.2036.

Some time yesterday (I don't remember exactly what time but I think it was early afternoon), I selected the drop-down on the server to check for a new pre-release to upgrade to.
At that time, the recording schedule was full all afternoon until late night (I think until 10:03 PM) so I didn't expect the server to start upgrading until probably 10:04 PM or later.

The funny thing is that in the evening (before 10 PM) my wife and daughter were watching something using the Channels app on a TiVo Stream 4K that has constant power even when the TV is off, and they left it paused on a show all night. I noticed this morning in the activity section of the server that it was showing "Watching [...] at 0s" so I assumed that they paused it at the very beginning of an episode after they finished one.

I didn't think much of it but I noticed that the DVR upgrade was still pending since yesterday. So it seems that the "Watching" state prevented the DVR from upgrading last night, which makes quite some sense.

This morning, busy schedule too, including 3 programs to be recorded between 12 PM and 2 PM approximately.
I noticed after 2 PM in DVR/Manage that all 3 recordings were interrupted so I checked the logs and it seems that the DVR proceeded to do the pending upgrade while the 3 recordings were in progress.

Here are samples of the log that clued me in:

2023/02/07 11:59:50.001188 [DVR] Starting job 1675789190-60 The Beach House (2018) on ch=[6090]

2023/02/07 11:59:50.280580 [DVR] Recording for job 1675789190-60 from TVE-DTV ch6090 into "Movies\The Beach House (2018) 2023-02-07-1159.mpg" for 2h2m9.9988112s

2023/02/07 12:57:00.008880 [DVR] Starting job 1675792620-239 GMA3: What You Need to Know on ch=[6001 5985]

2023/02/07 12:57:07.071804 [TNR] Opened connection to TVE-DTV for ch6001 WABC
2023/02/07 12:57:07.072487 [DVR] Recording for job 1675792620-239 from TVE-DTV ch6001 into "TV\GMA3 What You Need to Know\GMA3 What You Need to Know S03E105 2023-02-07-1257.mpg" for 1h7m59.9911198s

2023/02/07 12:59:30.003551 [DVR] Starting job 1675792770-306 Monk on ch=[6091 7005]

2023/02/07 12:59:30.004690 [DVR] Recording for job 1675792770-306 from TVE-DTV ch6091 into "TV\Monk\Monk S02E02 2003-06-27 Mr Monk Goes to Mexico 2023-02-07-1259.mpg" for 1h1m29.9964485s

2023/02/07 13:22:47.658127 [SYS] Created database snapshot: backup-20230207.182247
2023/02/07 13:22:47.658127 [SYS] Removing old backup backup-20230120.080210
2023/02/07 13:22:47.779004 [SYS] Shutting down for upgrade from v2023.02.02.2036 to v2023.02.05.1636
2023/02/07 13:22:48.300812 [SYS] Bonjour service stopped.
2023/02/07 13:22:48.333959 [DVR] Recording engine stopped.
2023/02/07 13:22:48.486322 database not open
2023/02/07 13:22:48.489080 [ERR] Recovered from panic: runtime error: invalid memory address or nil pointer dereference
main.httpDvrFileStream.func2.1()
    :629
github.com/fancybits/channels-server/dvr.(*Recorder).SetActivityMulti()
    :131
2023/02/07 13:22:49.371235 [SYS] Goodbye.
2023/02/07 13:22:49.675049 [SYS] Starting Channels DVR v2023.02.05.1636 (windows-x86_64 pid:16464) in C:\ProgramData\ChannelsDVR\data

2023/02/07 13:23:05.476412 [DVR] Starting job 1675789190-60 The Beach House (2018) on ch=[6090]
2023/02/07 13:23:06.451591 [DVR] Starting job 1675792620-239 GMA3: What You Need to Know on ch=[6001 5985]
2023/02/07 13:23:08.172325 [DVR] Starting job 1675792770-306 Monk on ch=[6091 7005]

Logs have been submitted as 13f211a0-cce9-4628-ad49-035b0e8afaa2 .

This has happened to me but could not figure out why ... Glad you caught it as it clearly shows it was shutdown to do the upgrade.

1 Like

It also interrupted my 24 hour Camera recording .... Well that answers why sometimes the Server would restart for no reason... I guess pending updates take priority over recording or watching. I redid my Cron job that Checks for prerelease to only Check when DVR is idle. This way it checks and updates right away if there is one.

2023/02/11 05:50:01.454858 [SYS] Shutting down for upgrade from v2023.02.10.0142 to v2023.02.10.1333
2023/02/11 05:50:01.530235 [DVR] Recording engine stopped.
2023/02/11 05:50:03.809352 [SYS] Starting Channels DVR v2023.02.10.1333 (linux-x86_64 pid:5732) in /mnt/HD/HD_a2/Nas_Prog/ChannelsDVR/channels-dvr/data
2023/02/11 05:50:04.322241 [SYS] Started HTTP Server on 8089
2023/02/11 05:50:05.124342 [HDR] Found 5 devices
2023/02/11 05:50:05.899000 [M3U] Refreshed lineup for AllChannels with 641 channels
2023/02/11 05:50:06.963309 [DVR] Starting job 1676102370-7 Office Camera on ch=[1.1]
2023/02/11 05:50:06.963921 [DVR] Recording engine started in /shares/MyShares/ChannelsDVRMAIN
2023/02/11 05:50:06.964179 [DVR] Waiting 18h9m23.035835163s until next job 1676188770-1 Law & Order: Criminal Intent
2023/02/11 05:50:06.964362 [SYS] Removing old update 2023.02.05.1636
2023/02/11 05:50:06.964709 [TNR] Opened connection to M3U-OfficeCamera for ch1.1 Office Camera
2023/02/11 05:50:06.964816 [DVR] Recording for job 1676102370-7 from M3U-OfficeCamera ch1.1 into "TV/Office Camera/Office Camera 2023-02-10-2359.mpg" for 18h10m53.036516963s
2023/02/11 05:50:07.015177 [HLS] ffmpeg: rtsp-Office Camera:  [rtsp @ 0x7eab340] method SETUP failed: 461 Unsupported Transport
2023/02/11 05:50:09.714955 [SYS] Created database snapshot: backup-20230211.135009
2023/02/11 05:50:09.715153 [SYS] Removing old backup backup-20230127.074510
2023/02/11 05:50:17.162191 [IDX] Pruned 1666 expired airings from XMLTV-AllChannels in 173.3562ms.
2023/02/11 05:50:17.242951 [IDX] Pruned 175 expired airings from X-M3U in 80.65445ms.

Looks like there must be a race condition with our locking that we'll need to dig into further. The intention is that no updates happen when there are any recordings or playback in progress.

2 Likes

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.