Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jellyfin songs listened to via Symfonium while offline are not scrobbled. #87

Open
AverageHoarder opened this issue Jul 15, 2023 · 25 comments
Labels
enhancement New feature or request help wanted Extra attention is needed

Comments

@AverageHoarder
Copy link

AverageHoarder commented Jul 15, 2023

Please check the FAQ before submitting a bug report.

Describe the bug
I listened to 2 albums which I had added to the offline-cache in Symfonium without internet connection. When I reconnected to the internet those plays were reported to jellyfin and did show up in the jellyfin activity log. However multi-scrobbler took no notice of them and thus they did not end up in lastfm or maloja.

To Reproduce
Steps to reproduce the behavior:

  1. Download a song to the offline cache in Symfonium.
  2. Turn off the internet connection.
  3. Listen to that song.
  4. Connect to the internet.

Expected behavior
I expected the scrobbles to end up on lastfm and maloja as soon as the internet connection was reestablished.

Versions (please complete the following information):

  • multi-scrobbler: :develop on Docker
  • maloja 3.1.5
  • jellyfin 10.8.10

Additional context
I've described the entire problem in greater detail on the Symfonium forum:
Here's the link

The developer Tolriq asked me to relay this as a solution to a similar problem:
Problem with listenbrainz

@FoxxMD
Copy link
Owner

FoxxMD commented Jul 15, 2023

Thanks for the detailed response and context links. The webhook plugin does allow sending events on User Data Saved. I'll need to investigate what data is returned here to see if its possible to use.

@FoxxMD
Copy link
Owner

FoxxMD commented Jul 18, 2023

CC'd on the symfonium support forum

Using UserDataSaved works under these conditions returned in the jellyfin webhook playload:

{
  "NotificationType": "UserDataSaved",
  "Timestamp": "2023-07-18T14:03:23.6061191Z",
  "Played": true,
  "SaveReason": "PlaybackFinished",
  "LastPlayedDate": "2023-07-18T14:03:23.6061191Z"
}

There is an issue specific to symfonium, however. The LastPlayedDate returned is always the time when symfonium came back online, not the time the track was actually played at.

Timeline:

  • Set phone to airplane mode
  • Played Song at 9:59:42 on symfonium (1:23 duration)
  • Song ended at 10:01:06
  • Waited till 10:03:20, turned off airplane mode
  • symfonium reported play to Jellyfin at 10:03:23 with payload(?) {"DatePlayed":"20230718100106"}
  • Jellyfin responds with payload containing "LastPlayedDate":"2023-07-18T14:03:23.6061191Z"

This scenario isn't tenable for scrobbling. All offline plays would be reported as played at the same time which doesn't make sense.

I was able to get Jellyfin to report the correct LastPlayedDate by making a manual API call to the PlayedItems endpoint so it is possible but there is something wrong with how symfonium is sending the payload, I guess.

Based on the code for MarkPlayed and how Jellyfin parses datetime strings from the api I think there are two possibilities:

1. (most likely) symfonium is sending JSON when datePlayed should be a query param

The api docs specify datePlayed should be a query parameter but it looks like symfonium is sending a JSON body payload:

2023-07-18 10:03:24.399 Verbose/JellyfinLogger: --> [725] POST http://192.168.0.140:8096/Users/275322ade41c450f8b4bdc1fe27f72b6/PlayedItems/6c9eb58169aff2a2ec02460f57a1bf3f (31-byte body)
2023-07-18 10:03:24.401 Verbose/JellyfinLogger: --> [725] {"DatePlayed":"20230718100106"}

31-byte body matches the number of bytes in {"DatePlayed":"20230718100106"} which makes it look like its JSON.

When I manually send an api request Jellyfin ignores datePlayed when its json but respects it if sent as a query param.

2. The parameter is case-sensitive

symfonium is sending DatePlayed but the api documentation and code specify the param is datePlayed so maybe Jellyfin is ignoring the param completely.

Additional issue

The jellyfin datetime parser assumes the datetime sent is UTC but symfonium is sending datePlayed using the local timezone.

20230718100106 -> 2023-07-18 10:01:06 (EST) should be 20230718140106 -> 2023-07-18 14:01:06 (UTC)


More details in

@AverageHoarder
Copy link
Author

Symfonium 5.6.0 was released which has "- Fixed Jellyfin/Emby offline playback count sync not sending the proper time of play" in the changelog.
Is your part of the fix in the development version of the docker container yet? I'll gladly test if the issue is resolved.

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 4, 2023

Not yet! I was waiting for symfonium so i could do some real-world testing and am not in the beta channel. I'll get on this shortly. Thanks for the notification.

