Skip to content

Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) - #130

Open
GustavoLR548 wants to merge 1 commit into
kanimaru:masterfrom
GustavoLR548:master
Open

Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient)#130
GustavoLR548 wants to merge 1 commit into
kanimaru:masterfrom
GustavoLR548:master

Conversation

@GustavoLR548

Copy link
Copy Markdown
Contributor

Symptom

I am currently working a game with the plugin, and shortly after a game starts, Helix API calls fail with errors like:

twitch_api.gd:933 @ get_channel_chat_badges(): Parse JSON failed. Error at line 0: Unknown error getting token
twitch_api.gd:935 @ get_channel_chat_badges(): Unexpected non-JSON response (code 0, result 13):
twitch_api.gd:852 @ get_channel_emotes(): Parse JSON failed. Error at line 0: Unknown error getting token
twitch_api.gd:1946 @ create_eventsub_subscription(): Parse JSON failed. Error at line 0: Unknown error getting token

result 13 is HTTPRequest.RESULT_TIMEOUT and code 0 means no HTTP response was ever received — the requests never actually completed. Because they returned an empty body, JSON.parse_string failed and the addon misreported it as a token problem, obscuring the real cause. The channel.chat.message EventSub subscription that fails as part of this batch is what stops chat from ever connecting for that session.

Setting use_threads = false on the underlying HTTPRequest did not fix it, which ruled out threading as the root cause and pointed at the request queue itself.

Root cause

addons/twitcher/lib/http/buffered_http_client.gd is documented as a "Http client that bufferes the requests and sends them sequentialy", but the implementation did not do that: every call to request() immediately created and started its own HTTPRequest node. On startup, TwitchChat.subscribe() fires three calls back-to-back in the same frame (preload_badges,
preload_emotes, and the EventSub subscription's create_eventsub_subscription call), each spinning up a parallel threaded HTTPRequest. Firing several threaded HTTP requests at once during Godot startup is exactly the pattern that stalls / times out unreliably — which is consistent with the ~30s timeout showing up on all three requests together.

Two secondary bugs in the same file made the failure worse once it happened:

  • Retry callback bound the wrong object. On RESULT_CONNECTION_ERROR / RESULT_TLS_HANDSHAKE_ERROR, the retry reconnected request_completed with .bind(http_request) (the new HTTPRequest node) instead of .bind(request_data) (the original RequestData). Since _on_request_completed expects a RequestData, this silently broke the retry's completion handling.
  • Exhausted retries never signaled completion. When retry == max_error_count, the function returned without emitting
    request_done, so anything awaiting wait_for_request() for that request would hang forever instead of receiving a (failed) response.

Fix

  • BufferedHTTPClient now actually queues and dispatches one request at a time per client instance (_dispatch_next()), matching its original design intent. The next request in the internal queue is only sent once the in-flight one completes (or exhausts its retries).
  • Fixed the retry path to rebind request_data instead of the new http_request, and to free the old HTTPRequest node instead of leaking it.
  • Exhausting max_error_count retries now clears the in-flight slot and advances the queue instead of leaving it stuck.
  • RequestData.queue_free() now null-checks http_request (it can be null before the request is dispatched, now that dispatch is decoupled from request()).

New: optional traffic logging

Added an @export var log_traffic: bool = false toggle on BufferedHTTPClient. When enabled it prints one line per request at queue time, dispatch time, and completion time, including the elapsed duration and HTTPRequest.Result / response code — e.g.:

[HTTPTraffic    2003] OAuthTokenClient queued https://id.twitch.tv/oauth2/validate (queue=1, inflight=none)
[HTTPTraffic    2366] OAuthTokenClient dispatch https://id.twitch.tv/oauth2/validate
[HTTPTraffic    3325] OAuthTokenClient done https://id.twitch.tv/oauth2/validate (result=0, code=200, took=959ms)

This is off by default and meant to make future connectivity issues in this client diagnosable without re-instrumenting the code.

Files changed

  • addons/twitcher/lib/http/buffered_http_client.gd

- Implement sequential request dispatching with a queue-based approach to ensure requests are processed one at a time.
- Add traffic logging feature to diagnose stalls and timeouts.
- Improvements include: tracking request dispatch timing, null-safety check in queue_free(), fixed retry logic to properly manage current_request state, and a _log_traffic() helper for timestamped diagnostics.
@kanimaru

Copy link
Copy Markdown
Owner

Hi Gustav,

Sorry for the late reply. I didn't want to ghost you, I actually read the review of this PR a while ago but didn't know what I should do with it.

On one hand the PR is technically correct but it introduces a regression problem that was solved by exactly the changes that makes the BufferedHttpClient not following its spec anymore.

Speaking the reason why it was going in parrallel instead of sequential how it was originally planed, is because of Emoji and Badge loading. Loading them sequentially introduces always a lag when you try to load the emotes of a broadcaster. That got almost fully resolved by loading them in parallel. Reintroducing sequentiallity in this case would also break the feature on another front.

I was thinking about making 2 different HTTP Clients (one sequentially buffering one for parrallel requests) but thats alot of work. Maybe as a flag in the request to signal parallel is allowed but that makes the logic more spongy.

TBH I'm not sure how to handle that correctly maybe you have an Idea how to beat both flys with one stone or maybe introduce multiple stones.

Best Regards
Kani

@GustavoLR548

Copy link
Copy Markdown
Contributor Author

Hi @kanimaru ,

No worries at all, thanks for explaining the context behind this! It definitely sounds like a tricky balancing act between performance and spec adherence.

I can take a closer look at this and investigate the regression to see if we can find a clean way to tackle both issues.

Before I dive in, how can I best test to verify that your original regression (related to the emoji/badge loading lag) and the one I found don't reappear? Are there specific benchmarks, tests, or manual steps you usually use to check this?

Best,
Gustavo

@kanimaru

Copy link
Copy Markdown
Owner

Best way to check it:

media_loader.preload_badges(broadcaster_user.id)
media_loader.preload_emotes(broadcaster_user.id)

That causes alot of requests depending on the streamer you pick.
Remember to delete the cache, otherwise it uses them from cache afterwards. TwitchMediaLoader has an easy Editor Script to delete the cache.

Also what helps with debugging it res://addons/twitcher/lib/http/debug_buffered_http_client.tscn.
That scene tracks the requests so you see how much time it needs.

I really should create a GUT test suite for twitcher :/ But it takes soooo much time.

Best Regards,
Kani

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants