search

Pycord-Development / pycord

Pycord is a modern, easy to use, feature-rich, and async ready API wrapper for Discord written in Python
https://docs.pycord.dev
MIT License
2.73k stars 460 forks source link

VOICE_SERVER_UPDATE can cause voice bots to leave and not rejoin #1567

Closed trwnh closed 2 years ago

trwnh commented 2 years ago

Summary

I have a Discord bot that joins a voice channel and performs tasks such as playing music. Occasionally it will leave and rejoin on its own, but sometimes it will leave and not rejoin.

Reproduction Steps

Option A:

1) Summon the bot using the join command 1) Wait for a random voice server update from Discord while voice channel region is set to "Automatic"

Option B:

1) Summon the bot using the join command 1) Manually change the voice channel region (possibly a few times, possibly region-dependent?)

Minimal Reproducible Code

app.py:

import discord

""" Declare intents that the bot will use """
intents = discord.Intents.default()
intents.emojis_and_stickers = True
intents.guilds = True
intents.integrations = True
intents.message_content = True
intents.messages = True
intents.members = True
intents.presences = True
intents.reactions = True
intents.voice_states = True

""" Load the bot token """
from dotenv import load_dotenv
from os import getenv
load_dotenv()
TOKEN = getenv("BOT_TOKEN")
GUILD = int(getenv("GUILD_ID"))

""" Initialize the bot """
from discord.ext.commands import Bot, when_mentioned_or
bot = Bot(
    command_prefix=when_mentioned_or('..', '>', '.'),
    description="A list of commands available",
    intents=intents,
    # debug_guilds=[GUILD],
    max_messages=100_000
)

@bot.event
async def on_ready():
    print(f"Logged in as {bot.user} (ID: {bot.user.id})")
    print("------")

""" Load cogs """
from os import listdir
def list_all_cogs() -> list[str]:
    return [file[:-3] for file in listdir("cogs") if file.endswith(".py")]

for cog in list_all_cogs():
    bot.load_extension(f"cogs.{cog}")

""" Run the bot """
bot.run(TOKEN)

music.py:

import discord
from discord.ext.commands import Cog, command, Context
from os import getenv, path, makedirs
import logging

if not path.exists('.logs'):
    makedirs('.logs')

logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)
fh = logging.FileHandler('.logs/music.log')
formatter = logging.Formatter('%(asctime)s | %(name)s | [%(levelname)s] %(message)s', '%Y-%m-%d %H:%M:%S')
fh.setFormatter(formatter)
if not len(logger.handlers):
    logger.addHandler(fh)

def setup(bot: discord.Bot):
    bot.add_cog(Music(bot))

class Music(Cog):
    """Play audio within a voice channel."""

    def __init__(self, bot: discord.Bot):
        self.bot: discord.Bot = bot
        print("Initialized Music cog")

@command(aliases=['start', 'summon', 'connect'])
    async def join(self, ctx: Context, *, channel: discord.VoiceChannel = None):
        """Joins a voice channel"""
        logger.info(f".join {channel}" if channel else ".join")
        if not channel: # Upon a raw "join" command without a channel specified,
            if not ctx.author.voice:
                msg =  await ctx.send(
                    "You must either be in a voice channel, "
                    "or specify a voice channel in order to use this command"
                    )
                if msg:
                    logger.info(f"Message sent: no channel specified, and {ctx.author} is not in a voice channel")
                return
            channel = ctx.author.voice.channel # bind to your current vc channel.
        if ctx.voice_client: # If the bot is in a different channel,
            await ctx.voice_client.move_to(channel) # move to your channel.
            logger.info(f"existing voice client moved to {channel}")
            return
        voice_client = await channel.connect() # Finally, join the chosen channel.
        if voice_client:
            logger.info("voice client created")

Expected Results

Voice client should gracefully handle voice server updates

Actual Results

Voice client sometimes does not reconnect

Intents

See reproducible code / app.py

System Information

(.venv) [trwnh@trwnh.com CyberBus2]$ python -m discord -v
- Python v3.10.5-final
- py-cord v2.0.0-final
- aiohttp v3.8.1
- system info: Linux 5.18.11-arch1-1 #1 SMP PREEMPT_DYNAMIC Tue, 12 Jul 2022 15:40:51 +0000

