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

feat(source): Stale/orphan scrobble and timestamp improvments #256

Open
wants to merge 8 commits into
base: master
Choose a base branch
from

Conversation

FoxxMD
Copy link
Owner

@FoxxMD FoxxMD commented Jan 21, 2025

Checklist before requesting a review

Type of change

Please delete options that are not relevant.

  • New feature (non-breaking change which adds functionality)

Describe your changes

  • Add user configurable stale/orphaned intervals
  • Clear listening progress after scrobbling stale Play to prevent excess scrobbling if Play is resumed before player is orphaned
  • Improve logging timestamps for activity and stale/orphaned statements

@FoxxMD FoxxMD added enhancement New feature or request safe to test trusted to build image labels Jan 21, 2025
@FoxxMD FoxxMD force-pushed the configurablePlayerStale branch from 973efde to 6c30135 Compare January 21, 2025 18:29
@FoxxMD FoxxMD added the bug Something isn't working label Jan 21, 2025
@FoxxMD
Copy link
Owner Author

FoxxMD commented Jan 21, 2025

@Fratt please try out this PR.

You can specify stale after X seconds like this in spotify.json

[
  {
    "name": "MySpotify",
    "data": {
      // ...
      "staleAfter": 60, // seconds after which Player becomes stale from no activity
      "orphanedAfter": 360 // seconds after which Player becomes orphaned from no activity (removed after 2x interval)
    }
  }
]

Though I would suggest trying it without these, first. I made a change that should prevent "resumed" plays from scrobbling again if the previous "paused" (before stale) play was scrobbled. There was a bug that let the "paused" listen time count towards the "resumed" (post-stale) listen time that has now been fixed.

Also, can you remind me what platform you are using spotify on when you see it goes stale after pausing? From my own experience -- if on web/desktop and the application remains open the Player never goes stale even if paused for a long time. I haven't tested what this is like on mobile but I imagine that might be where you see it becoming stale.

@Fratt
Copy link
Contributor

Fratt commented Jan 22, 2025

Thanks a lot! I'll try pr-256 right away. (without adding anything in spotify.json, at first)

I know for a fact that it happened on mobile, indeed. But I cannot say for sure that it never happend on Desktop. (I listen 90% of the time on my phone, 10% of the time on my computer)

@Fratt
Copy link
Contributor

Fratt commented Jan 23, 2025

I've been trying it for 2 days now, without any changes to my spotify.json : I'm still experiencing occasional double scrobbles when taking breaks while listening to a song. It's difficult for me to say if this happens "less often" though.

I will now try with staleAfter and orphanedAfter in my spotify.json, but I have two questions for you first:

  • What are the default values?
  • I'm not sure I really understand the difference between the two, so can you tell me which values I should give them if I want to be able to take breaks of up to 8 hours while listening to a song, without having a "double scrobble" ?

Thanks a lot!

@FoxxMD
Copy link
Owner Author

FoxxMD commented Jan 23, 2025

The default values are

  • stale = polling interval (10s) * 3
  • orphaned = polling interval (10s) * 5

The "no activity" mentioned in my previous comment means that the Source (spotify) is no longer returning any data for the unique player ID it was monitoring. This is not the same as the Player being in the same state (paused) for a long time -- it's literally "the data returned from the spotify API for getPlayers() has not included an object for the player with ID 123 for X seconds, consecutively"

Stale and Orphaned are two different levels of "what should MS do when player has no activity for X seconds"

  • When player becomes Stale => Try to scrobble, if there was a track being played
    • If Player becomes active again (new data from API) then MS continues from where it left off in monitoring
      • If it had scrobbled when it became stale then when it tries to scrobble next it (should) only use listening time after becoming active [1]
      • If it did not scrobble when it became stale then it will use all listening time still stored in MS (pre-stale and now active)
  • When player becomes Orphaned => Remove the Player and all data about it from MS
    • If the Source returns the same Player ID with new data, later, then MS treats it as a new Player/track. It doesn't know anything about the old Player since it was removed. [2]

which values I should give them if I want to be able to take breaks of up to 8 hours while listening to a song

