simon-weber / Autoplaylists-for-Google-Music

Adds autoplaylists, aka iTunes "smart playlists", to Google Music.
https://autoplaylists.simon.codes
MIT License
94 stars 18 forks source link

Numbers don't match #186

Closed brianzam closed 5 years ago

brianzam commented 6 years ago

Hi Simon,

Odd thing happenng. I have a playlist 'Thumbs Up Plus' as follows:

Synced 22/06/2018, 22:46:16 by Autoplaylists for Google Music™ to contain: (rating thumb equals "up" and play count less than 10 and (last played earlier than "10 days ago" or last played between now and "20 minutes ago")) sorted by: lastPlayed ascending.

When I run it in test, I get the numbers I'd expect (705). Whenever I sync, only 332 songs appear in the Google Playlist.

Thanks in advance,

Brian

simon-weber commented 6 years ago

This sounds like the same thing as https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/185. I don't yet see anything in my reporting to indicate a widespread issue, thankfully. Can you give the recommendation at https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/185#issuecomment-398489433 a try?

brianzam commented 6 years ago

HI Simon. tried it, no difference, sorry.

simon-weber commented 6 years ago

Gotcha. Can you try sending over some logs so I can take a look? Specifically I'm interested in the contents of lines that start with finished sync. I think you'll need to click on the responses section to expand the details (if there's a way to expand or print it all, that'd be ideal).

brianzam commented 6 years ago

Hi Simon,

Here you go…

Kind regards,

Brian Zammit

On 3 Jul 2018, at 17:56, Simon Weber notifications@github.com wrote:

Gotcha. Can you try sending over some logs https://github.com/simon-weber/Autoplaylists-for-Google-Music/wiki/Debugging#viewing-your-logs so I can take a look? Specifically I'm interested in the contents of lines that start with finished sync. I think you'll need to click on the responses section to expand the details (if there's a way to expand or print it all, that'd be ideal).

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-402224547, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5Rzf2QJgMeZ9ZVkEFT-ILfN-wru3Pks5uC6IpgaJpZM4U0eZc.