FoxxMD added a commit that referenced this issue Aug 4, 2023
* Refactor candidate/discovered Play maps to use tuple id instead of string so user can be compared later
* Add option to check all discovered platform plays (since jellyfin UserDataSaved doesn't include device id in payload)
* Check for UserDataSaved notification with correct reason as well as sanity check last played date (since jellyfin will save as played regardless of duration played)
* Bypass play tracking
FoxxMD added a commit that referenced this issue Aug 7, 2023
…rting due to incorrect timestamp #87

* Move UserDataSaved heuristics into scrobble method implementation with more descriptive logging
* Add more aggressive UserDataSaved filtering by discarding play if its found in memory tracking, regardless of play date
* Attempt to correct bad UTC offset for second UserDataSaved event
@FoxxMD
Copy link
Owner

FoxxMD commented Aug 7, 2023

@HairyOtter please try foxx/multi-scrobbler:jellyin docker image. There are still some issues i hope to resolve with Symphonium's developer but I believe these changes should be stable enough for tracking offline plays. Let me know if you have any issues.

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 8, 2023

Let me know if you have any issues.

Thanks for all your work, sadly I did have issues.

Scrobbles while online work fine with "foxx/multi-scrobbler:jellyin".
However offline plays do not work for me.

I've tried 4 songs.

First I listened to "The Unthanks - Magpie" online. That was scrobbled just fine.

Then I downloaded the album to the offline cache in Symfonium, turned off my wifi and listened to the same song again.
After that I turned my wifi back on, but no scrobble ended up in multi-scrobbler.

Then I listened to "Linkin Park - Heavy" while online, which was scrobbled successfully.

I downloaded another album by The Unthanks to the offline cache in symfonium after that, enabled debug logging in the app, turned off the wifi on my phone, listened to "The Unthanks - Starless", turned the wifi back on, waited a minute and then turned debug logging in symfonium off again.
That scrobble also did not make it to multi-scrobbler.

Here are the logs from multi-scrobbler.

2023-08-08T17:01:07+02:00 info : [Scrobblers] [Maloja - MalojaUser1] Scrobbled (Backlog) => (Lastfm) Linkin Park - Heavy @ 2023-08-08T17:00:06+02:00
2023-08-08T17:00:59+02:00 info : [Sources] [Lastfm - LastFmUser1Source] Discovered => Linkin Park - Heavy @ 2023-08-08T17:00:06+02:00
2023-08-08T17:00:42+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (New) => (Jellyfin) Linkin Park - Heavy @ 2023-08-08T17:00:06+02:00
2023-08-08T17:00:42+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => Linkin Park - Heavy @ 2023-08-08T17:00:06+02:00
2023-08-08T16:45:54+02:00 info : [Scrobblers] [Maloja - MalojaUser1] Scrobbled (Backlog) => (Lastfm) The Unthanks - Magpie @ 2023-08-08T16:44:47+02:00
2023-08-08T16:45:49+02:00 info : [Sources] [Lastfm - LastFmUser1Source] Discovered => The Unthanks - Magpie @ 2023-08-08T16:44:47+02:00
2023-08-08T16:45:20+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (New) => (Jellyfin) The Unthanks - Magpie @ 2023-08-08T16:44:47+02:00
2023-08-08T16:45:19+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => The Unthanks - Magpie @ 2023-08-08T16:44:47+02:00

Do I have to change something in the webhook plugin for jellyfin? The symfonium debug log looks like it did send the scrobbles to jellyfin.

So far I have only ticked:
Notification Type:
Playback Progress
Item Type:
Songs
Send All Properties (ignores template)

Edit:
I looked through the jellyfin logs and the plays did get reported to it:

[2023-08-08 16:59:13.365 +02:00] [INF] [35] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android" "12" playing "Magpie". Stopped at "unknown" ms
[2023-08-08 16:59:18.694 +02:00] [INF] [57] Emby.Server.Implementations.ScheduledTasks.TaskManager: "IntervalTrigger" fired for task: "Webhook Item Added Notifier"
[2023-08-08 16:59:18.694 +02:00] [INF] [57] Emby.Server.Implementations.ScheduledTasks.TaskManager: Queuing task "ItemAddedScheduledTask"
[2023-08-08 16:59:18.694 +02:00] [INF] [35] Emby.Server.Implementations.ScheduledTasks.TaskManager: Executing "Webhook Item Added Notifier"
[2023-08-08 16:59:18.694 +02:00] [INF] [35] Emby.Server.Implementations.ScheduledTasks.TaskManager: "Webhook Item Added Notifier" Completed after 0 minute(s) and 0 seconds
...
[2023-08-08 17:11:10.339 +02:00] [INF] [63] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android" "12" playing "Starless". Stopped at "unknown" ms
[2023-08-08 17:11:19.240 +02:00] [INF] [28] Emby.Server.Implementations.ScheduledTasks.TaskManager: "IntervalTrigger" fired for task: "Webhook Item Added Notifier"
[2023-08-08 17:11:19.241 +02:00] [INF] [28] Emby.Server.Implementations.ScheduledTasks.TaskManager: Queuing task "ItemAddedScheduledTask"
[2023-08-08 17:11:19.241 +02:00] [INF] [26] Emby.Server.Implementations.ScheduledTasks.TaskManager: Executing "Webhook Item Added Notifier"
[2023-08-08 17:11:19.241 +02:00] [INF] [26] Emby.Server.Implementations.ScheduledTasks.TaskManager: "Webhook Item Added Notifier" Completed after 0 minute(s) and 0 seconds

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 8, 2023

I think the issue may be that you are listening to the same song consecutively.

There are a lot of variables at play with offline detection (and UserDataSaved jellyfin event in general):

  • an issue with symphonium/jellyfin and the date jellyfin reports the track played -- jellyfin is reporting a track played by symphonium (online) as played twice with two different timestamps hours apart.
  • UserDataSaved event from jellyfin does not provide the device the user listened to the track on (can't tell its from phone/web/etc.)
  • UserDataSaved event from jellyfin occurs any and every time a track is "stopped" -- this isn't just a finished track. If the player is stopped its "finished". If you pause the track and then resume it or skip to next track three hours later then it's "finished". The timing of the event is not predictable.
  • The LastPlayedDate is client-dependent -- Jellyfin Web sets this as when the track stopped. Symphonium sets it as when the track was started.

All of these things make it hard to determine when a track is truly being reported from a client that was offline. The PlaybackProgress event used by MS is much more reliable for online plays as it doesn't have any of these issues.

Due to the unreliability of detection I had to make MS more aggressive about dropping found UserDataSaved events so it doesn't double-record online clients using both UserDataSaved and PlaybackProgress.

One of the things it does is check the recently played memory and drop the event if an identical track is found. MS only keeps the last played track in memory, though. So you shouldn't have any issue with offline recording as long as the last online track isn't the same as one of the offline ones being recorded.

So...please try listening to anything (Track X) online, then go offline and listen to Tracks A, B, and C. Then go back online. MS should correctly record A B and C.

FoxxMD added a commit that referenced this issue Aug 8, 2023
Check forward and backward offsets and use absolute difference
@FoxxMD
Copy link
Owner

FoxxMD commented Aug 8, 2023

I did make a small fix for timezone issues (first issue on that list). Please update your image to the latest with the same tag.

@AverageHoarder
Copy link
Author

So...please try listening to anything (Track X) online, then go offline and listen to Tracks A, B, and C. Then go back online. MS should correctly record A B and C.

I did. First I played "The Cranberries - The Icicle Melts" online. Got scrobbled just fine.

Then I deactivated wifi and played 3 tracks from the offline-cached Unthanks Album "Last". Tracks "No One Knows I'm Gone", "My Laddie Sits Ower Late Up" and "Last Reprise".

Then I reconnected the wifi.
Multi-Scrobbler log:

2023-08-09T00:41:48+02:00 info : [Scrobblers] [Maloja - MalojaUser1] Scrobbled (Backlog) => (Lastfm) The Cranberries - The Icicle Melts @ 2023-08-09T00:40:50+02:00
2023-08-09T00:41:48+02:00 info : [Sources] [Lastfm - LastFmUser1Source] Discovered => The Cranberries - The Icicle Melts @ 2023-08-09T00:40:50+02:00
2023-08-09T00:41:23+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (New) => (Jellyfin) The Cranberries - The Icicle Melts @ 2023-08-09T00:40:50+02:00
2023-08-09T00:41:22+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => The Cranberries - The Icicle Melts @ 2023-08-09T00:40:50+02:00

Once again none of the offline scrobbles made it to multi-scrobbler.

Jellyfin log:

[2023-08-09 00:50:59.721 +02:00] [INF] [41] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android" "12" playing "No One Knows I'm Gone". Stopped at "unknown" ms
[2023-08-09 00:50:59.764 +02:00] [INF] [21] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android" "12" playing "My Laddie Sits Ower Late Up". Stopped at "unknown" ms
[2023-08-09 00:50:59.875 +02:00] [INF] [21] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android" "12" playing "Last Reprise". Stopped at "unknown" ms

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 9, 2023

Have you enabled UserDataSaved in the jellyfin webhook plugin?
image

Also, please turn on debugging for MS logs and jellyfin.

MS: Start docker container with the environmental variables LOG_LEVEL=debug or add

  "logging": {
    "level": "debug",
  }

to your config.json.

For jellyfin modify logging.json for Debug minimum level logging and add this to the Override section:

"Jellyfin.Plugin.Webhook": "Debug"

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 9, 2023

Have you enabled UserDataSaved in the jellyfin webhook plugin?

I did not. Sorry. I was tired when I read your reply yesterday and failed to realize that you did answer my question:

Do I have to change something in the webhook plugin for jellyfin?

I have added "UserDataSaved" to the jellyfin webhook plugin, however now even online plays are no longer scrobbled.

2023-08-09T17:00:48+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-09T17:00:48+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-09T17:00:44+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:44+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:44+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:44+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:32+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:32+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:14+02:00 verbose : [Sources] [Lastfm - LastFmUser1Source] Sleeping for 60s
2023-08-09T17:00:14+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] Last activity was at 2023-08-09T16:21:39+02:00 which is 34 minutes outside of active polling period of (last activity + 300 seconds). Will sleep for max interval 60 seconds.
2023-08-09T17:00:14+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] No new tracks discovered
2023-08-09T17:00:14+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] Refreshing recently played
2023-08-09T17:00:01+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T17:00:01+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:59:30+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:59:30+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:59:14+02:00 verbose : [Sources] [Lastfm - LastFmUser1Source] Sleeping for 60s
2023-08-09T16:59:14+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] Last activity was at 2023-08-09T16:21:39+02:00 which is 33 minutes outside of active polling period of (last activity + 300 seconds). Will sleep for max interval 60 seconds.
2023-08-09T16:59:14+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] No new tracks discovered
2023-08-09T16:59:13+02:00 debug : [Sources] [Lastfm - LastFmUser1Source] Refreshing recently played
2023-08-09T16:58:59+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:59+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackStart
2023-08-09T16:58:57+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackStart

This is the debug output of multi-scrobbler when I play a track online.

The jellyfin debug log of the same time-frame is 381 lines and 305k characters, which is why I won't paste it here.
Any lines in particular that you need?

Edit: I tried an offline-played song as well and multi-scrobbler debug log shows:

2023-08-09T17:31:26+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-09T17:31:26+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 9, 2023

You need to have both event types enables in the webhook plugin:

  • Playback Progress is used to track online plays
  • User Data Saved used to record offline plays

Your logs looks right. MS only uses UserDataSaved when the SaveReason is PlaybackFinished which should be triggered by Symphonium when it comes back online with offline plays to report.

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 9, 2023

Forget all that, I am an idiot. I somehow managed to accidentally rename the jellyfin server when I was in the config.
Which explains why scrobbles stopped working.

After reverting the name-change, scrobbling online works again. Sorry for wasting your time.

I still had no luck with offline scrobbles tho.
Tried it 3 times, on the first track I reenabled wifi immediately after the song was finished.
On the second song I waited 10 seconds before reenabling the wifi.
On the 3rd song I waited over a minute before reenabling the wifi.

2023-08-09T21:11:27+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (3s) => (6149c161ef17c0434ae79200c3bf3be9) Calexico - Hear the Bells
2023-08-09T21:15:47+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7176s) => (ac8bff5397479f72024c97054876089e) Yann Tiersen - La Valse d'Amélie
2023-08-09T21:38:21+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7110s) => (88c866ee995d6b1bd48ba353bb783930) Max Richter - What Have They Done?

