Stuck m3u session on Channels DVR

Beta Community DVR Beta
#1

I have a few Channels servers. My main Channels server (192.168.12.30) has a custom channel config for my LinkPi/ADBTuner. I have a Channels server running in docker (192.168.12.41) where I am connecting to the main Channels server via m3u (http://192.168.12.30:8089/devices/M3U-LinkPi/channels.m3u?format=ts).

This works fine (usually). However today I noticed a stuck m3u session on my main Channels server
image

Looking at the logs it appears that when 192.168.12.41 attempted to tune ESPN, it failed for some unknown reason.

Channels Docker (192.168.12.41)
2024/05/18 10:48:23.143312 [TNR] Opened connection to M3U-LinkPi for ch5843 ESPN
2024/05/18 10:48:32.961707 [TNR] Opened connection to M3U-LinkPi for ch5843 ESPN
2024/05/18 10:48:32.961729 [HLS] Starting live stream for channel 5843 from 173.xx.xx.xx
2024/05/18 10:48:34.047725 [HLS] Probed live stream in 1.085927226s: h264 1920x1080 progressive 9616192bps
2024/05/18 10:48:35.073081 [HLS] Couldn't generate stream playlist for ch5843-dANY-eaf5e829067b: HLS: 901 Tuner Unreachable: Could not tune to ch5843 after 12s
2024/05/18 10:48:35.073230 [HLS] Stopping transcoder session ch5843-dANY-eaf5e829067b (out=2.090667s finished=false first_seq=0 last_seq=-1)
2024/05/18 10:48:35.082733 [TNR] Closed connection to M3U-LinkPi for ch5843 ESPN
2024/05/18 10:48:35.082809 [SNR] Buffer statistics for ch5843 ESPN: buf=0% drop=0%

Main Channels server (192.168.12.30)
2024/05/18 10:48:23.142133 [TNR] Opened connection to M3U-LinkPi for ch5843 ESPN
2024/05/18 10:48:32.960942 [TNR] Opened connection to M3U-LinkPi for ch5843 ESPN
2024/05/18 10:48:35.089638 [SNR] Buffer statistics for 192.168.12.41 (192.168.12.41) for ch5843 ESPN: buf=0% drop=0%
2024/05/18 10:48:35.089823 [TNR] Closed connection to M3U-LinkPi for ch5843 ESPN

On my main channels server it looks like the msu connection was closed and all is well, however it still shows active. This has happened a few times and the only way to get the stuck session to clear is to restart the DVR.

It may have failed becuase of the timeout. ADBTuner sometimes takes a little bit of time to tune. Would it be possible to increase the 12second timeout?

Tuner Unreachable: Could not tune to ch5843 after 12s

I've submitted diags
Main Channels Server 192.168.12.30: 50253c75-5225-4b67-b3f1-12b2ef6c9d49
Docker Channels Server 192.168.12.41: 223de517-949f-4932-a39b-195e178f872b

Lots of tuner locks lately (HDHomerun)
#2

It does look like it opened 2 connections on each server and only closed one of them on each server.

#3

Crazy thing is on the server that tuned espn there are zero sessions running now but it still shows on my main dvr

#4

Does it always open 2 connections like that (about 10 seconds apart) on your main server (.12.30) when using the m3u source?

#5

I dont believe so. It was probably my mother choosing to record whatever was playing and then watching the same channel. Not entirely sure though, with the hulu tve outage with channels i dont usually use that source for espn.

#6

Unfortunately I still can't get to the bottom of what's going on here. If anyone can ever come up with a simple test case that always causes this to happen, it would really be helpful for me to be able to locally debug what's happening and figure out how to fix it.

#7

Ill work on a relaible way to repro. I have noticed that m3us take a really long time to show terminated when the client ends the session. Not sure if thats related or not...

#8

I see that a lot of times recording from m3u sources. Sometimes takes up to 30 seconds to close after a recording finishes or after I cancel one in progress.

#9

This one blows me away.

I checked the TVE channel to make sure it was working since I was getting errors trying to stream it saying my password was invalid. About an hour and then again about 30 minutes before the recording started.

Then the recording starts saying it's Sharing existing connection.
What existing connection?

2024/05/19 20:00:00.000305 [DVR] Starting job 1716174000-91 Tracker on ch=[6003]
2024/05/19 20:00:00.000689 [TNR] Sharing existing connection to TVE-Comcast_SSO for ch6003 KOVR (clients=2, len=0)
2024/05/19 20:00:00.023106 [DVR] Recording for job 1716174000-91 from TVE-Comcast_SSO ch6003 into "TV/Tracker/Tracker S01E13 The Storm 2024-05-19-2000.mpg" for 1h0m59.999573293s

Logs have been submitted as 936baa43-3cd4-4922-af35-66203c07f0af

If you look at the error_screenshot it's showing [email protected]
In Channels DVR I only use username so I don't know where the @comcast.net came from?
Also on that screenshot is the cookie preference selection banner that appears at the bottom of the login web page and blocks you from interacting until you dismiss it.

Where can I see my TVE account credentials in Channels?
#10

The recording finished 33 seconds after it should have and the connection never closed. That was about 4 minutes before I submitted these diags.
Logs have been submitted as 02563dd9-0640-445d-ae1e-057c900c7237

The good thing is this Season Finale TVE recording wasn't interrupted!

UPDATE: (since forum software won't let me add a post)
Just checked and it appears at least one connection is still open this morning. [TNR] Sharing existing connection to TVE-Comcast_SSO for ch6003 KOVR (clients=2, len=0)
Status Activity says nothing going on, but then I went to watch ch6003 live and here's the log.

2024/05/19 21:29:57.291842 [DVR] Commercial detection for Tracker S01E13 The Storm 2024-05-19-2000.mpg finished with 12 markers in 28m21.912610285s.
2024/05/20 07:07:12.989333 [SYS] Created database snapshot: backup-20240520.140712
2024/05/20 07:07:12.989524 [SYS] Removing old backup backup-20240502.003304
2024/05/20 09:08:28.579696 [TNR] Sharing existing connection to TVE-Comcast_SSO for ch6003 KOVR (clients=2, len=0)
2024/05/20 09:08:28.579739 [HLS] Starting live stream for channel 6003 from 192.168.1.8 (bitrate=9858kbps)
2024/05/20 09:08:28.744220 [HLS] Session ch6003-dANY-ip192.168.1.8 started in 164.399664ms
2024/05/20 09:08:28.842148 [HLS] Probed live stream in 262.118528ms: h264 1920x1080 progressive 11033004bps
2024/05/20 09:08:32.122119 [HLS] Stopping transcoder session ch6003-dANY-ip192.168.1.8 (out=16.963678s finished=false first_seq=1 last_seq=13)
2024/05/20 09:08:33.210264 [SNR] Buffer statistics for ch6003 KOVR: buf=0% drop=0%
2024/05/20 09:08:33.210300 [SNR] Streaming statistics for ch6003 KOVR: timeouts=0 segment_timeouts=0 playlist_timeouts=0

Logs have been submitted as 6b3481aa-1f8b-4858-bd39-47e35e98de49

I'm going to restart the Channels DVR server. That should close any open connections.
After restarting the server it's back to normal.

2024/05/20 09:19:14.440523 [DVR] Recording engine stopped.
2024/05/20 09:19:16.577446 [SYS] Starting Channels DVR v2024.05.08.2334 (linux-x86_64 pid:14578) in /var/packages/ChannelsDVR/target/channels-dvr/data
2024/05/20 09:19:16.754648 [SYS] Started HTTP Server on 8190
2024/05/20 09:19:17.231586 [HDR] Found 1 devices
2024/05/20 09:19:17.971933 [DVR] Recording engine started in /volume1/chDVRsynotest
2024/05/20 09:19:18.267899 [SYS] Created database snapshot: backup-20240520.161918
2024/05/20 09:19:18.268122 [SYS] Removing old backup backup-20240502.003321
2024/05/20 09:19:28.101587 [IDX] Pruned 4538 expired airings from X-TVE in 312ms.
2024/05/20 09:20:11.907693 [TVE] stream timestamps: cbs: start_at=2024-05-20T09:19:08-07:00 end_at=2024-05-20T09:19:32-07:00 live_delay=33.821690541s
2024/05/20 09:20:11.907852 [TNR] Opened connection to TVE-Comcast_SSO for ch6003 KOVR
2024/05/20 09:20:11.907889 [HLS] Starting live stream for channel 6003 from 192.168.1.8 (bitrate=9858kbps)
2024/05/20 09:20:13.102196 [HLS] Session ch6003-dANY-ip192.168.1.8 started in 1.19424898s
2024/05/20 09:20:13.179804 [HLS] Probed live stream in 1.27093469s: h264 1920x1080 progressive 10656142bps
2024/05/20 09:21:26.758099 [HLS] Stopping transcoder session ch6003-dANY-ip192.168.1.8 (out=1m30.112344s finished=false first_seq=1 last_seq=78)
2024/05/20 09:21:31.981958 [TNR] Closed connection to TVE-Comcast_SSO for ch6003 KOVR
2024/05/20 09:21:31.982010 [SNR] Buffer statistics for ch6003 KOVR: buf=0% drop=0%
2024/05/20 09:21:31.982045 [SNR] Streaming statistics for ch6003 KOVR: timeouts=0 segment_timeouts=0 playlist_timeouts=0
1 Like
#11

Not sure it's the same but I was testing out PLEX and PLEX kept the channels open and they showed up in Channels as open. Even if I closed Plex, it would show as still open in Channels.

#12

Please try the latest pre-release and let us know if you still see the behavior.