background.js:11460 finished sync Objectaction: "update-all"userId: "08262833794545013034"proto: Object . responses Array(2) background.js:11460 setLastSyncInfo to Object background.js:11460 queued sync Object . queue is now Array(0) background.js:11460 start sync Object background.js:11460 set lastPSync to Tue Jun 26 2018 00:25:07 GMT+0100 (British Summer Time) background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 checking for remote track changes background.js:11460 cache: upserting 0 tracks background.js:11460 cache: deleting 0 tracks background.js:11460 no new poll timestamp; reusing 1529842404320000 background.js:11460 cache update res Object background.js:11460 syncPlaylists 08262833794545013034 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 finished sync Objectaction: "update-all"userId: "08262833794545013034"proto: constructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() . responses Array(2) background.js:11460 setLastSyncInfo to Object background.js:11460 sync interval changing to 0 background.js:11460 queued sync Object . queue is now Array(0) background.js:11460 start sync Object background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 checking for remote track changes background.js:11460 cache: upserting 0 tracks background.js:11460 cache: deleting 0 tracks background.js:11460 no new poll timestamp; reusing 1529842404320000 background.js:11460 cache update res Object background.js:11460 syncPlaylists 08262833794545013034 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 finished sync Objectaction: "update-all"syncType: "manual"userId: "08262833794545013034"proto: constructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() . responses Array(2) background.js:11460 setLastSyncInfo to Object background.js:11460 injected query getUserInfo 2 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 init tab 2 background.js:11460 see user 08262833794545013034 Object background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 precached license status: true background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 got verifyToken response: Object background.js:11460 reset random cache background.js:11460 syncing random fields background.js:11460 request to init syncs, but they're already started background.js:11460 cache: upserting 3530 tracks background.js:11460 done syncing random fields background.js:11460 queued sync Object . queue is now Array(0) background.js:11460 start sync Object background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 checking for remote track changes background.js:11460 cache: upserting 0 tracks background.js:11460 cache: deleting 0 tracks background.js:11460 no new poll timestamp; reusing 1529842404320000 background.js:11460 cache update res Object background.js:11460 syncPlaylist Thumbs Up Plus background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 finished sync Objectaction: "update"localId: "1496353399549"userId: "08262833794545013034"proto: Objectconstructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() . responses Array(2)0: {mutate_response: Array(379)}1: {mutate_response: Array(1)}length: 2proto: Array(0)Iterator: ƒ ArrayIterator(array, start, end)add: ƒ (el, index)addEach: ƒ (values)all: ƒ (a)any: ƒ (a)at: ƒ ()average: ƒ (map)clear: ƒ ()clone: ƒ ()compact: ƒ (all)compare: ƒ (that, compare)concat: ƒ concat()constructClone: ƒ (values)constructor: ƒ Array()copyWithin: ƒ copyWithin()count: ƒ (f)delete: ƒ (value, equals)deleteAll: ƒ (value, equals)deleteEach: ƒ (values, equals)each: ƒ (fn, index, loop)entries: ƒ entries()enumerate: ƒ (start)equals: ƒ (that, equals)every: ƒ (a)exclude: ƒ ()fill: ƒ fill()filter: ƒ (a)find: ƒ (a)findAll: ƒ (f, index, loop)findFrom: ƒ (f, index, loop)findIndex: ƒ (a)findIndexFrom: ƒ (f, index, loop)findLast: ƒ (value, equals)findLastValue: ƒ (value, equals)findValue: ƒ (value, equals, index)first: ƒ (num)flatten: ƒ (limit)forEach: ƒ forEach()from: ƒ (num)get: ƒ (index, defaultValue)group: ƒ (callback, thisp, equals)groupBy: ƒ (map, fn)has: ƒ (value, equals)inGroups: ƒ (num, padding)inGroupsOf: ƒ (num, padding)include: ƒ (el, index)includes: ƒ includes()indexOf: ƒ indexOf()insert: ƒ (el, index)intersect: ƒ ()isEmpty: ƒ ()iterate: ƒ (start, end)join: ƒ join()keys: ƒ keys()last: ƒ (num)lastIndexOf: ƒ lastIndexOf()least: ƒ (map, all)length: 0map: ƒ (a)max: ƒ (map, all)min: ƒ (map, all)most: ƒ (map, all)none: ƒ (a)one: ƒ ()only: ƒ ()peek: ƒ ()peekBack: ƒ ()poke: ƒ (value)pokeBack: ƒ (value)pop: ƒ pop()push: ƒ push()randomize: ƒ ()reduce: ƒ reduce()reduceRight: ƒ reduceRight()remove: ƒ ()removeAt: ƒ (start, end)reverse: ƒ reverse()reversed: ƒ ()sample: ƒ (num)set: ƒ (index, value)shift: ƒ shift()slice: ƒ slice()some: ƒ (a)sort: ƒ sort()sortBy: ƒ (map, desc)sorted: ƒ (compare, by, order)splice: ƒ splice()spliceOne: ƒ (index,itemToAdd)subtract: ƒ (a)sum: ƒ (map)swap: ƒ (start, length, plus)to: ƒ (num)toArray: ƒ ()toLocaleString: ƒ toLocaleString()toObject: ƒ ()toString: ƒ toString()union: ƒ ()unique: ƒ (map)unshift: ƒ unshift()values: ƒ values()zip: ƒ ()Symbol(Symbol.iterator): ƒ values()Symbol(Symbol.unscopables): {copyWithin: true, entries: true, fill: true, find: true, findIndex: true, …}proto: Object background.js:11460 queued sync Object . queue is now Array(0) background.js:11460 start sync Object background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 checking for remote track changes background.js:11460 received json response from streamingloadalltracks: {"success":false, "reloadXsrf": true}

console.(anonymous function) @ background.js:11460 background.js:11460 failed to getTrackChanges: {"success":false,"reloadXsrf":true} console.(anonymous function) @ background.js:11460 background.js:11460 cache update res Object background.js:11460 syncPlaylists 08262833794545013034 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 injected query getUserInfo 2 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 finished sync Objectaction: "update-all"syncType: "manual"userId: "08262833794545013034"proto: Objectconstructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() . responses Array(2)0: {mutate_response: Array(861)}1: {mutate_response: Array(9)}length: 2proto: Array(0) background.js:11460 setLastSyncInfo to Object background.js:11460 injected query getUserInfo 2 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 init tab 2 background.js:11460 see user 08262833794545013034 Object background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 precached license status: true background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 got verifyToken response: Object background.js:11460 reset random cache background.js:11460 syncing random fields background.js:11460 request to init syncs, but they're already started background.js:11460 cache: upserting 3530 tracks background.js:11460 done syncing random fields background.js:11460 queued sync Object . queue is now Array(0) background.js:11460 start sync Object background.js:11460 syncing splaylist cache. current cache has: 20 background.js:11460 checking for remote track changes background.js:11460 received json response from streamingloadalltracks: {"success":false, "reloadXsrf": true}

console.(anonymous function) @ background.js:11460 background.js:11460 failed to getTrackChanges: {"success":false,"reloadXsrf":true} console.(anonymous function) @ background.js:11460 background.js:11460 cache update res Object background.js:11460 syncPlaylists 08262833794545013034 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 injected query getUserInfo 2 background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 user id: 101248084355939882297 isDev: undefined background.js:11460 got cached license Object background.js:11460 license status Object background.js:11460 finished sync Object . responses Array(2) background.js:11460 setLastSyncInfo to Object

simon-weber commented 6 years ago

Is there anything interesting if you click further into the responses section? It's the contents of the mutate_response array that will have data like "too many tracks", etc.

brianzam commented 6 years ago

Hi Simon,

It’s stopped working completely now, same as error #188 https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/188 No syncing, even when I reset the extension. Getting frustrating now as I have not been able to sync properly for some weeks, and I constantly add new musing that needs to be sorted.

Logs attached, nothing showing in a ‘mutate_response’ array as far as I can tell, but errors are showing.

Kind regards,

Brian

On 6 Jul 2018, at 15:53, Simon Weber notifications@github.com wrote:

Is there anything interesting if you click further into the responses section? It's the contents of the mutate_response array that will have data like "too many tracks", etc.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-403057652, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5R-TGmQJUcpWN4vp8OzEEi0k0RDCIks5uD3nmgaJpZM4U0eZc.

ERROR GENERATED WHEN I CLICK ON TEST BUTTON WHEN VIEWING AN AUTOPLAYLIST. TEST SCREEN DOES NOT LOAD (NEW ERROR - WORKED ABOUT 5 MINUTES AGO)