You'd probably only want to set orphanedAfter so that the stale data sticks around.

"orphanedAfter": 28800

would be 8 hours in seconds.


But I would also like to address the double scrobble if this really is a bug, or find out if your idea of how scrobbling should work is just different from MS.

From the above explanation, [1] should be working but I don't think it fits your scenario since likely your Player is being orphaned/removed. For [2] you should only see a "double scrobble" if the track you resumed still had enough time left to meet the scrobble threshold of 4 minutes. For the tracks you've seen double scrobbled, is this the case? Put plainly:

  • Listening to Song A (track is longer than 8 minutes)
  • Listen for 4+ minutes, then pause or close spotify on mobile
  • MS stales => scrobbles (4 minutes of listen time)
  • MS orphans => removes player
  • Re-open spotify some hours later, resume Song A
  • Listen for another 4+ minutes
  • Track ends or new track is played or close spotify => stales
  • MS scrobbles (4 minutes of listen time)

@Fratt
Copy link
Contributor

Fratt commented Jan 24, 2025

I will take the time to answer your points properly soon.

In the meantime, I added last evening orphanedAfter into my config file :

[
  {
    "name": "Spotify",
    "enable": true,
    "clients": [],
    "data": {
      "clientId": "xxx",
      "clientSecret": "xxx",
      "redirectUri": "xxx",
      "interval": 60,
      "orphanedAfter": 28800
    },
    "options": {
      "logToFile": "debug"
    }
  }
]

