Tvheadend

Looking at the m3u8 files as they come through, the cue_out is tied to a segment. That means it is tied to a Added line queue item. Best solution is to add the cue status to the add queue item already being sent to internal_proxy. when internal_proxy pulls the next segment to play, it needs to check the cue status and do stuff accordingly.

One small issue. If one was to start in the middle of an ad section and was past the cue-out, then Cabernet would not know it was a possible issue and could timeout. Of course what would be nice is if the provider gave the cue-in to us whether at the beginning of the ads or when the play started.

Maybe a combo of looking at cue_out and also keeping the timeout fairly high?

Confirmed that I do not get a cue-out when starting in the middle of an ad section. AND, I would REALLY like to avoid having a 5 minute timeout. I have the implementation done. Just need to figure out how we are going to handle the start in the middle issue.

For now, I have pushed out .25 which contains the CUE-OUT/IN stuff, but does not address the middle of the ads start. Timeout not changed, so still 200.

Maybe assume a cue_out when you see the google ads when starting mid commercial?

That would imply having URL or PTS filtering on and getting a hit on the first item. What if filtering was not enabled?

I guess then PTS and/or URL filtering would need to be in monitor mode at all times. Actively looking at segments but not deleting segments. The trouble is the URL and/or PTS filtering parameters might be set very badly so that would not be good.

Not the best solution for sure.

Magic has occurred. 0.9.4.26 has the solution to all problems. It cleans, sweeps, and even does the dishes. And, yes it even fixes the timeout issue. Not only is the timeout issue fixed, but the value is back to 60 and that is probably too high, but good enough. I played a section on DABL that would normally have a 2 minute delay and it had at most a eight second delay. Yes, the church bells were ringing through out the square as the delay has shrunk to nothing.

Thank you!

I set up a M3U8 file and leveraged a handful of entries from Robert's list that Sean refers to it as the granddaddy list https://iptv-org.github.io/iptv/index.m3u

Well, the live streams I selected are HUGE and go back in time a long way.... Cabernet tries to only play 3 most recent segments which is excellent. However when cabernet reloads the m3u8 queue it gets another HUGE playlist and it then calls remove_from_stream_queue which goes into a loop that takes a huge amount of time and then the stream times out. After doing some diagnosing I found that the playlist has 4800 segments in it. Thus when the m3u8 queue is reloaded cabernet gets a new list with 4800 segments and then proceeds to check what items to delete. Effectively I saw the following loop:

For each item in old playlist (4800 items)
   for each item in new playlist (4800 items)
      check if new matches old, etc

CPU usage goes up to max and the remove_from_stream_queue can not get its work done before things timeout. Just to see I temporarily changed IDLE_TIMER_MAX to a higher number and remove_from_stream_queue was able to finish but the stream paused for a period of time while it was doing its thing. and each time remove_from_stream_queue was called CPU went to max for quite a while......

See if .28 works better...

G Kazaroth wrote:

See if .28 works better...

yup - all good now. Thanks!

I am seeing segments played out of order. It certainly happens when I start a stream and it may happen periodically as well. I notice because the program hesitates, jumps forward, then jumps back.

When I start a stream from that 4800 segment playlist the 4th segment is always played out of order. I have cabernet set to play 3 non VOD segments and those play in the correct order. But then the next 2 segments are played out of order.

update: it happens mid program when the m3u8_queue Reload gets more than one new segment as well. It that case it also flips the first 2 segments.

In this example of when I started the stream you can see the segments play in this order 098, 099, 100, 102, 101, 103, etc

