Upnext doesn't play the next episode, or can cause Kodi to crash

[michaelarnauts]

Describe the bug
I've noticed a few times already that Kodi crashes when the next episode should play with Up Next. It doesn't happen every time, so I think there's a race condition where we ask to play the next episode while the player is shutting down. I can't seem to find a log related to this, probably since Kodi crashed before it could write the log or something.

Maybe the playlist approach that VRT NU uses is a better way to start the next episode.

@dagwieers what do you think? Have you also noticed this behavior?

To Reproduce
Steps to reproduce the behavior:

1. Play something on VTM GO untill the end
2. When the next item should play, Kodi sometimes crashes

System

• Addon version: 1.1.4
• Kodi version: 18.8
• Inputstream adaptive version: latest
• Operating System: (Windows / Mac OS / Android / LibreElec / OSMC / ...) OSMC
• Special Hardware: (RPI / Vero4K+ / ...) Vero4k+

Additional context
Add any other context about the problem here.

[michaelarnauts]

kodi.log:

...
2020-10-11 12:34:43.588 T:140316486850304  NOTICE: [plugin.video.vtm.go] [vtmgo] Sending GET /vtmgo/programs/331d84b9-ac03-4c37-903f-e926fe55a3bb...
2020-10-11 12:34:43.591 T:140316486850304  NOTICE: [plugin.video.vtm.go] [urllib3.connectionpool] Starting new HTTPS connection (1): api.vtmgo.be:443
2020-10-11 12:34:43.634 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: loading setting definitions
2020-10-11 12:34:43.634 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: trying to load setting definitions from old format...
2020-10-11 12:34:43.635 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: loading setting values
2020-10-11 12:34:43.635 T:140315818186496   DEBUG: JSONRPC: Incoming request: {"jsonrpc": "2.0", "params": {"setting": "debug.showloginfo"}, "method": "Settings.GetSettingValue", "id": 0}
2020-10-11 12:34:43.635 T:140315818186496  NOTICE: [service.upnext] PlaybackManager -> playing media episode
2020-10-11 12:34:43.636 T:140315818186496   DEBUG: JSONRPC: Incoming request: {"jsonrpc": "2.0", "params": {"message": "NEXTUPWATCHEDSIGNAL", "data": ["eyJlcGlzb2RlaWQiOiAiMjU0MGIxYzQtY2RiNC00OGQ4LTllMjAtMGVhMWUzMTVlOWI5In0="], "sender": "service.upnext.SIGNAL"}, "method": "JSONRPC.NotifyAll", "id": 0}
2020-10-11 12:34:43.636 T:140318675826432   DEBUG: CAnnouncementManager - Announcement: NEXTUPWATCHEDSIGNAL from service.upnext.SIGNAL
2020-10-11 12:34:43.636 T:140318675826432   DEBUG: GOT ANNOUNCEMENT, type: 512, from service.upnext.SIGNAL, message NEXTUPWATCHEDSIGNAL
2020-10-11 12:34:43.636 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: loading setting definitions
2020-10-11 12:34:43.636 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: trying to load setting definitions from old format...
2020-10-11 12:34:43.636 T:140315818186496   DEBUG: CAddonSettings[service.upnext]: loading setting values
2020-10-11 12:34:43.637 T:140315818186496   DEBUG: JSONRPC: Incoming request: {"jsonrpc": "2.0", "params": {"setting": "debug.showloginfo"}, "method": "Settings.GetSettingValue", "id": 0}
2020-10-11 12:34:43.637 T:140315818186496  NOTICE: [service.upnext] Api -> Playing the next episode directly: plugin://plugin.video.vtm.go/play/catalog/episodes/805dd1a2-4e25-4e57-b65f-c202a98bc9d4
2020-10-11 12:34:43.637 T:140315818186496   DEBUG: JSONRPC: Incoming request: {"jsonrpc": "2.0", "params": {"item": {"file": "plugin://plugin.video.vtm.go/play/catalog/episodes/805dd1a2-4e25-4e57-b65f-c202a98bc9d4"}}, "method": "Player.Open", "id": 0}
2020-10-11 12:34:43.649 T:140318675839680   DEBUG: StartScript - calling plugin VTM GO('plugin://plugin.video.vtm.go/play/catalog/episodes/805dd1a2-4e25-4e57-b65f-c202a98bc9d4','5','','resume:true')
2020-10-11 12:34:43.649 T:140315323250432   DEBUG: Thread LanguageInvoker start, auto delete: false
2020-10-11 12:34:43.649 T:140315323250432    INFO: initializing python engine.
2020-10-11 12:34:43.649 T:140315323250432   DEBUG: CPythonInvoker(22, /home/michael/.kodi/addons/plugin.video.vtm.go/plugin.py): start processing
2020-10-11 12:34:43.669 T:140315805599488   DEBUG: Thread scriptobs start, auto delete: false

