Repeated scrobbles if jellyfin is left idle without stopping playback

[alexcannan]

I've noticed an issue with duplicated scrobbles when my jellyfin client is left idle without explicitly stopping the playback, just pausing.

Repeated scrobbles seem to happen every 1 to 2 hours.

My reproduction steps so far are: 1) begin music playback 2) pause playback at greater than halfway through the track, but before completion (not sure if this is strictly required yet) 3) wait for duplicate scrobbles to occur

I would be interested in pinpointing and fixing this issue myself, but I wanted to solicit comments first, if anyone had insight into how this could be happening.

[jesseward]

Hey @alexcannan thanks for reporting this.

Are you able to share the Jellyfin logs for a period where the multiple submissions are occurring.

I suspect that the Pause event fires the "Playback Stopped" event. This is the event we listen for when calculating the logic to determine if we should send to LastFM (https://github.com/jesseward/jellyfin-plugin-lastfm/blob/master/Jellyfin.Plugin.Lastfm/ServerEntryPoint.cs#L102-L171).

I am interested in seeing the logs to determine what keepalive event is firing to continually trigger such a failure.

[alexcannan]

Hi there, thanks for the info.

I've found some repeated Playback stopped events in my logs that occurred last night. In this particular case, the song was not at the 50%/4min minimum for scrobbling yet, so it didn't make it through the entry point, but it seems clear to me that is the cause of these repeated scrobbles.

Here is an excerpt from the logs:

[2024-02-06 07:45:44.920 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 08:03:47.678 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 08:21:54.002 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 08:39:16.531 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 08:55:51.792 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 09:11:47.182 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 09:28:18.123 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 09:44:09.898 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 10:03:32.847 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 10:20:46.449 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 10:36:37.670 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms
[2024-02-06 10:53:02.676 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Jesus' Blood Never Failed Me Yet". Stopped at "22337" ms

I am now curious if these repeated events are a bug from jellyfin itself, or the jellyfin media player app I use on my laptop. I'll attempt to recreate this state using the web player.

[alexcannan]

Tangential, but I'm also noticing the logs seems to be falsely reporting that the scrobbles have failed. These scrobbles show up on my last.fm page as expected.

[2024-02-06 12:20:52.189 -05:00] [DBG] "Jesus' Blood Never Failed Me Yet" - played 0%, Last.Fm requires minplayed=50% . played 0 ticks of minimumPlayTimeToScrobbleInTicks (2400000000), won't scrobble
[2024-02-06 12:20:52.192 -05:00] [INF] User policy for "alex". EnableAudioPlaybackTranscoding: True
[2024-02-06 12:20:52.932 -05:00] [ERR] The JSON value could not be converted to System.Boolean. Path: $.scrobbles.@attr.ignored | LineNumber: 0 | BytePositionInLine: 338.
[2024-02-06 12:20:52.933 -05:00] [ERR] Failed to Scrobble track: "Jesus' Blood Never Failed Me Yet"
[2024-02-06 12:20:53.024 -05:00] [INF] "$lastfmuser" is now playing artist="Frou Frou", track="A New Kind of Love (Demo)", album="Off Cuts"
[2024-02-06 12:22:53.684 -05:00] [WRN] Slow HTTP Response from "http://localhost:8096/Sessions/Playing/Progress" to "192.168.1.110" in 0:00:00.9237905 with Status Code 204
[2024-02-06 12:25:13.357 -05:00] [DBG] ReportPlaybackStopped PlaySessionId: ""
[2024-02-06 12:25:13.360 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "A New Kind of Love (Demo)". Stopped at "260501" ms
[2024-02-06 12:25:13.789 -05:00] [ERR] The JSON value could not be converted to System.Boolean. Path $.scrobbles.@attr.ignored | LineNumber: 0 | BytePositionInLine: 310.
[2024-02-06 12:25:13.789 -05:00] [ERR] Failed to Scrobble track: "A New Kind of Love (Demo)"

[csaavedra]

Same problem here, it's just enough to pause the player and resume playback later to get the track scrobbled twice. As Alex says, all scrobbles have an error, maybe that's what causing the double scrobbles?

[2024-02-23 14:52:16.129 +02:00] [ERR] The JSON value could not be converted to System.Boolean. Path: $.scrobbles.@attr.ignored | LineNumber: 0 | BytePositionInLine: 304.
[2024-02-23 14:52:16.130 +02:00] [ERR] Failed to Scrobble track: "Breaking Point"

[csaavedra]

I don't know if this has changed, but from looking at the doc api, it seems that the ignored attribute is not a boolean but an enumeration (https://www.last.fm/api/scrobbling#filtered-requests) but the plugin is considering it a boolean, so that might be causing the error that later triggers the error message, but the error is happening decoding the response, which doesn't necessarily mean that the scrobbling failed. In this case, it didn't. All this after 5 minutes checking, so please take this with a grain of salt, I might be off :)

[alexcannan]

I had another instance of the Playback stopped happening repeatedly, causing repeated scrobbles, but this time past the minimum duration to actually scrobble, and it indeed got posted to my last.fm a few times throughout the night.

[2024-02-25 00:57:50.256 -05:00] [DBG] Session "182af86ee5c5cd7ecdd7ffc3a1cc4321" has gone idle while playing
[2024-02-25 00:57:50.290 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Nothing To Declare". Stopped at "167991" ms
[2024-02-25 00:57:50.903 -05:00] [ERR] The JSON value could not be converted to System.Boolean. Path: $.scrobbles.@attr.ignored | LineNumber: 0 | BytePositionInLine: 302.
[2024-02-25 00:57:50.903 -05:00] [ERR] Failed to Scrobble track: "Nothing To Declare"
[2024-02-25 02:31:18.714 -05:00] [DBG] Session "182af86ee5c5cd7ecdd7ffc3a1cc4321" has gone idle while playing
[2024-02-25 02:31:18.714 -05:00] [INF] Playback stopped reported by app "Jellyfin Media Player" "1.9.1" playing "Nothing To Declare". Stopped at "167991" ms
[2024-02-25 02:31:19.106 -05:00] [ERR] The JSON value could not be converted to System.Boolean. Path: $.scrobbles.@attr.ignored | LineNumber: 0 | BytePositionInLine: 302.
[2024-02-25 02:31:19.106 -05:00] [ERR] Failed to Scrobble track: "Nothing To Declare"

repeat ad infinum...

To me, it seems like the root of this issue is from these repeated Playback stopped events. I'm also seeing these JSON decoding errors, but the posts succeed anyways. The last.fm plugin shouldn't have to figure out if these stopped events are from an idle session, or from someone listening to the same song every 90 minutes or so. So, I would be happy to close this issue on this repo and re-open it on the main jellyfin repo, I can look into that later today.

[csaavedra]

I disagree, the issue is that the plugin thinks that the scrobbling failed, but it didn't. This is because it's not parsing the json response correctly. Fixing that should fix all related issues.

[AlmaPlata]

Happening to me as well. The logs show the JSON value could not be converted to System.Boolean and Failed to Scrobble track messages repeatedly as well. As @csaavedra said, it most likely seems to be a problem with the error handling of the plugin, assuming that if the JSON parse fails, the scrobble does as well, but it doesn't, so it keeps trying and not failing each time.

[jesseward]

A new release was published at https://github.com/jesseward/jellyfin-plugin-lastfm/releases/tag/8.1.0.0 . This was working towards 10.9.0 compatibility, but I believe i also addressed the JSON/schema issue in the Last.FM scrobble API response...

You can install via the JF plugin repo, or install directly from the GitHub release page. If JF doesn't prompt for an upgrade of the plugin, try removing the plugin and reinstalling via the plugin repo selector.

[jesseward]

Should be fixed in #64 , please reopen if you're still seeing issues