Google-provided playCount is incorrect (particularly when equal to 0)

[ColossalMoose]

I have attached a screenshot of my playlist setup as well as the playlist in GPM

http://puu.sh/o9q88/7fb9689b28.jpg - The screenshot was take approximately 10 seconds after a sync.

http://puu.sh/o9qaP/96df4f9ea4.png - This is the playlist definition.

Is there something I am doing wrong, or is there some faulty logic here.

Thanks

[simon-weber]

That's an odd one. My guess as to what happened:

• the playlist initially had no rules, so it synced to contain all songs
• later, it was updated to limit to playCount == 0, but these syncs can take a bit, so you're still seeing the old version

If that's the case, I'd expect it to fix itself shortly. You can also try refreshing the page to force Google's client to refresh its cache, but realtime updates have been pretty reliable in my experience.

[ColossalMoose]

Ok, So I cleared the cache(Shift + F5) I now have an updated version but it still has the same issue, I will leave it for a couple of hours and update if it fixes itself.

Thanks for the quick reply!

[simon-weber]

Sure thing. Sorry for the trouble!

It sounds like something odd is happening either with the query or syncing. Let's check the query first, since that's easier: if you open the playlist definition and hit "test", how many tracks are found? Sorting by play count descending may help to check if there are any non-0 tracks in the result.

[ColossalMoose]

OK, so in testing, it found the correct number of tracks but the playlist still contains the incorrect files. Is there a way to dump out the created playlist to text?

[simon-weber]

Got it, so something is up with syncing.

I checked my error reporting quickly to see if anything stood out, but I didn't notice anything. So, let's check your logs. The syncing logs are pretty verbose: they'll tell you exactly what updates it's trying to make, along with the remote state of the playlist when it happens. You can either copy and paste a snippet from them here, or save them to a file and attach it.

[ColossalMoose]

Log.txt