2021-10-02 10:28:51,552-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164098.ts to play queue 241
2021-10-02 10:28:51,553-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164099.ts to play queue 241
2021-10-02 10:28:51,553-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164100.ts to play queue 241
2021-10-02 10:28:52,680-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:28:52,947-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164098.ts (6.0)s (2873392B) ttw:0.01s 0
2021-10-02 10:28:54,273-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:28:54,640-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164099.ts (6.0)s (3353920B) ttw:0.01s 1
2021-10-02 10:28:54,964-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:28:55,386-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164100.ts (6.0)s (3737628B) ttw:0.04s 0
2021-10-02 10:28:56,359-DEBUG:m3u8_queue Reloading m3u8 stream queue 241
2021-10-02 10:28:57,911-DEBUG:m3u8_queue Removed https://(redacted)/1280x720/1633159301.ts from play queue 241
2021-10-02 10:28:58,138-DEBUG:m3u8_queue Removed https://(redacted)/1280x720/1633159302.ts from play queue 241
2021-10-02 10:28:58,141-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164102.ts to play queue 241
2021-10-02 10:28:58,143-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164101.ts to play queue 241
2021-10-02 10:28:59,704-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:29:00,009-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164102.ts (6.0)s (3345272B) ttw:0.00s 0
2021-10-02 10:29:01,331-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:29:01,743-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164101.ts (6.0)s (3385692B) ttw:0.00s 0
2021-10-02 10:29:03,057-DEBUG:m3u8_queue Reloading m3u8 stream queue 241
2021-10-02 10:29:04,232-DEBUG:m3u8_queue Removed https://(redacted)/1280x720/1633159303.ts from play queue 241
2021-10-02 10:29:04,235-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164103.ts to play queue 241
2021-10-02 10:29:06,057-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:29:09,141-DEBUG:m3u8_queue Reloading m3u8 stream queue 241
2021-10-02 10:29:10,114-DEBUG:m3u8_queue Removed https://(redacted)/1280x720/1633159304.ts from play queue 241
2021-10-02 10:29:10,117-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164104.ts to play queue 241
2021-10-02 10:29:14,557-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164103.ts (6.0)s (3364824B) ttw:8.06s 1
2021-10-02 10:29:14,864-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:29:15,024-DEBUG:m3u8_queue Reloading m3u8 stream queue 241
2021-10-02 10:29:15,998-DEBUG:m3u8_queue Removed https://(redacted)/1280x720/1633159305.ts from play queue 241
2021-10-02 10:29:16,001-DEBUG:m3u8_queue Added https://(redacted)/1280x720/1633164105.ts to play queue 241
2021-10-02 10:29:18,560-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164104.ts (6.0)s (3200888B) ttw:3.31s 1
2021-10-02 10:29:18,871-DEBUG:atsc Updating ATSC SDT with service info b'M3U' b'(redacted)'
2021-10-02 10:29:19,194-INFO:internal_proxy Serving 241 https://(redacted)/1280x720/1633164105.ts (6.0)s (3489468B) ttw:0.00s 0

guess my thoughts on reducing performance in the add segment are did not quite pan out. I'll see what I can do.

Sorry about that. It turned out more complex than I thought it needed to be. .29 has the solution while keeping the add performance down.

.29 took care of the segments in the wrong order. Thank you!

Back to channels that terminate during commercials.

If I play DABL it does see commercials and the cue messages are logged. All is good.

However, my wife tried watching another PlutoTV channel (385 Midsomer Murders). It plays, then hits an ad section and filters the ad segments out. However after getting the ad segments it again does not see any segments for quite some time (the commercial segments are probably large again) and terminates after the IDLE_TIMEOUT. There is nothing in the log showing any 'cue' so it seems this channel may not insert cue messages.....

Looking. At the end of the movie, I got an exception
File "lib/streams/m3u8_queue.py", line 399, in add_to_stream_queue
last_key = list(PLAY_LIST.keys())[-1]
IndexError: list index out of range
which I can fix shortly. With the magic I put in, the cue should not be required, but we shall see. I'll put in the fix for this and test again. The exception is caused by the PLAY_LIST totally emptying (a very strange event).

Confirmed no cue items listed during ads, but again that should not be enough to cause an issue. Last ad test was successful.

After a second ad section, I am believing your issue was the exception. I will publish the update to fix this.

It looks like I did get multiple exceptions and my eyeballing of the log was in error. I too quickly assumed it was a timeout after doing some filtering of a large log. Sorry about that.

I had a large and complex log due to stress testing. During this testing 4 channels playing concurrently all via tvheadend/cabernet. Two were M3U8 channels and 2 were PlutoTV channels. All channels were being played live via either Kodi or a VLC window.

Each time a stream was terminated an exception occurred. The exceptions all looked like this.

2021-10-02 15:08:46,565-INFO:internal_proxy CabernetException: Provider has stop playing the stream. Terminating the connection 785 785
2021-10-02 15:08:46,566-ERROR:m3u8_queue UNEXPECTED EXCEPTION start=Queue <multiprocessing.queues.Queue object at 0x7efd0c060b50> is closed
Traceback (most recent call last):
  File "/app/lib/streams/m3u8_queue.py", line 505, in start
    q_item = IN_QUEUE.get()
  File "/usr/local/lib/python3.8/multiprocessing/queues.py", line 97, in get
    res = self._recv_bytes()
  File "/usr/local/lib/python3.8/multiprocessing/connection.py", line 216, in recv_bytes
    buf = self._recv_bytes(maxlength)
  File "/usr/local/lib/python3.8/multiprocessing/connection.py", line 421, in _recv_bytes
    return self._recv(size)
  File "/usr/local/lib/python3.8/multiprocessing/connection.py", line 379, in _recv
    chunk = read(handle, remaining)
TypeError: an integer is required (got type NoneType)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/app/lib/streams/m3u8_queue.py", line 514, in start
    STREAM_QUEUE.put({'uri_dt': 'terminate'})
  File "/usr/local/lib/python3.8/multiprocessing/queues.py", line 82, in put
    raise ValueError(f"Queue {self!r} is closed")

I have installed your new version and will test again.

The exception you have, shows the m3u8_queue process was exiting at the time. During an exit, things are pretty much broken as the process shuts down. A TypeError on a queue is normally caused by the queues closing in preparation of the process terminating. So is the ValueError. For some reason, I thought a ValueError was a subtype of TypeError (but it is not). Will update the exit code to include catching the ValueError. The possible result of this exception is the m3u8_queue process may not have closed correctly and would hang around until you restart the app. So, not a big deal.

Also found an exception on xmltv.xml requests. Fixing it in .32

No more exceptions today while playing 4 concurrent channels so I think your update caught that issue.

A new one.... I found that when playing various Pluto channels including Star Trek channel that 3 or 4 segments were replayed. It happens at the transition from one episode to another. I was live playing the channel (not recording).

Here is a description of what happens

The playback of the first episode was going well and the last segments came in and were served.
The first 3 segments of the new show came in and were added and then served.
Then 2 segments from the prev episode plus the 3 segments just played from the new show were removed.
Then the 3 segments already played were added again and then served.

I wonder if a empty playlist came in causing the current playlist to be cleared?

The channels kept playing so it was weird but not catastrophic.

Update: It doesn't happen every time a show transitions to a new episode (it didn't' happen just now (10:30am pacific) on Star Trek). But I see it happen on multiple Pluto channels.

Thanks for the info. I am really hoping the app is stabilizing; it has been a hard week. The only thing I can think of is associated with the time stamps. If between episodes, the provider starts a new play through (like vod) with different timestamps, then Cabernet would think the segments are different and replay them. I believe the m3u8 module tracks down to the second and not millisecond, so it would have to be fairly large. I was thinking to put in a variant to the timestamp saying... if not so much different from the original, then consider it the same. I have not come up with a short/low performance way to do that, so it is currently an exact match to the second.

Of course, there could be an issue with the m3u8 module...

I will check it out and see what is happening.

I have some data. At the end of star trek, two segments that played twice. They were the same segment, but different timestamps
2021-10-03 19:30:01.700000+00:00 hls_2400-00000.ts
2021-10-03 19:30:06.700000+00:00 hls_2400-00001.ts

