Playlist management functions some times silently fail

[mortenn]

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 with joinBooth.
To work around this, I made it automatically retry after 10 seconds of no callback happening, and after 6 retries, the operations completed successfully.

[SKIP] 02-11-17 18:32:01 KawaiiBot skipped the current song
GODJ Got request to join booth +0 0
[DATA] 02-11-17 18:32:02 Plays: 1
GODJ Found song: Asriel - Metamorphose +548 548
GODJ Song is available! +136 684
GODJ Enqueue(Asriel - Metamorphose) +0 684
GODJ Playlist exists. +1 685
GODJ Playlist contains 1 items +254 939
GODJ Clearing playlist 10802990 +0 939
GODJ Playlist already active +159 1098
GODJ Adding song to playlist: Asriel - Metamorphose +0 1098
GODJ Ready to join +174 1272
[WARN] 02-11-17 18:32:12 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: chaosangel209 - 東方Touhou Metal/Rock 1 +260 260
GODJ Song is available! +82 342
GODJ Enqueue(chaosangel209 - 東方Touhou Metal/Rock 1) +0 342
GODJ Playlist exists. +0 342
[WARN] 02-11-17 18:32:22 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: _dubtrack - cinema staff「YOUR SONG」MV（「WAYPOINT E.P.」 lead track) +273 273
GODJ Song is available! +147 420
GODJ Enqueue(_dubtrack - cinema staff「YOUR SONG」MV（「WAYPOINT E.P.」 lead track)) +0 420
GODJ Playlist exists. +0 420
[WARN] 02-11-17 18:32:32 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: Voca Vamp - 【GUMI】 Shinen ni Nemuru 深淵に睡る 【オリジナルPV】 +259 259
GODJ Song is available! +84 343
GODJ Enqueue(Voca Vamp - 【GUMI】 Shinen ni Nemuru 深淵に睡る 【オリジナルPV】) +0 343
GODJ Playlist exists. +0 343
[WARN] 02-11-17 18:32:42 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: Naruto Shippuden OST 3 -  My Friend(2016) +319 319
GODJ Song is available! +77 396
GODJ Enqueue(Naruto Shippuden OST 3 -  My Friend(2016)) +0 396
GODJ Playlist exists. +1 397
[WARN] 02-11-17 18:32:52 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: MC Moohyun - Endless Unji live 공연 +283 283
GODJ Song is available! +153 436
GODJ Enqueue(MC Moohyun - Endless Unji live 공연) +0 436
GODJ Playlist exists. +1 437
[WARN] 02-11-17 18:33:02 Timed out joining booth - retrying
GODJ Got request to join booth +0 0
GODJ Found song: Spice and Wolf OST - 21 - "Kenshi to Yopparai" +276 276
GODJ Song is available! +128 404
GODJ Enqueue(Spice and Wolf OST - 21 - "Kenshi to Yopparai") +0 404
GODJ Playlist exists. +0 404
GODJ Playlist contains 1 items +129 533
GODJ Clearing playlist 10802990 +0 533
GODJ Playlist already active +158 691
GODJ Adding song to playlist: Spice and Wolf OST - 21 - "Kenshi to Yopparai" +0 691
GODJ Ready to join +165 856

The "Ready to join" message is logged just before calling joinBooth, the "Playlist exists" message is logged just before getPlaylistMedias.
After getPlaylistMedias calls back, the message "playlist contains N items" is logged, and after joinBooth calls back, the timer that retries the join is cancelled.

[mortenn]

I've put some relevant extracts from the bot codebase in a gist here:
https://gist.github.com/mortenn/2114a16c9fbfbed34ef510d0b2792914

[mortenn]

Could this possibly be related to plug returning a 429 response code if the client sends too many api requests in a short interval?

[mortenn]

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 30799

For reference, this is my current iteration of the toPromise function 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)

[mortenn]

This seems to be 100% reproducible on startup, but after the bot has been running a while, it is rarer.

[srdesigns]

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