PM4K freeze if movie finishes by playing to 0:00

[liquid-ion]

Description:

PM4K will lock up for several minutes at a time if I let the movie run out the time on its own to 0:00. When the movie finishes, PM4K then tries to load the UI again, but freezes for several minutes, no inputs are accepted during this time.

Details:

• Add-on version: 0.7.9-beta6.2
• Kodi version: 21.1 nightly 0623
• OS Platform: CoreElec
• Hardware: Ugoos Am6b+

Checklist

• [ y] I have included a link to a log (or at the very least a link to a forum post with a log) from a session that had the issue
• [ ] I have added appropriate GitHub labels

[pannal]

Judging from your logs, this doesn't happen every time, right? Or can you reproduce this every time you watch a movie fully and get to the post play screen?

I have a sneaky suspicion on what this might be. It's hard to debug so I'll have to create a build for you that tries some things. Seems like two threads overlap, and no one else has this issue (might be coreelec/Ugoos related).

Also, Kodi complains about not being able to resolve your mounted smb server hostname. I'd fix that first to make sure it's not an issue (use the IP of the server for a quick fix).

[pannal]

To make reproducing this easier (and my theory on why this happens): You should be able to trigger this behaviour if you leave a movie running for at least 5 minutes and then let it play out (you could even seek to a couple of seconds before the end of the movie and let it run til the end).

[pannal]

Try this please: script.plexmod.zip

[liquid-ion]

I can reproduce essentially every time I watch a movie fully

Updated my SMB source to the IP address version and redid the SMB mapping in PM4K. Still get this issue.

[pannal]

With the version I've provided? If so, please attach logs again.

[liquid-ion]

Yes, with the new version. Logs attached 01_KODI.log

[liquid-ion]

Try this log instead:

https://paste.coreelec.org/PatientsHeroic

Starts at:

2024-06-26 09:52:35.040 T:4338 info : CVideoPlayer::OnExit()

[liquid-ion]

I think the issue is on what is called the movie "post-play screen"

When you exit a movie early OR when you exit a TV show early it goes back to the title card page. This is fine.

When a TV show ends to 0:00, it goes to the TV show post-play screen. This is fine.

But when a movie ends to 0:00, it goes to the film post-play screen. This has the delay I experience.

[pannal]

Yeah I know it's to do with the postplay screen, hence the additional logging there. I'd wager the same would happen if you'd disable TV binge mode (or skip post play), with episodes.

Can you open https://192-168-4-21.0ea8e66afe034a52b8064484ae0ea8b6.plex.direct:32400/hubs/metadata/75151/postplay?X-Plex-Token=**** in your browser with the correct plex token (I guess you know how to find that)? How long does that take to answer and how many items does it return?

[pannal]

Also what's your Plex Server setup? What hardware is it running on?

[pannal]

And the same for https://192-168-4-21.0ea8e66afe034a52b8064484ae0ea8b6.plex.direct:32400/library/metadata/75151/similar?count=36&X-Plex-Token=****

[pannal]

The reason I'm asking is because it seems like PM4K waits for the API response for a HUGE amount of time, or the XML parser takes a really long time, which would point to a client and/or hardware/memory/usage issue.

Do you have any other plugins installed in CoreELEC/Kodi?

@bowlingbeeg can you verify that this is happening on your Ugoos as well?

[pannal]

Sorry for the amount of questions: Could you re-do the logs while having Kodi/CoreELEC itself set to DEBUG (together with PM4K on DEBUG)

[liquid-ion]

Also what's your Plex Server setup? What hardware is it running on?

32GB ECC RAM Dual xeons P2000 GPU

Do you have any other plugins installed in CoreELEC/Kodi?

No other plugins on CE. Only PM4K

Will get the answers to your other questions throughout today

[bowlingbeeg]

I do not have this behavior on my Ugoos. Tried a couple of movies and the movie post play screen showed up right away after the movie hit 0:00

[pannal]

Thanks for testing, I suspected that. Something seems wrong with the setup and/or the PMS. It seems like in this case we're simply waiting for the API to answer (I don't know why it wouldn't time out earlier, though).

[liquid-ion]

Attaching the output from both of the links. The "postplay" link takes a while to pull back, and doesn't pull back much. "similar" pulls back a lot more, but runs quickly. postplay.txt similar.txt

[liquid-ion]

I'd wager the same would happen if you'd disable TV binge mode (or skip post play), with episodes.

