search

FoxxMD / multi-scrobbler

Scrobble plays from multiple sources to multiple clients
https://foxxmd.github.io/multi-scrobbler
MIT License
346 stars 16 forks source link

Double scrobbles occur when backlog is processed #121

Closed FoxxMD closed 6 months ago

FoxxMD commented 9 months ago

Based on comments from here

For some reason I keep getting double scrobbles with times about 5 minutes after the original scrobbles. They seem to always be after the original scrobble but before the next song.

Same problem for me. On FreeBSD, scrobble from spotify and save to Maloja. As long as the scrobbler is running, everything seems fine, but after restarting Multiscrobbler it reads a bunch of backlog songs which are already scrobbled and scrobbles them again with exactly 3 minutes of time difference. Sometimes it affects 5 songs, sometimes 20, it depends on the backlog size. edit: Just checked some of those songs. Every song with a duration longer than 3 minutes is scrobbled as a duplicate from backlog, and every song with less than 3 minutes duration is not.

Investigate if this is a bug in MS existing scrobble duration check or maybe an issue with timestamp reported from player vs. source

FoxxMD commented 9 months ago

@duckfromdiscord @wynkenstein

Do you know if the songs that are double scrobbled are from spotify or any other source specifically?

duckfromdiscord commented 9 months ago

I only use Spotify at the moment.

Is the backlog entirely scrobbled and it's left up to maloja to deny duplicates, or does multiscrobbler remove backlog that it knows has already been scrobbled?

What other sources support backlog?

FoxxMD commented 9 months ago

Is the backlog entirely scrobbled and it's left up to maloja to deny duplicates, or does multiscrobbler remove backlog that it knows has already been scrobbled?

Every Source (in MS) has "discovery" detection where it determines if some play is "new" to MS -- IE MS has not seen it before. At startup the discovered tracks list for all Sources is empty (because MS has just started). If a Source can fetch backlog it does so and triggers discovered events for all plays found. After startup discovery detection is done by the in-memory state player that tracks real time plays.

Each Scrobbler (in MS) listens for Discovered events. When it gets one it refreshes its own list of scrobbled plays from the scrobbler API (IE Maloja Scrobbler in MS gets last 20 plays from Maloja api) and then compares the play info/date for the Discovered play against the scrobbles from the API. If it does not find a close enough match it considers the play unique and scrobbles it.

The upstream scrobblers (Maloja API, Lastfm, etc...) do not do any duplicate detection on submissions AFAIK.

What other sources support backlog?

Lastfm, Listenbrainz, Deezer, and Spotify support backlogging.

FoxxMD commented 9 months ago

@wynkenstein @duckfromdiscord I've added more logging visibility into duplicate scrobble checks related to time logic. Available in the develop docker image.

The next time you start MS please modify you maloja client config (maloja.json) to include verbose matching in options like this:

[
  {
    "name": "default",
    "enable": true,
    "data": {
      "url": "MyMalojaUrl",
      "apiKey": "MyKey",
      "options": {
        "verbose": {
          "match": {
            "onNoMatch": true,
            "confidenceBreakdown": true
          }
        }
      }
    }
  }
]

This will make MS log additional info every time it scrobbles a new play to Maloja that looks like this...

2024-01-02T14:01:17-05:00 debug   : [Test - Test] [Dupe Check] Spotify: Frédéric Chopin / Krystian Zimerman - Ballade No. 2 in G Minor, O... @ 2024-01-02T13:51:08-05:00 => Closest Scrobble: Frédéric Chopin / Krystian Zimerman - Ballade No. 1 in G Minor, O... @ 2024-01-02T13:41:32-05:00 => Score 0.96 => No Match
2024-01-02T14:01:17-05:00 debug   : [Test - Test] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 0.89 * 0.4 = 0.36
Time: (Fuzzy) 0.6 * 0.5 = 0.30
Time Detail => Existing: 13:41:32-05:00 - Candidate: 13:51:08-05:00 | Temporal Sameness: Fuzzy | Play Diff: 576s (Needed <10s) | Fuzzy Duration Diff: 1s (Needed <10s) | Range Comparison N/A
Score 0.96 => No Match

Please post logs including this data when you see an erroneous/duplicate scrobble, thanks

wynkenstein commented 9 months ago

Allright, i've modified my config and will try to force it by playing a few songs via Spotify without the Scrobbler running. After that I will start it again to see how it processes my backlog.

wynkenstein commented 9 months ago

Ok, here we go. After some random plays on Spotify and 2 times of shutting down Multiscrobbler und turning it back on, there was another dupe from my backlog.

in Maloja it says:

03. Jan 2024 08:11 AM   
    Bassnectar, Locoqueen, xX0Xx, xXOXx – Time For Some Action - Locoqueen Remix
03. Jan 2024 08:08 AM   
    Bassnectar, Locoqueen, xX0Xx, xXOXx – Time For Some Action - Locoqueen Remix

now here is the part from my log where it happened: (i just removed my API key for Maloja)