Checklist

Additional Context

Logs: https://gist.github.com/trwnh/db000f367aac8bf79e36f0604675ccf5

1) I have not been able to observe this myself, but apparently sometimes the bot will appear to go offline despite it still running. problem1.log is a 10-minute segment of logs in which this supposedly happened.

2) Websocket can be observed to close with code 1006 after aiohttp sends CLOSED code 257. Pycord is unable to connect to voice even after retrying, likely due to the closed websocket. problem2.log should contain relevant lines, although more important ones are replicated below.

2022-08-15 16:19:13,870:DEBUG:discord.gateway: Received WSMessage(type=<WSMsgType.CLOSED: 257>, data=None, extra=None)
2022-08-15 16:19:13,871:ERROR:discord.voice_client: Disconnected from voice... Reconnecting in 0.90s.
Traceback (most recent call last):
  File "/home/trwnh/git/CyberBus2/.venv/lib/python3.10/site-packages/discord/voice_client.py", line 464, in poll_voice_ws
    await self.ws.poll_event()
  File "/home/trwnh/git/CyberBus2/.venv/lib/python3.10/site-packages/discord/gateway.py", line 933, in poll_event
    raise ConnectionClosed(self.ws, shard_id=None, code=self._close_code)
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 1006
2022-08-15 16:19:14,776:INFO:discord.voice_client: The voice handshake is being terminated for Channel ID 518624498421989386 (Guild ID 518624497780391948)
2022-08-15 16:19:14,776:DEBUG:discord.gateway: Updating our voice state to {'op': 4, 'd': {'guild_id': 518624497780391948, 'channel_id': None, 'self_mute': False, 'self_deaf': False}}.
2022-08-15 16:19:14,777:INFO:discord.voice_client: Connecting to voice...
2022-08-15 16:19:14,777:INFO:discord.voice_client: Starting voice handshake... (connection attempt 2)

