Kodi crashes when quickly running plugin:// URLs in succession

[TASSDevon]

Additional context

• Operating system: OSMC on rpi3
• Kodi version: 18.7
• Addon version: latest
• Using a VPN: no
• Country you are using the addon from: Belgium

In the mornings I have Kodi play the latest Journaal episode. About 1 in 5 or 6 times, OSMC locks up with the loading animation. I can still ssh into the rpi3 and everything except kodi is responsive. Rebooting usually locks up, I have to power cycle.

I've never had this issue with starting any other episode or show so I'm now, after months, suspecting it might be addon related?

Log (if available)

2020-06-29 07:13:28.338 T:1333785312 WARNING: CSettingsManager: unable to read value of setting "max_log_level"
2020-06-29 07:13:28.339 T:1333785312 WARNING: CAddonSettings[plugin.video.vrt.nu]: failed to load value "Info" for setting max_log_level
2020-06-29 07:13:28.755 T:1333785312 WARNING: CSettingsManager: unable to read value of setting "max_log_level"
2020-06-29 07:13:28.756 T:1333785312 WARNING: CAddonSettings[plugin.video.vrt.nu]: failed to load value "Info" for setting max_log_level
2020-06-29 07:13:31.110 T:1333785312   ERROR: EXCEPTION: Invalid setting type
2020-06-29 07:13:31.389 T:1915328048   ERROR: Previous line repeats 1 times.
2020-06-29 07:13:31.389 T:1915328048  NOTICE: VideoPlayer::OpenFile: plugin://plugin.video.vrt.nu/play/latest/het-journaal
2020-06-29 07:13:31.411 T:1316999904  NOTICE: Creating InputStream
2020-06-29 07:13:33.155 T:1316999904  NOTICE: Creating Demuxer
2020-06-29 07:13:33.195 T:1316999904  NOTICE: Opening stream: 1001 source: 256
2020-06-29 07:13:33.269 T:1316999904  NOTICE: Creating video codec with codec id: 27

[dagwieers]

Can you confirm that the version you are using is actually v2.3.5?
Would it be possible to enable Debug logging right before you expect this to happen?

This pretty much feels like an OSMC/Kodi issue, but if we are triggering it, it would be nice to know how. And either fix it upstream or work around it in our add-on.

I tried to reproduce this by running:

$ kodi-send -a 'PlayMedia(plugin://plugin.video.vrt.nu/play/latest/het-journaal)'

But I cannot reproduce this (yet) myself on an RPi3 using LibreELEC v9.2.3.

[TASSDevon]

Can you confirm that the version you are using is actually v2.3.5?

Yes, I am using 2.3.5

The lockup happens when my Home Assistant instance sends an RPC/API call to Kodi to start the latest Journaal episode. Weird thing is, when this happens and I ssh into the rpi3, I kill the kodi process, the screen turns black and when I issue a reboot, it still hangs during shutdown. I still have to power cycle the rpi3 to get it back up.

I will enable debug logging as this morning it happened again. Shouldn't take too long to hopefully get some useful debug logs.

I've never had this locking up behavior when starting a TV show or movie that's on an attached external HDD.
Once I've had the rpi3 lock up when issuing two calls to start VIER through Yelo addon quickly after one another (accidentally pressed the button twice in my UI).

[TASSDevon]

Funny thing I mention the crash when clicking twice, I can trigger it with the VRTNU plugin as well.
I had debug logging turned on, I will send you the logs through Facebook messenger as I don't want them out in the public :-)

As for the Journal crash, I tried triggering it before the double click crash but so far it kept working. I will try to get some logging asap.

[dagwieers]

I don't see anything obvious from the debug log. I tried again reproducing this on my RPi3/LibreELEC v9.2.3 using:

$ curl -n -X POST -H "content-type:application/json" http://kodi01/jsonrpc -d '{"jsonrpc": "2.0", "method": "Player.Open", "params": {"item": {"file": "plugin://plugin.video.vrt.nu/play/latest/het-journaal" }}, "id": 1}'

And all goes well if I run the commands with some delay, but if I run them very quickly in succession, my Kodi crashes and restarts.
Not completely the same symptoms, but still worrying.

Is it possible that your automated solution may run your remote command twice in quick succession some of the times?
I think I can see this from your debug log too:

...
2020-06-30 20:58:31.415 T:1915463216   DEBUG: StartScript - calling plugin VRT NU('plugin://plugin.video.vrt.nu/play/latest/het-journaal','12','','resume:true')
...
2020-06-30 20:58:31.737 T:1915463216   DEBUG: StartScript - calling plugin VRT NU('plugin://plugin.video.vrt.nu/play/latest/het-journaal','13','','resume:true')
...

Update: I think it appears to be hanging is because it is dumping core. I expect if you wait long enough Kodi will restart by itself. That is what happens on my system. Possibly your system is unable to dump its core and has some sort of resource starvation going on. You may want to troubleshoot this in detail and report this to OSMC if you find anything suspicious.

[dagwieers]

I can reproduce this issue with the VTM GO add-on as well.

$ curl -n -X POST -H "content-type:application/json" http://kodi01/jsonrpc -d '{"jsonrpc": "2.0", "method": "Player.Open", "params": {"item": {"file": "plugin://plugin.video.vtm.go/play/catalog/episodes/8c9f46ce-b835-4dfb-835a-f332c12cfc57" }}, "id": 1}'

But I cannot reproduce it with a direct stream (e.g. HLS or MP3 stream) only with plugin://-type URLs.

cc @michaelarnauts

[dagwieers]

I can also reproduce this using the Netflix add-on. cc @CastagnaIT

And the URL does not even have to be real:

$ curl -n -X POST -H "content-type:application/json" http://kodi01/jsonrpc -d '{"jsonrpc": "2.0", "method": "Player.Open", "params": {"item": {"file": "plugin://plugin.video.netflix/foo/bar" }}, "id": 1}'

[dagwieers]

Since it is easily reproduced with any add-on I reported it upstream at: xbmc/xbmc#18122

[mediaminister]

I guess this is related to concurrent busy dialogs in Kodi(what should be fixed in xbmc/xbmc#18104).
Calling xbmcplugin.endOfDirectory and a short xbmc.sleep in the play function of the VRT NU add-on may avoid concurrent busy dialogs.

[TASSDevon]

FWIW: the 2 times quickly starting results in a OSMC reboot (the blue screen with a sad face). The lockup issue I described results in the loading N animation of OSMC freezing mid-animation, they are two separate issues. Perhaps we should split this issue.

[dagwieers]

@TASSDevon I suspect both to have the same cause but different behaviour based on timing. I would wait for a fix from Kodi and re-evaluate when it is discussed/reviewed upstream.

[mediaminister]

Maybe this helps: #791
Test package: plugin.video.vrt.nu-2.3.5-play-4a422b1.zip