Repository navigation
Playlist management functions some times silently fail #149
Description
Activity
I've put some relevant extracts from the bot codebase in a gist here:
https://gist.github.com/mortenn/2114a16c9fbfbed34ef510d0b2792914Could this possibly be related to plug returning a 429 response code if the client sends too many api requests in a short interval?
I rewrote the bot code a bit, and made it rerun the PlugAPI call if the callback was not executed within 2 seconds, and this is what I got:
GODJ Playlist already loaded +0 482 [WARN] 06-12-18 01:38:26 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:28 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:30 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:32 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:34 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:36 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:38 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:40 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:42 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:44 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:46 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:48 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:50 PlugAPI call timed out, retrying.. [WARN] 06-12-18 01:38:52 PlugAPI call timed out, retrying.. GODJ media fetch: [] +28142 28624 GODJ Playlist contains 0 items +0 28624 GODJ Adding song to playlist: Cowboy Bebop Session XX - Recover the Sky of Day (Sora wo Torimodoshita Hi) +1 28625 [WARN] 06-12-18 01:38:55 PlugAPI call timed out, retrying.. GODJ Media added +2174 30799For reference, this is my current iteration of the
toPromisefunction I am using:function toPromise(call, autoretry) { let resolved = false; return new Promise( (resolve, reject) => { var caller = () => { let retry = null; if(autoretry) { let doRetry = () => { logger.data('WARN', 'PlugAPI call timed out, retrying..'); caller(); }; retry = setTimeout(doRetry, 2000); } call((err, data) => { if(retry) clearTimeout(retry); if(resolved) return; resolved = true; if(err) { logger.data('ERR', 'PlugAPI: ' + err); reject(err); } else resolve(data) }); }; caller(); } ); }
Which is then used like so:
function joinBooth() { if(amDJ() || amWaitlisted()) return Promise.reject('Redundant enqueue'); logger.debug('GODJ', 'Ready to join'); return toPromise(bot.joinBooth, true); }
And the top level execution flow is defined like this:
new Promise( (resolve, reject) => clearPlaylist(playlist) .then(() => addMedia(playlist, createMedia(song)), reject) .then(joinBooth, reject) .then(resolve, reject) );
The first sequence of retries is due to
toPromise((callback) => bot.getPlaylistMedias(playlist.id, callback), true)
The last one is due to
toPromise((callback) => bot.addSongToPlaylist(playlist.id, media, callback), true)
This seems to be 100% reproducible on startup, but after the bot has been running a while, it is rarer.
For some reason I'm unable to retrieve any data for getPlaylist() or getPlaylistMedias(), bot return "undefined" while getPlaylists() returns everything just fine. Not sure if this issue is related to what you mentioned above? Edit: seems to be the same undefined for getActivePlaylist()...
Example: console.log("PLAYLIST MEDIA", bot.getPlaylists(), bot.getPlaylist(11630973), bot.getPlaylistMedias(11630973))
returns: PLAYLIST MEDIA [ { active: true, count: 4, id: 11630973, name: 'Test' } ] undefined undefined
I've made our bot manage a playlist via PlugAPI, but some times, the callback is never called.
It seems to happen most frequently with
getPlaylistMedias, but it has also happened withjoinBooth.To work around this, I made it automatically retry after 10 seconds of no callback happening, and after 6 retries, the operations completed successfully.
The "Ready to join" message is logged just before calling
joinBooth, the "Playlist exists" message is logged just beforegetPlaylistMedias.After
getPlaylistMediascalls back, the message "playlist contains N items" is logged, and after joinBooth calls back, the timer that retries the join is cancelled.