Tvheadend

Looking at the "Added" lines, it looks like google is sending the segments in fast causing a significant delay at the end. Last section had a 19 seconds hole. Otherwise, use a complex calculation which counts the filtered items and durations along with time between servings... to determine just how long we may have to wait.

So, what timeout value are you using?

In my Pluto TV Instance Channel Update Timeout is set to 23

But I suspect that is not the Timeout you are looking for. Where is the timeout set?

Nope, wrong timeout. Here is the text from above. It seems to fix the issue by changing it to 60. not sure what value it should be set to. Looking over the logs filtered to "Added"

At the top of the lib/streams/internal_proxy.py there is a setting
IDLE_COUNTER_MAX = 20
It is NOT in seconds. This determines the length of time it waits for a timeout, before closing the connection. You can try to change this and see if that helps. If you find out it does, it would be helpful to know how long a delay DABL was having.

my bad. I missed the message. I will change it to 60 and try again.

Bingo, Got a hit.

2021-09-30 19:25:15,291-DEBUG:m3u8_queue Added 
2021-09-30 19:25:56,579-DEBUG:m3u8_queue Added 

60 didn't work. same issue. I will try 120.

BTW: I watched the commercials using PlutoTV via the web and they went on for a LONG time.

It is possible you will get different responses than I do. You may want to just jack it up to 240 just to get an idea of what the time between Added lines are. I have pushed out a quick release with the value of 90 as a temporary fix.

EDIT: Just got a timeout at 60. It was not that long a break, so I am thinking something else is also going on...

It worked at 120.
The actual commercials lasted 4 minutes.

17:36:33 - the last good segment (00042.ts) was added
17:36:38 to 17:38:36 - a bunch of google segments were added
17:38:36 - the next good segment added (00063.ts)

a second commercial just happened and all is ok at 120
the second set of commercials lasted 2 minutes.

17:45:21 - segment 00030.ts
17:45:26 to 17:47:55 - google segments
17:47:55 - segment 00056.ts

Update: Then the third commercial

17:53:41 - segment 00014.ts
17:53:49 to 17:55:59 - google segments
17:55:59 - segment 00037.ts

Looking god.

Your timing looks great with no time between adds. You have to wait for the delay between adds to show up before you can see if it worked. It does not always happen during that segment. What I am seeing is similar to Locast. It looks like PlutoTV is changing the m3u8 file (Locast was doing this every 15 minutes). Unless you migrate to the new m3u8 stream, the stream ends. It is a simple matter of calling refresh stream, but it is always to determine when...

Thanks for all your help. Things look good now and recordings are not stopping with 120 timeout. I will be recording my 3 shows again tomorrow and hope they are all good.

I have to run some errands now so logging off..

OH... BTW: I just noticed a zombie...

$ ps aux|grep Z
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     60453  0.3  0.0      0     0 ?        Z    17:32   0:08 [ffmpeg] <defunct>

I just had 2 adds that were over a minute apart
2021-09-30 20:20:55,175-DEBUG:m3u8_queue Added
2021-09-30 20:22:03,013-DEBUG:m3u8_queue Added

So, based on my standard of 2 times the value, I will also recommend 120. Still running a few more tests.

Did more runs. Found one with 1:45, so 120 is too close. Raised it to 200 in version .21. When I watched the stream on the pluto website, I realize they are adding additional commercials outside of the stream that we are not getting. We just have to guess at how long they will be. Up to 2 minutes seems to be fine, but I like to add buffer to any number. So, 200 is my best guess.

Also to Island. The ps -aux command is not as useful as the ps -ef command. It provides the parent process id that is attached to the defunc process. This is useful since the Cabernet log lists the process id on most of the m3u8 processing, so we might be able to tell why it happened. (if the log was reviewed)

I had stepped away from trying to get anything additional to work until this morning, when I discovered that I had no guide data for any of the m3u instances, so I looked at the xmltv.xml file that it was downloading and it turns out is is getting all the channel headers normally, but where the program data is supposed to be it says this (this is where the xmltv.xml file ends):

HTTP/1.0 501 Not Implemented
Server: BaseHTTP/0.6 Python/3.7.3
Date: Fri, 01 Oct 2021 10:38:35 GMT
Content-type: text/html

<html>
        <head></head>
        <body>
            <h2>501 - Server Error</h2>
        </body>
    </html>