2024-01-03T10:22:54+01:00 info    : [Sources] [Spotify - wynkenstein] Scrobbling backlogged tracks...
2024-01-03T10:22:54+01:00 info    : [Sources] [Spotify - wynkenstein] Backlog scrobbling complete.
2024-01-03T10:22:54+01:00 info    : [Sources] [Spotify - wynkenstein] Polling started
2024-01-03T10:22:54+01:00 debug   : [Sources] [Spotify - wynkenstein] Refreshing recently played
2024-01-03T10:22:54+01:00 debug   : [Sources] [Spotify - wynkenstein] No new tracks discovered
2024-01-03T10:22:54+01:00 debug   : [Sources] [Spotify - wynkenstein] Last activity was at 2024-01-03T10:22:54+01:00. Will check again in interval 60.00 seconds.
2024-01-03T10:22:54+01:00 verbose : [Sources] [Spotify - wynkenstein] Sleeping for 60.00s
2024-01-03T10:22:55+01:00 debug   : [Scrobblers] [Maloja - local] Refreshing recent scrobbles
2024-01-03T10:22:55+01:00 debug   : [Scrobblers] [Maloja - local] Found 40 recent scrobbles
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] (Existing Check) Source: Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat.... @ 2024-01-03T09:11:33+01:00 => Closest Scrobble: Bassnectar / Locoqueen / xX0Xx / xXOXx - Time For Some Action - Loco... @ 2024-01-03T09:08:20+01:00 => Score 0.87 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Breakdown:
Artist: 0.86 * 0.3 = 0.26
Title: 0.78 * 0.4 = 0.31
Time: 0.6 * 0.5 = 0.30
Score 0.87 => No Match
2024-01-03T10:22:56+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat. xXOXx) - Locoqueen Remix @ 2024-01-03T09:11:33+01:00
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Time for Some Action (Locoqueen Remix) / Acid Blackness (Bassnectar Remix)","artists":["Bassnectar","xX0Xx","Locoqueen"],"key":"***","length":192,"time":1704269493,"title":"Time For Some Action (feat. xXOXx) - Locoqueen Remix"}
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] (Existing Check) Source: Ummet Ozcan - My Beat Goes @ 2024-01-03T09:25:59+01:00 => Closest Scrobble: Rezz / fknsyd - Let Me In @ 2024-01-01T21:51:43+01:00 => Score 0.11 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Breakdown:
Artist: 0.00 * 0.3 = 0.00
Title: 0.28 * 0.4 = 0.11
Time: 0 * 0.5 = 0.00
Score 0.11 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] (Existing Check) Source: Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat.... @ 2024-01-03T09:11:33+01:00 => Closest Scrobble: Bassnectar / Locoqueen / xX0Xx / xXOXx - Time For Some Action - Loco... @ 2024-01-03T09:08:20+01:00 => Score 0.87 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Breakdown:
Artist: 0.86 * 0.3 = 0.26
Title: 0.78 * 0.4 = 0.31
Time: 0.6 * 0.5 = 0.30
Score 0.87 => No Match
2024-01-03T10:22:56+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat. xXOXx) - Locoqueen Remix @ 2024-01-03T09:11:33+01:00
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Time for Some Action (Locoqueen Remix) / Acid Blackness (Bassnectar Remix)","artists":["Bassnectar","xX0Xx","Locoqueen"],"key":"***","length":192,"time":1704269493,"title":"Time For Some Action (feat. xXOXx) - Locoqueen Remix"}
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] (Existing Check) Source: Ummet Ozcan - My Beat Goes @ 2024-01-03T09:25:59+01:00 => Closest Scrobble: Rezz / fknsyd - Let Me In @ 2024-01-01T21:51:43+01:00 => Score 0.11 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Breakdown:
Artist: 0.00 * 0.3 = 0.00
Title: 0.28 * 0.4 = 0.11
Time: 0 * 0.5 = 0.00
Score 0.11 => No Match
2024-01-03T10:22:56+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 547ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-03T10:22:58+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Ummet Ozcan - My Beat Goes @ 2024-01-03T09:25:59+01:00

edit: oh, i guess it doesn't have the information you needed? I have to checkout develop branch for this, right?

wynkenstein commented 9 months ago

Ok, next try! After installing develop version i did the following:

The same track (and this time 2 more!) got duped again, here is the relevant information on Maloja:

03. Jan 2024 08:11 AM   
    RVDY – Do Not Resist
03. Jan 2024 08:11 AM   
    Bassnectar, Locoqueen, xX0Xx, xXOXx – Time For Some Action - Locoqueen Remix
03. Jan 2024 08:08 AM   
    Bassnectar, Locoqueen, xX0Xx, xXOXx – Time For Some Action - Locoqueen Remix
03. Jan 2024 08:04 AM   
    HVDES, SVDDEN DEATH – Don't You Dare Go Hollow
03. Jan 2024 08:04 AM   
    Space Laces – In The Place
03. Jan 2024 08:01 AM   
    Space Laces – In The Place
03. Jan 2024 07:55 AM   
    poixone, Geoxor – I'm Here
03. Jan 2024 07:55 AM   
    Panda Eyes – Belle
03. Jan 2024 07:52 AM   
    Panda Eyes – Belle
03. Jan 2024 07:51 AM   
    Pendulum – Anti-Hero - triple j Like A Version

now for the logging part:

