7.0.6.x do not correctly set watched status

pezz commented 2 months ago

Context

Please provide any relevant information about your setup

Add-on Version: 7.0.6.1 .2 and .3 all do this, 7.0.5 doesn't
Kodi Version: 21.0
Kodi GUI Language: English
Operating System: Arch Linux
Operating System Language: en_AU / en_US

Expected Behavior

After watching a video it should be set to watched.

Current Behavior

After watching a video it is not set to watched / have the tick.

Steps to Reproduce

Please provide detailed steps for reproducing the issue.

Watch a video.
It's still set as unviewed after it's finished.

Log

Please include a complete debug log.

Would a log help here? It's easily observed behaviour.

Happy to provide if so.

Additional Information

Only using local playback history, not updating YouTube.

MoojMidge commented 2 months ago

Works fine for me and I have seen logs from other people showing that is working fine for them as well.

Will need a debug log to see why it doesn't seem to work for you

pezz commented 2 months ago

Ok cool, I'll get some more info tomorrow.

Fludizz commented 2 months ago

I have noticed a similar issue. Not consistently though. Most of the times it works OK but only in some cases it doesn't mark a video as watched. I only seem to notice it in the following situations:

Play a video, stop it at some point. Resume watching it later.
Without ever opening the Youtube plugin, send a video to play from some tool like "Yatsee".

In both cases, when it finishes playing the video, it may or may not be marked as watched.

Notable detail: If it is not marked as watched after playing, using the "w" keyboard shortcut to mark it watched does not work. It can only be marked as watched from the context menu in these cases. It's only been a minor inconvenience for me.

I'll see if I can reproduce and generate debug logs later today.

Fludizz commented 2 months ago

I had one instance again. Had a video that stalled and stopped playing and resumed watching a few minutes later. It did not get marked as watched. However, I was able to mark it as watched with the 'w' key this time. kodi.log Hope this debug log helps!

MoojMidge commented 2 months ago

Hope this debug log helps!

@Fludizz - yes it does, thanks. Even without the log, the description of what you are doing (resuming, using w key, etc.) and what you observed (w sometimes does nothing, but does work from context menu) provides enough detail to understand the problem.

However your issue may be different to the OP's, as the original provided details are less clear and seem to indicate a more general issue. @pezz - can you clarify a bit more?

TLDR: Try enabling `Settings > Advanced > Mark as watched > Refresh after watching`, or try the next beta release and see if there is any change.

> Notable detail: If it is not marked as watched after playing, using the "w" keyboard shortcut to mark it watched does not work. It can only be marked as watched from the context menu in these cases. It's only been a minor inconvenience for me. > It did not get marked as watched. However, I was able to mark it as watched with the 'w' key this time. What you are describing here, and what is shown in your log, is actually a race condition where Kodi is updating the display of the video listing independently of the plugin. Kodi does this a lot faster than the plugin does, which means that the plugin information will override what Kodi thinks the watched status is, because the plugin update happens before playback starts, and after playback ends after Kodi has already updated its details. If the plugin has identified that there is resume information for the video it will update the video to display this. In the Kodi GUI, the resume information icon will override the (un)watched state icon. When you press the `w` key, that only toggles the internal Kodi watched state and clears the internal resume information, but does not do anything to the plugin resume information. What this means is that if the plugin has recorded that a video has resume information then the `w` key is not going to appear to do anything. If the `w` key appears to work, then that means that the plugin has either not recorded any resume information, or has correctly cleared the resume information because it thinks the video has been watched. If the `w` appears to work after playback, then that means that the plugin has also successfully marked the video as watched, it just hasn't refreshed the display to show this, and is instead showing the resume information from before the playback started. There is a setting in the plugin to force the plugin to refresh the display to workaround this problem `Settings > Advanced > Mark as watched > Refresh after watching` If the `w` doesn't appear to work after playback, even after re-opening the video list, then that means that the plugin is showing old resume information, from before the playback started, and that the last playback did not correctly update that information. Looking at the code there are a few reasons why this may occur, predominantly associated with skipping/seeking to the end of the video, which are difficult to resolve due to the timing of the playback monitoring. As a workaround I may instead remove old resume information when playback starts. In the event that new resume information is correctly recorded then everything will still update correctly, but if no new resume information is recorded then at least the Kodi internal state will be shown. Note that the `w` key is not going to do anything with regards to the plugin watched state i.e. it won't update the YouTube watched status or the local plugin watched status, only what is (sometimes) shown in Kodi.

pezz commented 2 months ago

Apologies, I was going to provide a debug log but there's a lot of information in it that I don't want shared (info about library, searches etc).

