Cog-Creators / Red-DiscordBot

A multi-function Discord bot
https://docs.discord.red
GNU General Public License v3.0
4.72k stars 2.3k forks source link

Incorrect Disconnect Handling #5201

Open rtemelcea opened 3 years ago

rtemelcea commented 3 years ago

What Red version are you using?

3.4.12

What were you trying to do?

Restart the bot

What did you expect to happen?

Bot should restart and only resume real active players, or if no one was using it don't join or send any messages.

What actually happened?

When the bot restarts, it joins the last channels that it was connected in every server, sends an Auto Play started message then leaves

How can we reproduce this error?

Disconnects triggered by empty disconnect timeout don't terminate correctly Lavalink players. When the discord bot leaves the channel, Lavalink receives the following: "stop" command, then "destroy" command, then "play" command. Also the bot send the message "Auto Play Started".

This causes the following: -When [p]restart is issued, after the bot starts, connects to the last voice channel joined and sends a message in the last text channel with "Auto Play started.", then leaves. (This is consistent behavior with Auto Play enabled after the queue ends and empty disconnect timer) -When [p]audioset restart, after the bot starts, connects to the last voice channel joined and sends a message in the last text channel with "Auto Play started.", then leaves. (This is consistent behavior with Auto Play enabled after the queue ends and empty disconnect timer)

Red Bot has the following starting log:

[2021-07-28 03:04:45] [INFO] red.cogs.Audio.cog.Tasks.startup: Restored <Player: state=READY, connected=True, guild='Discord Bots Delevoping' (837659021782810645), channel='voice' (837681669224792074), playing=False, paused=False, volume=100, queue_size=0, current=None, position=0, length=0, node=<Node: state=READY, host=lavalink, port=2333, password=***, resume_key=Red-Core-Audio-824755869132390400-docker, shards=1, user=824755869132390400, stats=>>, [2021-07-28 03:05:00] [INFO] red.Audio.WS.RLL: Received voice disconnect from discord, removing player.

Lavalink has the following log:

2021-07-28 00:04:40.283 INFO 1 --- [ XNIO-1 task-7] l.server.io.HandshakeInterceptorImpl : Incoming connection from /172.20.0.2:45086, 2021-07-28 00:04:40.287 INFO 1 --- [ XNIO-1 task-7] lavalink.server.io.SocketServer : Connection successfully established from /172.20.0.2:45086, 2021-07-28 00:04:40.288 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "configureResuming", "key": "Red-Core-Audio-824755869132390400-docker", "timeout": 60}, 2021-07-28 00:04:45.340 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "play", "guildId": "837659021782810645", "track": "", "noReplace": false, "startTime": "0", "pause": false},

2021-07-28 00:04:46.003 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "voiceUpdate", "guildId": "837659021782810645", "sessionId": "489723cef01ca534d4afe1011c10ee32", "event": {"token": "b79e7f7a2818ae3e", "guild_id": "837659021782810645", "endpoint": "russia7442.discord.media:443"}},

2021-07-28 00:05:00.280 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "stop", "guildId": "837659021782810645"}, 2021-07-28 00:05:00.281 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "destroy", "guildId": "837659021782810645"}, 2021-07-28 00:05:00.386 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "play", "guildId": "837659021782810645", "track": "", "noReplace": false, "startTime": "0", "pause": false}

(Last three lines are the exact behavior of empty disconnect disconnects)

If the bot is disconnected using [p]disconnect the above things occur.

Disconnecting the bot using the Discord Disconnect button correctly terminates Lavalink player, but after a bot restart the same behavior occurs, but with some differences:

Red Logs:

[2021-07-28 02:53:16] [INFO] red.cogs.Audio.cog.Tasks.startup: Restored <Player: state=READY, connected=True, guild='Discord Bots Delevoping' (837659021782810645), channel='voice' (837681669224792074), playing=False, paused=False, volume=100, queue_size=0, current=None, position=0, length=0, node=<Node: state=READY, host=lavalink, port=2333, password=***, resume_key=Red-Core-Audio-824755869132390400-docker, shards=1, user=824755869132390400, stats=>>

Lavalink Logs:

