bug: (YTM) Songs skipped 0-9 seconds after their scrobble cause following song to be discarded

[xathon]

Please check existing knowledge before opening an issue

• I have checked the FAQ and documentation
• I have searched through existing issues and discussions.

Describe the Bug

In the attached log example, using youtube music, I skipped the song "And Plague Flowers the Kaleidoscope" a few seconds after it got scrobbled. This caused the following song "Invincible" to be scrobbled, but then rejected by Maloja. I'm not entirely certain whether that's something that Multiscrobbler can (or should) control, but maybe someone here has some better insight.

(Note: the scrobble of Army of the Night at 23:50:29 is a different issue, I'm still collecting data on that, but will raise another issue)

Platform

Docker

Versions

• multi-scrobbler: docker image foxxmd/multi-scrobbler:pr-203 (for yt auth)
• maloja: 3.2.2

Logs

############################################# Multiscrobbler log, copied from docker logs, so old -> new, not like in web interface

[2024-11-11 23:50:08.746 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-11 23:50:09.340 +0100] INFO   : [App] [Sources] [Ytmusic - YT Music] Discovered => Ne Obliviscaris - And Plague Flowers the Kaleidoscope @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:09.341 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-11T23:50:01+01:00 | Next check interval: 10.00s
[2024-11-11 23:50:09.784 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] [Upstream Refresh] Should refresh => newest queued scrobble playDate is newer than last refresh
[2024-11-11 23:50:09.785 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Refreshing recent scrobbles
[2024-11-11 23:50:09.806 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Found 40 recent scrobbles
[2024-11-11 23:50:09.852 +0100] INFO   : [App] [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (New)     => (YTMusic) Ne Obliviscaris - And Plague Flowers the Kaleidoscope @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:09.853 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Raw Payload:
[2024-11-11 23:50:18.851 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-11 23:50:19.397 +0100] WARN   : [App] [Sources] [Ytmusic - YT Music] YTM History returned temporally inconsistent order, resetting watched history to new list.
[2024-11-11 23:50:19.397 +0100] WARN   : [App] [Sources] [Ytmusic - YT Music] Changes from last seen list:
    1. (E4BrZxBFc24) Amaranthe - Invincible --- The Nexus => Replaced - Original => Ne Obliviscaris - And Plague Flowers the Kaleidoscope @ N/A
2. (sEuVjKWdoVc) Beyond The Black - Echo From The Past --- Heart Of The Hurricane (Black Edition)
3. (Il0yuLe8FBM) Within Temptation - Iron --- The Unforgiving
4. (my4fg5KWc-o) Powerwolf - Wolves Of War --- Interludium (Deluxe Version)
5. (hQ2JhlA6TpU) Nightwish - Perfume Of The Timeless --- Yesterwynde
6. (SbD9nAWtZTA) BABYMETAL - Road of Resistance (feat. Herman Li & Sam Totman) --- BABYMETAL
7. (WhTlsgAJXTw) Ice Nine Kills - The Shower Scene --- Welcome To Horrorwood: The Silver Scream 2
8. (8Sn0PSAqPn8) 妖精帝國 - IRON ROSE --- the age of villains
9. (Zx7K5wUYRSI) Beast In Black - Bella Donna --- Dark Connection
10. (MATJ_WRBv-c) Icon For Hire - Ready For Combat --- Ready For Combat
11. (clsxkUfFswk) Blackbriar - Preserved Roses --- Fractured Fairytales EP
12. (SQFzB_JUoIs) Saltatio Mortis / Tina Guo - Carry Me --- Finsterwacht
13. (9CjTdg6k0I8) Ad Infinitum - Somewhere Better --- Somewhere Better
14. (u-vHBUSDC6I) Warkings - Gladiator --- Gladiator
15. (804pjh6pcss) Mr. Hurley & Die Pulveraffen - Nichts zu verlieren --- Leuchtturm (Captain's Edition)
16. (lj4O63Swowo) Sabaton - To Hell and Back --- Heroes
17. (5aBZLwTONJ4) Amaranthe - Countdown --- HELIX
18. (wQLXo0aDFCw) Drei Meter Feldweg - Neue Single --- Neue Single
19. (ODiKg0BJr7k) Beyond The Black - Reincarnation --- Reincarnation
20. (Q_eM9qq6Zqw) Within Temptation - Supernova --- Resist (Extended Deluxe)
[2024-11-11 23:50:19.397 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] No new tracks discovered
[2024-11-11 23:50:19.398 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-11T23:50:01+01:00 | Next check interval: 10.00s
[2024-11-11 23:50:28.908 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-11 23:50:29.467 +0100] INFO   : [App] [Sources] [Ytmusic - YT Music] Discovered => Powerwolf - Army of the Night @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:29.468 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-11T23:50:01+01:00 | Next check interval: 10.00s
######## This scrobble/discovery shouldn't even be here, seperate issue. Gets rejected by Maloja.
[2024-11-11 23:50:29.878 +0100] INFO   : [App] [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (New)     => (YTMusic) Powerwolf - Army of the Night @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:29.879 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Raw Payload:
[2024-11-11 23:50:35.491 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] Refreshing recently played
[2024-11-11 23:50:35.577 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] No new tracks discovered
[2024-11-11 23:50:35.577 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] Last activity 2024-11-09T19:29:25+01:00 is 2 days outside of polling period (last activity + 300s) | Next check interval: (10 + 20)s
[2024-11-11 23:50:38.979 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-11 23:50:39.550 +0100] INFO   : [App] [Sources] [Ytmusic - YT Music] Discovered => Amaranthe - Invincible @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:39.551 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-11T23:50:01+01:00 | Next check interval: 10.00s
######## this scrobble gets rejected
[2024-11-11 23:50:39.905 +0100] INFO   : [App] [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (New)     => (YTMusic) Amaranthe - Invincible @ 2024-11-11T23:50:01+01:00 (S)
[2024-11-11 23:50:39.906 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Raw Payload:
[2024-11-11 23:50:49.063 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-11 23:50:49.626 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] No new tracks discovered
[2024-11-11 23:50:49.627 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-11T23:50:01+01:00 | Next check interval: 10.00s



############################################################ Maloja log
[database] Incoming scrobble [Client: multiscrobbler | API: native/v1]: {'track_artists': ['Ne Obliviscaris'], 'track_title': 'And Plague Flowers the Kaleidoscope', 'album_title': 'Portal of I', 'track_length': 693, 'scrobble_time': 1731365401}
[dbcache] Invalidated 9 of 45 DB cache entries
[database] Incoming scrobble [Client: multiscrobbler | API: native/v1]: {'track_artists': ['Powerwolf'], 'track_title': 'Army of the Night', 'album_title': 'Blessed & Possessed', 'track_length': 202, 'scrobble_time': 1731365401}
[sqldb] 1 Scrobbles have not been written to database!
[dbcache] Invalidated 4 of 40 DB cache entries
[database] Incoming scrobble [Client: multiscrobbler | API: native/v1]: {'track_artists': ['Amaranthe'], 'track_title': 'Invincible', 'album_title': 'The Nexus', 'track_length': 192, 'scrobble_time': 1731365401}
[sqldb] 1 Scrobbles have not been written to database!
[dbcache] Invalidated 4 of 40 DB cache entries

Additional Context

No response

[FoxxMD]

The scrobble is being rejected because MS is sending the scrobble with the same timestamp as an existing scrobble in Maloja.

And Plague Flowers the Kaleidoscope @ 2024-11-11T23:50:01+01:00
Army of the Night @ 2024-11-11T23:50:01+01:00

Maloja doesn't allow scrobbles with the same timestamps. This is due to defensive design in MS and (mostly) as expected -- MS sets the timestamp for a discovered scrobble as 1 second past the current minute. The assumption is that you aren't listening to many multiple songs per minute because tracks shouldn't be that short. If MS tries to scrobble multiple tracks in that minute then the scrobble client will reject all but the first one.

It's not great design but it does help with preventing false positives a bit...definitely something I need to improve so MS just drops the play instead of trying to scrobble it.

[FoxxMD]

@xathon The newest foxxmd/multi-scrobbler:pr-248 docker image now includes improvements for this:

• Detect skipped plays based on reasonable time elapsed since last discovered track
  *Newest track is always added as it could be playing now, n+1 tracks are added based on cumulative elapsed - duration
• Valid interim tracks are given play date based on now - cumulative duration of all prior interim tracks

Please try it out and let me know how it works for you. Note that this is a newer image than then one from #228 so if you are already running it please re-pull for the newest changes.

[FoxxMD]

Fixed in v0.9.0