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

bug: "duplicate_timestamp" error when scrobbling to Maloja 3.2.3 #254

Closed
2 tasks done
Fratt opened this issue Jan 17, 2025 · 12 comments · Fixed by #255
Closed
2 tasks done

bug: "duplicate_timestamp" error when scrobbling to Maloja 3.2.3 #254

Fratt opened this issue Jan 17, 2025 · 12 comments · Fixed by #255
Labels
bug Something isn't working

Comments

@Fratt
Copy link
Contributor

Fratt commented Jan 17, 2025

Please check existing knowledge before opening an issue

Describe the Bug

Maloja 3.2.3 has been released 2 days ago ! (yay!)

But... I have been experiencing some issues with Multi-Scrobbler since I updated to it :-(

When I pause a song in the middle of it, and I resume it later, the scrobble for that song cannot be pushed to Maloja, and I receive the following error in Multi-Scrobbler (see below).

It is not clear yet to me if this is every time the case, but it seems to happen often.

Pressing "Retry" in Multi-Scrobbler doesn't work : It returns the same error from Maloja.
This error seems "justified" from Maloja : If I look at the timestamp in question, I find a scrobble there : A scrobble for a different song.

When I find the time, I will try to find a reproduction scenario + submit more logs to help you debug it.

Thanks in advance!

Platform

Docker

Versions

  • multi-scrobbler 0.9.0
  • Maloja 3.2.3

Logs

[2025-01-17 15:13:35.204 +0100] ERROR  : [App] [Scrobblers] [Maloja - Maloja] Could not scrobble Ensiferum - Burning Leaves @ 2025-01-17T14:55:07+01:00 (S) from Source 'Spotify - Spotify' due to error
Error: Could not scrobble Ensiferum - Burning Leaves @ 2025-01-17T14:55:07+01:00 (S) from Source 'Spotify - Spotify' due to error
    at MalojaScrobbler.processDeadLetterScrobble (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:717:35)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at MalojaScrobbler.processDeadLetterQueue (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:684:43)
    at PromisePoolExecutor.handler (CWD/src/backend/tasks/heartbeatClients.ts:35:21)
    at async PromisePoolExecutor.waitForActiveTaskToFinish (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:375:9)
    at async PromisePoolExecutor.waitForProcessingSlot (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:368:13)
    at async PromisePoolExecutor.process (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:354:13)
    at async PromisePoolExecutor.start (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:273:16)
caused by: Error: Maloja API returned error of type duplicate_timestamp "A scrobble is already registered with this timestamp.": {"time":1737122107,"track":{"artists":["Ensiferum"],"title":"Burning Leaves","album":{"albumtitle":"Unsung Heroes (Japan Version)","artists":["Ensiferum"]},"length":363},"duration":240,"origin":"client:multi-scrobbler","extra":{"album_title":"Unsung Heroes (Japan Version)","album_artists":["Ensiferum"]},"rawscrobble":{"track_artists":["Ensiferum"],"track_title":"Burning Leaves","album_title":"Unsung Heroes (Japan Version)","scrobble_duration":240,"track_length":363,"scrobble_time":1737122107}}
    at MalojaScrobbler.callApi (CWD/src/backend/scrobblers/MalojaScrobbler.ts:158:27)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at MalojaScrobbler.doScrobble (CWD/src/backend/scrobblers/MalojaScrobbler.ts:406:30)
    at MalojaScrobbler.processDeadLetterScrobble (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:710:39)
    at MalojaScrobbler.processDeadLetterQueue (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:684:43)
    at PromisePoolExecutor.handler (CWD/src/backend/tasks/heartbeatClients.ts:35:21)
    at async PromisePoolExecutor.waitForActiveTaskToFinish (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:375:9)
    at async PromisePoolExecutor.waitForProcessingSlot (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:368:13)
    at async PromisePoolExecutor.process (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:354:13)
    at async PromisePoolExecutor.start (CWD/node_modules/@supercharge/promise-pool/dist/promise-pool-executor.js:273:16)
caused by: Error: Conflict
    at callback (CWD/node_modules/superagent/src/node/index.js:901:17)
    at <anonymous> (CWD/node_modules/superagent/src/node/index.js:1166:18)
    at IncomingMessage.<anonymous> (CWD/node_modules/superagent/src/node/parsers/json.js:19:7)
    at IncomingMessage.emit (node:events:530:35)
    at endReadableNT (node:internal/streams/readable:1696:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)

Additional Context

No response

@Fratt Fratt added the bug Something isn't working label Jan 17, 2025
@Fratt Fratt changed the title bug: "duplicate_timestmap" error when scrobbling to Maloja 3.2.3 bug: "duplicate_timestamp" error when scrobbling to Maloja 3.2.3 Jan 17, 2025
@FoxxMD
Copy link
Owner

FoxxMD commented Jan 17, 2025

This somewhat expected from the Maloja side, actually. In Maloja < 3.2.3 it still detected a duplicate timestamp but did not return an error, instead just silently failing and not scrobbling. This was fixed in January 2024 so it would return an error response but was not released until 3.2.3. In general, we do not want to be scrobbling tracks with the same timestamp.

From the MS side...I think I know the issue but would like to verify your behavior and what is expected.

As I mentioned in our discussion on scrobble thresholds MS will scrobble only when 1) the track changes or the Source becomes stale (no update for some time) 2) the played track has met the traditional scrobble thresholds IE 50% played or 4 minutes(?) of play time.