2024-01-03T10:56:36+01:00 debug   : [Sources] [Spotify - wynkenstein] No new tracks discovered
2024-01-03T10:56:36+01:00 debug   : [Sources] [Spotify - wynkenstein] Last activity was at 2024-01-03T10:56:36+01:00. Will check again in interval 60.00 seconds.
2024-01-03T10:56:36+01:00 verbose : [Sources] [Spotify - wynkenstein] Sleeping for 60.00s
2024-01-03T10:56:37+01:00 debug   : [Scrobblers] [Maloja - local] Refreshing recent scrobbles
2024-01-03T10:56:37+01:00 debug   : [Scrobblers] [Maloja - local] Found 40 recent scrobbles
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Panda Eyes - Belle @ 2024-01-03T08:55:28+01:00 => Closest Scrobble: Panda Eyes - Belle @ 2024-01-03T08:52:34+01:00 => Score 0.70 => No Matc                                                                 h
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 08:52:34+01:00 - Candidate: 08:55:28+01:00 | Temporal Sameness: No correlation | Play Diff: 174s (Needed <10s) | Fuzzy Duration Diff: 84s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-03T10:56:38+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Panda Eyes - Belle @ 2024-01-03T08:55:28+01:00
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Orange Soda","artists":["Panda Eyes"],"key":"***","length":257.566,"time":170                                                                 4268528,"title":"Belle"}
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Space Laces - In The Place @ 2024-01-03T09:04:34+01:00 => Closest Scrobble: Space Laces - In The Place @ 2024-01-03T09:01:38+01:00 => Score                                                                  0.70 => No Match
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 09:01:38+01:00 - Candidate: 09:04:34+01:00 | Temporal Sameness: No correlation | Play Diff: 176s (Needed <10s) | Fuzzy Duration Diff: 54s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Orange Soda","artists":["Panda Eyes"],"key":"***","length":257.566,"time":1704268528,"title":"Belle"}
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Space Laces - In The Place @ 2024-01-03T09:04:34+01:00 => Closest Scrobble: Space Laces - In The Place @ 2024-01-03T09:01:38+01:00 => Score 0.70 => No Match
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 09:01:38+01:00 - Candidate: 09:04:34+01:00 | Temporal Sameness: No correlation | Play Diff: 176s (Needed <10s) | Fuzzy Duration Diff: 54s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-03T10:56:38+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 612ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-03T10:56:39+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Space Laces - In The Place @ 2024-01-03T09:04:34+01:00
2024-01-03T10:56:39+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"In The Place","artists":["Space Laces"],"key":"***","length":230.4,"time":1704269074,"title":"In The Place"}
2024-01-03T10:56:39+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat.... @ 2024-01-03T09:11:33+01:00 => Closest Scrobble: Bassnectar / Locoqueen / xX0Xx / xXOXx - Time For Some Action - Loco... @ 2024-01-03T09:08:20+01:00 => Score 0.86 => No Match
2024-01-03T10:56:39+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 0.84 * 0.3 = 0.25
Title: 0.77 * 0.4 = 0.31
Time: (Fuzzy) 0.6 * 0.5 = 0.30
Time Detail => Existing: 09:08:20+01:00 - Candidate: 09:11:33+01:00 | Temporal Sameness: Fuzzy | Play Diff: 193s (Needed <10s) | Fuzzy Duration Diff: 1s (Needed <= 10s) | Range Comparison N/A
Score 0.86 => No Match
2024-01-03T10:56:39+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 633ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-03T10:56:41+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Bassnectar / xX0Xx / Locoqueen - Time For Some Action (feat. xXOXx) - Locoqueen Remix @ 2024-01-03T09:11:33+01:00
2024-01-03T10:56:41+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Time for Some Action (Locoqueen Remix) / Acid Blackness (Bassnectar Remix)","artists":["Bassnectar","xX0Xx","Locoqueen"],"key":"***","length":192,"time":1704269493,"title":"Time For Some Action (feat. xXOXx) - Locoqueen Remix"}
2024-01-03T10:56:42+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Tezra - Blacksaw @ 2024-01-03T10:52:14+01:00 => Closest Scrobble: Rezz - Levitate @ 2024-01-01T21:55:11+01:00 => Score 0.11 => No Match
2024-01-03T10:56:42+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 0.27 * 0.3 = 0.08
Title: 0.06 * 0.4 = 0.03
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 2024-01-01T20:55:11.000Z - Candidate: 2024-01-03T09:52:14.092Z | Temporal Sameness: No correlation | Play Diff: 133,023s (Needed <10s) | Fuzzy Duration Diff: 132,844s (Needed <= 10s) | Range Comparison N/A
Score 0.11 => No Match
2024-01-03T10:56:42+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Tezra - Blacksaw @ 2024-01-03T10:52:14+01:00
2024-01-03T10:56:42+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Blacksaw","artists":["Tezra"],"key":"***","length":178.8,"time":1704275534,"title":"Blacksaw"}
2024-01-03T10:57:36+01:00 debug   : [Sources] [Spotify - wynkenstein] Refreshing recently played
FoxxMD commented 9 months ago

Thank you for the logs! This is super helpful.

Bassnectar, Locoqueen, xX0Xx, xXOXx – Time For Some Action - Locoqueen Remix

This one isn't time related, funnily enough. It's two separate issues:

  1. Maloja automatically removes feat... joiners in a track's title but Spotify does not so there is a difference in the title

  2. It looks like there are multiple versions of this on Spotify where the Artist name is also different! Sometimes its xXOXx (with the letter O) and sometimes its xX0Xx (with the number zero).

image

The combination of those differences is enough for MS to consider it not the same track even though the time is similar. There is some improvement I can do on the time comparison so I'll see if that puts it over the fence on considering it a dupe...

03. Jan 2024 08:04 AM   
    Space Laces – In The Place
03. Jan 2024 08:01 AM   
    Space Laces – In The Place
...
03. Jan 2024 07:55 AM   
    Panda Eyes – Belle
03. Jan 2024 07:52 AM   
    Panda Eyes – Belle

With these duplicates, if you can remember, did you listen to most of the track but skip to the next song early? For example Panda Eyes - Belle is 4:17 long but you only listened for 3:45.

EDIT: I ask because I think the main issue, temporally, is that Spotify records the play listen timestamp as when the player stopped playing the track rather than how MS (and I think most other scrobblers) do which is when the player started the track.

wynkenstein commented 9 months ago

Thank you for looking into it!

In this specific test run, all tracks did run completely on my iPad, no skipping.

And for the special track with multiple names, it MAY be possible yes, but the duplicates I had a few weeks and month ago where completely random. Even with short names like "Spaces laces" etc. It always happens in some way after I had to restart the scrobbler (mostly after component updates on the machine it runs) and everything it finds in that spotify backlog list is a potential candidate for dupes.

EDIT: ah, just saw your edit. What I can do for testing is, what happens with songs i pause for a moment (because this happens here and there while listening). But this will take a while to build up some new more listenings

EDIT 2: and just to be clear, when the scrobblers runs for a weeks, there are absolutely no dupes in Maloja. It always happens after initializing when there is a backlog from spotify

FoxxMD commented 9 months ago

Pausing shouldn't affect things as MS doesn't scrobble until the track actually changes or Spotify's player is completely stopped but who knows.

In this specific test run, all tracks did run completely on my iPad, no skipping.

Dang. Well, to give you some insight into the logging you're seeing:

Artist: 0.84 * 0.3 = 0.25
Title: 0.77 * 0.4 = 0.31
Time: (Fuzzy) 0.6 * 0.5 = 0.30
Time Detail => Existing: 09:08:20+01:00 - Candidate: 09:11:33+01:00 | Temporal Sameness: Fuzzy | Play Diff: 193s (Needed <10s) | Fuzzy Duration Diff: 1s (Needed <= 10s) | Range Comparison N/A
Score 0.86 => No Match

MS takes a new scrobble and compares it to all the existing scrobbles it got from the scrobbler's (maloja) API. On each existing scrobble it compares Artist, Title, and Time which are scored with weights (0.3, 0.4, 0.5 respectively). If the score sum up to at least 1.0 then the existing scrobble is considered the "original" and the new scrobble is considered a duplicate and not scrobbled.

Artist and Title use a string comparison mechanism that normalizes a bunch of things and then compares how different the strings are. that's the first number for each.

Time uses a fixed score based on how close, temporally, the timestamps of the two scrobbles are.

fuzzy is used to account for things like spotify where the Maloja scrobble timestamp is at the start of the track but spotify timestamp is at the end. MS will take the maloja timestamp and add the track duration to it, then compare against the spotify timestamp, effectively getting a timestamp at the "end" of the track. If that timestamp is within 10 seconds then its "fuzzy".

You can see these diffs in the logs as Play Diff: 193s (Needed <10s) | Fuzzy Duration Diff: 1s (Needed <= 10s)