@AverageHoarder
Copy link
Author

I did another test today with 5 tracks offline.

2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7148s) => (9ef3a416d259386de975bda209e6ebb1) Max Richter - The Haunted Ocean 2
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7093s) => (c2c93280c87dec97064b8529a39e8073) Max Richter - Taxi And APC
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-6960s) => (28d51a044cccb05eb304d06cb17ab4f7) Max Richter - The Slaughterhouse
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-6865s) => (21de74b1478841242f7aba762a53ca11) Max Richter - The Haunted Ocean 5 (Solo Version)
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-6768s) => (bd0e8c49fe2f4f3e572f760d0923db53) Max Richter - The Haunted Ocean 1
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-10T15:22:52+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed

The negative 7200ish seconds offset looks like the difference from my timezone (UTC+2 summer time in Germany) to UTC.

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 10, 2023

@HairyOtter please try updating to the latest jellyfin docker image. And please ensure that jellyfin and multi-scrobbler are using the same timezone.

For MS you can set the timezone with the environment variable TZ=Europe/Berlin -- from docker run it would be docker run -e "TZ=Europe/Berlin" ... foxxmd/multi-scrobbler:jellyfin.

For jellyfin its the same variable if you are using linuxserver/jellfin

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 10, 2023

I already had the TZ in my compose (stack in portainer) for MS, which looks like this:

version: "3"
services:
  multi-scrobbler:
    image: foxxmd/multi-scrobbler:jellyfin
    container_name: multi-scrobbler
    environment:
      - TZ=Europe/Berlin
      - PUID=1000
      - PGID=1000
    volumes:
      - /opt/multi-scrobbler/config:/config
    ports:
      - 9078:9078 # first port is the HOST port multi-scrobbler will serve UI on
    restart: unless-stopped

For jellyfin its the same variable if you are using linuxserver/jellfin

I'm using jellyfin in a FreeBSD jail in TrueNAS Core. I don't know how to force jellyfin to use my timezone but it appears to already be using it.

If I use the "date" command within the FreeBSD jail for jellyfin I get:
Thu Aug 10 23:44:40 CEST 2023

And the logs which jellyfin creates also use my timezone:
[2023-08-10 23:48:02.605 +02:00]

However the timezone error seems to persist on my end:

2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7165s) => Max Richter - JSB/RPG
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7073s) => Max Richter - What Have They Done?
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-6960s) => Max Richter - The Haunted Ocean 1
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:28:12+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed

To ensure that I have the latest version of foxxmd/multi-scrobbler:jellyfin I deleted the container, deleted the image and then recreated it which pulled the latest image.
After that I played another song offline but the results were the same.

2023-08-11T00:34:04+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7170s) => Max Richter - The Haunted Ocean 5 (Solo Version)
2023-08-11T00:34:04+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T00:34:04+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 11, 2023

Hmmm...I set up my whole stack to use Europe/Berlin and was able to reproduce this error yesterday but the last changes i made fixed it.

Sorry this has been such a pain. Can you get a little more debugging information for me:

I imagine you are already using jellyfin.json config because you have multiple in your logs, but if you aren't already using one please setup a jellyfin.json config for multi-scrobbler. In your config add additional options property at the top level of one of your sources like this:

[
  {
    "name": "JellyUser1",
    "clients": [],
    "data": {
      "users": ["JellyUser1"],
    },
    "options": {
      "logPayload": true
    }
  }
]

This will make it so MS logs the raw payload received from jellyfin for every event. It will look like this:

...
2023-08-11T08:58:52-04:00 debug   : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"surfin' GBA","Artist":"Louie Zong","AudioStreamIndex":-1,"Audio_0_Bitrate":320000,"Audio_0_Channels":2,"Audio_0_Codec":"mp3","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"MP3 - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"f3f5b6bc4dd10d7c29f53378ed10e8f6","ItemType":"Audio","LastPlayedDate":"2023-08-11T12:58:42.9409515Z","Likes":false,"Name":"the road to fuchsia city","NotificationType":"UserDataSaved","NotificationUsername":"foxx","Overview":"","PlayCount":43,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:01:33","RunTimeTicks":938057152,"SaveReason":"PlaybackProgress","ServerId":"14c56359fd884267bbee31af3dabcc8b","ServerName":"8dd90cea7d9d","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T08:58:52.8253851-04:00","UserId":"275322ade41c450f8b4bdc1fe27f72b6","UtcTimestamp":"2023-08-11T12:58:52.8253932Z","Year":2021}
2023-08-11T08:58:52-04:00 debug   : [Sources] [Jellyfin - default] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: PlaybackProgress
...

It'll make your logs noisy 😅 ...what I need is a log excerpt that includes the payload output before one of these occurs:

...
2023-08-11T08:58:52-04:00 debug   : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"surfin' GBA","Artist":"Louie Zong","AudioStreamIndex":-1,"Audio_0_Bitrate":320000,"Audio_0_Channels":2,"Audio_0_Codec":"mp3"," ...
...
2023-08-11T08:58:53-04:00debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-6960s) => Louie Zong - surfin' GBA
...

Please also report the exact local time (to the second if possible) that:

  • you started playing the track offline at
  • the track finished playing

I believe we are very close to getting this to work. Timezones are the bane of my existence.

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 11, 2023

There you go. I might have had my config wrong. I had "options" at the same level as "users" and "servers" in jellyfin.json. However I think "logFilterFailure": false still worked like that.

Edit:
The example jellyfin config has "options" at the same level as I did. Are both valid or if not, which one is?