I attached the log as a .txt, I think that the issue seems to be that it thinks that one of the songs is playing(I checked my devices and it currently isn't anywhere) and then it seems to give up the sync?

If you need to log in another format or more specific info I can help.

[simon-weber]

Great, thanks for attaching it. I've got to head off to work now, but I'll take a look as soon as I can. Let me know if you find out anything in the meantime.

[ColossalMoose]

Thanks for that, I will have a look what I can do.

[simon-weber]

I took a quick look over lunch: "Unlistened V2 found 1000" means the query returned 1k tracks, so it does look like the problem is with the query.

Can you try doing the test query again? If that's definitely not returning 1k, then the problem must be in the middle somewhere.

[ColossalMoose]

The test on the page returns 5560 which shows there is an error with query.
http://puu.sh/oartt/8d0cb7a2a6.png

[simon-weber]

Hm, I think this may be like #8: Google is just sending the wrong information. Some observations from my library:

• when I try this, the query returns 4300 of my ~10k tracks
• when I sort that by last played descending, the first result is a track last played a few days ago, haha
• if in their web client I sort all tracks by play count, find the last with a 0 play count, then scroll back to the top of the page and shift+click the first track, the ui tells me I've selected 4300 tracks

Here's the track I'm referring to, note the inconsistency between play count and last played:

id: "28dae504-40a6-3d6c-98ee-53b993357982"
title: "Black Winter Day"
artist: "Amorphis"
album: "Forging the Land of Thousand Lakes"
album artist: "Amorphis"
composer: ""
genre: "Metal"
duration (ms): 236000
track: 13
total tracks: 25
disc: 2
total discs: 2
year: 2010
play count: 0
rating: 0
rating thumb: "none"
date added to library: 12/22/2011, 11:30:11 PM
last played: 4/3/2016, 5:49:14 AM
store id: "T3le4ibjvoewo75xgo7fd4nubfm"
type: 2
comment: ""
bitrate: 113

I was hoping that we could perhaps clean this up clientside by comparing date added vs last played, and artificially incrementing the count if they were equal, but that doesn't seem to be valid. Take this example:

id: "e2750104-42ce-3a58-84b0-c8b803d2d7f1"
title: "Au Privave"
artist: "Supersax"
album: "Stone Bird"
album artist: "Supersax"
composer: ""
genre: "Jazz"
duration (ms): 239000
track: 5
total tracks: 0
disc: 0
total discs: 0
year: 1988
play count: 0
rating: 0
rating thumb: "none"
date added to library: 12/22/2011, 10:39:33 PM
last played: 12/22/2011, 11:13:15 PM
store id: ""
type: 2
comment: ""
bitrate: 146

I'm relatively confident this actually was never played. But, it still has a last played slightly different from when it was added. We could try and fudge it a bit by looking for close values, but I don't think there's a way to make it 100% accurate.

[ColossalMoose]

if it is possible to alter the returned object in the playlist could the logic not be something akin to:
If (last played != null && playcount == 0)
MusicObjectToReturn.Playcount = 1

or if it is not possible to change the count, could it just remove from the returned playlist.

sorry for the syntax I know c#, but not alot of javascript haha. Surely you don't need to worry about the date added as long as the last played is null(if there is a null value anyway).

[simon-weber]

That's the trouble: it looks like last played is never null (at least in my library), but rather some arbitrary time shortly after the date added. But we can probably make something along those lines work.

[simon-weber]

For tracks with google playcount 0, we now increment those that were "played" more than 6 hours after the time they were added to the library. This threshold worked pretty well for my library - finding ~100 truly unplayed tracks out of ~4k with playcount 0 - but we can dial it in based on how it works for you.

Thanks for letting me know about this!

[ColossalMoose]

Thanks for looking at this, I have just looked in my library and I seem to have more issues now haha. I added my bulk of music in 2012 and those songs with a 0 play count seem to have a last played sometime in 2014 (I believe google may have forced setting them somewhere around here) This means that mine is now only returning ~600 songs when the actual number should be around 5000.

I think I might have to take a copy of the code and see on my library what I can do. I think I may have a strange library due to the age of my account. Is this something we can raise with Google so that we can discern why they populate Last played all the time?
example: http://puu.sh/oen7t/fe97cc5264.png

[simon-weber]

Huh, interesting. My creationdate/lastplayed seem to line up pretty well as far back as december 2011; if there was a backfill of some sort, it must have affected our accounts differently. Or maybe there was some kind of data loss on their end fixed with lossy recovery? Who knows.

Is this something we can raise with Google?

We probably should. Unfortunately, I don't have any reliable channels to reach out through. We've (seemingly, though it may have been a coincidence) had success in the past when many people reported the same bug, though, eg simon-weber/gmusicapi#203 (comment).

[ColossalMoose]

I have had a word with my work colleague who has a similar size and age library and we both have weird songs like that. I think the best thing for now would be to revert to what it was before as at least then it found the right number and was just adding some extras in.
I will have a look at my account and see if I can find some pattern to these dates.I will try and analyse my query and see what happens.

[simon-weber]

Sounds good; I'll revert that change.

[simon-weber]

Something that might be helpful when debugging: I pull in more fields that are hidden from the ui that get reported with errors to help with debugging. If you run from source, you can change this filter to make them appear in the ui. It could be that albumPlaylistTimestamp or recentTimestamp might help root out false positives.

[ColossalMoose]

Thanks for that!! I will have a look when I get back from work later.

[simon-weber]

Ok, 1.2.3 is up with the revert.

[ColossalMoose]

I have just been analysing the query with the code, I have managed to narrow it down a little further. I could use some help from you if possible.

I actually may have found something that may help with this issue.

http://puu.sh/ofwkx/b4a1c13cec.png - that screenshot was taken on 2 pc's in 2 locations (1 at work and 1 at home) done at the same time. Note how they are both returning the same song yet show 2 different values on play count... This may be why they are showing in the playlist yet are not in the filtered list. I have no idea why this could be the case. I only have 1 version of that song in my library. I have a feeling this is entirely googles issue.

Both computers are logged in at the same time (does that matter?)

Where can I intercept and dump out the exact query that goes to google music? I can find the "test" button query, just not the other.

FYI I have also looked into the other hidden fields and follow the same issue of always being filled in. I think the issue here is the query that goes to google music.

Thanks for any help

[simon-weber]

Woah, excellent sleuthing! 🔍

Here's my hypothesis: one of these computers has a local indexeddb, one doesn't, and the indexeddb is out of sync. Behind the scenes, if the idb is present we'll use it to initialize our database, then only retrieve differential updates from Google. If not, we retrieve the entire history from Google before switching to differential updates. So, if the idb is present but incorrect, that could definitely explain the inconsistency.

The easiest way to check this is to:

• go to chrome://extensions
• enable developer mode
• disable then enable Autoplaylists (to force it to reload)
• click "inspect view: background page" to open the logs
• open or reload a Play Music tab

At this point, you'll either see or not see a warning in the logs: "local idb not available; falling back to diffUpdate(0)".

[ColossalMoose]

Just tested this and I did not see that log. Is there a way for me to force it to update?

[simon-weber]

If you didn't see it, it means the indexeddb is present and being used. Did it not show up on both computers? If my idea is correct, it'll only show up on one.

[ColossalMoose]

I have just tested both for the messsage, I do not recieve the message on either one of my pc's

[simon-weber]

Interesting. Maybe just one idb is incorrect, then? I'll work on some steps to verify that.

[simon-weber]

Hm, I was hoping we could do this just through devtools, but it doesn't look like it's possible to actually copy values out, just view them. It looks like we'll need to write some code to do this.

[ColossalMoose]

Thanks for looking into that. It isn't urgent so no rush.

[simon-weber]

I forgot to update here, but recently we switched to a different lastPlayed field. I don't think this actually solves any problems for us here - the new field is always 0 if playCount is, but there are times where playCount is non-zero but the new field isn't - but it at least improves consistency in some cases.

See #8 (comment) for more details.