I'm still going to try changing scrobbles from spotify to use timestamp when the track changes and see if that makes a difference.

FoxxMD commented 9 months ago

@wynkenstein I've deployed a version of MS that uses timestamps from when Spotify changes tracks like mentioned above. Seems to be working fine for me so far. You can test it using the foxxmd/multi-scrobbler:experimental image

wynkenstein commented 9 months ago

Thank you.

I don't use docker, but I guess I can checkout the "playCompletedContext" branch for this to test?

FoxxMD commented 9 months ago

ah yes that works!

wynkenstein commented 9 months ago

unfortunately, same behaviour as before with this version. i just listened to a few tracks, then started MS for backlog process again and this time a lot of dupes happened.

Maloja:

04. Jan 2024 02:11 PM   
    Luca Eck, Nur Jaber – Violence
04. Jan 2024 02:05 PM   
    Luca Eck – When the Rain Washed It All Away
04. Jan 2024 02:00 PM   
    Luca Eck – When the Rain Washed It All Away
04. Jan 2024 01:59 PM   
    Typo – KICK BACK
04. Jan 2024 01:56 PM   
    Typo – KICK BACK
04. Jan 2024 01:55 PM   
    Voidnet – Living Hell
04. Jan 2024 01:53 PM   
    Voidnet – Living Hell
04. Jan 2024 01:51 PM   
    John Fulford Music – The Magic Flute
04. Jan 2024 01:51 PM   
    LŪN, ALEX – kiss the ring
04. Jan 2024 01:48 PM   
    LŪN, ALEX – kiss the ring
04. Jan 2024 01:47 PM   
    Rezz, Grabbitz – Signal
04. Jan 2024 01:44 PM   
    Rezz, Grabbitz – Signal
04. Jan 2024 01:43 PM   
    DeathbyRomy, NGHTMRE, Rezz – All Night
04. Jan 2024 01:41 PM   
    DeathbyRomy, NGHTMRE, Rezz – All Night

here is my log:

2024-01-04T15:19:38+01:00 verbose : [Sources] [Spotify - wynkenstein] Sleeping for 60.00s
2024-01-04T15:19:39+01:00 debug   : [Scrobblers] [Maloja - local] Refreshing recent scrobbles
2024-01-04T15:19:39+01:00 debug   : [Scrobblers] [Maloja - local] Found 40 recent scrobbles
2024-01-04T15:19:40+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: NGHTMRE / Rezz / DeathbyRomy - All Night @ 2024-01-04T14:43:52+01:00 (C) => Closest Scrobble: DeathbyRomy / NGHTMRE / Rezz - All Night @ 2024-01-04T14:41:09+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:40+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:41:09+01:00 - Candidate: 14:43:52+01:00 | Temporal Sameness: No correlation | Play Diff: 163s (Needed <10s) | Fuzzy Duration Diff: 46s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:41+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) NGHTMRE / Rezz / DeathbyRomy - All Night @ 2024-01-04T14:43:52+01:00 (C)
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"All Night","artists":["NGHTMRE","Rezz","DeathbyRomy"],"key":"***","length":208.846,"time":1704375832,"title":"All Night"}
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Rezz / Grabbitz - Signal @ 2024-01-04T14:47:09+01:00 (C) => Closest Scrobble: Rezz / Grabbitz - Signal @ 2024-01-04T14:44:53+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:44:53+01:00 - Candidate: 14:47:09+01:00 | Temporal Sameness: No correlation | Play Diff: 136s (Needed <10s) | Fuzzy Duration Diff: 59s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:41+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Rezz / Grabbitz - Signal @ 2024-01-04T14:47:09+01:00 (C)
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Signal","artists":["Rezz","Grabbitz"],"key":"***","length":194.823,"time":1704376029,"title":"Signal"}
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: LŪN / ALEX - kiss the ring @ 2024-01-04T14:51:29+01:00 (C) => Closest Scrobble: LŪN / ALEX - kiss the ring @ 2024-01-04T14:48:08+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:48:08+01:00 - Candidate: 14:51:29+01:00 | Temporal Sameness: No correlation | Play Diff: 201s (Needed <10s) | Fuzzy Duration Diff: 45s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 698ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:42+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) LŪN / ALEX - kiss the ring @ 2024-01-04T14:51:29+01:00 (C)
2024-01-04T15:19:42+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"kiss the ring","artists":["LŪN","ALEX"],"key":"HPu2ehxMdi2wszFltZ40FMpUi2024-01-04T15:19:41+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) NGHTMRE / Rezz / DeathbyRomy - All Night @ 2024-01-04T14:43:52+01:00 (C)
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"All Night","artists":["NGHTMRE","Rezz","DeathbyRomy"],"key":"***","length":208.846,"time":1704375832,"title":"All Night"}
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Rezz / Grabbitz - Signal @ 2024-01-04T14:47:09+01:00 (C) => Closest Scrobble: Rezz / Grabbitz - Signal @ 2024-01-04T14:44:53+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:44:53+01:00 - Candidate: 14:47:09+01:00 | Temporal Sameness: No correlation | Play Diff: 136s (Needed <10s) | Fuzzy Duration Diff: 59s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:41+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Rezz / Grabbitz - Signal @ 2024-01-04T14:47:09+01:00 (C)
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Signal","artists":["Rezz","Grabbitz"],"key":"***","length":194.823,"time":1704376029,"title":"Signal"}
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: LŪN / ALEX - kiss the ring @ 2024-01-04T14:51:29+01:00 (C) => Closest Scrobble: LŪN / ALEX - kiss the ring @ 2024-01-04T14:48:08+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:48:08+01:00 - Candidate: 14:51:29+01:00 | Temporal Sameness: No correlation | Play Diff: 201s (Needed <10s) | Fuzzy Duration Diff: 45s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:41+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 698ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:42+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) LŪN / ALEX - kiss the ring @ 2024-01-04T14:51:29+01:00 (C)
2024-01-04T15:19:42+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"kiss the ring","artists":["LŪN","ALEX"],"key":"***","length":245.861,"time":1704376289,"title":"kiss the ring"}
2024-01-04T15:19:42+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Voidnet - Living Hell @ 2024-01-04T14:55:47+01:00 (C) => Closest Scrobble: Voidnet - Living Hell @ 2024-01-04T14:53:03+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:42+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:53:03+01:00 - Candidate: 14:55:47+01:00 | Temporal Sameness: No correlation | Play Diff: 164s (Needed <10s) | Fuzzy Duration Diff: 31s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:42+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 771ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:44+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Voidnet - Living Hell @ 2024-01-04T14:55:47+01:00 (C)
2024-01-04T15:19:44+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Living Hell","artists":["Voidnet"],"key":"***","length":195.206,"time":1704376547,"title":"Living Hell"}
2024-01-04T15:19:44+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Typo - KICK BACK @ 2024-01-04T14:59:21+01:00 (C) => Closest Scrobble: Typo - KICK BACK @ 2024-01-04T14:56:47+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:44+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 14:56:47+01:00 - Candidate: 14:59:21+01:00 | Temporal Sameness: No correlation | Play Diff: 154s (Needed <10s) | Fuzzy Duration Diff: 37s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:44+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 793ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:45+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Typo - KICK BACK @ 2024-01-04T14:59:21+01:00 (C)
2024-01-04T15:19:45+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"KICK BACK","artists":["Typo"],"key":"***","length":190.952,"time":1704376761,"title":"KICK BACK"}
2024-01-04T15:19:45+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Luca Eck - When the Rain Washed It All... @ 2024-01-04T15:05:48+01:00 (C) => Closest Scrobble: Luca Eck - When the Rain Washed It All... @ 2024-01-04T15:00:21+01:00 (S) => Score 0.70 => No Match
2024-01-04T15:19:45+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 15:00:21+01:00 - Candidate: 15:05:48+01:00 | Temporal Sameness: No correlation | Play Diff: 327s (Needed <10s) | Fuzzy Duration Diff: 59s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-04T15:19:45+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 742ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:46+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Luca Eck - When the Rain Washed It All Away @ 2024-01-04T15:05:48+01:00 (C)
2024-01-04T15:19:46+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Planet OSF - Series I","albumartists":["Various Artists"],"artists":["Luca Eck"],"key":"***","length":385.688,"time":1704377148,"title":"When the Rain Washed It All Away"}
2024-01-04T15:19:46+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Luca Eck / Nur Jaber - Violence @ 2024-01-04T15:11:20+01:00 (C) => Closest Scrobble: Luca Eck - When the Rain Washed It All... @ 2024-01-04T15:00:21+01:00 (S) => Score 0.10 => No Match
2024-01-04T15:19:46+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 0.30 * 0.3 = 0.09
Title: 0.03 * 0.4 = 0.01
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 15:00:21+01:00 - Candidate: 15:11:20+01:00 | Temporal Sameness: No correlation | Play Diff: 659s (Needed <10s) | Fuzzy Duration Diff: 328s (Needed <= 10s) | Range Comparison N/A
Score 0.10 => No Match
2024-01-04T15:19:46+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 723ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:47+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Luca Eck / Nur Jaber - Violence @ 2024-01-04T15:11:20+01:00 (C)
2024-01-04T15:19:47+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Fall to Pieces","artists":["Luca Eck","Nur Jaber"],"key":"***","length":330.858,"time":1704377480,"title":"Violence"}
2024-01-04T15:19:47+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Tanzanfall - Velvet Skys - Original Mix @ 2024-01-04T15:13:20+01:00 (C) => Closest Scrobble: Draven / Zardonic / Jhofre / CONNÖR - In The Taste Of Blood - Rem... @ 2024-01-03T09:46:43+01:00 (S) => Score 0.08 => No Match
2024-01-04T15:19:47+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 0.06 * 0.3 = 0.02
Title: 0.16 * 0.4 = 0.06
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 2024-01-03T08:46:43.000Z - Candidate: 2024-01-04T14:13:20.358Z | Temporal Sameness: No correlation | Play Diff: 105,997s (Needed <10s) | Fuzzy Duration Diff: 105,878s (Needed <= 10s) | Range Comparison N/A
Score 0.08 => No Match
2024-01-04T15:19:47+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 732ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:49+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Tanzanfall - Velvet Skys - Original Mix @ 2024-01-04T15:13:20+01:00 (C)
2024-01-04T15:19:49+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"Digital Insomnia","artists":["Tanzanfall"],"key":"***","length":119.138,"time":1704377600,"title":"Velvet Skys - Original Mix"}
2024-01-04T15:19:49+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Spotify: Nur Jaber - Dance Dance (With the Morni... @ 2024-01-04T15:16:54+01:00 (C) => Closest Scrobble: Luca Eck - When the Rain Washed It All... @ 2024-01-04T15:00:21+01:00 (S) => Score 0.11 => No Match
2024-01-04T15:19:49+01:00 debug   : [Scrobblers] [Maloja - local] [Dupe Check] Breakdown:
Artist: 0.06 * 0.3 = 0.02
Title: 0.22 * 0.4 = 0.09
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 15:00:21+01:00 - Candidate: 15:16:54+01:00 | Temporal Sameness: No correlation | Play Diff: 993s (Needed <10s) | Fuzzy Duration Diff: 779s (Needed <= 10s) | Range Comparison N/A
Score 0.11 => No Match
2024-01-04T15:19:49+01:00 debug   : [Scrobblers] [Maloja - local] Waiting 714ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-04T15:19:50+01:00 info    : [Scrobblers] [Maloja - local] Scrobbled (Backlog)     => (Spotify) Nur Jaber - Dance Dance (With the Morning Light) @ 2024-01-04T15:16:54+01:00 (C)
2024-01-04T15:19:50+01:00 debug   : [Scrobblers] [Maloja - local] Raw Payload: {"album":"In My Memory","albumartists":["Nur Jaber","O.B.I."],"artists":["Nur Jaber"],"key":"***","length":214.43,"time":1704377814,"title":"Dance Dance (With the Morning Light)"}
FoxxMD commented 9 months ago

I want to confirm how you are testing this. With the changes in the playCompletedContext branch you need to:

  1. checkout the branch
  2. run npm run build to compile new code
  3. run npm start to start production app
  4. listen to spotify while MS is running for a few songs
  5. restart MS so it backlogs from spotify

The only scrobbles that will be relevant for checking for duplicate changes will be those that were scrobbled after step 3 because the branch changes how/when it scrobbles from Spotify compared to the develop/master branch.

I ask because the maloja scrobble timestamps in your log look like they are when the track started rather than at the end -- compare the Play Diff value to the length value found in the raw payload data, many of them are close-ish.

I've been testing playCompletedContext on my own server and the Play Diff values are close to exact or at least closer than the Fuzzy Diff values.

Do you know if you have Automix enabled? Are you playing these on your ipad only are you using Spotify Connect for any listening?

duckfromdiscord commented 9 months ago

I'd like to help a bit. What I'll do is, I'll screenshot maloja, update multi-scrobbler (how do I do that again?) and restart it, then check the logs.

The screenshot is just so I know what was scrobbled again, I'm not sending that

wynkenstein commented 9 months ago

To answer your questions:

I want to confirm how you are testing this. With the changes in the playCompletedContext branch you need to:

1. checkout the branch

2. run `npm run build` to compile new code

3. run `npm start` to start production app

4. listen to spotify while MS is running for a few songs

5. restart MS so it backlogs from spotify

This is exactly what I did (plus npm install before npm build) but with one diffence at step 4. I didn't listen while MS was running. I listened to a handfull of songs THEN started MS to catch up with the backlog and thats how I got my results and dupes.

Do you know if you have Automix enabled? Are you playing these on your ipad only are you using Spotify Connect for any listening?

I don't use Automix. I guess I use Spotify Connect, yes. On normale behaviour I listen to it on Smartphone, iPad, PS5, Windows App and so on. But for the sake of these tests I only used my iPad

FoxxMD commented 9 months ago

I listened to a handfull of songs THEN started MS to catch up with the backlog

How are the original scrobbles getting into Maloja? If MS isn't recording them where are they coming from?

wynkenstein commented 9 months ago

Maybe we have a missunderstanding here. As mentionend in my post a few days ago

EDIT 2: and just to be clear, when the scrobblers runs for a weeks, there are absolutely no dupes in Maloja. It always happens after initializing when there is a backlog from spotify

so, the problem with dupes only appears if I have to restart the scrobbler for some reasons. as long as it "just runs" it works without any problems

FoxxMD commented 9 months ago

Ok think I got it...

Then you need to do step 4 before testing backlog dupes because

The only scrobbles that will be relevant for checking for duplicate changes will be those that were scrobbled after step 3 4 because the branch changes how/when it scrobbles from Spotify compared to the develop/master branch.

So please listen to some music while using MS from the new branch to scrobble. Then try backlog and check for dupes only on the tracks that were scrobbled using the new branch.

wynkenstein commented 9 months ago

Alright, will do that. Thanks for trying to figure this out

wynkenstein commented 9 months ago

Ok, it looks very promising :)