2023-08-11T17:17:31+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-7184s) => Max Richter - Patchouli Oil And Karate
2023-08-11T17:17:31+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":657268,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"3881aa76a1b58b3a90646cb15b7c03f6","ItemType":"Audio","LastPlayedDate":"2023-08-11T17:17:16.0000000Z","Likes":false,"Name":"Patchouli Oil And Karate","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":2,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:00:36","RunTimeTicks":365066656,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T17:17:31.2140351+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T15:17:31.2140556Z","Year":2008}

I pressed play at 17:16:35 and the song ended at 17:17:12.

Sorry this has been such a pain.

I prefer a bit of productive pain to what I experienced in the jellyfin forum so far. I asked how to import my local playlists into jellyfin while restricting their scope to my user instead of having every user being able to see them. No one even bothered to reply.
I worked it out in the end but it's an ugly hack. If you want to read the pain.

Timezones are the bane of my existence.

They do tend to complicate things, I agree.

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 11, 2023

The example jellyfin config has "options" at the same level as I did. Are both valid or if not, which one is?

The jellyfin image is using the playerState branch which has a bunch of refactored and new code to simplify source state tracking. Part of that code refactor was required to make offline plays feasible so you're getting bleeding-edge that hasn't been documented yet. One of the changes is moving common properties out of data and into their own options property so data can be source-specific only. Makes validation easier too.

If you want to see a cool preview add "logPlayerState": true to your options 👀

Please pull the latest jellyfin image and give that a try for offline plays. Hoping this is the one.

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 11, 2023

My first 2 tests failed because I reenabled the wifi too quickly.
How long do I have to wait after the last offline track stops playing before I can enable the wifi again without the last track being filtered out?

First song: I reenabled the wifi seconds after the offline play was done:

2023-08-11T18:56:27+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (11s) => Max Richter - The Haunted Ocean 5 (Solo Version)
2023-08-11T18:56:27+02:00 warn : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (0 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Max Richter - The Haunted Ocean 5 (Solo Version)
2023-08-11T18:56:27+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":695076,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"21de74b1478841242f7aba762a53ca11","ItemType":"Audio","LastPlayedDate":"2023-08-11T18:56:16.0000000Z","Likes":false,"Name":"The Haunted Ocean 5 (Solo Version)","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":8,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:01:37","RunTimeTicks":976133312,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T18:56:27.5992615+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T16:56:27.5992634Z","Year":2008}

Second song: I waited ~ a minute before reenabling the wifi:

2023-08-11T18:59:58+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it is likely from online client (play date + track duration = ~now) => Max Richter - The Slaughterhouse
2023-08-11T18:59:58+02:00 warn : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (0 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Max Richter - The Slaughterhouse
2023-08-11T18:59:58+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":351876,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"28d51a044cccb05eb304d06cb17ab4f7","ItemType":"Audio","LastPlayedDate":"2023-08-11T18:59:28.0000000Z","Likes":false,"Name":"The Slaughterhouse","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":4,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:01:35","RunTimeTicks":952533312,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T18:59:58.2824113+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T16:59:58.2824148Z","Year":2008}

And for the last test I played 3 tracks offline, then waited 3 minutes and THEN enabled the wifi again.
These actually got scrobbled.

2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload: {"album":"Waltz With Bashir (Original Motion Picture Soundtrack)","artist":"Max Richter","duration":36,"track":"Patchouli Oil And Karate"}
2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload: {"album":"Waltz With Bashir (Original Motion Picture Soundtrack)","artist":"Max Richter","duration":54,"track":"The Haunted Ocean 2"}
2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:10+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload: {"album":"Waltz With Bashir (Original Motion Picture Soundtrack)","artist":"Max Richter","duration":91,"track":"JSB/RPG"}
2023-08-11T19:06:09+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Max Richter - Patchouli Oil And Karate @ 2023-08-11T19:03:02+02:00
2023-08-11T19:06:09+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Max Richter - The Haunted Ocean 2 @ 2023-08-11T19:03:56+02:00
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-11T19:06:09+02:00 info : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Max Richter - JSB/RPG @ 2023-08-11T19:02:25+02:00
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Maloja - MalojaUser1] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:09+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => Max Richter - The Haunted Ocean 2 @ 2023-08-11T19:03:56+02:00
2023-08-11T19:06:09+02:00 warn : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-2 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Max Richter - The Haunted Ocean 2
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":421882,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"9ef3a416d259386de975bda209e6ebb1","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:03:56.0000000Z","Likes":false,"Name":"The Haunted Ocean 2","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":4,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:00:54","RunTimeTicks":542533312,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.2639529+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.2639562Z","Year":2008}
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":421882,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"9ef3a416d259386de975bda209e6ebb1","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:03:56.0000000Z","Likes":false,"Name":"The Haunted Ocean 2","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":3,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:00:54","RunTimeTicks":542533312,"SaveReason":"TogglePlayed","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.2409124+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.2409144Z","Year":2008}
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Maloja - MalojaUser1] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:09+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => Max Richter - Patchouli Oil And Karate @ 2023-08-11T19:03:02+02:00
2023-08-11T19:06:09+02:00 warn : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-3 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Max Richter - Patchouli Oil And Karate
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":657268,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"3881aa76a1b58b3a90646cb15b7c03f6","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:03:02.0000000Z","Likes":false,"Name":"Patchouli Oil And Karate","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":4,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:00:36","RunTimeTicks":365066656,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.1937986+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.1938007Z","Year":2008}
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":657268,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"3881aa76a1b58b3a90646cb15b7c03f6","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:03:02.0000000Z","Likes":false,"Name":"Patchouli Oil And Karate","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":3,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:00:36","RunTimeTicks":365066656,"SaveReason":"TogglePlayed","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.1590836+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.1590873Z","Year":2008}
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-11T19:06:09+02:00 debug : [Scrobblers] [Maloja - MalojaUser1] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-11T19:06:09+02:00 info : [Sources] [Jellyfin - JellyUser1] Discovered => Max Richter - JSB/RPG @ 2023-08-11T19:02:25+02:00
2023-08-11T19:06:09+02:00 warn : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-3 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Max Richter - JSB/RPG
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":480894,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"486c295dcf0ec1369283657d4f7a05a1","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:02:25.0000000Z","Likes":false,"Name":"JSB/RPG","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":4,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:01:31","RunTimeTicks":916000000,"SaveReason":"PlaybackFinished","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.1238776+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.1238812Z","Year":2008}
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-11T19:06:09+02:00 debug : [App] [Jellyfin] Logging payload due to at least one Jellyfin source having 'logPayload: true {"Album":"Waltz With Bashir (Original Motion Picture Soundtrack)","Artist":"Max Richter","AudioStreamIndex":-1,"Audio_0_Bitrate":480894,"Audio_0_Channels":2,"Audio_0_Codec":"flac","Audio_0_Default":false,"Audio_0_Language":null,"Audio_0_SampleRate":44100,"Audio_0_Title":"FLAC - Stereo","Audio_0_Type":"Audio","Favorite":false,"ItemId":"486c295dcf0ec1369283657d4f7a05a1","ItemType":"Audio","LastPlayedDate":"2023-08-11T19:02:25.0000000Z","Likes":false,"Name":"JSB/RPG","NotificationType":"UserDataSaved","NotificationUsername":"User1","Overview":"","PlayCount":3,"PlaybackPosition":"00:00:00","PlaybackPositionTicks":0,"Played":true,"Rating":0,"RunTime":"00:01:31","RunTimeTicks":916000000,"SaveReason":"TogglePlayed","ServerId":"5a5c3918d47bbcd1df3017b56054866a","ServerName":"jellyfin","ServerUrl":"","ServerVersion":"10.8.10","SubtitleStreamIndex":-1,"Tagline":"","Timestamp":"2023-08-11T19:06:09.0932719+02:00","UserId":"4d14957963d91cd2de8b521b47dd7ffa","UtcTimestamp":"2023-08-11T17:06:09.0932748Z","Year":2008}