2022-08-15 16:20:14,780:INFO:discord.voice_client: The voice handshake is being terminated for Channel ID 518624498421989386 (Guild ID 518624497780391948)
2022-08-15 16:20:14,781:DEBUG:discord.gateway: Updating our voice state to {'op': 4, 'd': {'guild_id': 518624497780391948, 'channel_id': None, 'self_mute': False, 'self_deaf': False}}.
2022-08-15 16:20:14,781:WARNING:discord.voice_client: Could not connect to voice... Retrying...
2022-08-15 16:20:14,781:DEBUG:discord.gateway: Sending voice websocket frame: {'op': 5, 'd': {'speaking': 0, 'delay': 0}}.
2022-08-15 16:20:14,781:DEBUG:discord.gateway: Received WSMessage(type=<WSMsgType.CLOSED: 257>, data=None, extra=None)
2022-08-15 16:20:14,781:INFO:discord.voice_client: Disconnecting from voice normally, close code 1000.
2022-08-15 16:20:14,818:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'VOICE_STATE_UPDATE', 's': 37754, 'op': 0, 'd': {'member': {'user': {'username': 'Ricky', 'public_flags': 0, 'id': '949503750651936828', 'discriminator': '6849', 'bot': True, 'avatar': '49dadab54afe9f854b5bb643175f0e3e'}, 'roles': ['956209132472516710', '952367355793649704', '519028711480229899', '662418319554510860', '608084233625272332', '692142321268949073', '529192699602141204', '952367402404970526'], 'premium_since': None, 'pending': False, 'nick': 'What$App Ricky', 'mute': False, 'joined_at': '2022-03-23T15:13:42.722000+00:00', 'flags': 0, 'deaf': False, 'communication_disabled_until': None, 'avatar': None}, 'user_id': '949503750651936828', 'suppress': False, 'session_id': '48693e2e22ac78d2f61b257d759cec9d', 'self_video': False, 'self_mute': False, 'self_deaf': False, 'request_to_speak_timestamp': None, 'mute': False, 'guild_id': '518624497780391948', 'deaf': False, 'channel_id': None}}
2022-08-15 16:20:14,818:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 16:20:14,818:DEBUG:discord.client: Dispatching event voice_state_update
2022-08-15 16:20:14,983:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'MESSAGE_CREATE', 's': 37755, 'op': 0, 'd': {'type': 0, 'tts': False, 'timestamp': '2022-08-15T16:20:14.920000+00:00', 'referenced_message': None, 'pinned': False, 'mentions': [], 'mention_roles': [], 'mention_everyone': False, 'member': {'roles': ['956209132472516710', '952367355793649704', '519028711480229899', '662418319554510860', '608084233625272332', '692142321268949073', '529192699602141204', '952367402404970526'], 'premium_since': None, 'pending': False, 'nick': 'What$App Ricky', 'mute': False, 'joined_at': '2022-03-23T15:13:42.722000+00:00', 'flags': 0, 'deaf': False, 'communication_disabled_until': None, 'avatar': None}, 'id': '1008772117619294259', 'flags': 0, 'embeds': [{'type': 'rich', 'description': '**What$App Ricky** left **Main VC**', 'author': {'proxy_icon_url': 'https://images-ext-2.discordapp.net/external/jR8SFZy6_eIpkMXUetTINpFCYjDpHbcp0fac5zqWqcI/%3Fsize%3D1024/https/cdn.discordapp.com/avatars/949503750651936828/49dadab54afe9f854b5bb643175f0e3e.png', 'name': 'What$App Ricky (Ricky#6849)', 'icon_url': 'https://cdn.discordapp.com/avatars/949503750651936828/49dadab54afe9f854b5bb643175f0e3e.png?size=1024'}}], 'edited_timestamp': None, 'content': '', 'components': [], 'channel_id': '620028244887994408', 'author': {'username': 'Ricky', 'public_flags': 0, 'id': '949503750651936828', 'discriminator': '6849', 'bot': True, 'avatar_decoration': None, 'avatar': '49dadab54afe9f854b5bb643175f0e3e'}, 'attachments': [], 'guild_id': '518624497780391948'}}
2022-08-15 16:20:14,984:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 16:20:14,984:DEBUG:discord.client: Dispatching event message
2022-08-15 16:20:15,069:DEBUG:discord.http: POST https://discord.com/api/v10/channels/620028244887994408/messages with {"embeds":[{"author":{"name":"What$App Ricky (Ricky#6849)","icon_url":"https://cdn.discordapp.com/avatars/949503750651936828/49dadab54afe9f854b5bb643175f0e3e.png?size=1024"},"fields":[],"type":"rich","description":"**What$App Ricky** left **Main VC**"}]} has returned 200
2022-08-15 16:20:15,069:DEBUG:discord.http: POST https://discord.com/api/v10/channels/620028244887994408/messages has received {'id': '1008772117619294259', 'type': 0, 'content': '', 'channel_id': '620028244887994408', 'author': {'id': '949503750651936828', 'username': 'Ricky', 'avatar': '49dadab54afe9f854b5bb643175f0e3e', 'avatar_decoration': None, 'discriminator': '6849', 'public_flags': 0, 'bot': True}, 'attachments': [], 'embeds': [{'type': 'rich', 'description': '**What$App Ricky** left **Main VC**', 'author': {'name': 'What$App Ricky (Ricky#6849)', 'icon_url': 'https://cdn.discordapp.com/avatars/949503750651936828/49dadab54afe9f854b5bb643175f0e3e.png?size=1024', 'proxy_icon_url': 'https://images-ext-2.discordapp.net/external/jR8SFZy6_eIpkMXUetTINpFCYjDpHbcp0fac5zqWqcI/%3Fsize%3D1024/https/cdn.discordapp.com/avatars/949503750651936828/49dadab54afe9f854b5bb643175f0e3e.png'}}], 'mentions': [], 'mention_roles': [], 'pinned': False, 'mention_everyone': False, 'tts': False, 'timestamp': '2022-08-15T16:20:14.920000+00:00', 'edited_timestamp': None, 'flags': 0, 'components': [], 'referenced_message': None}

3) problem3.log contains the tail end of a session in which only the following actions occurred:

In this case, the codes observed are aiohttp WS CLOSING 256 and Websocket closed with error 4000, and later we can see the same CLOSED 257 / code 1000 behavior.

