[Bug]: Webhook ratelimit times out when spamming messages.

csmir commented 1 year ago

Check The Docs

[X] I double checked the docs and couldn't find any useful information.

Verify Issue Source

[X] I verified the issue was caused by Discord.Net.

Check your intents

[X] I double checked that I have the required intents.

Description

When spamming messages through a webhook client, it eventually just fails at bucketing and times out. I have tried to figure out the reason behind this by examining the ratelimit management code, but I have been unable to find any information on the matter.

Version

3.9.0

Working Version

None

Logs

2023-02-09 09:31:12 - TShock: ERROR: System.TimeoutException: The operation has timed out.
   at Discord.Net.Queue.RequestBucket.EnterAsync(Int32 id, IRequest request)
   at Discord.Net.Queue.RequestBucket.SendAsync(RestRequest request)
   at Discord.Net.Queue.RequestQueue.SendAsync(RestRequest request)
   at Discord.API.DiscordRestApiClient.SendInternalAsync(String method, String endpoint, RestRequest request)
   at Discord.API.DiscordRestApiClient.SendJsonAsync[TResponse](String method, String endpoint, Object payload, BucketId bucketId, ClientBucketType clientBucket, RequestOptions options)
   at Discord.API.DiscordRestApiClient.CreateWebhookMessageAsync(UInt64 webhookId, CreateWebhookMessageParams args, RequestOptions options, Nullable`1 threadId)
   at Discord.Webhook.WebhookClientHelper.SendMessageAsync(DiscordWebhookClient client, String text, Boolean isTTS, IEnumerable`1 embeds, String username, String avatarUrl, AllowedMentions allowedMentions, RequestOptions options, MessageComponent components, MessageFlags flags, Nullable`1 threadId)
   at Terraqord.GameManager.ChatSent(PlayerChatEventArgs arg)
   at Auxiliary.Events.AsyncEvent.InvokeAsync[T](AsyncEvent`1 eventHandler, T arg)
   at Terraqord.Terraqord.<>c.<<Initialize>b__33_2>d.MoveNext()
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
   at System.Threading.QueueUserWorkItemCallback.<>c.<.cctor>b__6_0(QueueUserWorkItemCallback quwi)
   at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[TState](ExecutionContext executionContext, Action`1 callback, TState& state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()

Sample

private readonly _messageHook = new DiscordWebhookClient("");

// spam this consistently for like 40 times...
await _messageHook.SendMessageAsync(
    ...);

Packages

Irrelevant.

itsHeroYT commented 1 year ago

Im having a similar issue with the webhooks for me it doesnt timeout but i get randomly rate-limited after about 70-ish requests. I set up the following scenario (i remember it being limited to 30 messages / min but i guess that changed recently?)

send message wait 1000ms repeat

this works as i said above fine for ~70 messages and then it starts to randomly spit out rate limits despite having requests left in the remaining i ran the test with d .net itself and with the config "DEBUG_LIMITS" to see what happens Here is a log of it:

log.txt

The very weird thing is that it the new request already got responses while the prior one hasnt resetted yet. Im not very familiar with the d .net code itself but maybe someone else might know whats going on

ben-reilly commented 1 year ago

I believe I'm seeing similar issues with webhooks. It looks an awful lot like the rate limits aren't being waited for even when Retry-After is greater than zero.

These lines make it look to me like the wait is occurring in an async task. But that task isn't being waited on anywhere.

https://github.com/discord-net/Discord.Net/blob/257f246d1dd7d8f5aea043417fd062924c856f8f/src/Discord.Net.Rest/Net/Queue/RequestQueueBucket.cs#L468-L469

This bears out with the logs I have in my application:

00:59:30.5940 | RETRY AFTER: 1 REMAINING: 3
00:59:30.5940 CLIENT (@1558119158.015): Rate limit triggered: <snip>
00:59:30.7054 | RETRY AFTER: 1 REMAINING: 3
00:59:30.7055 CLIENT (@1558119158.015): Rate limit triggered: <snip>
00:59:30.8109 | RETRY AFTER: 2 REMAINING: 2
00:59:30.8110 CLIENT (@1558119158.015): Rate limit triggered: <snip>
00:59:30.9086 | RETRY AFTER: 2 REMAINING: 1
00:59:30.9086 CLIENT (@1558119158.015): Rate limit triggered: <snip>
00:59:33.1086 | RETRY AFTER: - REMAINING: 4

The "RETRY AFTER" lines are from the rate limit callback I registered, and the "CLIENT" lines are the client logging callback. Also take note of the @1558119158.015 which is the ID of the internal event I'm processing.

It looks like the event is retried immediately after getting rate limited rather than waiting for 1 second. In fact, it's retried 4 times, using up all of the remaining requests before the SDK rate limiting actually kicks in and delays further requests -- note the jump at the end in the logs from 30.9086 seconds to 33.1086 and the increase from 1 to 4 remaining requests.

ben-reilly commented 1 year ago

I put together a patch that I think fixes the problems that each of us have been encountering.

It turns out that webhook rate limits weren't being enforced correctly, which I think ended up triggering harder rate limits / temporary bans, resulting in the various problems that each of us has seen.

discord-net / Discord.Net