Maybe a stupid question: How do you handle offline scrobbles that happened further in the past?
My timezone issues so far were obvious since the scrobbles came from the future.

If I wait more than 2 hours before reenabling the wifi that won't be the case anymore tho. Will those scrobbles end up shifted 2 hours into the future (for my timezone) or will they be caught and corrected as well?

Edit:
Doesn't the payload give you all the information needed to correct the timezone issue, no matter when the payload itself arrives?

"LastPlayedDate":"2023-08-11T19:02:25.0000000Z" is local time falsely written as UTC if I'm not mistaken.
"Timestamp":"2023-08-11T19:06:09.0932719+02:00" should be the correct local time of when the payload arrived.
"UtcTimestamp":"2023-08-11T17:06:09.0932748Z" should be the same in UTC.

Could you simply take the "+02:00" part of "Timestamp", invert it and apply it as an hour offset to "LastPlayedDate" if "Timestamp" and "UtcTimestamp" aren't equal? In my case -2 hours? Then you'd have a correct "LastPlayedDate" in UTC "2023-08-11T17:02:25.0000000Z", no matter when the payload was delivered.

@FoxxMD
Copy link
Owner

FoxxMD commented Aug 11, 2023

Doesn't the payload give you all the information needed to correct the timezone issue, no matter when the payload itself arrives?

If it was consistent, yes. Unfortunately I have seen Jellyfin send PlaybackFinished events with the correct LastPlayedDate timestamp as well as the incorrect one. Sometimes they follow each other, sometimes only one gets sent. I can't tell which is which since LastPlayedDate is always sent with UTC timezone. And so far I have not been able to discern a pattern that is causing this.

Maybe a stupid question: How do you handle offline scrobbles that happened further in the past?

Not stupid! This is the main pain point. I am trying to cover as many scenarios as possible for what I would consider to be a "typical" offline use-case while being aggressive about not letting jellyfin scrobble "online" plays.

The likely scenario:

You turn off data because of roaming. Or you lose a mobile connection on your phone. This outage is likely to occur for some time -- either you are in a location that does not get signal for some time (hours) or you have intentionally turned off data which is also likely not to be for only a few minutes at a time.

It's easier to explain all it is doing than just when play is in the past:

  • Try to correct LastPlayedDate timezone
    • If LastPlayedDate is in the future, compared to NOW, then obviously wrong and corrected with UTC offset from local
    • If LastPlayedDate is not in the future try to apply UTC offset anyway -- if the time is within 10 seconds of NOW then assume it was wrong and this came from an online play
  • Do not allow likely online plays based on LastPlayedDate
    • If LastPlayedDate is within 30 seconds of NOW, don't scrobble
    • If LastPlayedDate + track duration (checking if LastPlayedDate was set at the end of the listen instead of the beginning) is within 10 seconds of NOW, don't scrobble
  • Do not allow scrobble if the last played online track is the same as from PlaybackFinished

This covers most cases where Jellyfin sends PlaybackFinished for plays that are online. It covers future timestamps. And it covers incorrect timestamps that are very close to NOW after being adjusted.

It cannot do anything about plays in the past. If those timestamps are wrong, they will be wrong. But at least they will actually be in the past, likely offline, and not duplicate scrobbles from the present.

@AverageHoarder
Copy link
Author

Unfortunately I have seen Jellyfin send PlaybackFinished events with the correct LastPlayedDate timestamp as well as the incorrect one.

That's very frustrating. Have you asked about that in the jellyfin forum?
If not, I'll gladly ask if someone over there knows the pattern or (even better) knows how to make the behaviour consistent and correct.
Considering my last attempt to get information/help over there I'm not very hopeful tho.