But it seems to cause problems : It does double scrobbling even when I take a break of only 5 minutes while listening to a song, which is way worst than before :-(

image

Any idea why?

I'll rollback the config for now

…obble on resume

Clearing pre-stale listening range prevents any future resume (player becomes non-stale) from using old listening range to scrobble. Represents a physical "break" between listening sessions for the same song
Makes logs easier to read when looking for stale source/player
@FoxxMD FoxxMD force-pushed the configurablePlayerStale branch from 6c30135 to 0ea5463 Compare January 31, 2025 17:35
Copy link
Contributor

📦 A new release has been made for this pull request.

To play around with this PR, pull an image:

  • foxxmd/multi-scrobbler:pr-256

Images are available for x86_64 and ARM64.

Latest commit: 59013f4

@FoxxMD
Copy link
Owner Author

FoxxMD commented Jan 31, 2025

@Fratt please try the newest image, without staleAfter orphanedAfter, and let me know if you see any improvements. Thanks

@Fratt
Copy link
Contributor

Fratt commented Jan 31, 2025

I will, thanks!

@Fratt
Copy link
Contributor

Fratt commented Feb 1, 2025

First, thanks a lot for all the efforts trying to improve multi-scrobbler!

I'm not sure exactly what you fixed, but I can confirm that I still get double scrobbles, when I don't set staleAfter and/or orphanedAfter

Song : Epica - Sacred & Wild (duration : 4:47)
Timeline :

  • ~8:43 : Started playing the song on Spotify, on my Android phone.
  • ~8:46 : Paused the song @ 3:08, without closing Spotify.
  • ~9:00 : A first scrobble happens
  • ~11:27 : Resumed the song
  • ~11:29 : The song finished. A second (unwanted) scrobble happens.

It looks like this in Maloja (as if I listened to the song twice, which isn't the case)
image

Can I try again this config?

[
  {
    "name": "Spotify",
    "enable": true,
    "clients": [],
    "data": {
      "clientId": "xxx",
      "clientSecret": "xxx",
      "redirectUri": "xxx",
      "interval": 60,
      "orphanedAfter": 28800
    },
    "options": {
      "logToFile": "debug"
    }
  }
]

Here are the logs:

[2025-02-01 08:43:43.633 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild) does not match existing state, removing existing: (47NEutGUN9MH05KRSiwoMJ) Epica / Metropole Orkest - Beyond the Matrix - The Battle
[2025-02-01 08:43:43.634 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-01 08:43:43.635 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Listen duration was within 3s of Play duration, bumping duration to 100%  because we probably just missed Source reporting 100% before changing Play.
[2025-02-01 08:43:43.636 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-01 08:43:43.637 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild
[2025-02-01 08:43:43.638 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-02-01 08:43:43.639 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (47NEutGUN9MH05KRSiwoMJ) Epica / Metropole Orkest - Beyond the Matrix - The Battle added after met thresholds with tracked time of 515.16s (wanted 20s) and tracked percent of 94.00% (wanted 50%) and not matching any prior plays
[2025-02-01 08:43:43.645 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Epica / Metropole Orkest - Beyond the Matrix - The Battle @ 2025-02-01T08:43:43+01:00 (C)
[2025-02-01 08:43:43.645 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:43:43+01:00 | Next check in 60.00s
[2025-02-01 08:44:43.820 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:44:43+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:45:43.976 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:45:43+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:46:44.116 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:46:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:47:44.320 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-01 08:47:44.326 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:47:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:48:44.498 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:48:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:49:44.653 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:49:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:50:44.823 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:50:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:51:44.999 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:51:44+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:52:45.162 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:52:45+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:53:45.351 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:53:45+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:54:45.549 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:54:45+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:55:45.728 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:55:45+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:56:45.900 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:57:46.032 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:58:46.181 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-01 08:59:46.303 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (03:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-01 09:00:46.412 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Stale after no Play updates for 04:00 (staleAfter 180s)
[2025-02-01 09:00:46.422 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-01 09:00:46.423 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] [Stale Player Cleanup] (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild added after met thresholds with tracked time of 180.66s (wanted 20s) and tracked percent of 63.00% (wanted 50%) and not matching any prior plays
[2025-02-01 09:00:46.425 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Epica - Sacred & Wild @ 2025-02-01T09:00:46+01:00 (C)
[2025-02-01 09:00:46.426 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (04:00 ago) | Next check in 60.00s
[2025-02-01 09:01:46.524 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Orphaned after no Player updates for 05:00 5 (orhanedAfter 300s)
[2025-02-01 09:01:46.533 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (05:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:02:46.637 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (06:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:03:46.752 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Access token was not valid, attempting to refresh
[2025-02-01 09:03:46.921 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (07:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:04:47.068 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (08:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:05:47.174 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (09:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:06:47.268 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Removed after being orphaned for 05:00
[2025-02-01 09:06:47.270 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (10:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:07:47.350 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (11:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:08:47.441 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (12:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:09:47.531 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (13:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:10:47.641 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (14:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:11:47.751 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (15:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:12:47.896 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (16:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:13:48.036 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (17:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:14:48.141 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (18:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:15:48.231 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (19:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:16:48.321 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (20:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:17:48.433 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (21:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:18:48.540 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (22:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:19:48.665 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (23:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:20:48.808 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (24:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:21:48.964 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (25:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:22:49.061 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (26:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:23:49.158 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (27:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:24:49.259 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (28:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:25:49.360 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (29:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:26:49.498 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (30:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:27:49.625 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (31:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:28:49.773 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (32:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:29:49.872 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (33:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:30:49.961 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (34:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:31:50.067 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (35:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:32:50.165 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (36:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:33:50.294 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (37:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:34:50.422 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (38:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:35:50.560 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (39:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:36:50.709 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (40:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:37:50.808 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (41:04 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:38:50.930 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (42:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:39:51.015 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (43:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:40:51.136 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (44:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:41:51.269 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (45:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:42:51.383 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (46:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:43:51.546 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (47:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:44:51.648 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (48:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:45:51.735 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (49:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:46:51.842 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (50:05 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:47:51.961 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (51:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:48:52.093 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (52:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:49:52.220 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (53:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:50:52.354 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (54:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:51:52.450 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (55:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:52:52.543 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (56:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:53:52.659 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (57:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:54:52.758 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (58:06 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:55:52.893 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (59:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:56:53.025 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:00:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:57:53.184 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:01:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:58:53.291 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:02:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 09:59:53.366 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:03:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:00:53.471 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:04:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:01:53.568 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:05:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:02:53.660 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:06:07 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:03:53.753 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Access token was not valid, attempting to refresh
[2025-02-01 10:03:53.912 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:07:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:04:54.062 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:08:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:05:54.161 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:09:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:06:54.259 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:10:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:07:54.362 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:11:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:08:54.466 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:12:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:09:54.566 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:13:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:10:54.689 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:14:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:11:54.835 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:15:08 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:12:54.980 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:16:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:13:55.059 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:17:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:14:55.157 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:18:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:15:55.239 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:19:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:16:55.312 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:20:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:17:55.392 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:21:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:18:55.474 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:22:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:19:55.562 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:23:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:20:55.653 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:24:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:21:55.763 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:25:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:22:55.858 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:26:09 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:23:55.979 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:27:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:24:56.088 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:28:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:25:56.232 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:29:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:26:56.324 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:30:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:27:56.420 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:31:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:28:56.534 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:32:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:29:56.637 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:33:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:30:56.738 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:34:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:31:56.859 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:35:10 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:32:56.993 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:36:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:33:57.173 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:37:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:34:57.266 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:38:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:35:57.363 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:39:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:36:57.475 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:40:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:37:57.585 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:41:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:38:57.720 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:42:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:39:57.846 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:43:11 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:40:57.977 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:44:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:41:58.069 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:45:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:42:58.180 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:46:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:43:58.273 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:47:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:44:58.377 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:48:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:45:58.472 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:49:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:46:58.585 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:50:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:47:58.707 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:51:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:48:58.848 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:52:12 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:49:58.963 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:53:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:50:59.057 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:54:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:51:59.133 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:55:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:52:59.218 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:56:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:53:59.323 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:57:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:54:59.416 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:58:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:55:59.524 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (01:59:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:56:59.657 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:00:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:57:59.801 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:01:13 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 10:58:59.942 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:02:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:00:00.050 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:03:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:01:00.159 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:04:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:02:00.261 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:05:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:03:00.386 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:06:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:04:00.494 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Access token was not valid, attempting to refresh
[2025-02-01 11:04:00.668 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:07:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:05:00.758 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:08:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:06:00.869 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:09:14 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:07:00.964 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:10:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:08:01.070 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:11:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:09:01.227 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:12:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:10:01.358 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:13:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:11:01.519 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:14:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:12:01.606 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:15:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:13:01.720 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:16:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:14:01.828 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:17:15 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:15:01.939 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:18:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:16:02.056 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:19:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:17:02.198 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:20:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:18:02.321 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:21:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:19:02.409 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:22:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:20:02.499 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:23:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:21:02.600 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:24:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:22:02.709 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:25:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:23:02.812 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:26:16 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:24:02.922 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:27:17 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:25:03.041 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:28:17 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:26:03.186 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:29:17 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:27:03.298 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 08:56:45+01:00 (02:30:17 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-01 11:28:03.471 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild
[2025-02-01 11:28:03.473 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-02-01 11:28:03.484 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:28:03+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-01 11:29:03.629 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-02-01 11:29:03.635 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 21.01s due to Player **REDACTED**-SingleUser reporting track duration remaining (23.01s) less than normal interval (60.00s)
[2025-02-01 11:29:03.635 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:29:03+01:00 | Next check in 21.01s | No new tracks discovered
[2025-02-01 11:29:24.758 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to Player **REDACTED**-SingleUser reporting track duration remaining (1.88s) less than normal interval (60.00s)
[2025-02-01 11:29:24.759 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:29:24+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-01 11:29:25.859 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to Player **REDACTED**-SingleUser reporting track duration remaining (0.78s) less than normal interval (60.00s)
[2025-02-01 11:29:25.859 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:29:25+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-01 11:29:26.978 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((2XIg1qHsykDUjaM8iF4zOc) Ruurd Woltring / Epica - Forevermore) does not match existing state, removing existing: (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild
[2025-02-01 11:29:26.979 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-01 11:29:26.979 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Listen duration was within 3s of Play duration, bumping duration to 100%  because we probably just missed Source reporting 100% before changing Play.
[2025-02-01 11:29:26.979 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-01 11:29:26.979 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (2XIg1qHsykDUjaM8iF4zOc) Ruurd Woltring / Epica - Forevermore
[2025-02-01 11:29:26.979 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-02-01 11:29:26.988 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild added after met thresholds with tracked time of 83.20s (wanted 20s) and tracked percent of 29.00% (wanted 50%) and not matching any prior plays
[2025-02-01 11:29:26.990 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Epica - Sacred & Wild @ 2025-02-01T11:29:26+01:00 (C)
[2025-02-01 11:29:26.990 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:29:26+01:00 | Next check in 60.00s
[2025-02-01 11:30:27.143 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 11:30:27+01:00 | Next check in 60.00s | No new tracks discovered

@Fratt
Copy link
Contributor

Fratt commented Feb 3, 2025

(beside the double scrobbles, the rest seems to work as usual)

@FoxxMD
Copy link
Owner Author

FoxxMD commented Feb 3, 2025

Do you have scrobbleThresholds set anywhere in your configs? Like in config.json under sourceDefaults ?

This log line

[2025-02-01 11:29:26.988 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild added after met thresholds with tracked time of 83.20s (wanted 20s) and tracked percent of 29.00% (wanted 50%) and not matching any prior plays

indicates the time required for a track to be listened to in order to scrobble it is only 20 seconds while the default is 240s (4 minutes).

@Fratt
Copy link
Contributor

Fratt commented Feb 3, 2025

Yes, here is my configuration :

config.json

{
  "baseUrl": "https://xxx",
  "logging": {
	  "level": "debug"
  },
  "sourceDefaults": {
    "scrobbleThresholds": {
      "duration": 20,
      "percent": null
    },
    "maxPollRetries": 10,
    "maxRequestRetries": 10
  },
  "webhooks": [
	{
	  "type": "gotify",
	  "name": "Gotify",
	  "url": "https://xxx/gotify/",
	  "token": "xxx",
	  "priorities": {
	    "info": 5,
	    "warn": 7,
	    "error": 10
	  }
	}
  ]
}

maloja.json

[
  {
    "name": "Maloja",
    "enable": true,
    "data": {
      "url": "https://xxx",
      "apiKey": "xxx"
    }
  }
]

spotify.json

[
  {
    "name": "Spotify",
    "enable": true,
    "clients": [],
    "data": {
      "clientId": "xxx",
      "clientSecret": "xxx",
      "redirectUri": "https://xxx/callback",
      "interval": 60
    },
    "options": {
      "logToFile": "debug"
    }
  }
]

Should I remove

    "scrobbleThresholds": {
      "duration": 20,
      "percent": null
    },

from my config.json?

FYI, I added this as an attempt to have scrobbles for very short songs as well (songs shorter than 1 minute seemed to never get scrobbled), and left it here...

Really sorry for wasting your time...

@FoxxMD
Copy link
Owner Author

FoxxMD commented Feb 3, 2025

Yes, you should remove it. duration: 20 is what is causing the double scrobble.

tracked time of 83.20s indicates that MS is correctly recording the "resume in middle and do not count previous listen time" behavior:

Sacred & Wild -> 4:47 (287 seconds) length
First listen 8:43 - 8:46 = 3:06 (~180s)

[2025-02-01 09:00:46.423 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] [Stale Player Cleanup] (2ad3wWNPqiZTaLpBz6DGeC) Epica - Sacred & Wild added after met thresholds with tracked time of 180.66s (wanted 20s) and tracked percent of 63.00% (wanted 50%) and not matching any prior plays

Second listen 11:28:03 - 11:29:26 = ~83s listen time
Puts you at resuming from 3:06 (180) + 83 = ~263s length (track length minus missed time due to polling interval and buffer time for MS to calculate it was actually playing)

So MS is working correctly but the track is being scrobble because of the short duration requirement. Normally its 4 minutes OR 50%, whichever is met first. In a scenario with default thresholds it would not have scrobbled since duration (83s) is under 4min and percent (23%) is under 50%.

@Fratt
Copy link
Contributor

Fratt commented Feb 3, 2025

Thank you, I removed it and I will keep you updated.

Edit : Though, if I understand correctly, I could still get double scrobbles on very long tracks (> 8 minutes). Such tracks are quite rare indeed, so I could clearly live with that.

@FoxxMD
Copy link
Owner Author

FoxxMD commented Feb 7, 2025

Hey @Fratt how's it been going with the change?

@Fratt
Copy link
Contributor

Fratt commented Feb 7, 2025

Hi Foxx, thanks for checking in.

With the change, I seem to no longer have "double scrobbles" anymore! So, that's great :-) thanks for that

Though... I'm experiencing a few lost scrobbles again, and now I think I completely understand when and why.

It seems to happen when I take 2 breaks in the same song... 😅

I clearly remember that two days ago, a coworker told me "sorry to bother you, I see that you had just put your earphones back on again a short while ago" just when I was trying to listen to a song whose scrobble ended up getting lost... (oh, the joys of being PM 😂) Which totally makes sense : none of the three "parts" reached either of the thresholds...

I'm considering rolling back the config to 20 seconds, and fork multi-scrobbler to prevent the Maloja client from scrobbling the same song twice in a row (I just have to "cache" the last scrobble). I feel that I already took up too much of your time...

Any opinion on that?

Thanks a lot

@FoxxMD
Copy link
Owner Author

FoxxMD commented Feb 7, 2025

Glad to hear the double scrobbles are gone.

I think your break issue can now be solved with orphanedAfter. The time when you previously used it was before I added more commits to fix double scrobbling when stale. And now that we've eliminated the short threshold it should work as expected.

I would set it to whatever you would consider to be a reasonable amount of time for multiple breaks to occur without scrobbling again. Like maybe 1 or 2 hours.

"orphanedAfter": 3600 // 1 hour in seconds

This should then work so that if the amount of time between no activity on a single track is less than 1 hour at a time -- so you could take a break multiple times as long as they are each less than 1 hour -- then when the track does eventually change (or more than 1 hour passes OR it goes stale and has hit threshold) it will scrobble.

If this still doesn't work as expected then

I'm considering rolling back the config to 20 seconds, and fork multi-scrobbler to prevent the Maloja client from scrobbling the same song twice in a row (I just have to "cache" the last scrobble).

i have another idea of how to address this, generally, for MS so you don't need to do this. Just let me know.

@Fratt
Copy link
Contributor

Fratt commented Feb 7, 2025

oh of course! I have set orphanedAfter to 86400 (24 hours), and I'll revert back to you in a few days.
Thanks for your help!

@Fratt
Copy link
Contributor

Fratt commented Feb 9, 2025

Dear Foxx,

I have been experiencing a lot of lost scrobbles this weekend, despite having orphanedAfter set to 86400.

In this example, the song "Wake The World" here was not scrobbled, besides the fact that I listened to it fully (I'm not sure if it was in 2 or 3 parts) :

[2025-02-09 18:42:54.924 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (0.72s) less than normal interval (60.00s)
[2025-02-09 18:42:54.925 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:42:54+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-09 18:42:56.040 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Incoming play state ((3SuzLpQ0DVZ0goPYah4UmN) Epica / Phil Lanzon / Tommy Karevik - Wake The World (feat. Phil Lanzon & Tommy Karevik)) does not match existing state, removing existing: (1YB0sXwzA4Glu6WYR9WCf4) Kilmara / Daniel Heiman / Lost Horizon - Take Me Back
[2025-02-09 18:42:56.040 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-09 18:42:56.040 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Listen duration was within 3s of Play duration, bumping duration to 100%  because we probably just missed Source reporting 100% before changing Play.
[2025-02-09 18:42:56.040 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-09 18:42:56.041 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] New Play: (3SuzLpQ0DVZ0goPYah4UmN) Epica / Phil Lanzon / Tommy Karevik - Wake The World (feat. Phil Lanzon & Tommy Karevik)
[2025-02-09 18:42:56.041 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 18:42:56.041 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] (1YB0sXwzA4Glu6WYR9WCf4) Kilmara / Daniel Heiman / Lost Horizon - Take Me Back added after met thresholds with tracked time of 335.05s (wanted 240s) and tracked percent of 100.00% (wanted 50%) and not matching any prior plays
[2025-02-09 18:42:56.045 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Kilmara / Daniel Heiman / Lost Horizon - Take Me Back @ 2025-02-09T18:42:56+01:00 (C)
[2025-02-09 18:42:56.045 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:42:56+01:00 | Next check in 60.00s
[2025-02-09 18:43:56.220 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:43:56+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:44:56.415 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:44:56+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:45:56.577 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:45:56+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:46:56.721 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:46:56+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:47:56.909 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:47:56+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:48:57.129 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 18:48:57.137 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:48:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:49:57.281 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-02-09 18:49:57.300 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:49:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:50:57.471 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:50:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:51:57.635 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:51:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:52:57.814 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-09 18:52:57.819 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:52:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:53:57.956 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:53:57+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:54:58.129 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:54:58+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:55:58.304 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:55:58+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:56:58.435 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Access token was not valid, attempting to refresh
[2025-02-09 18:56:58.642 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:56:58+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:57:58.819 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:57:58+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:58:58.992 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:58:58+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 18:59:59.131 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 18:59:59+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:00:59.319 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:00:59+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:01:59.489 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:02:59.627 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (01:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:03:59.781 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (02:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:04:59.876 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (03:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:05:59.961 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Stale after no Play updates for 04:00 (staleAfter 180s)
[2025-02-09 19:05:59.967 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-09 19:05:59.967 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] [Stale Player Cleanup] (3SuzLpQ0DVZ0goPYah4UmN) Epica / Phil Lanzon / Tommy Karevik - Wake The World (feat. Phil Lanzon & Tommy Karevik) not added because did not meet thresholds with tracked time of 180.54s (wanted 240s) and tracked percent of 49.00% (wanted 50%).
[2025-02-09 19:05:59.967 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (04:00 ago) | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:07:00.076 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (05:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:08:00.200 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (06:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:09:00.321 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (07:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:10:00.465 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (08:00 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:11:00.617 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (09:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:12:00.732 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (10:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:13:00.849 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (11:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:14:00.966 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (12:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:15:01.089 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (13:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:16:01.223 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (14:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:17:01.388 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (15:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:18:01.474 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (16:01 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:19:01.576 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (17:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:20:01.684 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (18:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:21:01.794 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (19:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:22:01.922 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (20:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:23:02.066 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (21:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:24:02.221 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (22:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:25:02.319 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (23:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:26:02.424 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (24:02 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:27:02.541 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (25:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:28:02.662 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:01:59+01:00 (26:03 ago) | Next check in 30.00 | No new tracks discovered
[2025-02-09 19:29:02.834 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Incoming play state ((5bTxkjZHb0F3rm38IODQSP) Epica / Charlotte Wessels / Myrkur - Sirens - Of Blood And Water (feat. Charlotte Wessels & Myrkur)) does not match existing state, removing existing: (3SuzLpQ0DVZ0goPYah4UmN) Epica / Phil Lanzon / Tommy Karevik - Wake The World (feat. Phil Lanzon & Tommy Karevik)
[2025-02-09 19:29:02.836 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-09 19:29:02.837 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] New Play: (5bTxkjZHb0F3rm38IODQSP) Epica / Charlotte Wessels / Myrkur - Sirens - Of Blood And Water (feat. Charlotte Wessels & Myrkur)
[2025-02-09 19:29:02.838 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 19:29:02.839 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] (3SuzLpQ0DVZ0goPYah4UmN) Epica / Phil Lanzon / Tommy Karevik - Wake The World (feat. Phil Lanzon & Tommy Karevik) not added because did not meet thresholds with tracked time of 180.54s (wanted 240s) and tracked percent of 49.00% (wanted 50%).
[2025-02-09 19:29:02.844 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:29:02+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 19:30:03.074 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-02-09 19:30:03.091 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (0.00s) less than normal interval (60.00s)
[2025-02-09 19:30:03.092 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:30:03+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-09 19:30:04.247 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (0.00s) less than normal interval (60.00s)
[2025-02-09 19:30:04.248 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:30:04+01:00 | Next check in 1.00s | No new tracks discovered

@Fratt
Copy link
Contributor

Fratt commented Feb 9, 2025

Actually, it seems that now, every time a song is played in more than one sitting, it doesn't scrobble it.

Edit 1: I can confirm that it's the case. I just did a test with a simple pause of 6 minutes, and the scrobble was lost.

Song : "Wings of Freedom", duration: 5:34
Timeline:

  • 20:32 : Started playing the song
  • 20:34 : Paused the song @ 2:06
  • 20:40 : Resumed the song
  • 20:43 : Song finishes. No scrobble is made.

Logs:

[2025-02-09 20:31:39.412 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 38.88s due to **REDACTED**-SingleUser reporting track duration remaining (40.88s) less than normal interval (60.00s)
[2025-02-09 20:31:39.413 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:31:39+01:00 | Next check in 38.88s | No new tracks discovered
[2025-02-09 20:32:18.567 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (1.74s) less than normal interval (60.00s)
[2025-02-09 20:32:18.567 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:32:18+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-09 20:32:19.689 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (0.60s) less than normal interval (60.00s)
[2025-02-09 20:32:19.689 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:32:19+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-09 20:32:20.824 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to **REDACTED**-SingleUser reporting track duration remaining (0.00s) less than normal interval (60.00s)
[2025-02-09 20:32:20.824 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:32:20+01:00 | Next check in 1.00s | No new tracks discovered
[2025-02-09 20:32:21.931 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Incoming play state ((59RTfkiFiZn39FIfdwaAWR) Epica - Wings of Freedom) does not match existing state, removing existing: (31XLeIFY68pll9LNu1IkXV) Epica - Crimson Bow and Arrow
[2025-02-09 20:32:21.933 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-09 20:32:21.934 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Listen duration was within 3s of Play duration, bumping duration to 100%  because we probably just missed Source reporting 100% before changing Play.
[2025-02-09 20:32:21.935 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-09 20:32:21.936 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] New Play: (59RTfkiFiZn39FIfdwaAWR) Epica - Wings of Freedom
[2025-02-09 20:32:21.937 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 20:32:21.938 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] (31XLeIFY68pll9LNu1IkXV) Epica - Crimson Bow and Arrow added after met thresholds with tracked time of 341.49s (wanted 240s) and tracked percent of 100.00% (wanted 50%) and not matching any prior plays
[2025-02-09 20:32:21.942 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Epica - Crimson Bow and Arrow @ 2025-02-09T20:32:21+01:00 (C)
[2025-02-09 20:32:21.944 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:32:21+01:00 | Next check in 60.00s
[2025-02-09 20:33:22.065 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:33:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:34:22.218 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:34:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:35:22.363 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Ended current Player listen range.
[2025-02-09 20:35:22.365 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:35:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:36:22.564 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:36:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:37:22.758 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:37:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:38:22.941 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:38:22+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:39:23.128 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:39:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:40:23.286 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:40:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:41:23.429 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 20:41:23.435 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:41:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:42:23.592 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:42:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:43:23.752 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:43:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:44:23.909 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Incoming play state ((6bOGhjBs9luIUXrpRbCZ02) Epica - If Inside These Walls Was a House) does not match existing state, removing existing: (59RTfkiFiZn39FIfdwaAWR) Epica - Wings of Freedom
[2025-02-09 20:44:23.911 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-02-09 20:44:23.912 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] New Play: (6bOGhjBs9luIUXrpRbCZ02) Epica - If Inside These Walls Was a House
[2025-02-09 20:44:23.913 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Started new Player listen range.
[2025-02-09 20:44:23.914 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] (59RTfkiFiZn39FIfdwaAWR) Epica - Wings of Freedom not added because did not meet thresholds with tracked time of 120.58s (wanted 240s) and tracked percent of 36.00% (wanted 50%).
[2025-02-09 20:44:23.920 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:44:23+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:45:24.057 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [**REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-02-09 20:45:24.075 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:45:24+01:00 | Next check in 60.00s | No new tracks discovered
[2025-02-09 20:46:24.264 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:46:24+01:00 | Next check in 60.00s | No new tracks discovered

Edit 2 : It's just too tedious at the moment :-( I removed orphanedAfter and set back scrobbleThresholds.duration to 20.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working enhancement New feature or request safe to test trusted to build image
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants