Item Activity not recording correct info
Closed this issue · 23 comments
Describe the bug
Was watching 2 episodes, letting Jellyfin auto start the 2nd episode. I checked JellyStat while each episode was playing and it did show the sessions. After the 2nd episode ended, I checked the stats and only 1 Play was recorded for the entire show.
Environment Details (please complete the following information):
- OS: cyfershepard/jellystat:unstable
- AndroidTV - (Could test this in web if you want)
- Jellystat Version : 10.8.13
- Jellyfin Version : 1.1.0
To Reproduce
Steps to reproduce the behavior:
Take and TVShow where there are 2 episodes not watched, start 1st episode and leave the system to play both episodes back-to-back
Expected behavior
Recording both views in the stats with the correct times
Screenshots
Playback Reporting :
JellyStat:
Additional context
As you can see even the time on JellyStat is only showing 1min 18sec and the time stamp is the same time as the ending of e02.
I watched a single episode of another show and that recorded correctly (even though the playtime is incorrect).
Playback Reporting:
JellyStat:
Hey @ShakeSp33r , thanks for the additional info and testing, This happened to me once but I was never able to replicate it and just brushed it off as some weirdness in the dev build I was running. Will look back into this again, could have been reintroduced in the last fix I did
@CyferShepard
If you need me to test something specific let me know
Played the same file on Jellyfin Web & Android TV (0.16.8).
Actual media info:
JellyStat Activity Log:
Latest Unstable only show 1 record in watchdog even though same user watching 2 shows
I pushed another change now, think it may be because its the same user theres some overlap with the session id on jellyfins side, so i added a filter now for per DeviceId. It should be built in the next 10 minutes and ready to pull
I now see the 2 sessions for the same user, however I think there is something going on the the insert of the watchdog.
Steps followed:
- Starting the 1st session, everything is good and the session gets added to the watchdog table.
- Starting the 2nd session, no new record gets added to the watchdog table.
- Restart docker while both sessions are playing, the record in the watchdog table gets deleted, and both sessions added into watchdog table.
- Stop any session and the corresponding record gets deleted fro the watchdog, no record gets added to the playback activity table for the session that was stopped.
Cool that helps me replicate this so il be able to make a fix without working blindly at least
okay so that should be fixed in the newest build, let me know if it works for you
After a quick test, it No 1 through 4 is now working. Thank You
The only thing I noticed was that if the same user on the same device start the save video again, and then stop it later, instead of creating a new activity record, it just add the time to the existing record. I'm not saying this is wrong, it might even be better, might even add a setting where the user could decide if it should be added or new record.
So thats a new feature thats been added. How it works is, if there's an existing watch record within the last hour for that item per user and device, if its total watch time is less than 80% and the new watch time added to it is less then 100% it just adds it onto the existing record. Else it creates a new one. This was because many people myself included would watch something and stop and come back like 20 minutes later to continue. So instead of having multiple watches for the same item it just tracks it on existing records.
I was making dinner and started a movie. I paused the movie to go to the kitchen a few times and somehow that movie now has 4 plays :) (This was before the update) Hopefully the new update fixes this.
@kman3107 are you on v 1.0.9 or 1.1.0?
@CyferShepard I'm on v 1.0.9
I am running this on an unraid server with a community app by campu0999 from your docker image.
Okay cool, then yea once im done with these last few bugs these fixes will come to the stable branch and to the community app too
Latest unstable working.
I think I'm experiencing the original bug (auto-played items not being recorded by Jellystat). I don't want to make a new bug report as it seems to be the same as this; however I seem to have the added wrinkle where the playback time elapsed isn't correct on Jellystat either.
Setup details: Jellystat:latest (1.1.0); Jellyfin 10.9.7; playback via Kodi. No weirdness with transcoding or anything, just direct playback
Looking at the logs the weirdness seems to have started around the 23rd, though I'm not sure if that's when I just started letting auto-play run the next episode or not.
Been binging BSG; and on the 23rd I finished watching S2E7 at ~11pm; Jellystat properly records this. The next item from Jellystat is on the 25th where I watched ~7m of S2E11, followed by 2m of S2E12. Jellyfin properly records S8-S11 on the 24th (Jellystat shows nothing on the 24th). Similar shenanigans for subsequent viewings where JF shows ~45m each episode individually and JS shows craziness (ex 1 second of S2E15 as the only thing on the 26th, then jumping to the special movie Razor on the 27th, when it should be 15,16,17 on the 26th, ->Razor on the 27th)
The longer-than-they-should-be times (eg S2E19) are because I paused (not stopped) in the middle for phone calls, however JF doesn't seem to mark it as such (it shows the whole time as one segment); so I'm not sure if that's due to playing via Kodi or just "how it is" now.
The full JF activity log available through the web interface isn't very useful as it truncates the columns to the point of being unusable.
Adding a bit more info; watched some more last night and made sure to not allow it to auto-play the next episode, and it looks like everything was recorded in JS correctly:
JF logs match the times recorded by JS as expected.
Yea iv also noticed this behavior, been testing today but it was abit inconsistent, il focus on the autoplay function
Popping back in to add some more info.
Last few days I've been continuing my BSG binge, making sure to not allow the next episode to autoplay. As expected every single episode shows up in JS with the proper play length, count, and timestamp.
Tonight I went back to autoplaying and watched several in a row and JS only reports 1 second of the first episode watched with a timestamp of when my session ended. JF's activity log properly shows all the episodes watched and the correct times.
== Jellystat DB log:
2024-07-07 01:11:32.809 UTC [28] LOG: checkpoint starting: time
2024-07-07 01:11:38.011 UTC [28] LOG: checkpoint complete: wrote 52 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=5.109 s, sync=0.038 s, total=5.203 s; sync files=7, longest=0.030 s, average=0.006 s; distance=208 kB, estimate=231 kB
2024-07-07 01:16:32.048 UTC [28] LOG: checkpoint starting: time
2024-07-07 01:16:37.941 UTC [28] LOG: checkpoint complete: wrote 57 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=5.623 s, sync=0.123 s, total=5.894 s; sync files=13, longest=0.036 s, average=0.010 s; distance=251 kB, estimate=251 kB
2024-07-07 01:21:32.980 UTC [28] LOG: checkpoint starting: time
2024-07-07 01:21:37.301 UTC [28] LOG: checkpoint complete: wrote 43 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=4.108 s, sync=0.102 s, total=4.321 s; sync files=7, longest=0.042 s, average=0.015 s; distance=204 kB, estimate=247 kB
2024-07-07 01:26:32.400 UTC [28] LOG: checkpoint starting: time
== Jellystat log:
Scheduled Recently Added Sync Complete
Running Recently Added Scheduled Sync
Scheduled Recently Added Sync Complete
Running Recently Added Scheduled Sync
Scheduled Recently Added Sync Complete
Running Recently Added Scheduled Sync
Scheduled Recently Added Sync Complete
Running Recently Added Scheduled Sync
Scheduled Recently Added Sync Complete
Running Recently Added Scheduled Sync
Jellyfin's log is equally useless as I can see several Playback stopped reported by app Kodi with the correct episode and timestamp, for every one watched tonight (which makes sense as JF's activity page shows the same).
Some strange time recordings, when playing an entire episode on chrome, JellyStat records 42min, when using the latest Jellyfin for Android TV (Ver 0.17.3) it records between 15min & 30min per episode.
Environment Details (please complete the following information):
OS: cyfershepard/jellystat:unstable
AndroidTV - Ver 0.17.3
Jellystat Version : 1.1.1
Jellyfin Version : 10.9.9
Seems like this is still an issue, I did some test earlier today, and with 1 user on the server and pausing the media just before the end, so that watchdog gets updated, the correct time is recorded. (was monitoring the watchdog table). Now with 2 users, it seems like the watchdog keeps deleting records without updating the activity table (guess that is because of a minimum amount of time needed before updating activity table)
As you can see from the image I ran a select on jf_activity_watchdog 4x directly after each other, and it start with the correct records, then drop it, no records & then back with the correct records, however the ActivityDateInserted is 14seconds from the 1st to the 4th record, PlaybackDuration is still zero.
Another screen shot of watchdog:
Is there maybe a debug log that I can view as to what is pushed into watchdog etc.
Maybe something like Playback_Reporting's log
At the moment the Jellystat settings for Jellyfin Url is http://:8096 connecting straight to the Jellyfin docker (both containers on same machine) and not going through the NPM Reverse Proxy.
Running latest Jellystat : unstable
Jellyfin 10.9.10
Did some extra tests.
As soon as there are more than 1 user watching Jellyfin, the watchdog table start acting up:
As you can see from the following image, only one user and the ActivityDateInserted stay the same.
I then opened another browser and logged in as a different user (first browser still continue playing)...
As you can see where there should be 2 records in watchdog, it alternates between the 2 records and the ActivityDateInserted keeps on changing.
Everything record correctly now. Even the issue #157 seems to be fixed.