Sometimes they follow each other, sometimes only one gets sent.

I don't think I've seen that happen on my end yet, but I've only looked at a few offline payloads. How common would you guess the double occurrences to be on your end?

It's easier to explain all it is doing than just when play is in the past:

Thanks for the explanation, that's very thoughtful and should work for the majority of cases.

But at least they will actually be in the past, likely offline, and not duplicate scrobbles from the present.

Very true. Personally I don't care if I listened to a song at 2pm or 4pm.

However this behaviour could mess up the play order if I'm correct:

If I were to listen to music offline for a little over 4 hours in my utc+2 timezone, the first 2 hours would seem valid even with an offset of +2 hours (they would still be in the past), while the most recent 2 hours would be corrected since they would appear to be from the future.

As a result, the plays of 4 hours could end up being mixed and compressed into a 2 hour time frame as far as the scrobbles are concerned.
In winter time that could already start to happen after 1 hour for my timezone (utc+2 in summer, utc+1 in winter).

Anyways, I've pestered you enough about this topic.
I'm very thankful for your time, your explanations and your current solution!
I'll report back once I've tested offline scrobbles in the wild on an extended bicycle tour.

@AverageHoarder
Copy link
Author

AverageHoarder commented Aug 14, 2023

I've done a longer test today. Rode my bicycle for almost 2 hours and listened to an entire album offline that has 29 tracks and a duration of 1:22:02.

Of these 29 plays only the most recent 15 got scrobbled.

Here are the MS logs.

2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-1531s) => RADWIMPS - The First Encounter
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-1769s) => Kazuma Jinnouchi - Abandoned Resort
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-1854s) => RADWIMPS - First Aid
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-1989s) => RADWIMPS - Cat Chase
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2103s) => RADWIMPS - At Night in Ferry
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2196s) => RADWIMPS - Cat me if you can
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2387s) => Kazuma Jinnouchi - Abandoned School
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2564s) => RADWIMPS - Time for two
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2702s) => Kazuma Jinnouchi - Hitchhike
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-2784s) => Kazuma Jinnouchi - Two Little Terrors
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-3075s) => Kazuma Jinnouchi - Dreaming on Ferris Wheel
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:51+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:52+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-3246s) => RADWIMPS - Soldier's Break
2023-08-14T21:00:53+02:00 debug   : [Sources] [Lastfm - LastFmUser1Source] Refreshing recently played
2023-08-14T21:00:54+02:00 debug   : [Sources] [Lastfm - LastFmUser1Source] No new tracks discovered
2023-08-14T21:00:54+02:00 debug   : [Sources] [Lastfm - LastFmUser1Source] Last activity was at 2023-08-14T18:28:52+02:00 which is 2 hours outside of active polling period of (last activity + 300 seconds). Will sleep for max interval 60 seconds.
2023-08-14T21:00:54+02:00 verbose : [Sources] [Lastfm - LastFmUser1Source] Sleeping for 60s
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-3335s) => Kazuma Jinnouchi - Shinkansen Super Express
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble Play with event UserDataSaved-PlaybackFinished because it took place too recently (-3422s) => RADWIMPS - History of Mimizu
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-59 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - Significant Precursor
2023-08-14T21:00:55+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - Significant Precursor @ 2023-08-14T20:01:02+02:00
2023-08-14T21:00:55+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-55 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Sky Over Tokyo
2023-08-14T21:00:55+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Sky Over Tokyo @ 2023-08-14T20:05:17+02:00
2023-08-14T21:00:55+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:55+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-50 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - Suzume's Departure
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - Suzume's Departure @ 2023-08-14T20:10:47+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-48 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - Posessed
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - Posessed @ 2023-08-14T20:12:11+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-47 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Double Riding
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Double Riding @ 2023-08-14T20:13:55+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-45 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - It wasn't a dream
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - It wasn't a dream @ 2023-08-14T20:15:45+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 warn    : [API - Lastfm - LastFmUser1] API call was not good but recoverable (operation failed), retrying in 1.5 seconds...
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-44 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - The Other Side of the Door
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - The Other Side of the Door @ 2023-08-14T20:16:54+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-42 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - Aftermath
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - Aftermath @ 2023-08-14T20:18:37+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Refreshing recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-39 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => Kazuma Jinnouchi - Prayer
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => Kazuma Jinnouchi - Prayer @ 2023-08-14T20:21:44+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-35 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Closing the Door
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Closing the Door @ 2023-08-14T20:25:35+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-29 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - KANATA HALUKA
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - KANATA HALUKA @ 2023-08-14T20:31:30+02:00
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-25 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Suzume
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Suzume @ 2023-08-14T20:35:29+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Sky Over Tokyo @ 2023-08-14T20:05:17+02:00
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - Prayer @ 2023-08-14T20:21:44+02:00
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-20 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Tamaki
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Tamaki @ 2023-08-14T20:40:24+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - Suzume's Departure @ 2023-08-14T20:10:47+02:00
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser1] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 debug   : [Sources] [Jellyfin - JellyUser2] Will not scrobble event because event type of 'UserDataSaved' did not have a valid SaveReason of 'PlaybackFinished' - found reason: TogglePlayed
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Closing the Door @ 2023-08-14T20:25:35+02:00
2023-08-14T21:00:56+02:00 warn    : [Sources] [Jellyfin - JellyUser1] Play with event UserDataSaved-PlaybackFinished has a playDate that is from the future (-15 minutes from now). This is likely a local time with incorrect UTC offset and has been corrected. => RADWIMPS - Tears of Suzume
2023-08-14T21:00:56+02:00 info    : [Sources] [Jellyfin - JellyUser1] Discovered => RADWIMPS - Tears of Suzume @ 2023-08-14T20:45:05+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - Posessed @ 2023-08-14T20:12:11+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Double Riding @ 2023-08-14T20:13:55+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - KANATA HALUKA @ 2023-08-14T20:31:30+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Suzume @ 2023-08-14T20:35:29+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Tamaki @ 2023-08-14T20:40:24+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - It wasn't a dream @ 2023-08-14T20:15:45+02:00
2023-08-14T21:00:56+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) RADWIMPS - Tears of Suzume @ 2023-08-14T20:45:05+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - Aftermath @ 2023-08-14T20:18:37+02:00
2023-08-14T21:00:56+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - The Other Side of the Door @ 2023-08-14T20:16:54+02:00
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":254,"track":"Sky Over Tokyo"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":185,"track":"Prayer"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":329,"track":"Suzume's Departure"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":232,"track":"Closing the Door"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":84,"track":"Posessed"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":102,"track":"Double Riding"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":355,"track":"KANATA HALUKA"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":238,"track":"Suzume"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":295,"track":"Tamaki"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":111,"track":"It wasn't a dream"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"RADWIMPS","duration":275,"track":"Tears of Suzume"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":103,"track":"Aftermath"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":68,"track":"The Other Side of the Door"}
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:00:57+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Found 40 recent scrobbles
2023-08-14T21:00:58+02:00 info    : [Scrobblers] [Lastfm - LastFmUser1] Scrobbled (Backlog) => (Jellyfin) Kazuma Jinnouchi - Significant Precursor @ 2023-08-14T20:01:02+02:00
2023-08-14T21:00:59+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser1] Raw Payload:  {"album":"Suzume (Motion Picture Soundtrack)","artist":"Kazuma Jinnouchi","duration":184,"track":"Significant Precursor"}
2023-08-14T21:00:59+02:00 debug   : [Scrobblers] [Lastfm - LastFmUser2] Client was filtered out by Source 'Source - Jellyfin - JellyUser1'
2023-08-14T21:01:54+02:00 debug   : [Sources] [Lastfm - LastFmUser1Source] Refreshing recently played
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - Significant Precursor @ 2023-08-14T20:01:02+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Sky Over Tokyo @ 2023-08-14T20:05:17+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - Suzume's Departure @ 2023-08-14T20:10:47+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - Posessed @ 2023-08-14T20:12:11+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Double Riding @ 2023-08-14T20:13:55+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - It wasn't a dream @ 2023-08-14T20:15:45+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - The Other Side of the Door @ 2023-08-14T20:16:54+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - Aftermath @ 2023-08-14T20:18:37+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => Kazuma Jinnouchi - Prayer @ 2023-08-14T20:21:44+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Closing the Door @ 2023-08-14T20:25:35+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - KANATA HALUKA @ 2023-08-14T20:31:30+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Suzume @ 2023-08-14T20:35:29+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Tamaki @ 2023-08-14T20:40:24+02:00
2023-08-14T21:01:54+02:00 info    : [Sources] [Lastfm - LastFmUser1Source] Discovered => RADWIMPS - Tears of Suzume @ 2023-08-14T20:45:05+02:00

