Failed: program already started

[MikePHall]

I had a program fail to record starting at 8:59pm on 11/1/2021 for channel 103.1 (which is the 3.1 HEVC NextGen TV channel) which was the only 1 of the 2 HEVC tuner in use. I was watching a standard 1 of 2(4) ATSC 1.0 tuner channel 61.4 on TV which I wasn't recording. (A 9.59pm program on 103.1 did record).

Cut out of log around start time:
WHEN IT SHOULD HAVE STARTED:
2021/11/01 20:59:00.110138 [HTTP] | 200 | 24.887357ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:02.145533 [HTTP] | 200 | 26.712823ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:04.178694 [HTTP] | 200 | 26.086847ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:06.213960 [HTTP] | 200 | 24.745839ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:08.246328 [HTTP] | 200 | 27.027894ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:10.276125 [HTTP] | 200 | 24.753172ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:12.307047 [HTTP] | 200 | 25.345759ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:14.336676 [HTTP] | 200 | 23.229739ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:16.366539 [HTTP] | 200 | 24.243527ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:18.396659 [HTTP] | 200 | 23.425626ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:20.428162 [HTTP] | 200 | 24.418785ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:22.457586 [HTTP] | 200 | 24.201138ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:24.487650 [HTTP] | 200 | 24.51958ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:26.522520 [HTTP] | 200 | 26.109401ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:28.556337 [HTTP] | 200 | 24.782837ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:30.586820 [HTTP] | 200 | 23.412033ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:32.616392 [HTTP] | 200 | 24.805892ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:34.644554 [HTTP] | 200 | 23.173535ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:36.674012 [HTTP] | 200 | 23.628419ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:38.704538 [HTTP] | 200 | 23.297737ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:40.733092 [HTTP] | 200 | 23.378328ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:42.767320 [HTTP] | 200 | 24.453283ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:44.796894 [HTTP] | 200 | 24.562542ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:46.824866 [HTTP] | 200 | 23.341051ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:48.858461 [HTTP] | 200 | 24.818706ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:50.887906 [HTTP] | 200 | 24.276432ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:52.917567 [HTTP] | 200 | 23.953823ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:54.948343 [HTTP] | 200 | 25.353905ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:56.979161 [HTTP] | 200 | 24.400894ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 20:59:59.009480 [HTTP] | 200 | 23.444698ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:00:01.037501 [HTTP] | 200 | 23.726436ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"

WHEN IT TRIED TO START:
2021/11/01 21:11:24.076866 [HTTP] | 200 | 25.157531ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:26.107402 [HTTP] | 200 | 23.237678ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:28.140490 [HTTP] | 200 | 25.296363ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:30.173064 [HTTP] | 200 | 25.325382ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:32.204725 [HTTP] | 200 | 25.791508ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:34.237096 [HTTP] | 200 | 25.393307ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:36.271703 [HTTP] | 200 | 25.042773ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:37.793165 [DVR] Skipping job because program already started 1635814770-9 NCIS
2021/11/01 21:11:37.806178 [DVR] Waiting 47m52.193844654s until next job 1635818370-10 NCIS: Hawai'i
2021/11/01 21:11:37.818219 [HTTP] | 200 | 1.826298ms | 192.168.1.198 | GET "/dvr/jobs/1635814770-9"
2021/11/01 21:11:38.305066 [HTTP] | 200 | 28.474668ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:40.336323 [HTTP] | 200 | 25.85971ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:42.366277 [HTTP] | 200 | 24.682999ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:44.395914 [HTTP] | 200 | 23.777636ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:46.424380 [HTTP] | 200 | 23.378566ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"
2021/11/01 21:11:48.460888 [HTTP] | 200 | 25.826099ms | 192.168.1.198 | GET "/devices/10A12D75/status/2/debug"

OS
Linux Raspbian
10.11 (kernel: 5.10.63-v7l+)

CPU
4 cores / ARMv7 Processor rev 3 (v7l)
load averages: 0.52 0.58 0.59

RAM
3.51 GB
91.6% free

[racameron]

@MikePHall

Logs from yesterday are already gone.

The logs aren't gone; the web view just shows the last 1000 lines or so. To see more, just tell it:

Subscription FAQ

[MikePHall]

Thx

[speedingcheetah]

Just had this problem. Only noticed it after the show aired.
Pass was set to Record on REELZ the On Patrol LIVE new premier, and now i see it failed with error "failed" program already started".
it is via TVE, so it not have had a tuner not available issue.

EDIT: btw, the TVE stream for REELZ is crap quality.

[tmm1]

probably the stream was down and now only the low quality one is online

[speedingcheetah]

I only see this in the log
2022/07/23 00:20:15.068649 [TVE] action=error_response type=Document error=net::ERR_ABORTED url=https://sp.auth.adobe.com/adobe-services/completePassiveAuthentication
2022/07/23 00:20:15.669593 [TVE] action=error_response type=Other error=net::ERR_UNKNOWN_URL_SCHEME url=

And i just opened the channel and it plays fine, but looks crappy, but that is how it looked before anyways.

[Absenm]

@speedingcheetah

Pass was set to Record on REELZ the On Patrol LIVE new premier, and now i see it failed with error "failed" program already started".

Yeah On Patrol: Live had a ton of technical problems with their launch tonight. ‘On Patrol: Live’ Technical Launch Glitch Delays Show Debut On Reelz – Deadline. They eventually started it from the beginning 1.25 hrs late (so technically not live) but commercial free. And even then there were moments the channel cut out.

[mjitkop]

FYI, the last I checked on January 2nd this year, Reelz TVE had a low bit rate of 2.8 Mb/s. That put it in the 11th position of the worst bit rates of TVE channels.