In my log I see sections like this:

Oct  1 06:44:05 systemname locast[11766]: 2021-10-01 06:44:05,965-ERROR:web_admin UNEXPECTED EXCEPTION on GET=can only concatenate str (not "NoneType") to str
Oct  1 06:44:05 systemname locast[11766]: Traceback (most recent call last):
Oct  1 06:44:05 systemname locast[11766]:   File "/home/hts/cabernet/lib/clients/web_admin.py", line 95, in do_GET
Oct  1 06:44:05 systemname locast[11766]:     if getrequest.call_url(self, self.content_path):
Oct  1 06:44:05 systemname locast[11766]:   File "/home/hts/cabernet/lib/common/decorators.py", line 217, in call_url
Oct  1 06:44:05 systemname locast[11766]:     self.url2func[_name](_webserver, *args, **kwargs)
Oct  1 06:44:05 systemname locast[11766]:   File "/home/hts/cabernet/lib/clients/epg2xml.py", line 39, in xmltv_xml
Oct  1 06:44:05 systemname locast[11766]:     epg.get_epg_xml(_webserver)
Oct  1 06:44:05 systemname locast[11766]:   File "/home/hts/cabernet/lib/clients/epg2xml.py", line 75, in get_epg_xml
Oct  1 06:44:05 systemname locast[11766]:     self.gen_program_xml(xml_out, day_data, channel_list, ns, inst)
Oct  1 06:44:05 systemname locast[11766]:   File "/home/hts/cabernet/lib/clients/epg2xml.py", line 204, in gen_program_xml
Oct  1 06:44:05 systemname locast[11766]:     descr_add += '\n' + prog_data['desc']
Oct  1 06:44:05 systemname locast[11766]: TypeError: can only concatenate str (not "NoneType") to str
Oct  1 06:44:05 systemname locast[11766]: 2021-10-01 06:44:05,966-WARNING:web_handler [127.0.0.1] "GET /xmltv.xml HTTP/1.1" 501 -

If under the M3U Plex instance I uncheck "XMLTV Enabled" and then Reset EPG Data, the problem still exists - even if I actually remove the link to the .gz file that contains the guide data the problem is still present. However if I disable the M3U Plex instance entirely and then Reset EPG Data, it works and gets the guide data for all the other instances. Not just why just disabling the XMLTV isn't sufficient but anyway the problem must be in the "usa.xml" file that you get if you unzip the file from https://i.mjh.nz/Plex/us.xml.gz. I looked at that file and immediately noticed a couple things, first that the channel headers are not exactly like some of the other services, although as far as I can tell Cabernet was not having a problem reading those, but also rather than putting all the channels at the top of the file they are mixed in with the program listings, in other words it appears there is a channel section followed by all the programs for that channel, then another channel section and its programs, and so on. Anyway it seems that something is getting messed up in the concatenation, if the log is giving accurate info. I am not certain if that's because there is an error or problem in that usa.xml file, or if I have found a bug in Cabernet, but hopefully that log will give you some clues.

But then again there may not be any big rush in fixing this; when I had the instance enabled none of the Plex channels that I tried would play in VLC, so I am coming to the conclusion that Plex is kind of a hot mess.

I also noticed that for the channels in the short list of channels in my custom m3u file there are channel entries in the xml file produced by Cabernet (even though there is no program data available for those channels) even though I have "XMLTV Enabled" unchecked in that instance as well. So either the "XMLTV Enabled" checkbox is being ignored completely when unchecked, or at least it's not preventing the writing of data to the xmltv.xml file produced by Cabernet.

I am currently on Version: 0.9.4.21 if it makes any difference.

Its claim is that you have something wrong in the epg.db file. It is unlike the channels.db and is regenerated from pulling data from the provider, it can be removed, Cabernet restarted and all should come up fine. So, recommend removing the epg.db file to possibly fix the issue. I will take a look and see what happened.

In regard to the "XMLTV Enabled". I do not recall such a checkbox. I do see "EPG Collection Enabled" in the list. What this does is disable the collection of programs from the provider and removes the programs for the instance from the xmltv.xml file. It was not intended to also remove the channel data; although, I can take a look and see if it should also be removed.

I have imported the Plex xml without issue, but things can change. Will run some tests and see if I can tell what happened.