FoxxMD added a commit that referenced this issue Aug 15, 2023
…bsolute diff #87

May allow more UserDataSaved scrobbles to occur but gives up any form of disallowing future scrobbles from bad timestamps
@FoxxMD
Copy link
Owner

FoxxMD commented Aug 15, 2023

I'm sorry but I've run out of ideas. I started a completely clean Jellyfin server, played tracks from symphonium, and still receive bad timestamps. I played 4 offline songs, 2 of them had correct dates and 2 of them did not.

2023-08-15T12:01:48-04:00 info    : [Sources] [Jellyfin - default] Discovered => Washed Out - It's Kate's Birthday @ 2023-08-15T11:57:09-04:00
2023-08-15T12:01:50-04:00 info    : [Sources] [Jellyfin - default] Discovered => Washed Out - Good Luck @ 2023-08-15T07:59:54-04:00
2023-08-15T12:01:54-04:00 info    : [Sources] [Jellyfin - default] Discovered => Washed Out - You Will Be Sad @ 2023-08-15T08:01:23-04:00
2023-08-15T12:01:56-04:00 info    : [Sources] [Jellyfin - default] Discovered => Washed Out - Yeah @ 2023-08-15T11:52:22-04:00

I also had occurrences of this happen while just using the jellyfin web player.

I've added a final fix that will prevent because it took place too recently (-2103s) type filtering but the downside is that it will no longer prevent "future" scrobbles from bad timestamps (as long as they are at least 30 seconds in the future). Update to the latest jellyfin tag to use it.

I will file a bug report with jellyfin soon since this is reproducible but I don't expect much help from them.

Finally, I've added a big, fat warning in logs about using UserDataSaved because it's so unreliable. Please feel free to continue to use it but I won't be troubleshooting this any more as the issue is squarely on Jellyfin's side and there isn't anything else I can currently do to try to fix their mistake.

@FoxxMD FoxxMD added the help wanted Extra attention is needed label Aug 15, 2023
@AverageHoarder
Copy link
Author

I will file a bug report with jellyfin soon since this is reproducible but I don't expect much help from them.

Thanks! I'm not overly optimistic either, but it might at least tell others encountering the same problem that it's not their fault.

Please feel free to continue to use it but I won't be troubleshooting this any more as the issue is squarely on Jellyfin's side and there isn't anything else I can currently do to try to fix their mistake.

I understand. Thank you for all your effort. It's a pity that such a "simple" error caused so much trouble and turned out not to be resolvable without jellyfin fixing their side.

This is what my sisters boyfriend (who works with databases and statistics as his job) sent me when I told him about the scrobble problem. It might amuse you if you don't already know it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request help wanted Extra attention is needed
Projects
None yet
Development

No branches or pull requests

2 participants