bug: (YTM) With each scrobble, another song gets scrobbled

[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

As seen in the logs below, whenever a song gets scrobbled, 10 seconds later, another song gets scrobbled. I checked, and it's consistently the 20th spot in the YouTube Music play history. Something to do with this, somehow?

multi-scrobbler/src/backend/sources/YTMusicSource.ts

Line 276 in eb26ee0

const plays = listPlays.slice(0, 20);

This scrobble always (I think) gets rejected by Maloja, so it's not responsible for the duplicate scrobbles, but odd nonetheless.

Platform

Docker

Versions

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

Logs

[2024-11-12 00:31:07.628 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-12 00:31:08.236 +0100] INFO   : [App] [Sources] [Ytmusic - YT Music] Discovered => Ice Nine Kills - A Rash Decision @ 2024-11-12T00:31:01+01:00 (S)
[2024-11-12 00:31:08.237 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-12T00:31:01+01:00 | Next check interval: 10.00s
[2024-11-12 00:31:10.068 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] [Upstream Refresh] Should refresh => newest queued scrobble playDate is newer than last refresh
[2024-11-12 00:31:10.070 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Refreshing recent scrobbles
[2024-11-12 00:31:10.088 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Found 40 recent scrobbles
[2024-11-12 00:31:10.140 +0100] INFO   : [App] [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (New)     => (YTMusic) Ice Nine Kills - A Rash Decision @ 2024-11-12T00:31:01+01:00 (S)
[2024-11-12 00:31:10.141 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Raw Payload:
[2024-11-12 00:31:14.292 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] Refreshing recently played
[2024-11-12 00:31:14.375 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] No new tracks discovered
[2024-11-12 00:31:14.376 +0100] DEBUG  : [App] [Sources] [Spotify - unnamed] Last activity 2024-11-12T00:12:03+01:00 is 14 minutes outside of polling period (last activity + 300s) | Next check interval: (10 + 20)s
[2024-11-12 00:31:17.741 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
######### this shouldn't be here!
[2024-11-12 00:31:18.287 +0100] INFO   : [App] [Sources] [Ytmusic - YT Music] Discovered => 妖精帝國 - IRON ROSE @ 2024-11-12T00:31:01+01:00 (S)
[2024-11-12 00:31:18.287 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-12T00:31:01+01:00 | Next check interval: 10.00s
[2024-11-12 00:31:20.165 +0100] INFO   : [App] [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (New)     => (YTMusic) 妖精帝國 - IRON ROSE @ 2024-11-12T00:31:01+01:00 (S)
[2024-11-12 00:31:20.166 +0100] DEBUG  : [App] [Scrobblers] [Maloja - unnamed-mlj] Raw Payload:
[2024-11-12 00:31:27.798 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Refreshing recently played
[2024-11-12 00:31:28.314 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] No new tracks discovered
[2024-11-12 00:31:28.315 +0100] DEBUG  : [App] [Sources] [Ytmusic - YT Music] Last activity was at 2024-11-12T00:31:01+01:00 | Next check interval: 10.00s

Additional Context

This doesn't actually happen all the time, as I've just seen, but I'd guess it shows up in at least 80% of the cases.

[FoxxMD]

I'll try to reproduce this, thanks.

If you still see this occurring could you provide some more logs by changing your ytmusic config to have these options:

{
	"type": "ytmusic",
	"name": "YT Music",
	// ...
	"options": {
	    "logToFile": true,
	    "logDiff": true
	}
}

logToFile will cause MS to write a log file specifically for YTM which should help with keeping track of what it's doing. "logDiff": true will cause MS to log every YTM history change, not just when it thinks it's inconsistent. That should reveal the log diffs that are occurring when this 20th dropped track is accidentally "discovered'"

[xathon]

Still occurring, yeah. I'll set the options and get back to you.

[FoxxMD]

@xathon forgot to mention please change your docker image, use the latest foxxmd/multi-scrobbler:edge which includes improvements for those options logToFile logDiff

[xathon]

Some logfiles:
scrobble-2024-12-10.1.log
ytmusic-YTMusic-2024-12-10.1.log

YTM history:


=== everything after this was before I updated/restarted the server and the logfiles started

Maloja screenshot (pretty sure those timestamps are in UTC):

and for reference, the maloja log:
database.log

I think I see what's happening. A lot of times a song will get discovered, but 10 seconds later it's gone from the list (see for example l. 4416 ff. in the ytmusic log). This causes everything to move back up again, so that song 21 gets moved up to 20 and appears as a "new" song. Why that happens, no idea. Played around a bit with the web history, but when something gets added there, it stays.

The issue might be here?

multi-scrobbler/src/backend/sources/YTMusicSource.ts

Line 460 in b93274f

this.recentlyPlayed = plays;

Because the plays object doesn't yet have the new song, so when checking next time it compares the fetched list against the old list, moving everything back down? I can't say that I understand exactly what's happening, but that was the only thing that stood out to me a bit.