Tasks stop looping following a connection reset

[lexicalunit]

Summary

After I see the connection reset stack trace, I've noticed that while everything else is working fine, tasks simply do not ever loop again.

Reproduction Steps

Sadly I have been struggling to reproduce this but I see it in the wild every now and then.

Minimal Reproducible Code

I have some tasks in my codebase that are set up like so:

from discord.ext import commands, tasks
import MyBot

class TasksCog(commands.Cog):
    def __init__(self, bot: MyBot):
        self.bot = bot
        self.my_task.start()

    @tasks.loop(minutes=5)
    async def my_task(self):
        # do stuff...
        # await interaction.[...]

    @my_task.before_loop
    async def before_my_task(self):
        await self.bot.wait_until_ready()

async def setup(bot: MyBot):
    await bot.add_cog(TasksCog(bot))

Expected Results

Connection resets happen, sometimes the network is flakey. When this happens the bot should attempt to reconnect and carry on.

Actual Results

This seems to work just fine most of the time. Every now and then though I get this stack trace. When I do it means that my tasks have stopped looping. The bot continues to work just fine in all other respects, but the tasks completely stop happening. In my example code the my_task() code should execute every 5ish minutes. But when I see this stack trace it means that my_task() will never execute again. It just stops looping tasks completely.

future: <Task finished name='Task-10' coro=<ConnectionState._delay_ready() done, defined at /usr/local/lib/python3.10/site-packages/discord/state.py:533> exception=ConnectionResetError('Cannot write to closing transport')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 545, in _delay_ready
    future = await self.chunk_guild(guild, wait=False)
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 1172, in chunk_guild
    await self.chunker(guild.id, nonce=request.nonce)
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 510, in chunker
    await ws.request_chunks(guild_id, query=query, limit=limit, presences=presences, nonce=nonce)
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 730, in request_chunks
    await self.send_as_json(payload)
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 658, in send_as_json
    await self.send(utils._to_json(data))
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 654, in send
    await self.socket.send_str(data)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_ws.py", line 151, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 690, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 646, in _send_frame
    self._write(header + mask + message)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 663, in _write
    raise ConnectionResetError("Cannot write to closing transport")
ConnectionResetError: Cannot write to closing transport

Maybe relevant, just before this stack trace is a bunch of logs like:

[2022-11-17 00:28:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.98 seconds

This exception also seems to happen after my bot is restarted. If it doesn't happen just after my bot is started, then it doesn't ever seem to happen. Whenever I see it, it's always just after the bot has been restarted.

Intents

3276543

System Information

• Python v3.10.5-final
• discord.py v2.0.1-final
• aiohttp v3.8.1
• system info: Darwin 21.5.0 Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:37 PDT 2022; root:xnu-8020.121.3~4/RELEASE_ARM64_T6000

Checklist

• I have searched the open issues for duplicates.
• I have shown the entire traceback, if possible.
• I have removed my token from display, if visible.

Additional Context

Here's the actual tasks cog code from my bot: https://github.com/lexicalunit/spellbot/blob/main/src/spellbot/cogs/tasks_cog.py

[Rapptz]

This issue seems to have a few layers involved, very few of which involve the task extension.

The task extension already retries on OSError, at the very least it does this within the body. This excludes things like before_loop and after_loop, so if an exception is raised there then by design the task will actually just die. Now, wait_until_ready does not raise. It's just waiting for an internal future to be marked as completed and that never gets set to an exception.

This brings me to your traceback, which points to a connection reset while the library is internally chunking and delaying the ready event. I'm not exactly sure how this would cause your task to die, I suspect instead it causes wait_until_ready to never return because the ready delay has been interrupted due to a networking issue.

I'm unsure what the proper course of action for this is at the moment, since a networking issue in the middle of this should cause the library to loop back and redo the flow but the fact wait_until_ready is presumably hanging means that some state along the way is being messed with.

Do you have any other logs?

[lexicalunit]

Here's the full logs from application start to Shard ID None has successfully RESUMED session...:

[2022-11-17 00:23:27][discord.client][WARNING] - PyNaCl is not installed, voice will NOT be supported
[2022-11-17 00:23:27][datadog.api][INFO] - No agent or invalid configuration file found
[2022-11-17 00:23:27] [INFO    ] discord.client: logging in using static token
[2022-11-17 00:23:27][discord.client][INFO] - logging in using static token
[2022-11-17 00:23:27][spellbot.client][INFO] - initializing database connection...
[2022-11-17 00:23:27][alembic.runtime.migration][INFO] - Context impl PostgresqlImpl.
[2022-11-17 00:23:27][alembic.runtime.migration][INFO] - Will assume transactional DDL.
[2022-11-17 00:23:27][spellbot.utils][INFO] - loading cogs...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.about_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.admin_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.ban_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.block_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.config_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.events_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.leave_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.lfg_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.score_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.sync_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.tasks_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.verify_cog...
[2022-11-17 00:23:27][spellbot.cogs][INFO] - loading extension spellbot.cogs.watch_cog...
[2022-11-17 00:23:27][spellbot.utils][INFO] - registered commands: about, setup, set, channels, awards, award, info, block, unblock, power, game, leave, lfg, score, history, verify, unverify, watched, watch, unwatch
[2022-11-17 00:23:28] [INFO    ] discord.gateway: Shard ID None has connected to Gateway (Session ID: 01c50bce7b447780449757ecdd353f94).
[2022-11-17 00:23:28][discord.gateway][INFO] - Shard ID None has connected to Gateway (Session ID: 01c50bce7b447780449757ecdd353f94).
[2022-11-17 00:23:28] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.42 seconds
[2022-11-17 00:23:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.42 seconds
[2022-11-17 00:24:28] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.97 seconds
[2022-11-17 00:24:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.97 seconds
[2022-11-17 00:25:27] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.99 seconds
[2022-11-17 00:25:27][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.99 seconds
[2022-11-17 00:26:28] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.97 seconds
[2022-11-17 00:26:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.97 seconds
10.1.24.221 [17/Nov/2022:00:26:50 +0000] "HEAD / HTTP/1.1" 200 170 "https://lexicalunit-spellbot.herokuapp.com/" "Mozilla/5.0+(compatible; UptimeRobot/2.0; http://www.uptimerobot.com/)"
[2022-11-17 00:27:28] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.98 seconds
[2022-11-17 00:27:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.98 seconds
[2022-11-17 00:28:28] [WARNING ] discord.gateway: WebSocket in shard ID None is ratelimited, waiting 59.98 seconds
[2022-11-17 00:28:28][discord.gateway][WARNING] - WebSocket in shard ID None is ratelimited, waiting 59.98 seconds
[2022-11-17 00:29:28][asyncio][ERROR] - Task exception was never retrieved
future: <Task finished name='Task-10' coro=<ConnectionState._delay_ready() done, defined at /usr/local/lib/python3.10/site-packages/discord/state.py:533> exception=ConnectionResetError('Cannot write to closing transport')>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 545, in _delay_ready
    future = await self.chunk_guild(guild, wait=False)
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 1172, in chunk_guild
    await self.chunker(guild.id, nonce=request.nonce)
  File "/usr/local/lib/python3.10/site-packages/discord/state.py", line 510, in chunker
    await ws.request_chunks(guild_id, query=query, limit=limit, presences=presences, nonce=nonce)
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 730, in request_chunks
    await self.send_as_json(payload)
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 658, in send_as_json
    await self.send(utils._to_json(data))
  File "/usr/local/lib/python3.10/site-packages/discord/gateway.py", line 654, in send
    await self.socket.send_str(data)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_ws.py", line 151, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 690, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 646, in _send_frame
    self._write(header + mask + message)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/http_websocket.py", line 663, in _write
    raise ConnectionResetError("Cannot write to closing transport")
ConnectionResetError: Cannot write to closing transport
[2022-11-17 00:29:28] [INFO    ] discord.gateway: Shard ID None has successfully RESUMED session 01c50bce7b447780449757ecdd353f94.
[2022-11-17 00:29:28][discord.gateway][INFO] - Shard ID None has successfully RESUMED session 01c50bce7b447780449757ecdd353f94.

[Rapptz]

Do you receive the ready event at some point?

[lexicalunit]

I'm not sure, I don't override on_ready() for my bot and I don't see any logs that say something like "bot is ready" even when tasks are working.

I could add an on_ready() and log something if that would help (if/when I see this issue again)?

[Rapptz]

There isn't a default log for the ready event being triggered unfortunately so you'd have to add your own. Right now my working theory is that on_ready is never called which leads to wait_until_ready's internal future not being set, which leads to your task hanging (presumably until the next time you get the ready event). The manifestation of the bug would be that during the initial ready delay disconnect it skips the ready event completely and goes straight to a resume.

[lexicalunit]

I have more logs now. Here's a full run from start up to the point where I noticed tasks were not running:

2023-07-03 00:03:29,779 INFO supervisord started with pid 3
2023-07-03 00:03:30,781 INFO spawned: 'api' with pid 4
2023-07-03 00:03:30,782 INFO spawned: 'bot' with pid 5
2023-07-03 00:03:30,783 INFO spawned: 'datadog-agent' with pid 6
2023-07-03 00:03:30,784 INFO spawned: 'process-agent' with pid 7
2023-07-03 00:03:30,785 INFO spawned: 'trace-agent' with pid 8
will start spellapi...
running with ddtrace...
will start spellbot...
running with ddtrace...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
2023-07-03 00:03:31,821 INFO success: api entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 00:03:31,822 INFO success: bot entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 00:03:31,822 INFO success: datadog-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 00:03:31,822 INFO success: process-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 00:03:31,822 INFO success: trace-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
statsd server is up!
statsd server is up!
starting spellapi now!
starting spellbot now!
[2023-07-03 00:03:35 +0000] [81] [INFO] Starting gunicorn 20.1.0
[2023-07-03 00:03:35 +0000] [81] [INFO] Listening at: http://0.0.0.0:37965 (81)
[2023-07-03 00:03:35 +0000] [81] [INFO] Using worker: aiohttp.worker.GunicornWebWorker
[2023-07-03 00:03:35 +0000] [90] [INFO] Booting worker with pid: 90
[2023-07-03 00:03:36 +0000] [93] [INFO] Booting worker with pid: 93
[2023-07-03 00:03:36 +0000] [101] [INFO] Booting worker with pid: 101
[2023-07-03 00:03:36 +0000] [103] [INFO] Booting worker with pid: 103
[2023-07-03 00:03:36][root][INFO] - metrics enabled, checking for connection to statsd server...
[2023-07-03 00:03:36][root][INFO] - statsd server connection established
[2023-07-03 00:03:36][root][INFO] - waiting for statsd server to finish initialization...
[2023-07-03 00:03:41][spellbot.client][INFO] - intents.value: 3276543
[2023-07-03 00:03:41][discord.client][WARNING] - PyNaCl is not installed, voice will NOT be supported
[2023-07-03 00:03:41][datadog.api][INFO] - No agent or invalid configuration file found
[2023-07-03 00:03:41] [INFO    ] discord.client: logging in using static token
[2023-07-03 00:03:41][discord.client][INFO] - logging in using static token
[2023-07-03 00:03:42][spellbot.client][INFO] - initializing database connection...
[2023-07-03 00:03:42][alembic.runtime.migration][INFO] - Context impl PostgresqlImpl.
[2023-07-03 00:03:42][alembic.runtime.migration][INFO] - Will assume transactional DDL.
[2023-07-03 00:03:42][spellbot.utils][INFO] - loading cogs...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.about_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.admin_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.block_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.config_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.events_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.leave_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.lfg_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.owner_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.score_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.sync_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.tasks_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.verify_cog...
[2023-07-03 00:03:42][spellbot.cogs][INFO] - loading extension spellbot.cogs.watch_cog...
[2023-07-03 00:03:42][spellbot.utils][INFO] - registered commands: about, setup, forget_channel, set, channels, awards, award, info, block, unblock, power, game, leave, lfg, score, history, top, verify, unverify, watched, watch, unwatch
[2023-07-03 00:03:42] [INFO    ] discord.gateway: Shard ID 0 has connected to Gateway (Session ID: 93b40e9a3ac8d443519c0505304c45a4).
[2023-07-03 00:03:42][discord.gateway][INFO] - Shard ID 0 has connected to Gateway (Session ID: 93b40e9a3ac8d443519c0505304c45a4).
[2023-07-03 00:03:43] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.42 seconds
[2023-07-03 00:03:43][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.42 seconds
[2023-07-03 00:03:47] [INFO    ] discord.gateway: Shard ID 1 has connected to Gateway (Session ID: 7eda1841ecaacc8b2b46d3d00dedefa9).
[2023-07-03 00:03:47][discord.gateway][INFO] - Shard ID 1 has connected to Gateway (Session ID: 7eda1841ecaacc8b2b46d3d00dedefa9).
[2023-07-03 00:03:48] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 54.32 seconds
[2023-07-03 00:03:48][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 54.32 seconds
[2023-07-03 00:04:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:04:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:04:42] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:04:42][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:05:25] [INFO    ] discord.gateway: Shard ID 1 has successfully RESUMED session 7eda1841ecaacc8b2b46d3d00dedefa9.
[2023-07-03 00:05:25][discord.gateway][INFO] - Shard ID 1 has successfully RESUMED session 7eda1841ecaacc8b2b46d3d00dedefa9.
[2023-07-03 00:05:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:05:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:06:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:06:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:07:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:07:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:08:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.98 seconds
[2023-07-03 00:08:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.98 seconds
[2023-07-03 00:09:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:09:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 00:10:42] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 0.00 seconds
[2023-07-03 00:10:42][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 0.00 seconds

When I noticed the issue, I restarted the bot manually and got this:

[2023-07-03 01:04:34 +0000] [101] [INFO] Worker exiting (pid: 101)
[2023-07-03 01:04:34 +0000] [81] [WARNING] Worker with pid 101 was terminated due to signal 15
2023-07-03 01:05:11,875 INFO supervisord started with pid 3
2023-07-03 01:05:12,880 INFO spawned: 'api' with pid 4
2023-07-03 01:05:12,882 INFO spawned: 'bot' with pid 5
2023-07-03 01:05:12,887 INFO spawned: 'datadog-agent' with pid 6
2023-07-03 01:05:12,889 INFO spawned: 'process-agent' with pid 7
2023-07-03 01:05:12,894 INFO spawned: 'trace-agent' with pid 8
will start spellapi...
running with ddtrace...
will start spellbot...
running with ddtrace...
waiting for statsd server to start...
waiting for statsd server to start...
2023-07-03 01:05:13,969 INFO success: api entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 01:05:13,969 INFO success: bot entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 01:05:13,970 INFO success: datadog-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 01:05:13,970 INFO success: process-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-07-03 01:05:13,970 INFO success: trace-agent entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
waiting for statsd server to start...
statsd server is up!
statsd server is up!
starting spellapi now!
starting spellbot now!
[2023-07-03 01:05:20 +0000] [91] [INFO] Starting gunicorn 20.1.0
[2023-07-03 01:05:20 +0000] [91] [INFO] Listening at: http://0.0.0.0:5380 (91)
[2023-07-03 01:05:20 +0000] [91] [INFO] Using worker: aiohttp.worker.GunicornWebWorker
[2023-07-03 01:05:20 +0000] [100] [INFO] Booting worker with pid: 100
[2023-07-03 01:05:20 +0000] [104] [INFO] Booting worker with pid: 104
[2023-07-03 01:05:20 +0000] [108] [INFO] Booting worker with pid: 108
[2023-07-03 01:05:20 +0000] [114] [INFO] Booting worker with pid: 114
[2023-07-03 01:05:21][root][INFO] - metrics enabled, checking for connection to statsd server...
[2023-07-03 01:05:21][root][INFO] - statsd server connection established
[2023-07-03 01:05:21][root][INFO] - waiting for statsd server to finish initialization...
[2023-07-03 01:05:26][spellbot.client][INFO] - intents.value: 3276543
[2023-07-03 01:05:26][discord.client][WARNING] - PyNaCl is not installed, voice will NOT be supported
[2023-07-03 01:05:26][datadog.api][INFO] - No agent or invalid configuration file found
[2023-07-03 01:05:26] [INFO    ] discord.client: logging in using static token
[2023-07-03 01:05:26][discord.client][INFO] - logging in using static token
[2023-07-03 01:05:26][spellbot.client][INFO] - initializing database connection...
[2023-07-03 01:05:26][alembic.runtime.migration][INFO] - Context impl PostgresqlImpl.
[2023-07-03 01:05:26][alembic.runtime.migration][INFO] - Will assume transactional DDL.
[2023-07-03 01:05:26][spellbot.utils][INFO] - loading cogs...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.about_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.admin_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.block_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.config_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.events_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.leave_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.lfg_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.owner_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.score_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.sync_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.tasks_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.verify_cog...
[2023-07-03 01:05:26][spellbot.cogs][INFO] - loading extension spellbot.cogs.watch_cog...
[2023-07-03 01:05:26][spellbot.utils][INFO] - registered commands: about, setup, forget_channel, set, channels, awards, award, info, block, unblock, power, game, leave, lfg, score, history, top, verify, unverify, watched, watch, unwatch
[2023-07-03 01:05:27] [INFO    ] discord.gateway: Shard ID 0 has connected to Gateway (Session ID: a374798fbe5074de225ae972de982bc1).
[2023-07-03 01:05:27][discord.gateway][INFO] - Shard ID 0 has connected to Gateway (Session ID: a374798fbe5074de225ae972de982bc1).
[2023-07-03 01:05:27] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.24 seconds
[2023-07-03 01:05:27][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.24 seconds
[2023-07-03 01:05:32] [INFO    ] discord.gateway: Shard ID 1 has connected to Gateway (Session ID: 51679a9f672d275a66aa882347d35bb2).
[2023-07-03 01:05:32][discord.gateway][INFO] - Shard ID 1 has connected to Gateway (Session ID: 51679a9f672d275a66aa882347d35bb2).
[2023-07-03 01:05:32] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 54.46 seconds
[2023-07-03 01:05:32][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 54.46 seconds
[2023-07-03 01:06:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:06:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:06:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:06:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:07:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:07:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:07:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:07:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:08:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:08:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:08:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:08:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:09:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:09:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:09:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:09:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:10:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:10:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:10:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:10:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:11:26] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:11:26][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:11:27] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:11:27][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-03 01:13:18][spellbot.client][INFO] - client ready
[2023-07-03 01:13:18][spellbot.actions.tasks_action][INFO] - starting task cleanup_old_voice_channels
[2023-07-03 01:13:18][spellbot.actions.tasks_action][INFO] - starting task expire_inactive_games

This time we see the new log I added: client ready. We never see that log in the case where the tasks were not running. In this second log we see that the bot becomes ready after about 8 minutes uptime.

Edit: I'm just now looking at the uptime for the 2nd log, it looks like it was about 7ish minutes. So maybe it would have eventually become ready. 🤔 I thought the alert I get for tasks not running wasn't that tight. I'll adjust it so I don't react to a false alarm next time.

[lexicalunit]

Ok, better logs this time. Here we see the bot start loading cogs around 18:07:52, and then the client still isn't ready by 20:34:00, around 2.5 hours later.

[2023-07-06 18:07:52][spellbot.utils][INFO] - loading cogs...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.about_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.admin_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.block_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.config_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.events_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.leave_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.lfg_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.owner_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.score_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.sync_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.tasks_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.verify_cog...
[2023-07-06 18:07:52][spellbot.cogs][INFO] - loading extension spellbot.cogs.watch_cog...
[2023-07-06 18:07:52][spellbot.utils][INFO] - registered commands: about, setup, forget_channel, set, channels, awards, award, info, block, unblock, power, game, leave, lfg, score, history, top, verify, unverify, watched, watch, unwatch
[2023-07-06 18:07:52] [INFO    ] discord.gateway: Shard ID 0 has connected to Gateway (Session ID: 985460006efca4913c1792a51a406a21).
[2023-07-06 18:07:52][discord.gateway][INFO] - Shard ID 0 has connected to Gateway (Session ID: 985460006efca4913c1792a51a406a21).
[2023-07-06 18:07:53] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.37 seconds
[2023-07-06 18:07:53][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.37 seconds
[2023-07-06 18:07:57] [INFO    ] discord.gateway: Shard ID 1 has connected to Gateway (Session ID: 7a46af91b421d3e2896490105be31453).
[2023-07-06 18:07:57][discord.gateway][INFO] - Shard ID 1 has connected to Gateway (Session ID: 7a46af91b421d3e2896490105be31453).
[2023-07-06 18:07:58] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 54.39 seconds
[2023-07-06 18:07:58][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 54.39 seconds
[2023-07-06 18:08:52] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:08:52][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:08:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:08:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:09:52] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:09:52][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:09:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:09:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:10:52] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:10:52][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:10:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 0.00 seconds
[2023-07-06 18:10:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 0.00 seconds
[2023-07-06 18:10:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:10:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:11:52] [WARNING ] discord.gateway: WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:11:52][discord.gateway][WARNING] - WebSocket in shard ID 0 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:11:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:11:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:12:45] [INFO    ] discord.gateway: Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.
[2023-07-06 18:12:45][discord.gateway][INFO] - Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.
[2023-07-06 18:12:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:12:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:13:52] [WARNING ] discord.gateway: WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:13:52][discord.gateway][WARNING] - WebSocket in shard ID 1 is ratelimited, waiting 59.99 seconds
[2023-07-06 18:24:44] [INFO    ] discord.gateway: Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.
[2023-07-06 18:24:44][discord.gateway][INFO] - Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.
[2023-07-06 20:29:32][spellbot.client][INFO] - Game 433115 was deleted manually.
[2023-07-06 20:31:00] [INFO    ] discord.gateway: Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.
[2023-07-06 20:31:00][discord.gateway][INFO] - Shard ID 0 has successfully RESUMED session 985460006efca4913c1792a51a406a21.

I have a !stats command that the bot responds to via DM that prints out some details:

> me: 
    !stats

> spellbot:
    status:   online
    activity: None
    ready:    False
    shards:   2
    guilds:   1742
    users:    234476

So we can see that the bot has never got the on_ready() hook. I also have a log when that happens, which we don't see in the above log snippet:

    async def on_ready(self) -> None:
        logger.info("client ready")

Predictably, in the past 2.5 hours my tasks have not executed, which is what alerted me to the issue in the first place. What I usually do to fix this is manually kill the bot and restart it. Then 🤞🏻 and hope that it doesn't happen again when it starts back up.

[lexicalunit]

As a workaround, I'm going to try something like this:

WAIT_UNTIL_READY_TIMEOUT = 900.0  # 15 minutes

async def wait_until_ready(bot: Client) -> None:
    while True:
        try:
            if bot.is_ready():
                logger.info("wait_until_ready: already ready")
                break
            ready = bot.wait_for("ready", timeout=WAIT_UNTIL_READY_TIMEOUT)
            resumed = bot.wait_for("resumed", timeout=WAIT_UNTIL_READY_TIMEOUT)
            await asyncio.wait([ready, resumed], return_when=asyncio.FIRST_COMPLETED)
            ready.close()
            resumed.close()
            logger.info("wait_until_ready: ready or resumed")
            break
        except TimeoutError:
            logger.warning("wait_until_ready: timeout waiting for ready or resumed")
            break
        except BaseException as e:  # Catch EVERYTHING so tasks don't die
            logger.exception("error: exception in task before loop: %s", e)

[Rapptz]

Is there a reason why these logs do not have anything from discord.state which actually handles the READY event dispatching?

[lexicalunit]

Not sure, I don't see any logs from discord.state at all. It's in my list of loggers tho: <Logger discord.state (INFO)>. Maybe I need to change the log level?

[Rapptz]

DEBUG is pretty spammy so it won't be too helpful. WARNING/INFO should at least show some information on how the chunking state is going. That being said the logs you're showing so far don't actually show anything other than your WS being rate limited, presumably because of chunking taking its time though it is kind of odd to see it this hammered with only 2 shards.

Your workaround doesn't actually do anything except change the event from wait_until_ready to wait_until_resume because the ready wait_for will just hang.

[Rapptz]

Out of curiosity, does on_shard_ready ever fire?