No, TV post-play screen is fine and loads quickly. I don't use binge mode or skip post-play.

[pannal]

Something hangs when we show postplay on your setup. I've pinpointed the issue down to either the API being slow or anything inbetween, such as throughput, parsing speed, something swapping to disk, or kodi running out of memory.

I'll need the logs with kodi/CE in full debug mode, maybe I can find out more.

If not, we'll have to take a look at the plex server and it's verbose/debug logs at that time.

Edit: you can see it for yourself, I've added two additional debug lines around the call to the postplay API, where the time is lost. At the /similar endpoint as well. Now that could be the API itself, or us parsing the data.

[liquid-ion]

Kodi and PM4K debug both on:

https://paste.coreelec.org/QuickInsects

Not sure if you saw my comment above since it was almost at the same time as your response, no issue on TV post-play screen.

EDIT: Relevant log lines start here: 2024-06-27 13:38:39.283 T:4356 info <general>: Process - eof reading from demuxer

[pannal]

The "postplay" link takes a while to pull back, and doesn't pull back much.

But nothing compared to the time it takes for the UI freeze?

The only two things I can make out from the last log are:

The duplicated "fix your malloc" as well as the unknown error:

2024-06-27 13:38:41.023 T:3942    debug <general>: Alignment of external buffer is not suitable for ffmpeg intrinsics - please fix your malloc
2024-06-27 13:38:41.024 T:3942     info <general>: Skipped 1 duplicate messages..
2024-06-27 13:38:41.024 T:3942    debug <general>: Error [-541478725] while reading frame: Unknown error 541478725
2024-06-27 13:39:09.657 T:3942    debug <general>: SECTION:UnloadDelayed(DLL: libamcodec.so)
2024-06-27 13:39:10.282 T:4113    debug <general>: Thread JobWorker 3409162752 terminating (autodelete)
2024-06-27 13:39:10.308 T:4002    debug <general>: Thread JobWorker 3679420928 terminating (autodelete)
2024-06-27 13:39:10.317 T:3988    debug <general>: Thread JobWorker 3748655616 terminating (autodelete)
2024-06-27 13:39:10.320 T:4060    debug <general>: Thread JobWorker 3545227776 terminating (autodelete)

and "Samba is idle":

2024-06-27 13:40:04.045 T:3942    debug <general>: ------ Window Deinit (/storage/.kodi/addons/script.plexmod/resources/skins/Main/1080i/script-plex-busy.xml) ------
2024-06-27 13:40:13.152 T:3942     info <general>: Samba is idle. Closing the remaining connections

Not much else to see here. Did you adjust the worker count in PM4K's external addon settings to something different than 3?

I also can see:

<samba>
 <clienttimeout>30</clienttimeout>
</samba>

In your advancedsettings - does removing that change anything, or moving from path mapping to HTTP?

Edit: Also, was this always the case, or can you roughly point to a version of PM4K where you remember this not happening? If so, could you revert to that one and test it again?

[pannal]

Here's another build with a debug log entry right after an API response has been received (might be spammy), so we can pinpoint the issue further (no version change): script.plexmod.zip

[liquid-ion]

01_KODI.log Used this build and captured 2x logs.

First is successful post-play screen load from TV section. Believe the logs are here:

2024-06-28 17:44:59.088 T:9926 info : Process - eof reading from demuxer

The 2nd is unsuccessful post-play screen from movie section. Starts here:

2024-06-28 11:55:30.858 T:4167 info : Process - eof reading from demuxer

[pannal]

Hmm, that logging step didn't work out. Please try: script.plexmod.zip

One thing that's interesting is that you seem to have the "Time-to-wait between videos on post-play" in addonSettings set to two hours. Can you try setting that to the default? Also, separately, could you disable post play auto play for your particular user (inside PM4Ks settings)?

Thanks!

[liquid-ion]

"Time-to-wait between videos on post-play" in addonSettings set to two hours

I looked, it is set to 16. That's what shows up in the menu.

Will try disabling post play.

[pannal]

Post play auto play, not post play in general.

I looked, it is set to 16. That's what shows up in the menu.

Interesting.

Edit: No I mixed up the passout protection with "Time-to-wait between videos on post-play", never mind.

[liquid-ion]

This is fixed by upgrading to latest Plex version.

[pannal]

What? Plex Media Server or PM4K?

[liquid-ion]

Updated PMS to latest public release. Before was 1-2 releases behind.

[pannal]

Oh OK, nice.