I listened to about 6 Tracks while MS was running, those tracks were saved at Maloja just fine (as always). After that I terminated MS and listend to 7 more tracks, waited a few minutes and started MS again for backlog scrobbling.

So far no dupes, everyhing at Maloja seems to be saved correctly.

wynkenstein commented 8 months ago

Hi. Just did a few tests again and didn't encounter any dupes or problems so far. I guess it's safe to say the problem is fixed.

FoxxMD commented 8 months ago

@duckfromdiscord these improvements are in the flatpak package now as well

duckfromdiscord commented 8 months ago

Just updated (to 0.6.3?) and enabled verbose logging, but still getting double scrobbles; here's an example of a logged one

2024-01-12T14:06:01+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Spotify: Kero Kero Bonito - Flamingo @ 2024-01-11T20:59:40+00:00 (C) => Closest Scrobble: Kero Kero Bonito - Flamingo @ 2024-01-11T20:55:16+00:00 (S) => Score 0.70 => No Match
2024-01-12T14:06:01+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 20:55:16+00:00 - Candidate: 20:59:40+00:00 | Temporal Sameness: No correlation | Play Diff: 264s (Needed <10s) | Fuzzy Duration Diff: 66s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
2024-01-12T14:06:01+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Waiting 907ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-01-12T14:06:02+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobbled (Backlog)     => (Spotify) Kero Kero Bonito - Flamingo @ 2024-01-11T20:59:40+00:00 (C)
2024-01-12T14:06:02+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Raw Payload: {"album":"Flamingo","artists":["Kero Kero Bonito"],"key":"[redacted]","length":197.528,"time":1705006780,"title":"Flamingo"}

I started with one scrobble of this song at 03:55 and now I have another at 03:59

Here are a couple more:

2024-01-12T14:06:00+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 03:09:39+00:00 - Candidate: 03:13:18+00:00 | Temporal Sameness: No correlation | Play Diff: 219s (Needed <10s) | Fuzzy Duration Diff: 12s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match

...

2024-01-12T14:06:00+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 1.00 * 0.4 = 0.40
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 20:45:49+00:00 - Candidate: 20:48:16+00:00 | Temporal Sameness: No correlation | Play Diff: 147s (Needed <10s) | Fuzzy Duration Diff: 18s (Needed <= 10s) | Range Comparison N/A
Score 0.70 => No Match
FoxxMD commented 8 months ago

@duckfromdiscord were these tracks scrobbled after the update or before? Duplicates will only be fixed for backlog scrobbling of tracks that were tracked after updating

duckfromdiscord commented 8 months ago

My apologies, this was with the version from flatpak.

duckfromdiscord commented 8 months ago

Do I clone master or playCompletedContext?

FoxxMD commented 8 months ago

No you're good 0.6.3 flatpak is what you need. I'm trying to make sure that the dups/testing you are seeing is for scrobbles made after you started using 0.6.3. As in:

  1. started using 0.6.3
  2. scrobbled tracks while using 0.6.3
  3. restarted MS and the dups are occurring on the scrobbles made in step 2
duckfromdiscord commented 8 months ago

Good point. All messages from now on will be with the updated version.

multi-scrobbler io.github.foxxmd.multiscrobbler 0.6.3 stable system

After I updated, multi-scrobbler randomly stopped ("Terminated", perhaps out of memory or CPU) and when I restarted it, everything re-scrobbled but most of them with the exact same time. Since I'm running in a screen instance, sadly Unicode characters (i.e. Japanese song titles) turned into question marks, and text is in a square. I'll try to fix that. This is not a multi-scrobbler issue, ignore the song titles; for the sake of readability I will truncate them.

Stuff got pretty complicated after this update:

2024-01-13T15:42:10+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check]
 Breakdown:
Artist: 0.09 * 0.3 = 0.03
Title: 0.00 * 0.4 = 0.00
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 2024-01-11T01:27:22.000Z - Candidate: 2024-01-12T21:44:20.306Z | Temporal Sameness: No correlation | Play Diff: 159,418s (Needed <10s) |
Fuzzy Duration Diff: 158,763s (Needed <= 10s) | Range Comparison N/A
Score 0.03 => No Match
2024-01-13T15:42:10+00:00 warn    : [Scrobblers] [Maloja - myMaloja] Request failed but retries (0) less than max (1), retrying request after 1.5 seconds...
2024-01-13T15:42:11+00:00 error   : [Scrobblers] [Maloja - myMaloja] API Call failed: Server Response => Conflict {"response":{"error":{"desc":"A scrobble is already registered with this timestamp.","type":"duplicate_timestamp","value":{"duration":null,"extra":{"album_artists":["..."],"album_title":"..."},"origin":"client:default","rawscrobble":{"album_title":"...","scrobble_time":1705095860,"track_artists":["..."],"track_length":654,"track_title":"..."},"time":1705095860,"track":{"album":{"albumtitle":"...","artists":["..."]},"artists":["..."],"length":654,"title":"..."}}},"status":"error"},"status":409}

A couple of these started happening too:

[Scrobblers] [Maloja - myMaloja] Error occurred while trying to scrobble
ErrorWithCause:
    at m.doProcessing (CWD/build/server.js:1:46066)
    at async m.startScrobbling (CWD/build/server.js:1:42862)

caused by: Error: Conflict
    at Request.callback (CWD/node_modules/superagent/lib/node/index.js:845:17)
    at CWD/node_modules/superagent/lib/node/index.js:1070:18
    at IncomingMessage.<anonymous> (CWD/node_modules/superagent/lib/node/parsers/
json.js:21:7)
    at IncomingMessage.emit (node:events:529:35)
    at endReadableNT (node:internal/streams/readable:1400:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21
)
[Scrobblers] [Maloja - myMaloja] Scrobble processing retries (2) less than max processing retries (5), restarting processing after 16 second delay...

On the maloja side we'll see maloja.database.exceptions.DuplicateTimestamp errors.

It's strange! It seems that a lot of the duplicates are at the same time as the originals, there are still some that are a couple minutes off, but more of them show up at the exact times than in the previous updates.

In fact, we'll see entirely different songs showing up during the "Closest Scrobble` comparison.

Where will I find log files? Copying stuff from the screen seems to be kind of counterproductive as it cuts off a lot of text. When I set file logging to true, multi-scrobbler immediately exits after printing Version: unknown.

duckfromdiscord commented 8 months ago

Here's a backlog that definitely happened after the update, that I discovered while writing #130 

: [Scrobblers] [Maloja - myMaloja] [Dupe Check] Spotify: VAPERROR / t e l e p a t h テレパシー能力者 - 切っても切れない @ 2024-01-25T13:21:01+00:00 (C) => Closest Scrobble: Radiohead - Black Star @ 2024-01-25T13:12:55+00:00 (S) => Score 0.30 => No Match
2024-01-27T00:51:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 0.00 * 0.3 = 0.00
Title: 0.00 * 0.4 = 0.00
Time: (Fuzzy) 0.6 * 0.5 = 0.30
Time Detail => Existing: 13:12:55+00:00 - Candidate: 13:21:01+00:00 | Temporal Sameness: Fuzzy | Play Diff: 486s (Needed <10s) | Fuzzy Duration Diff: 0s (Needed <= 10s) | Range Comparison N/A
Score 0.30 => No Match

I notice the two songs here are entirely different, but if you look at maloja, the double scrobble is right next to the old one! image

FoxxMD commented 8 months ago

You can enable file logging for warning/errors by modifying config.json to include this:

  "logging": {
    "level": "debug",
    "file": "warn"
  }

MS must have file permissions to write to CONFIG_DIR/log

caused by: Error: Conflict

This is a new error thrown by maloja that is not yet included in an official release. Previously it silently ignored the error and did not scrobble the duplicate. 0.6.4 handles this as a dead letter scrobble now.

duckfromdiscord commented 8 months ago

Should c2f0147 be marked as fixing #130?

FoxxMD commented 8 months ago

No, its (potentially) addressing the double scrobble from your comment above.

P.S. I know you sometimes redact artist/track info in the logs...please leave all information in as it can be critical to fixing the bug, like in the example above. Thanks

duckfromdiscord commented 8 months ago

Is my issue different from @.wynkenstein's then? It seems like their issue is not caused by Unicode/non-English characters.

FoxxMD commented 8 months ago

If you feel #130 has been solved by switching to docker please feel free to close it.

I don't know if all of your issues were caused by non-english characters. This issue is a "catch-all" for double scrobbling on backlog. Until you are satisfied it has been resolved the issue stays open.

FoxxMD commented 7 months ago

non-english characters bug fix released in 0.6.5

FoxxMD commented 6 months ago

@duckfromdiscord how has behavior been since this fix?

duckfromdiscord commented 6 months ago

I haven't had any crashes since I moved to Docker so I haven't had any chances to test backlog scrobbling! I'll have to start manually restarting the container every so often to check behavior

duckfromdiscord commented 6 months ago

It looks like after a restart I'm getting new scrobbles of songs I didn't finish/started and paused within the first minute or so.