2021-10-03 19:29:58.811000+00:00 hls_2400-00000.ts
2021-10-03 19:30:03.811000+00:00 hls_2400-00001.ts

As you can see, they have very different times. The second set was played in the past, which could be a filter. Will check some other stations to see how VOD works and others. My concern is that timestamps can change dramatically (even go into the past) and should not be ruled out.

After looking at the repeating segments, it would take a significant effort to clean it up. The way it would work is the timestamp would be a variant of "+-" so many seconds. So instead of a perfect match, it would be a few tests for a match. The google issue was about 30 seconds while the current issue is less than 6. My assumption is that we could use a number like 10 seconds, but it would cause more programming and CPU to make it happen. (also that time variance is unknown) It would detect a segment with a timestamp (+-seconds) and not remove or add, if found. Now if they had some commercials between the duplicate segments, then all bets would be off.

So, I don't have a good solution at this time. I'll think on this, since it only happens when a new show begins.

I have added it to the enhancement list for 0.9.5.

Interesting.
I agree that fixing this is not critical and can wait. I figured I would tell you about this weird behavior in case it could trigger bigger problems like having the playback or recording fail. Getting a bit of replay may be a bit distracting but since it does not cause the playback to fail I can certainly deal with it.

I have run into the problem that Sean had a while back. Some of my m3u streams will not play when I play the channel live from Kodi. However if I use Kodi to set the channel to record the show, wait 10-20 seconds and then start playback of the recording everything works ok. Also if I play the channel directly from the tvheadend interface on a Windows PC and then pay the channel via VLC it works fine as well.

There is an unsual message when playing live from Kodi, the channel (m3u stream) Kodi says the audio stream is 'None' and there is no alternate audio streams. TVheadend also spits out the following message when viewing starts:

2021-10-05 12:39:11.152 tsfix: The timediff for AAC is big (291000), using current dts

When setting the program to record in Kodi, waiting 10 seconds and then playing the recording from Kodi there is no tsfix message and the audio works. Kodi says the audio stream is 'English - AAC 0 channels - 0 channels (1/1)'. This is what it says about the recording.

2021-10-05 12:46:34.142 dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
2021-10-05 12:46:34.142 dvr:  1  H264                    1920x1080   ?                                    
2021-10-05 12:46:34.142 dvr:  2  AAC               eng                             96000        ?

When playing live via VLC from TVHeadend there is no tsfix message and the audio is ok. VLC Codec info on the audio stream is --> Original ID:257, Codec:ADTS, Language:English, Type:Audio, Channels:Stereo, Sample rate:48000 Hz, Bits per sample: 32

Since recording shows works fine and I have a workaround for playing live this is not a critical item.

I have seen this as well. What I know is the stream coming from the provider does not have a SDT ATSC message. (It may not have any ATSC packets) Testing DABL... If I have nothing enabled and directly to VLC then the video plays with no audio in VLC and VLC says there is a video stream with 4 subtitle streams. If I enable PTS Resync, then it will play both audio and video. VLC says the stream number starts at 5 instead of 0, but now has an audio stream. If I have PTS Resync disabled and play through TVH, the audio channel again is present in VLC (through TVH).

Cabernet log shows that without the PTS Resync enabled, the segments do not contain any SDT msg. If I enable PTS Resync, it now has the SDT msg.

My thought is that TVH and FFMPEG are adding ATSC packets into the message so that it can play the video. I have it on my list to review in more detail what is going on, but I suspect it may take some effort to add the ATSC missing packets (if indeed the segments have none.)

Also, one last note. If I take the m3u8 file and feed it directly into VLC, it works. So, need to spend some time determining what is happening.

DABL works fine for me with PTS Resync.

The stream I am having trouble with is one of the ones that had 4800 segments in each playlist from Roberts URL (the one with something like 8000-10000 channels). The info in my previous message had PTS Resync enabled for all test cases. I originally tried the problem channel without PTS resync but when I received no audio when playing live from Kodi I switched it on and never turned it off.

This is FYI - the problem is not critical.