What I'm guessing is happening is that:

  • you are playing a track long enough it meets scrobble threshold
  • pause the source and it becomes stale, somehow, which causes MS to scrobble
  • resume the track later while MS still has the track in memory as stale, which causes it to be active again
  • track finishes/changes, MS tries to scrobble again but Maloja rejects it

And the reason its rejecting it is because MS only set the "first seen at" date, which it uses as scrobble timestamp, once, when it first encountered the track. Since it never drops the track from the Source player (in MS) the second scrobble uses the original timestamp, instead of a timestamp from when you resumed the track.

Does that align with what you are seeing behavior wise from MS? IE Do you see track is stale in logs but not something like dropping due to orphaned player?

@Fratt
Copy link
Contributor Author

Fratt commented Jan 17, 2025

Hello,

This is not exactly what is happening, I looked at it more closely.

What seems to happen is that when a track becomes stale (and has reached the threshold before), MS will scrobble it with the same timestamp as the previous track that he scrobbled before, instead of using a more "recent" timestamp. Maloja then rejects that scrobble.

This just happened now : I went to eat, so I paused the music. 15-20 minutes later, I got a notification from MS telling me that it couldn't scrobble the song that I was listening before going to eat... I checked, the timestamp it tried to use was the same timestamp as the previous song (that I can see in Maloja).

I assume that when such thing happen, if I resume the play and there was not enough time to hit the threshold (a second time), then the scrobble is lost forever.

Does that make sense to you ?

A dirty workaround I see (if you cannot find a "better" timestamp for the track that got stale) is to keep the "last timestamp used" in the client, and simply increment it by 1 if trying to scrobble a song with the same timestamp...

@Fratt
Copy link
Contributor Author

Fratt commented Jan 17, 2025

Would it help you to see some logs?

@FoxxMD
Copy link
Owner

FoxxMD commented Jan 17, 2025

Hmm ok that is definitely unexpected then. More logs are always helpful but your description is enough to get started on. Thanks for the input, I'll see if I can isolate this bug.

FoxxMD added a commit that referenced this issue Jan 17, 2025
… timestamp

Missing arg to pass to getPlayedObject to ensure the timestamp used for playDate is the same as normally discovered tracks. Without the arg two tracks played with the second being scrobbled on stale would cause the latter to have the same TS as the former

fixes #254
@FoxxMD FoxxMD linked a pull request Jan 17, 2025 that will close this issue
2 tasks
@FoxxMD
Copy link
Owner

FoxxMD commented Jan 17, 2025

Try out docker image foxxmd/multi-scrobbler:pr-255 and let me know if that fixes things for you

@Fratt
Copy link
Contributor Author

Fratt commented Jan 17, 2025

Just saw your message now, I will try immediately, thanks a lot !

