Large EPG fails to load in FireStick 4K

[im85288]

First of all thanks for this addon, it has got me coding again in Python!

I am experiencing a problem on my FireStick 4k where when the EPG created is a very long string it fails to be parsed by service.iptv.manager. An error along the lines of: 'Something went wrong in... Unterminated string at: line 1 column 1048528 (char 1048527)' is shown in the logs. As the FireStick is fairly locked down I cannot download the full logs...but that line was enough for me to attempt the sync with a smaller EPG (in this case I got the epg for only one channel and the length of the epg was around 43817 chars). This worked without any issues.

On my MacBook where I did the developing it successfully loads the full EPG (2146760 chars long) so there is no real consistency there.

Both tests are using the stable Kodi 18 releases on the relevant devices.

Is there anything I can do to try and help debug/check this issue?

[michaelarnauts]

There are some addons to upload your Kodi log. It might help to know where the exception is thrown.

[im85288]

Thanks I had forgotten about them, here is the link: https://paste.kodi.tv/lacomuguge

Do you want me to enable debug in the kodi settings as all that is really visible is:

ERROR: [service.iptv.manager] [resources.lib.modules.addon] Something went wrong while calling plugin.video.emby.livetv: Unterminated string starting at: line 1 column 1048528 (char 1048527)

[im85288]

Here's another log this time with kodi debug enabled: https://paste.kodi.tv/ciluqiruvu

Slightly different error shown (but also one I had seen before) which I think is to do with the size of the data being returned from my addon:

ERROR: [service.iptv.manager] [resources.lib.modules.addon] Something went wrong while calling plugin.video.emby.livetv: 'NoneType' object is not callable

[michaelarnauts]

Hmm, I don't really know what happened here... Could you add some more logging to your plugin.video.emby.livetv addon?

[im85288]

I did add extra logging to my addon as it was strange for me too to see it working correctly on the Mac but not on the FireStick...but the log file is too large to upload using the kodi addon.

Here is a link to the actual EPG content generated just before it is returned to this addon: https://www.dropbox.com/s/vlsp6dcri7cepjq/epg.pdf?dl=0

The amount of characters in the string is the problem on the Firestick, like I mentioned in the initial report once I made it much smaller in size it worked without issues.

[michaelarnauts]

Thanks!

I assume this is only a dump of the epg attribute of the full JSON EPG dict? I can't find the version attribute.

There doesn't seem to be a specific maximum string length in Python, besides the system memory, but I assume that 2MB should be free on the Firestick. Can you try to narrow it down to see where the cutoff point is?

[im85288]

Yes exactly I use the same IPTVManager as suggested on the wiki, so what you see there is prior to this code:

@via_socket def send_epg(self): epg = fetch_livetv_epg() return dict(version=1, epg=epg)

I will experiment some more tomorrow, when I generated it for one channel at the length of 43817 that was fine.

I can also try on a Nvidia Shield to see if it is a general Android limitation or indeed as you mentioned maybe memory related...very strange!

[im85288]

An update here, tried it out on the Shield and it worked fine there too. So there must be a limitation with devices such as the FireStick 4K (8mb memory).

After yesterday I have successfully got the FireStick to work with a EPG of length 528002 characters. My guess is the physical limit is as was stated in the error message from this addon:

Something went wrong while calling plugin.video.emby.livetv: Unterminated string starting at: line 1 column 1048528 (char 1048527) of just over 1 million characters.

This is most likely to do with the way things work with the transmission of the data via a socket. I presume you looked into the standard XBMC Monitor solution (as done in my up next addon for example) for transferring data between addons and ruled it out?

For example: def send_event_notification(method, data): message_data = json.dumps(data) source_id = "embylivetv" base64_data = base64.b64encode(message_data) escaped_data = '\\"[\\"{0}\\"]\\"'.format(base64_data) command = 'XBMC.NotifyAll({0}.SIGNAL,{1},{2})'.format(source_id, method, escaped_data) log.debug("Sending notification event data: {0}", command) xbmc.executebuiltin(command)

[dagwieers]

We originally intended to do this but found a bug with large payloads that made this not a viable option. https://github.com/add-ons/service.iptv.manager/wiki/Design#json-rpc

We think moving to an HTTP service in IPTV Manager is a better course of action in all regards, but this has not been implemented yet. https://github.com/add-ons/service.iptv.manager/wiki/Design#http-based-communication