2022-08-15 18:00:33,576:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'VOICE_SERVER_UPDATE', 's': 26, 'op': 0, 'd': {'token': '15f157a2f0580095', 'guild_id': '518624497780391948', 'endpoint': 'southafrica7730.discord.media:443'}}
2022-08-15 18:00:33,576:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 18:00:33,577:DEBUG:discord.gateway: Received WSMessage(type=<WSMsgType.CLOSING: 256>, data=None, extra=None)
2022-08-15 18:00:33,577:ERROR:discord.voice_client: Disconnected from voice... Reconnecting in 1.09s.
Traceback (most recent call last):
  File "/home/trwnh/git/CyberBus2/.venv/lib/python3.10/site-packages/discord/voice_client.py", line 464, in poll_voice_ws
    await self.ws.poll_event()
  File "/home/trwnh/git/CyberBus2/.venv/lib/python3.10/site-packages/discord/gateway.py", line 933, in poll_event
    raise ConnectionClosed(self.ws, shard_id=None, code=self._close_code)
discord.errors.ConnectionClosed: Shard ID None WebSocket closed with 4000
2022-08-15 18:00:34,668:INFO:discord.voice_client: The voice handshake is being terminated for Channel ID 817793224797061142 (Guild ID 518624497780391948)
2022-08-15 18:00:34,669:DEBUG:discord.gateway: Updating our voice state to {'op': 4, 'd': {'guild_id': 518624497780391948, 'channel_id': None, 'self_mute': False, 'self_deaf': False}}.
2022-08-15 18:00:34,669:INFO:discord.voice_client: Connecting to voice...
2022-08-15 18:00:34,669:INFO:discord.voice_client: Starting voice handshake... (connection attempt 2)
2022-08-15 18:01:30,867:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'VOICE_SERVER_UPDATE', 's': 61, 'op': 0, 'd': {'token': '5b07b5e43313a634', 'guild_id': '518624497780391948', 'endpoint': 'singapore6073.discord.media:443'}}
2022-08-15 18:01:30,868:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 18:01:33,366:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'PRESENCE_UPDATE', 's': 62, 'op': 0, 'd': {'user': {'id': '647368715742216193'}, 'status': 'online', 'guild_id': '518624497780391948', 'client_status': {'web': 'online'}, 'activities': [{'type': 3, 'name': 'Your Links... | Servers: 4854', 'id': 'ec0b28a579ecb4bd', 'created_at': 1660586493224}]}}
2022-08-15 18:01:33,366:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 18:01:33,366:DEBUG:discord.client: Dispatching event presence_update
2022-08-15 18:01:34,070:DEBUG:discord.gateway: For Shard ID None: WebSocket Event: {'t': 'PRESENCE_UPDATE', 's': 63, 'op': 0, 'd': {'user': {'id': '254855291466678272'}, 'status': 'dnd', 'guild_id': '518624497780391948', 'client_status': {'mobile': 'dnd', 'desktop': 'dnd'}, 'activities': []}}
2022-08-15 18:01:34,071:DEBUG:discord.client: Dispatching event socket_event_type
2022-08-15 18:01:34,071:DEBUG:discord.client: Dispatching event presence_update
2022-08-15 18:01:34,671:INFO:discord.voice_client: The voice handshake is being terminated for Channel ID 817793224797061142 (Guild ID 518624497780391948)
2022-08-15 18:01:34,671:DEBUG:discord.gateway: Updating our voice state to {'op': 4, 'd': {'guild_id': 518624497780391948, 'channel_id': None, 'self_mute': False, 'self_deaf': False}}.
2022-08-15 18:01:34,671:WARNING:discord.voice_client: Could not connect to voice... Retrying...
2022-08-15 18:01:34,672:DEBUG:discord.gateway: Received WSMessage(type=<WSMsgType.CLOSED: 257>, data=None, extra=None)
2022-08-15 18:01:34,672:INFO:discord.voice_client: Disconnecting from voice normally, close code 1000.
BobDotCom commented 2 years ago

For clarification, under what conditions does number 2 occur?

trwnh commented 2 years ago

1 happens under unclear conditions 2 occurs when an automatic voice server update happens, I think. 3 happens when a manual voice server update happens.

BobDotCom commented 2 years ago

I've identified the cause to be introduced in #1273. I'll make a PR soon to fix the issue.