In the meantime, I gathered this for you (probably for nothing :D) - Since I did the job, I'll post it anyway.

  • 7:49 PM : Started "My Ancestor's Blood"
  • 7:53 PM : Finished "My Ancestor's Blood" -> Scrobbled successfully to Maloja
  • 7:53 PM : Started "Descendants, Defiance, Domination"
  • 8:04 PM : Paused "Descendants, Defiance, Domination" @ 10:15
  • 8:17 PM : Receive an alert from MS ("Descendants, Defiance, Domination", "A scrobble is already registered with this timestamp", 1737140030 = 7:53 PM)
  • 8:21 PM : Resumed "Descendants, Defiance, Domination" @ 10:15
  • 8:22 PM : Finished "Descendants, Defiance, Domination" (total duration 11:20) -> *Not scrobbled to Maloja!
  • 8:22 PM : Started "Neito Pohjolan"
  • 8:26 PM : Finished "Neito Pohjolan" -> Scrobbled successfully to Maloja
[2025-01-17 19:49:14.493 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:49:24.747 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((5AFr1Jt1cRTBxE1uUIWnKm) Ensiferum - My Ancestors' Blood) does not match existing state, removing existing: (60f1s0PSfuYNDqmA3wEOQk) Ensiferum - Two of Spades
[2025-01-17 19:49:24.749 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-01-17 19:49:24.751 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (5AFr1Jt1cRTBxE1uUIWnKm) Ensiferum - My Ancestors' Blood
[2025-01-17 19:49:24.752 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 19:49:24.754 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (60f1s0PSfuYNDqmA3wEOQk) Ensiferum - Two of Spades not added because did not meet thresholds with tracked time of 0.00s (wanted 20s) and tracked percent of 0.00% (wanted 50%).
[2025-01-17 19:49:24.768 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:49:24+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:49:44.505 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:50:14.529 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:50:24.899 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-01-17 19:50:24.917 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:50:24+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:50:44.552 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:51:14.571 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:51:25.084 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:51:25+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:51:44.602 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:52:14.623 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:52:25.218 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:52:25+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:52:44.644 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:53:14.664 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:53:25.348 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 23.49s due to Player **REDACTED**-SingleUser reporting track duration remaining (25.49s) less than normal interval (60.00s)
[2025-01-17 19:53:25.349 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:53:25+01:00 | Next check in 23.49s | No new tracks discovered
[2025-01-17 19:53:35.156 +0100] VERBOSE: [App] [Heartbeat] [Clients] Starting check...
[2025-01-17 19:53:35.158 +0100] VERBOSE: [App] [Scrobblers] [Maloja - Maloja] 0 of 5 dead scrobbles have less than 1 retries, will skip processing.
[2025-01-17 19:53:35.160 +0100] VERBOSE: [App] [Heartbeat] [Clients] Checked Dead letter queue for 1 clients.
[2025-01-17 19:53:35.200 +0100] VERBOSE: [App] [Heartbeat] [Sources] Starting check...
[2025-01-17 19:53:35.202 +0100] VERBOSE: [App] [Heartbeat] [Sources] Checked 2 sources for start signals.
[2025-01-17 19:53:44.688 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:53:49.024 +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-01-17 19:53:49.025 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:53:49+01:00 | Next check in 1.00s | No new tracks discovered
[2025-01-17 19:53:50.155 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((7lruqjGsAYKuY3a3O4rKT2) Ensiferum - Descendants, Defiance, Domination) does not match existing state, removing existing: (5AFr1Jt1cRTBxE1uUIWnKm) Ensiferum - My Ancestors' Blood
[2025-01-17 19:53:50.157 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-01-17 19:53:50.158 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-01-17 19:53:50.162 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (7lruqjGsAYKuY3a3O4rKT2) Ensiferum - Descendants, Defiance, Domination
[2025-01-17 19:53:50.164 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 19:53:50.166 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (5AFr1Jt1cRTBxE1uUIWnKm) Ensiferum - My Ancestors' Blood added after met thresholds with tracked time of 266.09s (wanted 20s) and tracked percent of 98.00% (wanted 50%) and not matching any prior plays
[2025-01-17 19:53:50.176 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Ensiferum - My Ancestors' Blood @ 2025-01-17T19:53:50+01:00 (C)
[2025-01-17 19:53:50.177 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:53:50+01:00 | Next check in 60.00s
[2025-01-17 19:53:51.962 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] [Upstream Refresh] Should refresh => newest queued scrobble playDate is newer than last refresh
[2025-01-17 19:53:51.964 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Refreshing recent scrobbles
[2025-01-17 19:53:51.990 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Found 40 recent scrobbles
[2025-01-17 19:53:52.043 +0100] INFO   : [App] [Scrobblers] [Maloja - Maloja] Scrobbled (New)     => (Spotify) Ensiferum - My Ancestors' Blood @ 2025-01-17T19:53:50+01:00 (C)
[2025-01-17 19:53:52.043 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Raw Payload:
[2025-01-17 19:54:14.704 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:54:44.724 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:54:50.347 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:54:50+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:55:14.753 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:55:44.776 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:55:50.510 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:55:50+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:56:14.795 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:56:44.820 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:56:50.675 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:56:50+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:57:14.840 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:57:44.862 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:57:50.871 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:57:50+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:58:14.888 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:58:44.909 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:58:51.066 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:58:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 19:59:14.936 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:59:44.968 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 19:59:51.233 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 19:59:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:00:14.982 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:00:45.006 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:00:51.440 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:00:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:01:15.028 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:01:45.052 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:01:51.648 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:01:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:02:15.074 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:02:45.096 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:02:51.794 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:02:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:03:15.119 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:03:45.138 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:03:51.937 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:03:51+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:04:15.154 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:04:45.176 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:04:52.187 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-01-17 20:04:52.193 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:04:52+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:05:15.201 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:05:45.225 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:05:52.370 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:05:52+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:06:15.250 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:06:45.274 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:06:52.539 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:06:52+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:07:15.298 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:07:45.316 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:07:52.733 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:07:52+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:08:15.339 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:08:45.359 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:08:52.914 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:08:52+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:09:15.380 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:09:45.399 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:09:53.067 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:09:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:10:15.414 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:10:45.431 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:10:53.280 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:10:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:11:15.449 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:11:45.469 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:11:53.459 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:11:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:12:15.489 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:12:45.511 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:12:53.603 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:12:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:13:15.537 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:13:35.156 +0100] VERBOSE: [App] [Heartbeat] [Clients] Starting check...
[2025-01-17 20:13:35.158 +0100] VERBOSE: [App] [Scrobblers] [Maloja - Maloja] 0 of 5 dead scrobbles have less than 1 retries, will skip processing.
[2025-01-17 20:13:35.160 +0100] VERBOSE: [App] [Heartbeat] [Clients] Checked Dead letter queue for 1 clients.
[2025-01-17 20:13:35.199 +0100] VERBOSE: [App] [Heartbeat] [Sources] Starting check...
[2025-01-17 20:13:35.201 +0100] VERBOSE: [App] [Heartbeat] [Sources] Checked 2 sources for start signals.
[2025-01-17 20:13:45.555 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:13:53.753 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:14:15.574 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:14:45.594 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:14:53.859 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:15:15.610 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:15:45.627 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:15:53.978 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:16:15.649 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:16:45.672 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:16:54.103 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Access token was not valid, attempting to refresh
[2025-01-17 20:16:54.271 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:17:15.690 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:17:45.702 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:17:54.393 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Stale after no Play updates for 240 seconds
[2025-01-17 20:17:54.405 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] [Stale Player Cleanup] (7lruqjGsAYKuY3a3O4rKT2) Ensiferum - Descendants, Defiance, Domination added after met thresholds with tracked time of 601.24s (wanted 20s) and tracked percent of 88.00% (wanted 50%) and not matching any prior plays
[2025-01-17 20:17:54.409 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Ensiferum - Descendants, Defiance, Domination @ 2025-01-17T19:53:50+01:00 (S)
[2025-01-17 20:17:54.412 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 60.00s
[2025-01-17 20:17:56.254 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] [Upstream Refresh] Should refresh => last refresh (1444s ago) was longer than refreshStaleAfter (60s)
[2025-01-17 20:17:56.255 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Refreshing recent scrobbles
[2025-01-17 20:17:56.279 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Found 40 recent scrobbles
[2025-01-17 20:17:56.342 +0100] VERBOSE: [App] [Notifiers] [Gotify - Gotify] Pushed notification.
[2025-01-17 20:17:56.343 +0100] ERROR  : [App] [Scrobblers] [Maloja - Maloja] Scrobble Error (New)
[2025-01-17 20:17:56.343 +0100] ERROR  : [App] [Scrobblers] [Maloja - Maloja] Raw Response:
[2025-01-17 20:17:56.343 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Raw Payload:
[2025-01-17 20:17:56.344 +0100] WARN   : [App] [Scrobblers] [Maloja - Maloja] Could not scrobble Ensiferum - Descendants, Defiance, Domination @ 2025-01-17T19:53:50+01:00 (S) from Source 'Spotify - Spotify' but error was not show stopping. Adding scrobble to Dead Letter Queue and will retry on next heartbeat.
Error: Could not scrobble Ensiferum - Descendants, Defiance, Domination @ 2025-01-17T19:53:50+01:00 (S) from Source 'Spotify - Spotify' but error was not show stopping. Adding scrobble to Dead Letter Queue and will retry on next heartbeat.
    at MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:633:50)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:553:27)
caused by: Error: Maloja API returned error of type duplicate_timestamp "A scrobble is already registered with this timestamp.": {"time":1737140030,"track":{"artists":["Ensiferum"],"title":"Descendants, Defiance, Domination","album":{"albumtitle":"One Man Army","artists":["Ensiferum"]},"length":680},"duration":601,"origin":"client:multi-scrobbler","extra":{"album_title":"One Man Army","album_artists":["Ensiferum"]},"rawscrobble":{"track_artists":["Ensiferum"],"track_title":"Descendants, Defiance, Domination","album_title":"One Man Army","scrobble_duration":601,"track_length":680,"scrobble_time":1737140030}}
    at MalojaScrobbler.callApi (CWD/src/backend/scrobblers/MalojaScrobbler.ts:158:27)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at MalojaScrobbler.doScrobble (CWD/src/backend/scrobblers/MalojaScrobbler.ts:406:30)
    at MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:627:51)
    at MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:553:27)
caused by: Error: Conflict
    at callback (CWD/node_modules/superagent/src/node/index.js:901:17)
    at <anonymous> (CWD/node_modules/superagent/src/node/index.js:1166:18)
    at IncomingMessage.<anonymous> (CWD/node_modules/superagent/src/node/parsers/json.js:19:7)
    at IncomingMessage.emit (node:events:530:35)
    at endReadableNT (node:internal/streams/readable:1696:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
[2025-01-17 20:18:15.732 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:18:45.754 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:18:54.536 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Orphaned after no player updates for 5 minutes
[2025-01-17 20:18:54.539 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 30.00 | No new tracks discovered
[2025-01-17 20:19:15.773 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:19:45.788 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:19:54.664 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 30.00 | No new tracks discovered
[2025-01-17 20:20:15.808 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:20:45.827 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:20:54.811 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:13:53+01:00 | Next check in 30.00 | No new tracks discovered
[2025-01-17 20:21:15.850 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:21:45.882 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:21:54.999 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 20:21:55.017 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:21:54+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:22:15.902 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:22:45.929 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:22:55.160 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((0cgqwX4zz1Ac7hbLc36Jtm) Ensiferum - Neito Pohjolan) does not match existing state, removing existing: (7lruqjGsAYKuY3a3O4rKT2) Ensiferum - Descendants, Defiance, Domination
[2025-01-17 20:22:55.160 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-01-17 20:22:55.161 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (0cgqwX4zz1Ac7hbLc36Jtm) Ensiferum - Neito Pohjolan
[2025-01-17 20:22:55.161 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 20:22:55.161 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (7lruqjGsAYKuY3a3O4rKT2) Ensiferum - Descendants, Defiance, Domination not added because an identical play with the same timestamp was already discovered.
[2025-01-17 20:22:55.165 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:22:55+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:23:15.945 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:23:45.963 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:23:55.281 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Player position changed between current -> last update. Updated calculated status to playing
[2025-01-17 20:23:55.285 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:23:55+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:24:15.985 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:24:46.002 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:24:55.444 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:24:55+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:25:16.015 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:25:46.035 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:25:55.591 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 38.76s due to Player **REDACTED**-SingleUser reporting track duration remaining (40.76s) less than normal interval (60.00s)
[2025-01-17 20:25:55.591 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:25:55+01:00 | Next check in 38.76s | No new tracks discovered
[2025-01-17 20:26:16.057 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 2025-01-16T12:33:35+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:26:34.709 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to Player **REDACTED**-SingleUser reporting track duration remaining (1.64s) less than normal interval (60.00s)
[2025-01-17 20:26:34.710 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:26:34+01:00 | Next check in 1.00s | No new tracks discovered
[2025-01-17 20:26:35.852 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to Player **REDACTED**-SingleUser reporting track duration remaining (0.54s) less than normal interval (60.00s)
[2025-01-17 20:26:35.853 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:26:35+01:00 | Next check in 1.00s | No new tracks discovered
[2025-01-17 20:26:36.948 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((5b9zZvx94km0eGxFm5wvV3) Ensiferum - Rawhide (Bonus Track)) does not match existing state, removing existing: (0cgqwX4zz1Ac7hbLc36Jtm) Ensiferum - Neito Pohjolan
[2025-01-17 20:26:36.950 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-01-17 20:26:36.952 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-01-17 20:26:36.955 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (5b9zZvx94km0eGxFm5wvV3) Ensiferum - Rawhide (Bonus Track)
[2025-01-17 20:26:36.957 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 20:26:36.959 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (0cgqwX4zz1Ac7hbLc36Jtm) Ensiferum - Neito Pohjolan added after met thresholds with tracked time of 221.20s (wanted 20s) and tracked percent of 88.00% (wanted 50%) and not matching any prior plays
[2025-01-17 20:26:36.970 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Ensiferum - Neito Pohjolan @ 2025-01-17T20:26:36+01:00 (C)
[2025-01-17 20:26:36.972 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:26:36+01:00 | Next check in 60.00s
[2025-01-17 20:26:38.433 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] [Upstream Refresh] Should refresh => newest queued scrobble playDate is newer than last refresh
[2025-01-17 20:26:38.435 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Refreshing recent scrobbles
[2025-01-17 20:26:38.462 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Found 40 recent scrobbles
[2025-01-17 20:26:38.514 +0100] INFO   : [App] [Scrobblers] [Maloja - Maloja] Scrobbled (New)     => (Spotify) Ensiferum - Neito Pohjolan @ 2025-01-17T20:26:36+01:00 (C)
[2025-01-17 20:26:38.515 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Raw Payload:

@Fratt
Copy link
Contributor Author

Fratt commented Jan 17, 2025

I tried pr255, but I'm afraid it's not working :-(

  • 8:48 PM : Finished "For Those About To Fight For Metal" -> Scrobbled successfully to Maloja
  • 8:48 PM : Started "Way of the Warrior" (length: 3:57)
  • 8:52 PM : Paused "Way of the Warrior" @ 3:35
  • 9:05 PM : Receive an alert from MS ("Way of the Warrior", "A scrobble is already registered with this timestamp", 1737143296 = 8:48 PM)

Logs:

[2025-01-17 20:48:10.383 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:48:14.882 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Temporarily decreasing polling interval to 1.00s due to Player **REDACTED**-SingleUser reporting track duration remaining (1.92s) less than normal interval (60.00s)
[2025-01-17 20:48:14.882 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:48:14+01:00 | Next check in 1.00s | No new tracks discovered
[2025-01-17 20:48:15.999 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Incoming play state ((5XJ1jQYn3l4KCNx3IoIC3r) Ensiferum - Way of the Warrior) does not match existing state, removing existing: (43q96dY1coOtTywVVeOdAc) Ensiferum - For Those About to Fight for Metal
[2025-01-17 20:48:16.002 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-01-17 20:48:16.004 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Generating play object with playDateCompleted
[2025-01-17 20:48:16.005 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] New Play: (5XJ1jQYn3l4KCNx3IoIC3r) Ensiferum - Way of the Warrior
[2025-01-17 20:48:16.006 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 20:48:16.008 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] (43q96dY1coOtTywVVeOdAc) Ensiferum - For Those About to Fight for Metal added after met thresholds with tracked time of 316.52s (wanted 20s) and tracked percent of 100.00% (wanted 50%) and not matching any prior plays
[2025-01-17 20:48:16.017 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Ensiferum - For Those About to Fight for Metal @ 2025-01-17T20:48:16+01:00 (C)
[2025-01-17 20:48:16.019 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:48:15+01:00 | Next check in 60.00s
[2025-01-17 20:48:17.852 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] [Upstream Refresh] Should refresh => last refresh (318s ago) was longer than refreshStaleAfter (60s)
[2025-01-17 20:48:17.853 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Refreshing recent scrobbles
[2025-01-17 20:48:17.874 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Found 40 recent scrobbles
[2025-01-17 20:48:17.933 +0100] INFO   : [App] [Scrobblers] [Maloja - Maloja] Scrobbled (New)     => (Spotify) Ensiferum - For Those About to Fight for Metal @ 2025-01-17T20:48:16+01:00 (C)
[2025-01-17 20:48:17.933 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Raw Payload:
[2025-01-17 20:48:40.427 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:49:10.456 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:49:16.155 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Detected player was seeked -9.12s, starting new listen range
[2025-01-17 20:49:16.157 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Started new Player listen range.
[2025-01-17 20:49:16.168 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:49:16+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:49:40.488 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:50:10.520 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:50:16.364 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:50:16+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:50:40.538 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:51:10.556 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:51:16.554 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:51:16+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:51:40.582 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:52:10.617 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:52:16.754 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Ended current Player listen range.
[2025-01-17 20:52:16.760 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:52:16+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:52:40.650 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:53:10.672 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:53:16.916 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:53:16+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:53:40.703 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:54:10.732 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:54:17.094 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:54:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:54:40.750 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:55:10.763 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:55:17.266 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:55:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:55:40.780 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:56:10.802 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:56:17.431 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:56:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:56:40.831 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:57:10.858 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:57:17.591 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:57:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:57:40.881 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:57:50.065 +0100] VERBOSE: [App] [Heartbeat] [Clients] Starting check...
[2025-01-17 20:57:50.067 +0100] VERBOSE: [App] [Heartbeat] [Clients] Checked Dead letter queue for 1 clients.
[2025-01-17 20:57:50.068 +0100] VERBOSE: [App] [Heartbeat] [Sources] Starting check...
[2025-01-17 20:57:50.069 +0100] VERBOSE: [App] [Heartbeat] [Sources] Checked 2 sources for start signals.
[2025-01-17 20:58:10.906 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:58:17.773 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:58:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:58:40.930 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:59:10.946 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 20:59:17.948 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 20:59:17+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 20:59:40.976 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:00:11.010 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:00:18.114 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:00:18+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 21:00:41.034 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:01:11.058 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:01:18.271 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:01:18+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 21:01:41.073 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:02:11.106 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:02:18.389 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:01:18+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 21:02:41.132 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:03:11.152 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:03:18.519 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:01:18+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 21:03:41.176 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:04:11.192 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:04:18.649 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:01:18+01:00 | Next check in 60.00s | No new tracks discovered
[2025-01-17 21:04:41.215 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:05:11.229 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:05:18.794 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Stale after no Play updates for 240 seconds
[2025-01-17 21:05:18.800 +0100] VERBOSE: [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] [Stale Player Cleanup] (5XJ1jQYn3l4KCNx3IoIC3r) Ensiferum - Way of the Warrior added after met thresholds with tracked time of 120.38s (wanted 20s) and tracked percent of 51.00% (wanted 50%) and not matching any prior plays
[2025-01-17 21:05:18.800 +0100] INFO   : [App] [Sources] [Spotify - Spotify] Discovered => Ensiferum - Way of the Warrior @ 2025-01-17T20:48:16+01:00 (S)
[2025-01-17 21:05:18.801 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] Last activity was at 21:01:18+01:00 | Next check in 60.00s
[2025-01-17 21:05:20.082 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] [Upstream Refresh] Should refresh => last refresh (1022s ago) was longer than refreshStaleAfter (60s)
[2025-01-17 21:05:20.084 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Refreshing recent scrobbles
[2025-01-17 21:05:20.118 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Found 40 recent scrobbles
[2025-01-17 21:05:20.173 +0100] VERBOSE: [App] [Notifiers] [Gotify - Gotify] Pushed notification.
[2025-01-17 21:05:20.173 +0100] ERROR  : [App] [Scrobblers] [Maloja - Maloja] Scrobble Error (New)
[2025-01-17 21:05:20.174 +0100] ERROR  : [App] [Scrobblers] [Maloja - Maloja] Raw Response:
[2025-01-17 21:05:20.174 +0100] DEBUG  : [App] [Scrobblers] [Maloja - Maloja] Raw Payload:
[2025-01-17 21:05:20.174 +0100] WARN   : [App] [Scrobblers] [Maloja - Maloja] Could not scrobble Ensiferum - Way of the Warrior @ 2025-01-17T20:48:16+01:00 (S) from Source 'Spotify - Spotify' but error was not show stopping. Adding scrobble to Dead Letter Queue and will retry on next heartbeat.
Error: Could not scrobble Ensiferum - Way of the Warrior @ 2025-01-17T20:48:16+01:00 (S) from Source 'Spotify - Spotify' but error was not show stopping. Adding scrobble to Dead Letter Queue and will retry on next heartbeat.
    at MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:633:50)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:553:27)
caused by: Error: Maloja API returned error of type duplicate_timestamp "A scrobble is already registered with this timestamp.": {"time":1737143296,"track":{"artists":["Ensiferum"],"title":"Way of the Warrior","album":{"albumtitle":"Two Paths","artists":["Ensiferum"]},"length":237},"duration":120,"origin":"client:multi-scrobbler","extra":{"album_title":"Two Paths","album_artists":["Ensiferum"]},"rawscrobble":{"track_artists":["Ensiferum"],"track_title":"Way of the Warrior","album_title":"Two Paths","scrobble_duration":120,"track_length":237,"scrobble_time":1737143296}}
    at MalojaScrobbler.callApi (CWD/src/backend/scrobblers/MalojaScrobbler.ts:158:27)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async MalojaScrobbler.doScrobble (CWD/src/backend/scrobblers/MalojaScrobbler.ts:406:30)
    at async MalojaScrobbler.doProcessing (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:627:51)
    at async MalojaScrobbler.startScrobbling (CWD/src/backend/scrobblers/AbstractScrobbleClient.ts:553:27)
caused by: Error: Conflict
    at callback (CWD/node_modules/superagent/src/node/index.js:901:17)
    at <anonymous> (CWD/node_modules/superagent/src/node/index.js:1166:18)
    at IncomingMessage.<anonymous> (CWD/node_modules/superagent/src/node/parsers/json.js:19:7)
    at IncomingMessage.emit (node:events:530:35)
    at endReadableNT (node:internal/streams/readable:1698:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
[2025-01-17 21:05:41.247 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:06:11.272 +0100] DEBUG  : [App] [Sources] [Plex - Plex] Last activity was at 20:37:50+01:00 | Next check in (5 + 25) | No new tracks discovered
[2025-01-17 21:06:18.907 +0100] DEBUG  : [App] [Sources] [Spotify - Spotify] [Player **REDACTED**-SingleUser] Orphaned after no player updates for 5 minutes

(PS : I made sure I'm using pr-255:
Image)

@FoxxMD
Copy link
Owner

FoxxMD commented Jan 17, 2025

I think there may be a problem with some changes I made today to the docker image publishing github actions. It looks like it didnt include the actual changes, for some reason. I'll figure that out later...

I have manually built and pushed the PR tag again. Please try updating your image, the correct version should now be pr255-1486613744c4b73d25d43b4e46d816f9d3df33fb

@Fratt
Copy link
Contributor Author

Fratt commented Jan 18, 2025

I can confirm that it works as expected, thanks a lot! The scrobble made when a track is stale has a different timestamp than the previous one.

One final point : When the track resumes, if there is enough time left to reach the threshold (again), it scrobbles the track a second time. Is it by design / a limitation ? I can live with that, I'll take duplicate scrobble over missed scrobble anytime :D

Thanks a lot again for the fast fix!

FoxxMD added a commit that referenced this issue Jan 18, 2025
fix(spotify): Generate played object from cleanup with correct TS
@FoxxMD
Copy link
Owner

FoxxMD commented Jan 18, 2025

It is by design. I treat it as a second play because enough time passed between the original "session", which became stale (not listening), and this new "listen" of the same track.

I might consider adding a "staleAfter" configuration option to allow making that buffer time longer

@Fratt
Copy link
Contributor Author

Fratt commented Jan 18, 2025

Thanks for the explanation! Would be a very nice configuration option, I often pause music for a few hours

@FoxxMD
Copy link
Owner

FoxxMD commented Jan 21, 2025

Released in 0.9.1 and available in the latest docker tag.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants