Live scrobbling from Spotify suddenly not working. Backlog is, but is double scrobbling.

[duckfromdiscord]

Please check the FAQ before submitting a bug report.

Describe the bug multi scrobbler has stopped scrobbling from Spotify while running. It polls every 30-60s and no song is detected as playing, even when the poll happens during a song. All of these songs are then rescrobbled from backlog, including duplicates, when multi-scrobbler is restarted.

To Reproduce Steps to reproduce the behavior:

1. Open multi-scrobbler with a previously working Spotify -> Maloja config
2. Play a song
3. No scrobble shows up
4. Ctrl-C multi-scrobbler and restart
5. A bunch of duplicate scrobbles are made

Expected behavior Songs should be detected in a poll that runs during a song. Previous scrobbles should not be rescrobbled.

Logs Startup:

Checking CONFIG_DIR for existing configs: /root/.var/app/io.github.foxxmd.multiscrobbler/config
Directory is not empty! Will not add default config/examples
2023-08-19T21:40:02+00:00 debug   : [App] Config Dir ENV: /root/.var/app/io.github.foxxmd.multiscrobbler/config -> Resol
ved: /root/.var/app/io.github.foxxmd.multiscrobbler/config
2023-08-19T21:40:02+00:00 info    : [App] multi-scrobbler can be run as a background service! See: https://github.com/Fo
xxMD/multi-scrobbler/blob/develop/docs/service.md
2023-08-19T21:40:02+00:00 debug   : [Scrobblers] Constructing maloja (unnamed-mlj) client...
2023-08-19T21:40:02+00:00 debug   : [Scrobblers] Attempting maloja (unnamed-mlj) initialization...
2023-08-19T21:40:02+00:00 info    : [Scrobblers] [Maloja - unnamed-mlj] Communication test succeeded.
2023-08-19T21:40:02+00:00 info    : [Scrobblers] [Maloja - unnamed-mlj] Maloja Server Version: 3.1.5
2023-08-19T21:40:02+00:00 info    : [Scrobblers] maloja (unnamed-mlj) client initialized
2023-08-19T21:40:02+00:00 debug   : [Scrobblers] Checking maloja (unnamed-mlj) client auth...
2023-08-19T21:40:02+00:00 info    : [Scrobblers] [Maloja - unnamed-mlj] Auth test passed!
2023-08-19T21:40:02+00:00 info    : [Scrobblers] maloja (unnamed-mlj) client auth OK
2023-08-19T21:40:03+00:00 debug   : [Sources] (unnamed) Constructing spotify source
2023-08-19T21:40:03+00:00 debug   : [Sources] Attempting spotify (unnamed) initialization...
2023-08-19T21:40:03+00:00 info    : [Sources] spotify (unnamed) source initialized
2023-08-19T21:40:03+00:00 debug   : [Sources] Checking spotify (unnamed) source auth...
2023-08-19T21:40:03+00:00 info    : [Sources] spotify (unnamed) source auth OK
2023-08-19T21:40:04+00:00 info    : [App] Server started at http://localhost:9078
2023-08-19T21:40:05+00:00 info    : [Sources] [Spotify - unnamed] Checking recently played API for tracks to backlog...
2023-08-19T21:40:05+00:00 info    : [Sources] [Spotify - unnamed] Discovered => [some songs]
2023-08-19T21:40:05+00:00 info    : [Sources] [Spotify - unnamed] Backlog complete.
2023-08-19T21:40:05+00:00 info    : [Sources] [Spotify - unnamed] Polling started
2023-08-19T21:40:05+00:00 debug   : [Sources] [Spotify - unnamed] Refreshing recently played
2023-08-19T21:40:05+00:00 info    : [Scrobblers] [Maloja - unnamed-mlj] Server reported database is built and status is
healthy
2023-08-19T21:40:05+00:00 debug   : [Scrobblers] [Maloja - unnamed-mlj] Refreshing recent scrobbles
2023-08-19T21:40:05+00:00 debug   : [Scrobblers] [Maloja - unnamed-mlj] Found 40 recent scrobbles
2023-08-19T21:40:05+00:00 error   : [Scrobblers] [Maloja - unnamed-mlj] Encountered error while refreshing scrobbles
2023-08-19T21:40:05+00:00 error   : [Scrobblers] Cannot destructure property 'name' of '{}' as it is null.
TypeError:
    at MalojaScrobbler.formatPlayObj (CWD/src/clients/MalojaScrobbler.js:285:84)
    at MalojaScrobbler.formatPlayObj (CWD/src/clients/MalojaScrobbler.js:18:69)
    at CWD/src/clients/MalojaScrobbler.js:171:61
    at Array.map (<anonymous>)
    at MalojaScrobbler.refreshScrobbles (CWD/src/clients/MalojaScrobbler.js:171:45)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async ScrobbleClients.scrobble (CWD/src/clients/ScrobbleClients.js:349:25)
    at async EventEmitter.<anonymous> (CWD/src/clients/ScrobbleClients.js:391:13)
2023-08-19T21:40:05+00:00 info    : [Scrobblers] [Maloja - unnamed-mlj] Scrobbled (Backlog) => [some songs]

Example of a poll that ran while a song was playing:

2023-08-19T21:52:15+00:00 debug   : [Sources] [Spotify - unnamed] Refreshing recently played
2023-08-19T21:52:16+00:00 debug   : [Sources] [Spotify - unnamed] No new tracks discovered
2023-08-19T21:52:16+00:00 debug   : [Sources] [Spotify - unnamed] Last activity was at 2023-08-19T21:40:05+00:00 which is 7 minutes outside of active polling period of (last activity + 300 seconds). Will sleep for max interval 60 seconds.
2023-08-19T21:52:16+00:00 verbose : [Sources] [Spotify - unnamed] Sleeping for 60s

Versions (please complete the following information):

• multi-scrobbler: 0.4.4 flatpak
• maloja next_minor_version branch combined with the Spotify extended listening history fix: https://github.com/duckfromdiscord/maloja/tree/import_fix

Additional context maloja seems to occasionally glitch out until restarted, usually when trying to log in with the admin password. This has been happening even before upgrading to the new version, with no major scrobbling issue.

[duckfromdiscord]

Additionally, it seems like maloja is actually auto-removing some but not all of the double scrobbles:

[database] Incoming scrobble [Client: default | API: native/v1]: { [some song data] 'scrobble_time': 1692476203}
[dbcache] Invalidated 3 of 3 DB cache entries
[sqldb] 1 Scrobbles have not been written to database!
[dbcache] Invalidated 1 of 1 DB cache entries
[database] Incoming scrobble [Client: default | API: native/v1]: { [some song data] 'scrobble_time': 1692476498}
[dbcache] Invalidated 3 of 3 DB cache entries

From maloja logs, it seems the first song is skipped and the second one is not.

[duckfromdiscord]

Not happening right now, may have been a server issue?

[FoxxMD]

Could have been. Spotify isn't 100% reliable, but i usually find it to be good enough. Has it happened since?

[duckfromdiscord]

Yes, but I am not sure it’s the same issue. Now, it starts off working, but seems to randomly stop scrobbling after some unknown amount of time. Scrolling back in the logs I see “Access token was not valid, attempting to refresh” and then it continues to poll and receive nothing despite listening through multiple songs. Then when I restart it, it gets its backlog and works for another couple min/hr.

[duckfromdiscord]

Similarly to the initial issue, some of the backlog does get double scrobbled but not all of it.

[FoxxMD]

2023-08-19T21:40:05+00:00 error : [Scrobblers] Cannot destructure property 'name' of '{}' as it is null.

This can be fixed by bumping your flatpak version to 0.4.8

I've got a potential improvement for spotify (logging more error messages) in develop. I only build official releases for flatpak, however, so you'll need to use docker/git install to test it.

[duckfromdiscord]

Everything is updated now. Will re open if this issue reoccurs