~nicoco/slidcord#6: 
Crashes when rate limited

slidcord crashes when rate limited. Log below.

I would expect slidcord to handle this gracefully, rather than crashing and retrying forever. I expect the crash+retry behavior is causing it to be rate limited more.

As a side note, I see that all backoffs are 0.30s and don't seem to be global. Should backoff be more aggressive (potentially exponential) and apply to all requests?

Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: WARNING:discord.http:We are being rate limited. GET https://discord.com/api/v9/channels/-redacted-/messages responded with 429. Retrying in 0.30 seconds.
Nov 21 16:31:31 hv01 slidge[421388]: ERROR:slixmpp.stanza.rootstanza:Error handling {jabber:component:accept}iq stanza
Nov 21 16:31:31 hv01 slidge[421388]: Traceback (most recent call last):
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slixmpp/xmlstream/handler/coroutine_callback.py", line 60, in pointer_wrapper
Nov 21 16:31:31 hv01 slidge[421388]:     await pointer(stanza)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/core/gateway/mam.py", line 39, in __handle_mam
Nov 21 16:31:31 hv01 slidge[421388]:     await muc.send_mam(iq)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 712, in send_mam
Nov 21 16:31:31 hv01 slidge[421388]:     await self.__fill_history()
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 185, in __fill_history
Nov 21 16:31:31 hv01 slidge[421388]:     await self.backfill(legacy_id, oldest_date)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 166, in backfill
Nov 21 16:31:31 hv01 slidge[421388]:     await self.history(oldest_date)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in history
Nov 21 16:31:31 hv01 slidge[421388]:     messages = [
Nov 21 16:31:31 hv01 slidge[421388]:                ^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in <listcomp>
Nov 21 16:31:31 hv01 slidge[421388]:     messages = [
Nov 21 16:31:31 hv01 slidge[421388]:                ^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2242, in history
Nov 21 16:31:31 hv01 slidge[421388]:     data, state, limit = await strategy(retrieve, state, limit)
Nov 21 16:31:31 hv01 slidge[421388]:                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2184, in _before_strategy
Nov 21 16:31:31 hv01 slidge[421388]:     data = await self._state.http.logs_from(channel.id, retrieve, before=before_id)
Nov 21 16:31:31 hv01 slidge[421388]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/http.py", line 864, in request
Nov 21 16:31:31 hv01 slidge[421388]:     raise HTTPException(response, data)
Nov 21 16:31:31 hv01 slidge[421388]: discord.errors.HTTPException: 429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:31 hv01 slidge[421388]: ERROR:slidge.core.gateway.base:429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:31 hv01 slidge[421388]: Traceback (most recent call last):
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slixmpp/xmlstream/handler/coroutine_callback.py", line 60, in pointer_wrapper
Nov 21 16:31:31 hv01 slidge[421388]:     await pointer(stanza)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/core/gateway/mam.py", line 39, in __handle_mam
Nov 21 16:31:31 hv01 slidge[421388]:     await muc.send_mam(iq)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 712, in send_mam
Nov 21 16:31:31 hv01 slidge[421388]:     await self.__fill_history()
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 185, in __fill_history
Nov 21 16:31:31 hv01 slidge[421388]:     await self.backfill(legacy_id, oldest_date)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 166, in backfill
Nov 21 16:31:31 hv01 slidge[421388]:     await self.history(oldest_date)
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in history
Nov 21 16:31:31 hv01 slidge[421388]:     messages = [
Nov 21 16:31:31 hv01 slidge[421388]:                ^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in <listcomp>
Nov 21 16:31:31 hv01 slidge[421388]:     messages = [
Nov 21 16:31:31 hv01 slidge[421388]:                ^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2242, in history
Nov 21 16:31:31 hv01 slidge[421388]:     data, state, limit = await strategy(retrieve, state, limit)
Nov 21 16:31:31 hv01 slidge[421388]:                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2184, in _before_strategy
Nov 21 16:31:31 hv01 slidge[421388]:     data = await self._state.http.logs_from(channel.id, retrieve, before=before_id)
Nov 21 16:31:31 hv01 slidge[421388]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:31 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/http.py", line 864, in request
Nov 21 16:31:31 hv01 slidge[421388]:     raise HTTPException(response, data)
Nov 21 16:31:31 hv01 slidge[421388]: discord.errors.HTTPException: 429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:42 hv01 slidge[421388]: ERROR:slixmpp.stanza.rootstanza:Error handling {jabber:component:accept}iq stanza
Nov 21 16:31:42 hv01 slidge[421388]: Traceback (most recent call last):
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slixmpp/xmlstream/handler/coroutine_callback.py", line 60, in pointer_wrapper
Nov 21 16:31:42 hv01 slidge[421388]:     await pointer(stanza)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/core/gateway/mam.py", line 39, in __handle_mam
Nov 21 16:31:42 hv01 slidge[421388]:     await muc.send_mam(iq)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 712, in send_mam
Nov 21 16:31:42 hv01 slidge[421388]:     await self.__fill_history()
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 185, in __fill_history
Nov 21 16:31:42 hv01 slidge[421388]:     await self.backfill(legacy_id, oldest_date)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 166, in backfill
Nov 21 16:31:42 hv01 slidge[421388]:     await self.history(oldest_date)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in history
Nov 21 16:31:42 hv01 slidge[421388]:     messages = [
Nov 21 16:31:42 hv01 slidge[421388]:                ^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in <listcomp>
Nov 21 16:31:42 hv01 slidge[421388]:     messages = [
Nov 21 16:31:42 hv01 slidge[421388]:                ^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2242, in history
Nov 21 16:31:42 hv01 slidge[421388]:     data, state, limit = await strategy(retrieve, state, limit)
Nov 21 16:31:42 hv01 slidge[421388]:                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2184, in _before_strategy
Nov 21 16:31:42 hv01 slidge[421388]:     data = await self._state.http.logs_from(channel.id, retrieve, before=before_id)
Nov 21 16:31:42 hv01 slidge[421388]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/http.py", line 864, in request
Nov 21 16:31:42 hv01 slidge[421388]:     raise HTTPException(response, data)
Nov 21 16:31:42 hv01 slidge[421388]: discord.errors.HTTPException: 429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:42 hv01 slidge[421388]: ERROR:slidge.core.gateway.base:429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:42 hv01 slidge[421388]: Traceback (most recent call last):
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slixmpp/xmlstream/handler/coroutine_callback.py", line 60, in pointer_wrapper
Nov 21 16:31:42 hv01 slidge[421388]:     await pointer(stanza)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/core/gateway/mam.py", line 39, in __handle_mam
Nov 21 16:31:42 hv01 slidge[421388]:     await muc.send_mam(iq)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 712, in send_mam
Nov 21 16:31:42 hv01 slidge[421388]:     await self.__fill_history()
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/group/room.py", line 185, in __fill_history
Nov 21 16:31:42 hv01 slidge[421388]:     await self.backfill(legacy_id, oldest_date)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 166, in backfill
Nov 21 16:31:42 hv01 slidge[421388]:     await self.history(oldest_date)
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in history
Nov 21 16:31:42 hv01 slidge[421388]:     messages = [
Nov 21 16:31:42 hv01 slidge[421388]:                ^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/slidge/plugins/discord/group.py", line 176, in <listcomp>
Nov 21 16:31:42 hv01 slidge[421388]:     messages = [
Nov 21 16:31:42 hv01 slidge[421388]:                ^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2242, in history
Nov 21 16:31:42 hv01 slidge[421388]:     data, state, limit = await strategy(retrieve, state, limit)
Nov 21 16:31:42 hv01 slidge[421388]:                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/abc.py", line 2184, in _before_strategy
Nov 21 16:31:42 hv01 slidge[421388]:     data = await self._state.http.logs_from(channel.id, retrieve, before=before_id)
Nov 21 16:31:42 hv01 slidge[421388]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 21 16:31:42 hv01 slidge[421388]:   File "/usr/lib/slidge/lib/python3.11/site-packages/discord/http.py", line 864, in request
Nov 21 16:31:42 hv01 slidge[421388]:     raise HTTPException(response, data)
Nov 21 16:31:42 hv01 slidge[421388]: discord.errors.HTTPException: 429 Too Many Requests (error code: 0): You are being rate limited.
Nov 21 16:31:42 hv01 systemd[1]: slidge@discord.service: Main process exited, code=exited, status=1/FAILURE
Nov 21 16:31:42 hv01 systemd[1]: slidge@discord.service: Failed with result 'exit-code'.
Nov 21 16:31:42 hv01 systemd[1]: slidge@discord.service: Consumed 49.663s CPU time.
Nov 21 16:31:47 hv01 systemd[1]: slidge@discord.service: Scheduled restart job, restart counter is at 7.
Nov 21 16:31:47 hv01 systemd[1]: Stopped slidge@discord.service - Slidge XMPP discord bridge.
Status
RESOLVED FIXED
Submitter
~m-johnson
Assigned to
No-one
Submitted
1 year, 5 months ago
Updated
1 year, 1 month ago
Labels
No labels applied.

~nicoco 1 year, 5 months ago

Thanks for the report!

Slidcord does not handle rate limiting at all, the underlying lib is supposed to do it transparently... which does not seem to happen here, since the HTTPException ended up in slidcord's "backfill" handler. Did it work after a restart? Did it happen for a specific discord channel? Does it happen consistently? I could make this channel history backfilling non fatal, but I'd like to try and understand what happened here exactly first.

~m-johnson 1 year, 5 months ago

It typically happens after a slidge restart. I think what's happening is that, after slidge restarts, my client is trying to rejoin all of the channels that it's in. This causes slidge to be rate limited by Discord. slidge crashes due to the rate limit. The crash disconnects the client and the process repeats from the beginning. To break this cycle, I usually have to stop the clients that are in many channels for a while.

~nicoco 1 year, 5 months ago

I opened https://github.com/dolfies/discord.py-self/issues/615 about this. Possibly related: https://github.com/dolfies/discord.py-self/issues/608 too

~nicoco REPORTED FIXED 1 year, 5 months ago

nicoco referenced this ticket in commit 08dd101.

~m-johnson 1 year, 5 months ago

You're awesome. Thank you. :)

~nicoco 1 year, 5 months ago

Some groups will have less backfilled messages with this patch, but it won't affect "live" messages.

~tsdh referenced this from ~tsdh/highlight-parentheses.el#6 1 year, 1 month ago

~tsdh referenced this from ~tsdh/highlight-parentheses.el#5 1 year, 1 month ago

Register here or Log in to comment, or comment via email.