2021-07-28 00:14:05.738 INFO 1 --- [ XNIO-1 I/O-2] lavalink.server.io.SocketServer : {"op": "play", "guildId": "837659021782810645", "track": "", "noReplace": false, "startTime": "0", "pause": false}, (play track) 2021-07-28 00:14:16.073 INFO 1 --- [ XNIO-1 I/O-2] lavalink.server.io.SocketServer : {"op": "destroy", "guildId": "837659021782810645"}, (press discord disconnect button) 2021-07-28 00:14:24.196 INFO 1 --- [ XNIO-1 I/O-2] lavalink.server.io.SocketServer : {"op": "configureResuming", "key": null}, (restart command) 2021-07-28 00:14:24.199 INFO 1 --- [ XNIO-1 I/O-2] lavalink.server.io.SocketServer : Connection closed from /172.20.0.2:45396 -- CloseStatus[code=1000, reason=], (restart command) 2021-07-28 00:14:24.199 INFO 1 --- [ XNIO-1 I/O-2] lavalink.server.io.SocketContext : Shutting down 0 playing players., (restart command) 2021-07-28 00:14:41.484 INFO 1 --- [ XNIO-1 task-11] l.server.io.HandshakeInterceptorImpl : Incoming connection from /172.20.0.2:45666, (restart command) 2021-07-28 00:14:41.487 INFO 1 --- [ XNIO-1 task-11] lavalink.server.io.SocketServer : Connection successfully established from /172.20.0.2:45666, (restart command) 2021-07-28 00:14:41.488 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "configureResuming", "key": "Red-Core-Audio-824755869132390400-docker", "timeout": 60}, (restart command) 2021-07-28 00:14:46.734 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "voiceUpdate", "guildId": "837659021782810645", "sessionId": "ed8de63964c7bf4c3c37c937a7ade4c4", "event": {"token": "2f350c9797948ac0", "guild_id": "837659021782810645", "endpoint": "eu-central1396.discord.media:443"}}, (bot joins then...) 2021-07-28 00:14:46.542 INFO 1 --- [ XNIO-1 I/O-4] lavalink.server.io.SocketServer : {"op": "play", "guildId": "837659021782810645", "track": "": false, "startTime": "0", "pause": false} (bot requests a song then leaves because of the empty disconnect timer doing the original behavior "when disconnecting it stops and destroys the player, then starts another one and send message Auto Play Started message.)

Anything else?

If you need more details or a demo my discord is rtemelcea#6348 .

Drapersniper commented 2 years ago

What did you expect to happen? Bot should restart and only resume real active players, or if no one was using it don't join or send any messages.

This is wrong -

Autoplay should always be restored - if it's playing regardless of how many users are in the VC, f a player is in a VC at the time of shutdown, it should always restore - regardless of your settings.

That being said:

Disconnects triggered by empty disconnect timeout don't terminate correctly Lavalink players. When the discord bot leaves the channel, Lavalink receives the following: "stop" command, then "destroy" command, then "play" command. Also the bot send the message "Auto Play Started".

Is indeed an issue.

Just looking at the root cause of the issue - I believe #5651 should address the issue you are seeing as well as possibly superceeding #5360

Drapersniper commented 2 years ago

Turns out there was a race condition due to autoplay being enabled - when emptyDC triggered a QUEUE_END event - we would go and then dispatch a new autoplay to play the next track - this caused us to write to config with the new track meta (currently_auto_playing_in) which triggered the player restore on Audio refresh.

I actually fixed that in 1942562 (#5651) which should make https://github.com/Cog-Creators/Red-DiscordBot/pull/5360 not needed (as the config values should now be getting cleaned up which will cause the player to not be restored)

rtemelcea commented 2 years ago

I don’t know if this is related, but is it possible to allow the “skip” command with autoplay turned off and empty queue. Basically, it would stop(not pause) the song. Now it says that the queue is empty.

Razvan Temelcea

On 3 Apr 2022, at 15:00, Draper @.***> wrote:



Turns out there was a race condition due to autoplay being enabled - when emptyDC triggered a QUEUE_END event - we would go and then dispatch a new autoplay to play the next track - this caused us to write to config with the new track meta (currently_auto_playing_in) which triggered the player restore on Audio refresh.

I actually fixed that in 1942562 (#5651)https://github.com/Cog-Creators/Red-DiscordBot/pull/5651/commits/19425625a50c5572e605f0009b269a8230c7d706 which should make #5360https://github.com/Cog-Creators/Red-DiscordBot/pull/5360 not needed (as the config values should now be getting cleaned up which will cause the player to not be restored)

— Reply to this email directly, view it on GitHubhttps://github.com/Cog-Creators/Red-DiscordBot/issues/5201#issuecomment-1086850719, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AIFJM6RP3QHCYK2QDZIQ2GTVDGB4VANCNFSM5BDI4WYA. You are receiving this because you authored the thread.Message ID: @.***>

Drapersniper commented 2 years ago

With autoplay off, you can't currently use the skip command if the queue is empty.

Drapersniper commented 2 years ago

Forgot to mention, there is an open PR the pr you are asking for https://github.com/Cog-Creators/Red-DiscordBot/pull/5369