Nothing gets marked as watched at all for me (automatically)
If I stop a video early it does not remember the playback state (e.g. no resume from time x)
I don't use the w key as I drive Kodi with a remote control in most cases, but using the info menu and manually setting watched does work
Videos that have been previously marked as watched or partially watched still display as such and will resume and the remembered position

MoojMidge commented 2 months ago

@pezz - without a log can't do much. There is nothing specific to v7.0.6 that could cause this as far as I can see.

Are you skipping/seeking or using something like SponsorBlock?

FWIW I don't need a full log, just the section from when you start playback to when it stops. You should see something like this in the log, need everything in the middle and inclusive of these lines:

2024-05-07 09:45:04.359 T:12172    debug <general>: [plugin.video.youtube] PlayerMonitorThread[<VIDEO_ID>]: Starting
2024-05-07 09:45:04.359 T:12172    debug <general>: [plugin.video.youtube] send_notification: |PlaybackStarted| -> |{'video_id': '<VIDEO_ID>', 'channel_id': '<CHANNEL_ID>', 'status': {'unlisted': False, 'private': False, 'crawlable': True, 'family_safe': False, 'live': False}}|
2024-05-07 09:45:04.460 T:10084    debug <general>: [plugin.video.youtube] onNotification: |unhandled method| -> |Other.PlaybackStarted|

...

2024-05-07 09:45:14.371 T:10084    debug <general>: [plugin.video.youtube] onNotification: |unhandled method| -> |Other.PlaybackStopped|

pezz commented 2 months ago

Not sure what SponsorBlock is, so no, I'm not using it.

It doesn't matter if I seek or leave the playback alone, it never sets watched status.

Also, I tried "refresh after playback" as well and it made no difference.

Here's a log, I included some of the lines after the stopped event in case they're relevant. https://gist.github.com/pezz/fe4b9fc1cec31241b33e68d2624a4dbc

MoojMidge commented 2 months ago

In that log you opened then immediately stopped the video. Is the expectation that this should mark the video as watched? Did it do this before? It should not have.

Can you get a log of where you play a video to the end and it doesn't get set as watched? Can skip to a few seconds before the end, then allow the video to play to the end.

pezz commented 2 months ago