For the full list, see this:

TV Everywhere Stream Specs

[speedingcheetah]

Well I tuned in a little bit after midnight for the rerun and started a manual recording

Also according to the guide episode one reairs at 2 PM tomorrow

[speedingcheetah]

Even checking the Xfininty Stream site, the REELZ stream there, looks like VOD, but seems to just open the live channel feed, is the same terrible quality stream.

Playing back the Channels DVR .ts file, it is not deinterlacing by default, and when i engage deinterlace in MPV, wow does it look bad.

Is this how REELZ is normally even on cable tv or ay other streaming service that offers it?

[chDVRuser]

The TVE feed I get for Reelz is 1280x720p @ 59.94FPS
It's not interlaced.
It is a low bit rate though (about 2Mbps).

[speedingcheetah]

forgot a thread already was a thing for Reelz and On Patrol specifically

On Patrol: Live coming to Reelz July 2022

too bad Reelz stream is SO bad quality. I have never seen such a poor quality "HD" stream ever. I have SD channels that look better. [On Patrol Live S01E01 2022-07-22 2022-07-23-1659_00.07.25] [On Patrol Live S01E01 2022-07-22 2022-07-23-1659_00.33.55] is it any better via cable card or elsewhere? It appears to be the same low quality on the Xfinity Stream app.

[hancox]

Got an instance of this last night, on a basically idle DVR (but not totally idle as I was watching a TVE stream, but recording would be on HDHR):

2023/02/06 18:45:19.403706 [DVR] Waiting 1h14m30.596302s until next job 1675731590-60 The Bachelor
2023/02/06 18:45:19.449320 [DVR] Recording engine started in /Volumes/DVR_SSD
2023/02/06 18:45:19.450420 [SYS] Removing old update 2023.02.01.1933
2023/02/06 18:45:19.462185 [NAT] Successfully mapped port 8089 using natpmp
2023/02/06 18:45:19.574145 [SYS] Created database snapshot: backup-20230206.234519
2023/02/06 18:45:19.574217 [SYS] Removing old backup backup-20230127.105250
2023/02/06 18:45:20.253378 [SYS] Bonjour service registered with Roberts-mini
2023/02/06 18:59:27.995825 [HC] Removed 505.5K from /Volumes/DVR_SSD/Images/tmsimg to keep under cache limit of 1G
2023/02/06 18:59:30.262069 [IDX] Pruned 56 expired airings from XMLTV-FrndlyTV2 in 11.733958ms.
2023/02/06 18:59:30.279022 [IDX] Pruned 6 expired airings from XMLTV-ESPNPlus in 16.768167ms.
2023/02/06 18:59:30.318164 [IDX] Pruned 1593 expired airings from XMLTV-SamsungTVPlus in 38.892625ms.
2023/02/06 18:59:30.346149 [IDX] Pruned 884 expired airings from USA-CT56421-X in 27.921416ms.
2023/02/06 18:59:30.410260 [IDX] Pruned 2057 expired airings from X-TVE in 64.072542ms.
2023/02/06 18:59:30.436088 [IDX] Pruned 1080 expired airings from USA-OTA06468 in 25.775959ms.
2023/02/06 18:59:30.458004 [IDX] Pruned 422 expired airings from X-M3U in 21.869291ms.
2023/02/06 19:09:19.528611 [DVR] Deleted #5396 /Volumes/DVR_SSD/TV/Pardon the Interruption/Pardon the Interruption 2023-02-06-1729.mpg (user)
2023/02/06 19:59:20.259896 [NAT] Successfully mapped port 8089 using natpmp
2023/02/06 20:02:42.099829 [TVE] stream timestamps: nesn: start_at=2023-02-06T20:02:27-05:00 end_at=2023-02-06T20:02:35-05:00 live_delay=4.629821001s
2023/02/06 20:02:42.100200 [TNR] Opened connection to TVE-Fubo for ch6163 NESN
2023/02/06 20:04:17.932880 [SNR] Buffer statistics for 192.168.50.76 (tv room) for ch6163 NESN: buf=0% drop=0%
2023/02/06 20:04:17.948900 [TNR] Closed connection to TVE-Fubo for ch6163 NESN
2023/02/06 20:13:50.786822 [DVR] Skipping job because program already started 1675731590-60 The Bachelor

[chDVRuser]

Looks like some log entry lines are missing. Did you submit diagnostics so the devs can see the full log.

[hancox]

Yes, but that was complete log. Promise.

[chDVRuser]

Just thought it was strange that you have two of these entries
[NAT] Successfully mapped port 8089 using natpmp

And the fact your skipped recording should have started 30 seconds after that second entry, almost 3 minutes before you started streaming NESN

Hope they can figure it out from the diagnostics.

[hancox]

Another instance today. 350732c0-1aab-48e0-ab3c-e563099278cd submitted.

[hancox]

Tap tap - this thing on?

[chDVRuser]

Just stabbing in the dark, but what are you running Channels DVR on and what disk does it record to?

Thinking maybe your server sleeps or powers down and something with how Channels schedules the recording to start (timer, sleep until, whatever) that its method is being foiled by something on your server.
Like Channels sets itself an internal wake timer to wake a process/thread at a certain time to start recording, but that timing gets thrown off for some reason.

The only time that's happened to me is when I had an extended power outage and my old Synology NAS went into safe mode, then shut down before the UPS battery ran out. Because the time keeper battery on it needed replaced, it didn't have the correct time when powered back up until it synced with an NTP server.

[hancox]

In the first case, the DVR was actively being used for other shows, so not a sleep case.