Found the issue in the new xmltv parser for M3U. It is being fixed in .22 shortly. and I would recommend removing the epg.db file after the upgrade.

Thanks very much! I got .22 and removed the epg.db and re-enabled the Plex instance, the good news is that the xmltv.xml file produced by Cabernet is good. The bad news is that it doesn't seem to contain any actual program data for Plex, at least not yet - all the channels show several one hour blocks of the channel name as the title and "Not Available" as the description. I did try removing both the epg.db amd epg_programs.db files in the hope that they would regenerate with good data, and it appears they did but just not for Plex, for some reason. Hopefully that will resolve itself at some point. The Plex channels do play now, too, so not sure what that was all about.

The "XMLTV Enabled" checkbox is on each instance page, down in the EPG section (it's the first item there).

Anyway thanks again, all in all Cabernet seems to be getting a lot more reliable, it's just Plex that has been unusually flaky. Pluto, XUMO, and SamsungTV all seem to be working fine on the channels I have tried to watch!

I switched to Plex on my test instance and the EPG was not clean with the switch. The Data Mgmt reset stuff and imports need more work. So, I upgraded to .22 and got the EPG exception. Removed the epg.db file and did clean reset on channels for m3u. All worked and Plex came up fine with the xmltv file containing the data (used http://ipaddress:6077/m3u/test/xmltv.xml to test)

The epg_programs.db file should not be deleted. It contains the cache for XUMO, like zap2it does. Removing it will cause XUMO EPG to take a very long time to re-cache the data.

Will probably do more epg testing and fixes today. Plan is to continue to let 0.9.4 stew and get more reliable for a while before starting on enhancements.

Some of the instances say "EPG Collection Enabled" while others say "XMLTV Enabled". Will update the other plugins to be the same.

Well whatever the problem is, everything I tried failed to get good program data. I deleted the epg.db file, I did a clean reset on the channels, and when that failed I temporarily removed the epg.db AND channels.db files and let Cabernet build new ones (which I know it did because I lost all my channel edits), and when THAT didn't work I tried creating a whole new instance for Plex (again removing epg.db and channels.db) and even in the new instance it would only build an epg with entries like

<programme channel="5e20b730f2f8d5003d739db7-5f6b8e5900b0950040d0f2af" start="20211001190000 -0400" stop="20211001200000 -0400">
<title lang="en">Cheddar News</title>
<desc lang="en"> Not Available</desc>
<length units="minutes">60</length>
<previously-shown/>
</programme>
<programme channel="5e20b730f2f8d5003d739db7-5ef11487d33ab9004048a1d3" start="20211001130000 -0400" stop="20211001140000 -0400">
<title lang="en">Choppertown</title>
<desc lang="en"> Not Available</desc>
<length units="minutes">60</length>
<previously-shown/>
</programme>
<programme channel="5e20b730f2f8d5003d739db7-5ef11487d33ab9004048a1d3" start="20211001140000 -0400" stop="20211001150000 -0400">

Just picked those at random from the the .xml file. In other words for some reason it not using the guide data in https://i.mjh.nz/Plex/us.xml.gz. Also, I am still seeing sections like this in the log:

Oct  1 15:22:01 systemname locast[444]: 2021-10-01 15:22:01,793-ERROR:scheduler UNEXPECTED EXCEPTION on GET=[Errno 2] No such file or directory: '/home/hts/cabernet/data/tmp/xmltv/1633116116.451873'
Oct  1 15:22:01 systemname locast[444]: Traceback (most recent call last):
Oct  1 15:22:01 systemname locast[444]:   File "/home/hts/cabernet/lib/schedule/scheduler.py", line 157, in call_trigger
Oct  1 15:22:01 systemname locast[444]:     call_f()
Oct  1 15:22:01 systemname locast[444]:   File "/home/hts/cabernet/lib/plugins/plugin_instance_obj.py", line 71, in refresh_epg
Oct  1 15:22:01 systemname locast[444]:     self.epg.refresh_epg()
Oct  1 15:22:01 systemname locast[444]:   File "/home/hts/cabernet/lib/plugins/plugin_epg.py", line 66, in refresh_epg
Oct  1 15:22:01 systemname locast[444]:     self.refresh_programs(epg_day, False)
Oct  1 15:22:01 systemname locast[444]:   File "/home/hts/cabernet/plugins/provider_video_m3u/lib/epg.py", line 61, in refresh_programs
Oct  1 15:22:01 systemname locast[444]:     iterator = iter(xmltv)
Oct  1 15:22:01 systemname locast[444]:   File "/home/hts/cabernet/lib/common/xmltv.py", line 61, in __iter__
Oct  1 15:22:01 systemname locast[444]:     self.context = ElementTree.iterparse(self.file, events=('start', 'end',))
Oct  1 15:22:01 systemname locast[444]:   File "/usr/lib/python3.7/xml/etree/ElementTree.py", line 1243, in iterparse
Oct  1 15:22:01 systemname locast[444]:     source = open(source, "rb")
Oct  1 15:22:01 systemname locast[444]: FileNotFoundError: [Errno 2] No such file or directory: '/home/hts/cabernet/data/tmp/xmltv/1633116116.451873'

The name of the file that is not found on the last line is different every time, and I have no clue what causes these entries.

I know you are still working on this, so hopefully this is of some use to you.

I have a new push for the epg, but will not help with your issue. The error says the *.xml file that was pull from where ever and placed in the data/tmp/xmltv folder disappeared. Obviously, there is something else going on for it to disappear and it has little to do with the databases. It pulls down the file that is compressed and then uncompresses it into the file listed (that was not found). So, the log must have more info on what happened. It got broken before it got here.

I was recording my shows on DABL today. The first one at 1pm worked. The second one at 2pm failed.
I just changed IDLE_COUNTER_MAX from 200 to 300 and will see if that works.

G Kazaroth wrote:

I have a new push for the epg, but will not help with your issue. The error says the *.xml file that was pull from where ever and placed in the data/tmp/xmltv folder disappeared. Obviously, there is something else going on for it to disappear and it has little to do with the databases. It pulls down the file that is compressed and then uncompresses it into the file listed (that was not found). So, the log must have more info on what happened. It got broken before it got here.

I wish the log had more info, but it doesn't. And all the other services (SamsungTV, Pluto, XUMO) have no problem. Also, Cabernet is the only thing running under the hts user account on that system - Tvheadend also runs as the hts user, but on a completely different machine.

So I tried this:

In the plex instance changed the url for the epg data to https://i.mjh.nz/Plex/us.xml so it would come in uncompressed.
Set the log level to INFO
Went to Data Management and clicked the button to Reset EPG Data, after specifying M3U in the dropdown.
Went to Scheduled Tasks and clicked the icon to Refresh M3U Plex Channels

While that was running this is ALL the log showed for the entire period:

Oct  1 17:47:58 systemname locast[5097]: 2021-10-01 17:47:58,033-INFO:web_handler [127.0.0.1] "GET /api/schedulehtml?task=7A5DF3B8-22ED-11EC-BE39-CA6F026676A3&run=1 HTTP/1.1" 200 -
Oct  1 17:47:58 systemname locast[5097]: 2021-10-01 17:47:58,139-INFO:web_handler [127.0.0.1] "GET /modules/scheduler/scheduler.js HTTP/1.1" 200 -
Oct  1 17:48:03 systemname locast[5097]: 2021-10-01 17:48:03,237-INFO:web_handler [127.0.0.1] "GET /api/schedulehtml HTTP/1.1" 200 -
Oct  1 17:48:03 systemname locast[5097]: 2021-10-01 17:48:03,326-INFO:web_handler [127.0.0.1] "GET /modules/scheduler/scheduler.js HTTP/1.1" 200 -
Oct  1 17:49:04 systemname locast[5097]: 2021-10-01 17:49:04,845-INFO:web_handler [127.0.0.1] "GET /m3u/plex/xmltv.xml HTTP/1.1" 200 -

Just those five lines and that was it! Even several minutes later nothing new had been added, except for a couple lines from systemd about a process that runs under a completely different user account. It wasn't until 18:13:45 that I got another set of those UNEXPECTED EXCEPTION messages, and there was nothing before them. There actually were two setd, one complaining "No such file or directory: '/home/hts/cabernet/data/tmp/xmltv'" and the other "No such file or directory: '/home/hts/cabernet/data/tmp/xmltv/1633126423.0377953'" - the first one makes me wonder if maybe the actual filename is xmltv.xml? I checked that tmp directory a few times and never saw anything in it, and I did check the ownership and permissions to make sure they were okay.

But back to the attempt to get the Plex listings - just out of curiosity I compared a "dummy" program listing that's being produced by Cabernet now to an actual program listing for the same channel:

<programme channel="5e20b730f2f8d5003d739db7-612919784f53e1002c9aa219" start="20211001080000 -0400" stop="20211001090000 -0400">
<title lang="en">Are We There Yet?</title>
<desc lang="en"> Not Available</desc>
<length units="minutes">60</length>
<previously-shown/>
</programme>

<programme channel="5e20b730f2f8d5003d739db7-612919784f53e1002c9aa219" start="20211001184814 +1300" stop="20211001191407 +1300">
<title>The First .45 Episode</title>
<desc>
As Lindsey films a reality show about her family, Kevin comes across a gun in Suzanne's handbag.
</desc>
<icon src="https://db6iftd8li11q.cloudfront.net/MSL1411.jpg"/>
</programme>

I first note the time zone designations are different (-0400 compared to +1300), not sure if that could be an issue. Second, the ' lang="en"' is not used in the actual listings, could something be looking for that?

These are the channel segments at the top of the

http://localhost:6077/m3u/plex/xmltv.xml

<channel id="5e20b730f2f8d5003d739db7-612919784f53e1002c9aa219">
<display-name>Are We There Yet?</display-name>
<icon src="https://provider-static.plex.tv/epg/images/ott_channels/logos/AreWeThereYet_logo_dark.png"/>
</channel>

<channel id="5e20b730f2f8d5003d739db7-612919784f53e1002c9aa219">
<display-name>AREPX Are We There Yet?</display-name>
<display-name>AREPX Are We There Yet?</display-name>
<display-name>AREPX</display-name>
<display-name>Are We There Yet?</display-name>
<display-name>Are We There Yet?</display-name>
</channel>

In case you are wondering where AREPX came from, I had set it up to use PX as a channel suffix and at that point you hadn't enabled the feature to use channel numbers if none are present, so I used three letter codes derived from the channel name, just so each would be unique. So my next question is, does the logic that extracts the channel listings expect that some of those display-name fields will start with a number? If so that's my fault but I had thought that internally it only used the channel id string for matching.

Let me ask this, suppose I wanted to start over with a mostly fresh install, but not lose my channel edits. If I did a fresh install from scratch and ONLY brought over my config.ini file (with the Plex instance stripped back to the bare minimum, as if I was just installing it) and my current channels.db, would that preserve my channel edits while doing enough of a refresh that it might make these issues go away? Or could the channels.db file be part of the problem?

Anyway I hope I am giving you some useful feedback. Thanks for looking at this, and I really wish I could give you some better clues as to what is going on.

Island, I think we are going to have to use #EXT-X-CUE-OUT and #EXT-X-CUE-IN. They are basically tags that indicate a section of the video has a section that a re-transmitter can put ads into. It also contains a duration of the ads section. The spec also defines that the provider can give an additional #EXT-X-CUE-OUT tag to extend the ads void. Right now, without the long delay issue showing, the #EXT-X-CUE-OUT is set to 270 seconds.

I also tracked down the reason for the void in Cabernet sending to TVH. Pluto via google is sending the exact same 6 ad segments 3 times in a row (in this case). Each segment set is 30 seconds in duration. So, if you have enough of these duplicates, it would be a long time. Since they are exactly the same, Cabernet believes them to be a duplicate and already provided, so it ignores the segment. All makes sense now.

The EXT-X-CUE-OUT tells Cabernet the ad section is starting and approximately how long the ad section is, so the process should be...
If we receive a EXT-X-CUE-OUT, we should wait for a EXT-X-CUE-IN before continuing any countdowns. This should mean the extra large timeout we are using should NOT be required. Still need to determine the correct value.

I did some reading and what you say makes a lot of sense. And yes, I too have seen DABL insert the same video over and over during a commercial break....

It looks like the playlist will have a booleans that we can check similar to how you checked for 'vod' via looking at _playlist.playlist_type

When the m3u8 playlist has cue_out_start or cue_out set to True then internal_proxy.py needs to know this. It looks like internal_proxy.py will reset the timeout counter when it sees a 'running' entry in the queue. Maybe have m3u8_queue.py add a periodic 'running' item into the queue when cue_out_start or cue_out is True?