[im85288]

Cool yes agreed the HTTP service method would be more robust, for now I have a lot to do with the emby livetv addon but will comeback and help here if anyone needs assistance.

[michaelarnauts]

The issue with the JSON-RPC is that there was no limit on how large the messages could be (you could send a message of a few GB in size, and crash Kodi). Also, there was a memory leak, since every message you send kept increasing the memory usage of Kodi. This is problematic for other reasons, but we didn't look more closely into it for now. We probably should open an issue at Kodi for this.

The HTTP callback makes it more complex since it makes synchronisation harder. With the socket, we can block the IPTV Manager processing until we get a response from the Add-on. With HTTP, this isn't as straighforward since it will be multithreaded. It's because we would like to do the communication to Simple IPTV trough HTTP instead of writing the files to disk that we want to implement HTTP. The biggest benefit is that it would allow Addons to provide new EPG data any time, not just during a refresh cycle.

Besides this, I don't think that HTTP will solve your issue here. The sockets are really low overhead, and if you have a problem here, you will also see a problem when we use HTTP. I still find it very odd that you can only send about one megabyte of data over a socket.

[im85288]

It would help if someone else could also test this limit out on the FireStick so as to exclude it being a local problem. I have though as stated got it working on other devices where it is larger than the one megabyte range.

It is not a major issue as I can work around it, but for sure something to keep in mind for any future bug reports/issues.

[michaelarnauts]

It could be interesting to see what happens if you try to save the large json to disk, and try to parse that file with a json.load() on your Firestick. It looks like json can have quite a bit of overhead, but I find it hard to believe that the firestick has so little free memory. I would also expect a different error message in this case (more like could not allocate memory).

[im85288]

The 'json.load()' works fine as it is done prior to the debug I posted yesterday of the large EPG, I checked this to make sure it was not crashing on the FireStick. That's why it for me points at something in the socket parsing of the data, I'm not sure if you can add logging for whilst parsing the buffer? Not sure if that would work but just a suggestion.

Whilst I have your attention is there some way I can assure the stream called is that of the one I pass in with the Program data rather than the Channel data?

For example I pass this in for a Channel:

channels.append(dict(
            name=name,
            id=epg_id,
            logo=logo,
            stream=u"plugin://plugin.video.emby.livetv/play/id/{}".format(epg_id)
        ))

And then for the EPG:

programs.append(dict(
                id=epg_id,
                start=utc_timestamp_to_epg_timestamp(program.get('StartDate')),
                stop=utc_timestamp_to_epg_timestamp(program.get('EndDate')),
                title=program.get('Name', ''),
                subtitle=program.get('EpisodeTitle', ''),
                episode=episode,
                image=downloadUtils.getArtwork(program, "Primary", server=server),
                stream=u"plugin://plugin.video.emby.livetv/play/program/{}".format(program.get('Id'))
            ))

Which results in for example this in the epg.xml:

<programme start="20200611234500 " stop="20200612013500 " channel="14722" catchup-id="plugin://plugin.video.emby.livetv/play/program/405321">
 <title>A Good Woman Is Hard to Find [COLOR green][B]•[/B][/COLOR][CR]</title>
 <icon src="http://192.168.1.230:8096/emby/Items/405321/Images/Primary/0?Format=original&amp;Tag=0e68ad89ee20b9396964d9f0e9918e98"/>
</programme>

I actually want the stream from the EPG data called when pressing play..but it is taking the one from Channels

[dagwieers]

@im85288 Can you open a new issue/request for this, I think it would help if we can keep this separate from this current issue.

[michaelarnauts]

I actually want the stream from the EPG data called when pressing play..but it is taking the one from Channels

This isn't an issue, this is currently how Simple IPTV works in Kodi 18. To play the program itself trough vod, you have to use the context menu. In Kodi 19, it plays the selected program when you select it.

[im85288]

@dagwieers I will just leave it as is after the comment from @michaelarnauts I was not aware it works correctly with Kodi 19. I will try it out there, thanks guys.

[michaelarnauts]

The 'json.load()' works fine as it is done prior to the debug I posted yesterday of the large EPG, I checked this to make sure it was not crashing on the FireStick. That's why it for me points at something in the socket parsing of the data, I'm not sure if you can add logging for whilst parsing the buffer? Not sure if that would work but just a suggestion.

Could you change these lines in addon.py to just raise? This should give a stacktrace in your log.

_LOGGER.error('Something went wrong while calling %s: %s', self.addon_id, exc)

[im85288]

Sure will give that a shot and report back

Actually do you mean here:

 if not buf:
                # We got an empty reply, this means that something didn't go according to plan
                # raise Exception('Something went wrong in %s' % self.addon_id)
                _LOGGER.error('Something went wrong while calling %s: %s', self.addon_id, exc)

If so there is no exception to log?

Actually I guess you mean here:

 try:
            data = self._get_data_from_addon(self.epg_uri)
            _LOGGER.debug(data)
        except Exception as exc:  # pylint: disable=broad-except
            # _LOGGER.error('Something went wrong while calling %s: %s', self.addon_id, exc)
            raise Exception('Something went wrong while calling %s: %s' % self.addon_id, exc)
            return {}

[michaelarnauts]

Indeed, I meant:

        try:
            data = self._get_data_from_addon(self.epg_uri)
            _LOGGER.debug(data)
        except Exception as exc:  # pylint: disable=broad-except
            raise
            return {}

But I've found out you can also do:

        try:
            data = self._get_data_from_addon(self.epg_uri)
            _LOGGER.debug(data)
        except Exception as exc:  # pylint: disable=broad-except
            _LOGGER.error('Something went wrong while calling %s', self.addon_id, exc_info=1)
            return {}

You shouldn't do string interpolation since that drops the stacktrace from the exception.

[michaelarnauts]

Ooh, I just saw the _LOGGER.debug(data) there inside the try block. Could it be that logging is refusing to log such a large message? Have you tried commenting it out?

[im85288]

Ooh, I just saw the _LOGGER.debug(data) there inside the try block. Could it be that logging is refusing to log such a large message? Have you tried commenting it out?

I have not but that probably only gets called when the Kodi log level is Debug? Mostly I run without that setting

[michaelarnauts]

Ooh, I just saw the _LOGGER.debug(data) there inside the try block. Could it be that logging is refusing to log such a large message? Have you tried commenting it out?

I have not but that probably only gets called when the Kodi log level is Debug? Mostly I run without that setting

It should not cause this issue, but I was just wondering if it could have anything to do with it, but the full stacktrace should tell.

[im85288]

https://paste.kodi.tv/xizotakinu

So a better stack trace:

2020-06-12 14:48:27.914 T:24119   ERROR: EXCEPTION Thrown (PythonToCppException) : -->Python callback/script returned the following error<--
                                             - NOTE: IGNORING THIS CAN LEAD TO MEMORY LEAKS!
                                            Error Type: <type 'exceptions.ValueError'>
                                            Error Contents: Unterminated string starting at: line 1 column 1048459 (char 1048458)
                                            Traceback (most recent call last):
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/default.py", line 9, in <module>
                                                run(sys.argv)
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/resources/lib/functions.py", line 63, in run
                                                function_map.get(function)()
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/resources/lib/functions.py", line 32, in refresh
                                                Addon.refresh(True)
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/resources/lib/modules/addon.py", line 80, in refresh
                                                epg.update(addon.get_epg())
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/resources/lib/modules/addon.py", line 179, in get_epg
                                                data = self._get_data_from_addon(self.epg_uri)
                                              File "/storage/emulated/0/Android/data/org.xbmc.kodi/files/.kodi/addons/service.iptv.manager/resources/lib/modules/addon.py", line 212, in _get_data_from_addon
                                                data = json.loads(result)
                                              File "/home/jenkins/workspace/Android-ARM-Leia/tools/depends/xbmc-depends/arm-linux-androideabi-21-release/lib/python2.7/json/__init__.py", line 339, in loads
                                              File "/home/jenkins/workspace/Android-ARM-Leia/tools/depends/xbmc-depends/arm-linux-androideabi-21-release/lib/python2.7/json/decoder.py", line 364, in decode
                                              File "/home/jenkins/workspace/Android-ARM-Leia/tools/depends/xbmc-depends/arm-linux-androideabi-21-release/lib/python2.7/json/decoder.py", line 380, in raw_decode
                                            ValueError: Unterminated string starting at: line 1 column 1048459 (char 1048458)

[michaelarnauts]

Could you also try to log len(result), I'm wondering how large it is exactly. I think something might be wrong in my while loop in _wait_for_data.

[michaelarnauts]

I've created branch issue-35 with more debugging for this issue.

-> https://github.com/add-ons/service.iptv.manager/tree/issue-35

[im85288]

Cool, will try it now

[michaelarnauts]

If possible, can you try with debugging turned on?

[im85288]

Yes of course, I'll enable it and hopefully the file is not too large to upload to pastebin

[michaelarnauts]

Hmm, maybe you should remove the debug statement _LOGGER.debug(data). It will probably be to large otherwise.

EDIT: I've removed it in the issue-35 branch.

[im85288]

It worked out fine, here is the log: https://paste.kodi.tv/vomuyabuge

[michaelarnauts]

2020-06-12 15:07:19.263 T:26538 WARNING: [service.iptv.manager] [resources.lib.modules.addon] Received a chunk of 4096 bytes...
2020-06-12 15:07:19.591 T:26538 WARNING: Previous line repeats 221 times.
2020-06-12 15:07:19.591 T:26538 WARNING: [service.iptv.manager] [resources.lib.modules.addon] Received a chunk of 4064 bytes...
2020-06-12 15:07:19.593 T:26538 WARNING: [service.iptv.manager] [resources.lib.modules.addon] Received a chunk of 0 bytes...

This seems to be okay, it seems that the addon didn't send all the data. I'm wondering if it's okay that we send the full string in one time in sock.send(json.dumps(func()).encode()). Maybe we need multiple smaller sock.send commands...

[michaelarnauts]

I think I've found it. You should use sock.sendall to send the data. Can you try that?

[michaelarnauts]

Unlike send(), this method continues to send data from string until either all data has been sent or an error occurs.

It's odd that it works fine on other systems.

[im85288]

Yeah very strange, but for sure worth a try. Where should I change the code to try the sock.sendall ?

[michaelarnauts]

It's in the code you've copied from our wiki to your addon, in the via_socket method.

[im85288]

Ahh yeah cool :) Will try that now

[im85288]

Bingo

https://paste.kodi.tv/kedomodowu

That worked like a charm 🥇

[michaelarnauts]

Awesome!

[im85288]

Thanks for your help here, maybe add the sendall as the example on the wiki.

I will close this now. I have some queries about the program stream on kodi 19 but will create a new issue once I test it properly from my side (my addon needs updated!)

Also maybe nice to create a matrix branch for this addon? Initially I could not install it as I needed to change the addon.xml to set python to version 3.0.0

[michaelarnauts]

I went ahead and fixed this in the other IPTV Manager implementations we already have.

Thanks for helping troubleshoot this!

• https://github.com/add-ons/plugin.video.vtm.go/pull/187
• https://github.com/add-ons/plugin.video.viervijfzes/pull/32
• https://github.com/add-ons/plugin.video.yelo/pull/21
• https://github.com/add-ons/plugin.video.regiotv/pull/14
• https://github.com/add-ons/plugin.video.vrt.nu/pull/779
• https://github.com/add-ons/plugin.audio.vrt.radio/pull/20

[michaelarnauts]

Thanks for your help here, maybe add the sendall as the example on the wiki.

I will close this now. I have some queries about the program stream on kodi 19 but will create a new issue once I test it properly from my side (my addon needs updated!)

Also maybe nice to create a matrix branch for this addon? Initially I could not install it as I needed to change the addon.xml to set python to version 3.0.0

I've updated the wiki.

Regarding a matrix branch, I don't want to keep multiple branches up to date since the code supports both Leia and Matrix. The only change needed is indeed the xbmc.python version. We have this automated in the release scripts to create a package for Leia or Matrix, but when running the code from git, you need to change this for Matrix. Once Matrix is officially released, we will probably change the master branch to have 3.0.0.

[michaelarnauts]

@MarcelRoozekrans you probably also want to change this in your Add-on.

[dagwieers]

@im85288 @michaelarnauts Great work! This fixes the issue with the Yelo add-on as well. Or at least I haven't been able to reproduce the problem (yet) :laughing:

[MarcelRoozekrans]

@MarcelRoozekrans you probably also want to change this in your Add-on.

Thnx ! implemented it.