Kodi stacktrace:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f9e81575859 in __GI_abort () at abort.c:79
#2  0x00007f9e810a4951 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007f9e810b047c in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00007f9e810b04e7 in std::terminate() () from /lib/x86_64-linux-gnu/libstdc++.so.6
#5  0x00007f9e810b0799 in __cxa_throw () from /lib/x86_64-linux-gnu/libstdc++.so.6
#6  0x000055be5fc3ab44 in ?? ()
#7  0x000055be5fe85a16 in XFILE::CPluginDirectory::WaitOnScriptResult(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool) ()
#8  0x000055be5fe88bf7 in XFILE::CPluginDirectory::StartScript(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool, bool) ()
#9  0x000055be5fe93111 in XFILE::CPluginDirectory::GetPluginResult(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItem&, bool) ()
#10 0x000055be602a4512 in PLAYLIST::CPlayListPlayer::OnApplicationMessage(KODI::MESSAGING::ThreadMessage*) ()
#11 0x000055be60564efa in KODI::MESSAGING::CApplicationMessenger::ProcessMessage(KODI::MESSAGING::ThreadMessage*) ()
#12 0x000055be6056aec9 in KODI::MESSAGING::CApplicationMessenger::ProcessMessages() ()
#13 0x000055be60300e91 in CApplication::Process() ()
#14 0x000055be60475d2d in CGUIWindowManager::ProcessRenderLoop(bool) ()
#15 0x000055be60462c6f in CGUIDialogBusy::WaitOnEvent(CEvent&, unsigned int, bool) ()
#16 0x000055be60462e67 in CGUIDialogBusy::Wait(IRunnable*, unsigned int, bool) ()
#17 0x000055be606918e3 in CGUIMediaWindow::GetDirectoryItems(CURL&, CFileItemList&, bool) ()
#18 0x000055be606991b6 in CGUIMediaWindow::GetDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItemList&) ()
#19 0x000055be607701d2 in CGUIWindowVideoBase::GetDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItemList&) ()
#20 0x000055be6077ba9c in CGUIWindowVideoNav::GetDirectory(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CFileItemList&) ()
#21 0x000055be6069ad79 in CGUIMediaWindow::Update(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool) ()
#22 0x000055be6076b9ef in CGUIWindowVideoNav::Update(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, bool) ()
#23 0x000055be6068d9fa in CGUIMediaWindow::Refresh(bool) ()
#24 0x000055be606a7f3f in CGUIMediaWindow::OnMessage(CGUIMessage&) ()
#25 0x000055be60792bf1 in CGUIWindowVideoBase::OnMessage(CGUIMessage&) ()
#26 0x000055be6077d5f8 in CGUIWindowVideoNav::OnMessage(CGUIMessage&) ()
#27 0x000055be60485df3 in CGUIWindowManager::DispatchThreadMessages() ()
#28 0x000055be60300d17 in CApplication::Process() ()
#29 0x000055be6026bdef in CXBApplicationEx::Run(CAppParamParser const&) ()
#30 0x000055be6058ebc0 in XBMC_Run ()
#31 0x000055be5fd9eaa6 in main ()

[michaelarnauts]

I think I've found another issue here. I've only managed to crash Kodi once (stacktrace above), but the other times, it actually doesn't start the next episode.

When testing, I play an episode and click at about a minute before the end. Then, at about 30 seconds before the end, the popup appears, and when the UpNext dialog has still a few seconds left, the stream already ends (I assume this could be related to a bug with the Periods handling, where the full stream length isn't correctly calculated or something). In the log, I can see the message exit launch_popup early due to disabled tracking.

Is it possible that UpNext thinks I've stopped the stream myself, and doesn't play the next episode?

[michaelarnauts]

Okay, this last issue seems to be fixed in the latest master branch of service.upnext. I'll need to do some further testing.

@dagwieers is it possible to do a release of service.upnext with this fix?

[dagwieers]

This may explain I haven't seen crashes for a long time now. We can do a new release, but I am not sure if the master branch had sufficient testing. (I am running a PR myself)

[michaelarnauts]

Looking at the changes really quick, it seems that this PR fixes it: im85288/service.upnext#198 (it's actually the only code-change since the latest release besides CI and translations).

I can keep on running the master branch for a while, but we might want to have some more testing. I'll also do some more testing now.

[michaelarnauts]

I'm mainly testing the playback of the next episode automatically (without selecting an option). This seems to work reliable now after testing 5 episodes.

[michaelarnauts]

It seems that when playing an episode, somehow, it starts playing at -00:02 seconds, therefore, not triggering upnext correctly at the end. By putting it in a playlist, it will be picked up by Kodi automatically.

[michaelarnauts]

This will be fixed with a 1.1.3 release of UpNext and this PR: #220

See im85288/service.upnext#217

[michaelarnauts]

Fixed in latest UpNext