_generated_background_page.html:1 Error in response to storage.get: TypeError: Cannot read property 'getSchema' of undefined at Storage.getPlaylistsForUser.playlists (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:27954:22) at Object.chrome.storage.sync.get.Utils.unlessError.items (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:26547:5) at Object.unlessErrorWrapper [as callback] (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:28044:12) at Object.getPlaylistsForUser (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:26532:23) at Object.queryTracks (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:27947:11) at chrome.runtime.onMessage.addListener (chrome-extension://blbompphddfibggfmmfcgjjoadebinem/js-built/background.js:24690:18)

ERROR WHEN I CLICK ON THE SYNC NOW BUTTON. THE ICON CHANGES TO THE SYNCING ICON, BUT NOTHING ELESE HAPPENS

background.js:11460 queued sync {userId: "08262833794545013034", action: "update-all", syncType: "manual"} . queue is now [{…}] background.js:11460 start sync {userId: "08262833794545013034", action: "update-all", syncType: "manual"} background.js:11460 sync for {userId: "08262833794545013034", action: "update-all", syncType: "manual"}action: "update-all"syncType: "manual"userId: "08262833794545013034"proto: constructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() failed: TypeError: Cannot read property 'splaylists' of undefined at Object.sync (background.js:26154) at resolve (background.js:27278) at new Promise () at playlistsP.then.playlists (background.js:27277) console.(anonymous function) @ background.js:11460 syncSplaylistcache.then.then.catch.e @ background.js:26721 Promise.catch (async) _doSyncs @ background.js:26720 requestSync @ background.js:26661 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::eventbindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::eventbindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392 background.js:11460 finished sync {userId: "08262833794545013034", action: "update-all", syncType: "manual"}action: "update-all"syncType: "manual"userId: "08262833794545013034"proto: constructor: ƒ Object()hasOwnProperty: ƒ hasOwnProperty()isPrototypeOf: ƒ isPrototypeOf()propertyIsEnumerable: ƒ propertyIsEnumerable()toLocaleString: ƒ toLocaleString()toString: ƒ toString()valueOf: ƒ valueOf()defineGetter: ƒ defineGetter()defineSetter: ƒ defineSetter()lookupGetter: ƒ lookupGetter()lookupSetter: ƒ lookupSetter()get proto: ƒ proto()set proto: ƒ proto() . responses undefined

ERRORS IN SYNCING SCREEN - SEE [NOTES IN CAPS & SQUARE BRACKETS]

Syncing The last full sync was manual and happened 7 days ago. The next full sync is expected 13 days ago. [I CHANGED THE DURATION FROM ZERO TO TWENTY THEN TO TEN. STILL SHOWS 13 DAYS 'AGO'] Individual playlists can be synced by opening them and clicking the save button.

random ordering The ordering used by random sorts is shared across all playlists. It will automatically reset when: a Google Music tab is refreshed a new Google Music tab is opened the extension or Chrome is reloaded You can also manually reset it here. The random ordering was last reset 14 minutes ago. [I HAVE NOT RESET THIS AT ALL]

simon-weber commented 6 years ago

Sorry to hear it's gotten worse! I'll make some time this evening to dig into it a bit more.

Those most recent errors look related to not being able to pull in your library from Google, which is hopefully unrelated (unless something has degraded further on Google's end).

simon-weber commented 6 years ago

Also, a quick question: do you have multiple Google accounts signed in at once? If so, does it help if you sign out of all but the one used for Music and then reload the extension? There's some auth errors in the earlier logs which suggest that might be related.

Also, do you have a subscription Music account, or a free one?

simon-weber commented 6 years ago

I had an idea in the other thread that's worth trying for you as well: https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/188#issuecomment-403317752. This seems to have solved the problem for them.

simon-weber commented 6 years ago

@brianzam any luck with the auth token refresh? If it works for you I'll probably send it out to the mailing list in case anyone else is seeing it.

brianzam commented 6 years ago

Hi Simon,

Looks like I didn't have a token at all.

Tried revoking, nothing happened, but sorted it buy clicking on the little Autoplaylist button top right. Had to re-log in, so as you thought, something to do with authentication and seeing my library.

Back to original problem. Still disparity between numbers. Not consistent. I can play with the ‘Limit’ variable and by tweaking it down to a value (eg: 150), then it matches, then slowly increasing limit up to 500, there was a disparity, then it matched again by tweaking down to 440.

Odd.

Kind regards,

Brian Zammit

On 11 Jul 2018, at 02:02, Simon Weber notifications@github.com wrote:

@brianzam https://github.com/brianzam any luck with the auth token refresh? If it works for you I'll probably send it out to the mailing list in case anyone else is seeing it.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-404011843, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5R4NYye3PuFSeiEbDTtv2dCLLad2Bks5uFU6KgaJpZM4U0eZc.

simon-weber commented 6 years ago

Having no token is pretty bizarre. Glad that part is worked out, though.

I think what I'll do is push changes to automatically report the parts of https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/185#issuecomment-399159165 that I'm interested in.

Overloading still seems like the most likely cause, though if you were without an auth token for a while it'd expect things to have gotten better. Is it possible there's another computer that's also running the extension? Disabling the extension for a day or two might be worth a shot if that's the case; I think that state would eventually propagate to all devices.

brianzam commented 6 years ago

Hi Simon,

Stopped synching completely again.

navbar.js:5126 Error: timed out for callback => { chrome.runtime.sendMessage({action: 'getStatus'}, status => callback(new Date().getTime() - status.lastSyncInfo.ts < 60000)); }: [object Arguments] at r (syncpage.js:8886) at chrome.runtime.sendMessage.status (syncpage.js:8917) at sendResponseAndClearCallback (extensions::messaging:419) at messageListener (extensions::messaging:451) at EventImpl.dispatchToListener (extensions::eventbindings:403) at Event.publicClassPrototype.(chrome-extension://b…/anonymous function) [as dispatchToListener] (extensions::utils:138:26) at EventImpl.dispatch (extensions::event_bindings:387) at EventImpl.dispatch (extensions::event_bindings:409) at Event.publicClassPrototype.(chrome-extension://b…/anonymous function) [as dispatch] (extensions::utils:138:26) at dispatchOnMessage (extensions::messaging:392) console.(anonymous function) @ navbar.js:5126 console.(anonymous function) @ syncpage.js:5126 err @ syncpage.js:8920 r @ syncpage.js:8886 chrome.runtime.sendMessage.status @ syncpage.js:8917 sendResponseAndClearCallback @ extensions::messaging:419 messageListener @ extensions::messaging:451 EventImpl.dispatchToListener @ extensions::eventbindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392

On 13 Jul 2018, at 16:24, Simon Weber notifications@github.com wrote:

Having no token is pretty bizarre. Glad that part is worked out, though.

I think what I'll do is push changes to automatically report the parts of #185 (comment) https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/185#issuecomment-399159165 that I'm interested in.

Overloading still seems like the most likely cause, though if you were without an auth token for a while it'd expect things to have gotten better. Is it possible there's another computer that's also running the extension? Disabling the extension for a day or two might be worth a shot if that's the case; I think that state would eventually propagate to all devices.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-404866222, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5R_xVbT7u4ckD8vgQhf9w9b7_BObdks5uGLuXgaJpZM4U0eZc.

simon-weber commented 6 years ago

I just pushed a few changes in 5.10.0 that should help:

The first one is most important. There should now be a line in the background script logs that starts with "codeCounts" for each sync. My guess is yours will show a mix of "OK" and something else, since your syncs are only partially applying. I've also started sending these to GA, which might help in figuring out why some users get particular codes more often.

brianzam commented 6 years ago

Hi Simon,

OK, I’ve run some more tests. Logs and details below, but the summary is that I’ve removed a bunch of playlists I didn't need and re-started everything and I think that’s made some difference, though I’m still seeing some errors (but ‘better’ ones?).

This is what I saw when I tried to synch files.

codeCounts: {"OK":286,"TOO_MANY_ITEMS":775}

received non-ok codes in response console.(anonymous function) @ background.js:11460 Promise.then (async)
_doSyncs @ background.js:26743 requestSync @ background.js:26674 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::eventbindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::eventbindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392

Tried re-syncing, sync page ‘crashed’ (never finished syncing, button stays disabled).

Then re-started Chrome.

After a load of debug relating to synching each playlist, I see:

180 "mutations" background.js:12535 POST https://www.googleapis.com/sj/v2.5/plentriesbatch?dv=0&hl=en-US&tier=aa 500 () (anonymous) @ background.js:12535 send @ jquery-1.9.1.min.js:5 ajax @ jquery-1.9.1.min.js:5 chrome.identity.getAuthToken.Utils.unlessError.token @ background.js:25005 unlessErrorWrapper @ background.js:28085 safeCallbackApply @ extensions::uncaught…xception_handler:27 handleResponse @ extensions::sendRequest:67 background.js:11460 playlistbatch failed {readyState: 4, getResponseHeader: ƒ, getAllResponseHeaders: ƒ, setRequestHeader: ƒ, overrideMimeType: ƒ, …} abort : ƒ (e) always : ƒ () complete : ƒ () done : ƒ () error : ƒ () fail : ƒ () getAllResponseHeaders : ƒ () getResponseHeader : ƒ (e) overrideMimeType : ƒ (e) pipe : ƒ () progress : ƒ () promise : ƒ (e) arguments : null caller : null length : 1 name : "promise" prototype : {constructor: ƒ} proto : ƒ () [[FunctionLocation]] :

[[Scopes]] : Scopes[3] readyState : 4 responseText : "{"error":{"errors":[{"domain":"global","reason":"backendError","message":"Backend Error"}],"code":500,"message":"Backend Error"}}" setRequestHeader : ƒ (e,t) state : ƒ () status : 500 statusCode : ƒ (e) arguments : null caller : null length : 1 name : "statusCode" prototype : {constructor: ƒ} __proto__ : ƒ () [[FunctionLocation]] : [[Scopes]] : Scopes[3] statusText : "error" success : ƒ () then : ƒ () __proto__ : Object console.(anonymous function) @ background.js:11460 err @ background.js:25258 c @ jquery-1.9.1.min.js:3 fireWith @ jquery-1.9.1.min.js:3 k @ jquery-1.9.1.min.js:5 r @ jquery-1.9.1.min.js:5 XMLHttpRequest.send (async) (anonymous) @ background.js:12535 send @ jquery-1.9.1.min.js:5 ajax @ jquery-1.9.1.min.js:5 chrome.identity.getAuthToken.Utils.unlessError.token @ background.js:25005 unlessErrorWrapper @ background.js:28085 safeCallbackApply @ extensions::uncaught…xception_handler:27 handleResponse @ extensions::sendRequest:67 background.js:11460 sync for {userId: "08262833794545013034", action: "update-all", syncType: "manual"} action : "update-all" syncType : "manual" userId : "08262833794545013034" __proto__ : constructor : ƒ Object() hasOwnProperty : ƒ hasOwnProperty() isPrototypeOf : ƒ isPrototypeOf() propertyIsEnumerable : ƒ propertyIsEnumerable() toLocaleString : ƒ toLocaleString() toString : ƒ toString() valueOf : ƒ valueOf() __defineGetter__ : ƒ __defineGetter__() __defineSetter__ : ƒ __defineSetter__() __lookupGetter__ : ƒ __lookupGetter__() __lookupSetter__ : ƒ __lookupSetter__() get __proto__ : ƒ __proto__() set __proto__ : ƒ __proto__() failed: {readyState: 4, getResponseHeader: ƒ, getAllResponseHeaders: ƒ, setRequestHeader: ƒ, overrideMimeType: ƒ, …} console.(anonymous function) @ background.js:11460 syncSplaylistcache.then.then.catch.e @ background.js:26734 Promise.catch (async) _doSyncs @ background.js:26733 requestSync @ background.js:26674 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392 background.js:11460 entering backoff console.(anonymous function) @ background.js:11460 syncSplaylistcache.then.then.catch.e @ background.js:26740 Promise.catch (async) _doSyncs @ background.js:26733 requestSync @ background.js:26674 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392 background.js:11460 finished sync {userId: "08262833794545013034", action: "update-all", syncType: "manual"} action : "update-all" syncType : "manual" userId : "08262833794545013034" __proto__ : Object . responseBatches undefined background.js:26746 Uncaught (in promise) TypeError: Cannot read property 'length' of undefined at syncSplaylistcache.then.then.catch.then.responseBatches (background.js:26746) syncSplaylistcache.then.then.catch.then.responseBatches @ background.js:26746 Promise.then (async) _doSyncs @ background.js:26743 requestSync @ background.js:26674 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392 background.js:11460 backoffMins 0.012866666666666667 background.js:12535 POST https://app.getsentry.com/api/66349/store/?sentry_version=7&sentry_client=raven-js%2F3.17.0&sentry_key=ea691c5… 429 (TOO MANY REQUESTS) (anonymous) @ background.js:12535 _makeRequest @ background.js:13179 _sendProcessedPayload @ background.js:13102 _send @ background.js:13044 captureMessage @ background.js:11927 syncSplaylistcache.then.then.catch.e @ background.js:26735 Promise.catch (async) _doSyncs @ background.js:26733 requestSync @ background.js:26674 chrome.runtime.onMessage.addListener @ background.js:24686 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 messageListener @ extensions::messaging:240 EventImpl.dispatchToListener @ extensions::event_bindings:403 publicClassPrototype.(anonymous function) @ extensions::utils:138 EventImpl.dispatch_ @ extensions::event_bindings:387 EventImpl.dispatch @ extensions::event_bindings:409 publicClassPrototype.(anonymous function) @ extensions::utils:138 dispatchOnMessage @ extensions::messaging:392 background.js:12535 POST https://app.getsentry.com/api/66349/store/?sentry_version=7&sentry_client=raven-js%2F3.17.0&sentry_key=ea691c5… 403 (FORBIDDEN) (anonymous) @ background.js:12535 _makeRequest @ background.js:13179 _sendProcessedPayload @ background.js:13102 _send @ background.js:13044 _processException @ background.js:12818 _handleStackInfo @ background.js:12724 captureException @ background.js:11862 window.addEventListener.event @ background.js:25878 wrapped @ background.js:11795 background.js:11460 backoffMins 0.04635 background.js:11460 backoffMins 0.07985 background.js:11460 backoffMins 0.11335 background.js:11460 backoffMins 0.14691666666666667 background.js:11460 backoffMins 0.18034999999999998 background.js:11460 backoffMins 0.2138 background.js:11460 backoffMins 0.24726666666666666 background.js:11460 backoffMins 0.28923333333333334 background.js:11460 backoffMins 0.3392833333333333 background.js:11460 backoffMins 0.3893166666666667 background.js:11460 backoffMins 0.4393166666666667 background.js:11460 backoffMins 0.4893166666666667 No sign of the codeCounts var Disable/enabled extension Re-started chrome Removed unneeded playlists See DIFFERENT RESULTS including: This several times in log: 17:51:45.849 background.js:11460 codeCounts: {"OK":1} 17:51:52.911 background.js:11460 codeCounts: {"OK":1} 17:51:58.731 background.js:11460 codeCounts: {"OK":1} 17:52:55.369 background.js:11460 codeCounts: {"OK":1} 17:53:00.795 background.js:11460 codeCounts: {"OK":1} And the logs still show errors but not the same as before: 180 "mutations" 17:55:32.135 www.googleapis.com/s…&hl=en-US&tier=aa:1 Failed to load resource: the server responded with a status of 500 () 17:55:32.136 background.js:11460 playlistbatch failed Object abort : ƒ (e) always : ƒ () complete : ƒ () done : ƒ () error : ƒ () fail : ƒ () getAllResponseHeaders : ƒ () getResponseHeader : ƒ (e) overrideMimeType : ƒ (e) pipe : ƒ () progress : ƒ () promise : ƒ (e) readyState : 4 responseText : "{"error":{"errors":[{"domain":"global","reason":"backendError","message":"Backend Error"}],"code":500,"message":"Backend Error"}}" setRequestHeader : ƒ (e,t) state : ƒ () status : 500 statusCode : ƒ (e) statusText : "error" success : ƒ () then : ƒ () __proto__ : Object console.(anonymous function) @ background.js:11460 17:55:32.138 background.js:11460 sync for Object action : "update-all" syncType : "manual" userId : "08262833794545013034" __proto__ : constructor : ƒ Object() hasOwnProperty : ƒ hasOwnProperty() isPrototypeOf : ƒ isPrototypeOf() propertyIsEnumerable : ƒ propertyIsEnumerable() toLocaleString : ƒ toLocaleString() toString : ƒ toString() valueOf : ƒ valueOf() __defineGetter__ : ƒ __defineGetter__() __defineSetter__ : ƒ __defineSetter__() __lookupGetter__ : ƒ __lookupGetter__() __lookupSetter__ : ƒ __lookupSetter__() get __proto__ : ƒ __proto__() set __proto__ : ƒ __proto__() failed: Object abort : ƒ (e) always : ƒ () complete : ƒ () done : ƒ () error : ƒ () fail : ƒ () getAllResponseHeaders : ƒ () getResponseHeader : ƒ (e) overrideMimeType : ƒ (e) pipe : ƒ () progress : ƒ () promise : ƒ (e) readyState : 4 responseText : "{"error":{"errors":[{"domain":"global","reason":"backendError","message":"Backend Error"}],"code":500,"message":"Backend Error"}}" setRequestHeader : ƒ (e,t) state : ƒ () status : 500 statusCode : ƒ (e) statusText : "error" success : ƒ () then : ƒ () __proto__ : Object console.(anonymous function) @ background.js:11460 17:55:32.144 background.js:11460 entering backoff console.(anonymous function) @ background.js:11460 17:55:32.145 background.js:11460 finished sync Object . responseBatches undefined 17:55:32.151 background.js:26746 Uncaught (in promise) TypeError: Cannot read property 'length' of undefined at syncSplaylistcache.then.then.catch.then.responseBatches (background.js:26746) syncSplaylistcache.then.then.catch.then.responseBatches @ background.js:26746 17:55:32.798 app.getsentry.com/ap…085df5e5aee9a46f3:1 Failed to load resource: the server responded with a status of 403 (FORBIDDEN) 17:55:32.806 app.getsentry.com/ap…085df5e5aee9a46f3:1 Failed to load resource: the server responded with a status of 429 (TOO MANY REQUESTS) 17:55:33.486 background.js:11460 backoffMins 0.022333333333333334 17:55:35.495 background.js:11460 backoffMins 0.05583333333333333 17:55:37.505 background.js:11460 backoffMins 0.08933333333333333 17:55:39.518 background.js:11460 backoffMins 0.12288333333333333 17:55:41.529 background.js:11460 backoffMins 0.15638333333333332 17:55:43.539 background.js:11460 backoffMins 0.18988333333333335 17:55:45.552 background.js:11460 backoffMins 0.22343333333333334 17:55:47.561 background.js:11460 backoffMins 0.2569166666666666 17:55:49.572 background.js:11460 backoffMins 0.2904333333333333 17:55:51.583 background.js:11460 backoffMins 0.3239666666666666 17:55:53.598 background.js:11460 backoffMins 0.35755 17:55:55.610 background.js:11460 backoffMins 0.39108333333333334 17:55:57.623 background.js:11460 backoffMins 0.4246166666666667 17:55:59.634 background.js:11460 backoffMins 0.45815 > On 14 Jul 2018, at 05:21, Simon Weber wrote: > > I just pushed a few changes in 5.10.0 that should help: > > Google's response codes are now logged and reported > the backoff status - when the extension disables itself to avoid overloading Google - now shows up on the syncing page > the syncing page will now properly stop the blinker (rather than just logging that timeout you posted above) > The first one is most important. There should now be a line in the background script logs that starts with "codeCounts" for each sync. My guess is yours will show a mix of "OK" and something else, since your syncs are only partially applying. I've also started sending these to GA, which might help in figuring out why some users get particular codes more often. > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub , or mute the thread . >
simon-weber commented 6 years ago

Got it. This at least looks more normal, and seems to suggest things are just overloaded on Google's end. The TOO_MANY_ITEMS bit is especially indicative of this: it seems to mean that Google has gotten behind on the state of your playlists, and isn't processing entry deletes fast enough to keep up with additions.

This might sound ridiculous, but I'm pretty sure this will fix itself if you disable the extension and wait a few days before re-enabling (as solution that, as Slack puts it I "suggest to you now only with great regret and self-loathing"). It's also a good bet to turn your sync period way up to reduce syncs once you re-enable and enable mutation batching in the settings menu.

brianzam commented 6 years ago

Hi Simon,

I’m of the same opinion and am just about to set the sync period to once a day.

One other note to consider, just in general. I think there is an issue, possibly at Google’s end, with ‘null’ playlists that have no songs in them. If I use any playlists for auto playlist, I always make sure that I have at least one song in the playlist, otherwise the auto playlist fails to see that playlist and seems to fall over until I put a song in the playlist.

So I’m rationalising all my Google playlists as well, just in case. Shouldn’t have affected what I was experiencing, but you never know...

Kind regards,

On 15 Jul 2018, at 18:56, Simon Weber notifications@github.com wrote:

Got it. This at least looks more normal, and seems to suggest things are just overloaded on Google's end. The TOO_MANY_ITEMS bit is especially indicative of this: it seems to mean that Google has gotten behind on the state of your playlists, and isn't processing entry deletes fast enough to keep up with additions.

This might sound ridiculous, but I'm pretty sure this will fix itself if you disable the extension and wait a few days before re-enabling (as solution that, as Slack puts it I "suggest to you now only with great regret and self-loathing"). It's also a good bet to turn your sync period way up to reduce syncs once you re-enable and enable mutation batching in the settings menu.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-405107202, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5RxaLQFC36eX-WHuBtnFS5leZ925eks5uG4JWgaJpZM4U0eZc.

simon-weber commented 6 years ago

Sounds good. Keep me posted.

Good catch with the empty playlists: I'll look into that and see if there's a bug on my end.

brianzam commented 6 years ago

Thanks. Just FYI,. Have re-enabled and re-started and as expected, we’re seeing:

background.js:11460 codeCounts: {"OK":355,"TOO_MANY_ITEMS":369,"CONFLICT":1}

I’ll disable auto sync and try again in a day or two.

On 15 Jul 2018, at 19:11, Simon Weber notifications@github.com wrote:

Sounds good. Keep me posted.

Good catch with the empty playlists: I'll look into that and see if there's a bug on my end.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-405108041, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5RySgCsBr6Qm_LTAkRKouU--9Sb1Qks5uG4XSgaJpZM4U0eZc.

simon-weber commented 6 years ago

Sounds good.

"Conflict" is a new code to me. According to my metrics there's only a handful of users who have ever seen it before.

simon-weber commented 6 years ago

Whoops, did not mean to close this.

brianzam commented 6 years ago

Good to know I'm pushing the boundaries 😊

On Sun, 15 Jul 2018, 20:12 Simon Weber, notifications@github.com wrote:

Sounds good.

"Conflict" is a new code to me. According to my metrics there's only a handful of users who have ever seen it before.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/186#issuecomment-405111530, or mute the thread https://github.com/notifications/unsubscribe-auth/ADO5R2diMzqFUlOYWsl_vlaznNHyxT_aks5uG5QygaJpZM4U0eZc .

brianzam commented 6 years ago

Hi Simon,

Just tried loading the auto sync again after a few days. No difference I’m afraid


295 "mutations"
22:04:59.908
background.js:11460 finished sync 
{userId: "08262833794545013034", action: "update-all", syncType: "manual"}

background.js:11460 codeCounts: {"TOO_MANY_ITEMS":295,"OK":61,"CONFLICT":1}
22:04:59.914
background.js:11460 received non-ok codes in response
22:04:59.923
background.js:11460 setLastSyncInfo to 
{syncType: "manual", ts: 1532034299908}
syncType
:
"manual"
ts
:
1532034299908
__proto__
:
Object
```
simon-weber commented 5 years ago

The TOO_MANY_ITEMS code is really interesting, especially since I've got someone else with the same symptoms.

Can you try a few tests for me?

simon-weber commented 5 years ago

Heads up that I'm moving this into a new issue so I can combine multiple threads: https://github.com/simon-weber/Autoplaylists-for-Google-Music/issues/193. If you get a chance, please put your responses over there.