Failed: program already started

Channels DVR Server Troubleshooting
#41

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
#42

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

#43

Yes, but that was complete log. Promise.

#44

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. :crossed_fingers:

#45

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

#46

Tap tap - this thing on?

#47

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.

#48

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