In that log I started a single video and let it play to the end (there's only one start and stop section).

I'll do it again.

pezz commented 2 months ago

This looks pretty wrong I guess? It seems I start a video and it immediately notifies that it has ended?

Here I started playing one video, let it play for a bit (much more than a second), stopped it, then started a second video.


% grep PlayerMonitorThread kodi.log
2024-05-07 15:06:32.692 T:11681   debug <general>: [plugin.video.youtube] PlayerMonitorThread[CjE2biiE3Ro]: Starting
2024-05-07 15:06:32.693 T:11681   debug <general>: [plugin.video.youtube] PlayerMonitorThread[CjE2biiE3Ro]: Stop event set
2024-05-07 15:06:32.724 T:11681   debug <general>: [plugin.video.youtube] PlayerMonitorThread[CjE2biiE3Ro]: End event set
2024-05-07 15:07:19.748 T:11644   debug <general>: [plugin.video.youtube] PlayerMonitorThread[CjE2biiE3Ro]: clean up
2024-05-07 15:07:27.478 T:11738   debug <general>: [plugin.video.youtube] PlayerMonitorThread[4KRom9XnFa4]: Starting
2024-05-07 15:07:27.479 T:11738   debug <general>: [plugin.video.youtube] PlayerMonitorThread[4KRom9XnFa4]: Stop event set
2024-05-07 15:07:27.513 T:11738   debug <general>: [plugin.video.youtube] PlayerMonitorThread[4KRom9XnFa4]: End event set```

MoojMidge commented 2 months ago

Yep, not what should happen at all. I cannot replicate or even explain why it would happen.

Can you grep for [plugin.video.youtube] instead of PlayerMonitorThread? Too much stuff missing to understand what is happening.

pezz commented 2 months ago

I grepped out a few things, my grep is at the top. Hope it helps.

https://gist.github.com/pezz/31510d0eac0a5f05ba34e8942fd82cbf

P.S. This was a new run and I only played a single video.

MoojMidge commented 2 months ago

Two more things:

Add some extra logging to https://github.com/anxdpanic/plugin.video.youtube/blob/a820606d29df4237d11c98be10ac65707f249afa/resources/lib/youtube_plugin/kodion/monitors/player_monitor.py#L105-L112 Change it to:

    while not self.abort_now():
        self._context.log_debug(f'{playing_file = }')  # Extra logging
        try:
            current_file = player.getPlayingFile()
            self.current_time = player.getTime()
            self.total_time = player.getTotalTime()
        except RuntimeError:
            self.stop()
            break
        self._context.log_debug(f'{current_file = }')  # Extra logging

Get the output of the log:

grep '\[plugin.video.youtube\]|EXCEPTION' kodi.log | grep -v Converting | grep -v googlevideo | grep -v youtube.api

pezz commented 2 months ago

Pretty sure I've done this right, there's two huge googlevideo URLs, not sure if they contain my API info or not, but this is what that extra code seems to produce, if there's an arg in there that you want let me know.

% grep '\[plugin.video.youtube\]' kodi.log | grep -i _file                                                                 
2024-05-07 19:12:17.258 T:30112   debug <general>: [plugin.video.youtube] playing_file = 'https://<googlevideo>
2024-05-07 19:12:17.258 T:30112   debug <general>: [plugin.video.youtube] current_file = 'https://<googlevideo>

MoojMidge commented 2 months ago

Unfortunately there is not much point in adding the extra logging if you aren't willing to share it.

Anyway I have worked around what I think the problem may be, and it should be fixed in the next beta.

If you are still having problems with the next beta release then you can provide an update, but without at least a complete section of the log I won't be willing to investigate further to determine the underlying root cause. Too much guess work with just the bits and pieces of the logs provided.

pezz commented 2 months ago

Yeah fair enough. If there was part of the URL that you were interested in I would've provided it. I'm just wary of what info is encoded in the entire thing.

Will close this and stop the noise.

Cheers.

MoojMidge commented 2 months ago

I can understand the need to avoid sharing PII, but it means that you will need to deal with some friction at times.

Like I said the next beta should avoid the problem, even if the root cause is not addressed: https://github.com/anxdpanic/plugin.video.youtube/pull/740

MoojMidge commented 2 months ago

@pezz - https://github.com/anxdpanic/plugin.video.youtube/releases/tag/v7.0.7%2Bbeta.1 is available. Can see if it fixes this issue.

@Fludizz - this beta release should also improve the issue you identified, but they won't be properly fixed until the next beta.

pezz commented 2 months ago

@MoojMidge This is much better, I need to test with a few more videos / give it more tries, as I think it's a bit hit-and-miss as sometimes it's not setting the status properly at the end of some vids, but I need to do much more testing.

Saving the played position when stopping a video part of the way through is also working.

Kodi not exiting properly is still an issue on this version too.

Also, I've noticed occasionally I get a notification from the addon that says something like "Error 98: port already in use" or similar.

MoojMidge commented 2 months ago

Also, I've noticed occasionally I get a notification from the addon that says something like "Error 98: port already in use" or similar.

You could have saved me a lot of time by letting me know this earlier - it is the root cause of your entire issue. This is why logs are important. Tried to make some changes that may fix this in the next beta.

Kodi not exiting properly is still an issue on this version too.

Can you clarify? You previously indicated the following:

I noticed this as well with 7.0.5 after recent upgrades. None of the 7.0.6.x versions do this on my system.

Is it actually the other way around? Kodi was exiting properly using Arch and Python v3.12 with v7.0.5 of this plugin, but not in any more recent version?

I think it's a bit hit-and-miss as sometimes it's not setting the status properly at the end of some vids, but I need to do much more testing.

I am not aware of anything other than seeking/skipping that can cause the Kodi video player to not properly identify the video progress, and that should now be resolved (if not in the current beta, then in the next beta). If you identify any other scenario where the watched status doesn't update, let me know.

Fludizz commented 2 months ago

@Fludizz - this beta release should also improve the issue you identified, but they won't be properly fixed until the next beta.

I've again had some instances where it didn't mark a video as watched. Having the refresh option toggled like you suggested didn't make a difference unfortunately. Will try to get a debug log.

MoojMidge commented 2 months ago

I've again had some instances where it didn't mark a video as watched.

This was with normal playback? Not seeking or skipping to the end?

Having the refresh option toggled like you suggested didn't make a difference unfortunately.

This will only help if the correct resume/watched information was saved but just not displayed in time. What does the w key do, when you see a video not being marked as watched now?

Will try to get a debug log.

That will really help, thanks.

Fludizz commented 2 months ago

It was a video I stopped and watched later with "Resume from " - after that it again did not let me mark it as watched with w and had to use the context menu.

I frequently seek through video's (to skip the sponsored segments) and that does not appear to trigger the issue.

I've tried to force the issue but it hasn't happend again yet. But then again, it already didn't happen a lot to begin with.

MoojMidge commented 2 months ago

Just to confirm this is with v7.0.7+beta.1? See if there is any difference with v7.0.7+beta.2

Fludizz commented 2 months ago

Yes, this was after updating to 7.0.7+beta.1 I have updated i to 7.0.7+beta.2 now and will report back if I can reproduce.

Fludizz commented 2 months ago

I have not seen any occurrences since updating to beta.2 - It seems resolved. Thanks @MoojMidge :)

MoojMidge commented 2 months ago

Thanks for confirming

anxdpanic / plugin.video.youtube