2024-03-22T14:10:48+00:00 verbose : [Sources] [Spotify - MySpotify] Sleeping for 10.00s
2024-03-22T14:10:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Refreshing recent scrobbles
2024-03-22T14:10:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Found 40 recent scrobbles
2024-03-22T14:10:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Spotify: ２８１４ - 一緒に私たちは、市内の遺跡を歩く @ 2024-03-21T12:24:36+00:00 (C) => Closest Scrobble: ２８１４ - 2814スカイライン @ 2024-03-21T12:24:28+00:00 (S) => Score 0.80 => No Match
2024-03-22T14:10:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 0.00 * 0.4 = 0.00
Time: (Close) 1 * 0.5 = 0.50
Time Detail => Existing: 12:24:28+00:00 - Candidate: 12:24:36+00:00 | Temporal Sameness: Close | Play Diff: 8s (Needed <10s) | Range Comparison N/A
Score 0.80 => No Match
2024-03-22T14:10:49+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobbled (Backlog)     => (Spotify) ２８１４ - 一緒に私たちは、市内の遺跡を歩く @ 2024-03-21T12:24:36+00:00 (C)
2024-03-22T14:10:49+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Raw Payload: {"album":"2814","artists":["２８１４"],"key":"x","length":895.91,"time":1711023876,"title":"一緒に私たちは、市内の遺跡を歩く"}
2024-03-22T14:10:50+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Spotify: t e l e p a t h テレパシー能力者 - あなたは私の心にいつもしている @ 2024-03-21T22:23:34+00:00 (C) => Closest Scrobble: t e l e p a t h テレパシー能力者 - アトラクション @ 2024-03-20T19:38:02+00:00 (S) => Score 0.30 => No Match
2024-03-22T14:10:50+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 0.00 * 0.4 = 0.00
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 2024-03-20T19:38:02.000Z - Candidate: 2024-03-21T22:23:34.303Z | Temporal Sameness: No correlation | Play Diff: 96,332s (Needed <10s) | Fuzzy Duration Diff: 95,648s (Needed <= 10s) | Range Comparison N/A
Score 0.30 => No Match
2024-03-22T14:10:50+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Waiting 411ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-03-22T14:10:51+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobbled (Backlog)     => (Spotify) t e l e p a t h テレパシー能力者 - あなたは私の心にいつもしている @ 2024-03-21T22:23:34+00:00 (C)
2024-03-22T14:10:51+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Raw Payload: {"album":"断線","artists":["t e l e p a t h テレパシー能力者"],"key":"x","length":683.835,"time":1711059814,"title":"あなたは私の心にいつもしている"}
2024-03-22T14:10:51+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Spotify: t e l e p a t h テレパシー能力者 - 光る目 @ 2024-03-21T22:23:42+00:00 (C) => Closest Scrobble: t e l e p a t h テレパシー能力者 - アトラクション @ 2024-03-20T19:38:02+00:00 (S) => Score 0.30 => No Match
2024-03-22T14:10:51+00:00 debug   : [Scrobblers] [Maloja - myMaloja] [Dupe Check] Breakdown:
Artist: 1.00 * 0.3 = 0.30
Title: 0.00 * 0.4 = 0.00
Time: (No correlation) 0 * 0.5 = 0.00
Time Detail => Existing: 2024-03-20T19:38:02.000Z - Candidate: 2024-03-21T22:23:42.074Z | Temporal Sameness: No correlation | Play Diff: 96,340s (Needed <10s) | Fuzzy Duration Diff: 96,048s (Needed <= 10s) | Range Comparison N/A
Score 0.30 => No Match
2024-03-22T14:10:51+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Waiting 931ms to scrobble so time passed since previous scrobble is at least 1000ms
2024-03-22T14:10:52+00:00 info    : [Scrobblers] [Maloja - myMaloja] Scrobbled (Backlog)     => (Spotify) t e l e p a t h テレパシー能力者 - 光る目 @ 2024-03-21T22:23:42+00:00 (C)
2024-03-22T14:10:52+00:00 debug   : [Scrobblers] [Maloja - myMaloja] Raw Payload: {"album":"ロストエデンへのパス","albumartists":["t e l e p a t h テレパシー能力者","Nmesh"],"artists":["t e l e p a t h テレパシー能力者"],"key":"x","length":291.715,"time":1711059822,"title":"光る目"}
2024-03-22T14:10:58+00:00 debug   : [Sources] [Spotify - MySpotify] Refreshing recently played

I got three NEW scrobbles (i.e. scrobbles that did not have any of the same song right near them), but I did not see any new "double" scrobbles where the same track has two different entries within 3 minutes of each other. That was the issue I had previously before your update and my move to Docker. This container runs foxxmd/multi-scrobbler:develop.

It's worth noting that these were the only three tracks that were displayed in the log, though I listened to many more tracks yesterday.

I did have to truncate this log just a bit to remove the API key.

FoxxMD commented 6 months ago

If spotify says you listened to them who are we to disagree? ¯\_(ツ)_/¯

Interesting that it didn't discover any more tracks but it sounds like its working as intended.

duckfromdiscord commented 6 months ago

I only got to around 30 seconds in each of these tracks. If I had listened to them they would have been scrobbled already since multi-scrobbler had already been up and running for over half a week at the times of these plays.

FoxxMD commented 6 months ago

Spotify's listening history is a black box, they don't document how it works. If you'd prefer to use MS only you can disable backlog scrobbling in spotify.json:

[
  {
    "name": "mySpotify",
    "enable": true,
    "clients": [],
    "data": {
      "clientId": "...",
      "clientSecret": "...",
      "redirectUri": "http://localhost:9078/callback"
    },
    "options": {
      "scrobbleBacklog": false
    }
  }
]
duckfromdiscord commented 6 months ago

I know about scrobbleBacklog, I had requested that feature. It is quite useful for skipping backlog scrobbling after an update during which no music was played.

Is the listen length saved in the history? And if so, could that tell us whether the plays were too short to be considered backlog? If the listen lengths stored by Spotify in the history are the same ones shown in the payloads there, then they're either just stored by Spotify incorrectly entirely or also count pause time.

I would also like to add that these were not the only discovered tracks, these were the only scrobbled ones. It always finds 40 recent scrobbles, but these three were the only ones that ended up being scrobbled.

duckfromdiscord commented 6 months ago

I do agree that it sounds like multi scrobbler is working as intended; it is skipping scrobbles that have already happened, and scrobbling ones that have not. So it sounds like the main issue is fixed (I will continue to test to make sure of this). The new issue is that either Spotify or multi scrobbler are qualifying short scrobbles/"skips" to be tested in the first place.

FoxxMD commented 6 months ago

Spotify does not store the duration the track was listened to. Though in my past experience it has not added the track to history unless it was fully played. Who knows...they have have changed that or it may apply differently depending on the device listened to.

duckfromdiscord commented 6 months ago

It was my phone so perhaps. I believe the duration is stored in the extended listening history (maloja is scripted to drop <30 second scrobbles from the extended history), so I am a bit surprised it is not stored in the history provided by the API. But since that is the case, there is no issue with multi scrobbler as of now. I will try to do a same-day container restart with some music played and see if there's any double scrobbles at that time.

EDIT: link had wrong line + I thought this was an issue I had made

duckfromdiscord commented 6 months ago

I think everything is fixed. The only issue I've been having is half-listened songs being backlog scrobbled, and that is both potentially not fixable and also not within the scope of double scrobbles. I just scrobbled some backlog from songs that didn't get scrobbled this morning because my computer decided to update or crash without asking. Everything worked perfectly.

FoxxMD commented 6 months ago

Closed with 0.7.0 that includes these additional fixes:

(these were already in develop, now they are in a release)