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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Add copy buttons to all
 blocks
(function() {
function addCopyButtons() {
document.querySelectorAll('pre code').forEach(function(codeBlock) {
if (codeBlock.parentElement.hasAttribute('data-copy-added')) return;
codeBlock.parentElement.setAttribute('data-copy-added', 'true');
var btn = document.createElement('button');
btn.textContent = 'Copy';
btn.style.cssText = 'position:absolute;top:4px;right:4px;padding:2px 8px;font-size:11px;background:#4ecdc4;border:none;border-radius:4px;color:#1a1a2e;cursor:pointer;opacity:0.7;transition:opacity 0.2s;';
btn.onmouseover = function() { this.style.opacity = '1'; };
btn.onmouseout = function() { this.style.opacity = '0.7'; };
btn.onclick = function() {
navigator.clipboard.writeText(codeBlock.textContent).then(function() {
btn.textContent = 'Copied!';
setTimeout(function() { btn.textContent = 'Copy'; }, 1500);
});
};
codeBlock.parentElement.style.position = 'relative';
codeBlock.parentElement.appendChild(btn);
});
}
addCopyButtons();
// Re-run on dynamic content
var observer = new MutationObserver(addCopyButtons);
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:Add Copy Buttons to Code Blocks]', __e); }
})();
(function(){
try {
var __m = "github.com";
var __re = new RegExp('^' + "github\\.com" + '
Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Force GitHub README to respect dark mode (function() { var style = document.createElement('style'); style.textContent = ' .markdown-body { color-scheme: dark light; } .markdown-body pre { background: #161b22 !important; } .markdown-body code { background: rgba(110, 118, 129, 0.4) !important; } .markdown-body table th, .markdown-body table td { border-color: #30363d !important; } .markdown-body img { background: #0d1117; } .markdown-body blockquote { border-left-color: #8b949e; } .markdown-body hr { border-color: #30363d; } '; document.head.appendChild(style); })(); } } catch(__e) { console.warn('[Userscript:GitHub Dark Mode README Fix]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Highlight search terms from Google/DuckDuckGo/Bing referrer (function() { var ref = document.referrer; var terms = []; if (ref.includes('google.com') || ref.includes('duckduckgo.com') || ref.includes('bing.com')) { var url = new URL(ref); var q = url.searchParams.get('q') || url.searchParams.get('p'); if (q) { terms = q.split(/\s+/).filter(function(t) { return t.length > 2; }); } } if (terms.length === 0) return; var style = document.createElement('style'); style.textContent = '.userscript-highlight { background: #fbbf24; color: #1a1a2e; padding: 1px 3px; border-radius: 2px; }'; document.head.appendChild(style); function highlight(node) { if (node.nodeType === 3) { // text node var text = node.textContent; var found = false; terms.forEach(function(term) { var regex = new RegExp('(' + term.replace(/[.*+?^${}()|[\]\\]/g, '\\') + ')', 'gi'); if (regex.test(text)) { found = true; var frag = document.createDocumentFragment(); var parts = text.split(regex); parts.forEach(function(part, i) { if (i % 2 === 0) { frag.appendChild(document.createTextNode(part)); } else { var span = document.createElement('span'); span.className = 'userscript-highlight'; span.textContent = part; frag.appendChild(span); } }); node.parentNode.replaceChild(frag, node); } }); } else if (node.nodeType === 1 && node.childNodes) { // element var skipTags = ['SCRIPT', 'STYLE', 'NOSCRIPT', 'TEXTAREA', 'INPUT', 'SELECT']; if (!skipTags.includes(node.tagName)) { Array.from(node.childNodes).forEach(highlight); } } } highlight(document.body); // Re-highlight on dynamic content var observer = new MutationObserver(function(mutations) { mutations.forEach(function(m) { m.addedNodes.forEach(function(node) { if (node.nodeType === 1 || node.nodeType === 3) highlight(node); }); }); }); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:Highlight Search Terms]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Strip utm_, fbclid, gclid, etc. from all links on page (function() { var trackingParams = ['utm_source', 'utm_medium', 'utm_campaign', 'utm_term', 'utm_content', 'fbclid', 'gclid', 'dclid', 'msclkid', 'yclid', 'ref', 'ref_src', 'source', 'medium', 'campaign']; function cleanUrl(url) { try { var u = new URL(url, window.location.origin); var changed = false; trackingParams.forEach(function(p) { if (u.searchParams.has(p)) { u.searchParams.delete(p); changed = true; } }); return changed ? u.toString() : url; } catch (e) { return url; } } function cleanLinks() { document.querySelectorAll('a[href]').forEach(function(a) { var clean = cleanUrl(a.href); if (clean !== a.href) a.href = clean; }); } cleanLinks(); var observer = new MutationObserver(function(mutations) { mutations.forEach(function(m) { m.addedNodes.forEach(function(node) { if (node.nodeType === 1) { if (node.tagName === 'A') cleanLinks(); node.querySelectorAll('a[href]').forEach(function(a) { var clean = cleanUrl(a.href); if (clean !== a.href) a.href = clean; }); } }); }); }); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:Remove Tracking Parameters from Links]', __e); } })(); (function(){ try { var __m = "youtube.com"; var __re = new RegExp('^' + "youtube\\.com" + ' Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Auto-enable theater mode on YouTube (function() { function tryTheater() { var btn = document.querySelector('button[aria-label="Theater mode"], ytd-player #player button[title="Theater mode"]'); if (btn && !btn.classList.contains('activated')) { btn.click(); } } // Try immediately tryTheater(); // Try after navigation (SPA) var lastUrl = location.href; setInterval(function() { if (location.href !== lastUrl) { lastUrl = location.href; setTimeout(tryTheater, 500); } }, 1000); // Also try on player load var observer = new MutationObserver(tryTheater); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:YouTube Theater Mode Default]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Remove or un-stick sticky/fixed headers that block content (function() { function unstick() { document.querySelectorAll('header, nav, [role="banner"], .header, .navbar, .sticky, .fixed-top, [style*="position: fixed"], [style*="position:sticky"]').forEach(function(el) { if (el.style.position === 'fixed' || el.style.position === 'sticky' || getComputedStyle(el).position === 'fixed' || getComputedStyle(el).position === 'sticky') { el.style.position = 'static'; el.style.top = 'auto'; el.style.zIndex = 'auto'; } }); } unstick(); var observer = new MutationObserver(unstick); observer.observe(document.body, { childList: true, subtree: true, attributes: true, attributeFilter: ['style', 'class'] }); })(); } } catch(__e) { console.warn('[Userscript:Kill Sticky Headers]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru
, 'i'); if (__m === '*' || __re.test(location.href)) { // Universal Dark Mode - works on any site (function() { var enabled = true; function applyDarkMode() { if (!enabled) return; // Create style element if it doesn't exist var style = document.getElementById('universal-dark-mode-style'); if (!style) { style = document.createElement('style'); style.id = 'universal-dark-mode-style'; document.head.appendChild(style); } // Dark mode CSS - inverts colors but preserves images/video style.textContent = ' /* Invert everything except media */ html { filter: invert(1) hue-rotate(180deg) !important; background: #1a1a2e !important; } /* Restore images, videos, iframes, canvas */ img, video, iframe, canvas, svg, picture, [style*="background-image"] { filter: invert(1) hue-rotate(180deg) !important; } /* Preserve specific elements that should not be inverted */ .no-dark-mode, .no-dark-mode *, [data-theme="light"], [data-theme="light"], .ace_editor, .ace_editor *, .CodeMirror, .CodeMirror *, .monaco-editor, .monaco-editor *, .markdown-body pre, .markdown-body pre *, .highlight, .highlight *, pre code, pre code * { filter: none !important; } /* Fix common UI elements */ .modal, .popup, .dropdown-menu, .tooltip, .popover { filter: invert(1) hue-rotate(180deg) !important; background: #2d2d44 !important; border-color: #444 !important; } /* Scrollbars */ ::-webkit-scrollbar { background: #1a1a2e !important; } ::-webkit-scrollbar-thumb { background: #444 !important; } ::-webkit-scrollbar-thumb:hover { background: #555 !important; } /* Selection */ ::selection { background: #4ecdc4 !important; color: #1a1a2e !important; } ::-moz-selection { background: #4ecdc4 !important; color: #1a1a2e !important; } '; } function removeDarkMode() { var style = document.getElementById('universal-dark-mode-style'); if (style) style.remove(); } // Toggle with Alt+Shift+D document.addEventListener('keydown', function(e) { if (e.altKey && e.shiftKey && e.key === 'D') { e.preventDefault(); enabled = !enabled; if (enabled) { applyDarkMode(); console.log('[Universal Dark Mode] Enabled'); } else { removeDarkMode(); console.log('[Universal Dark Mode] Disabled'); } } }); // Apply on load applyDarkMode(); // Re-apply on dynamic content var observer = new MutationObserver(function(mutations) { if (enabled && !document.getElementById('universal-dark-mode-style')) { applyDarkMode(); } }); observer.observe(document.head, { childList: true }); console.log('[Universal Dark Mode] Loaded - Press Alt+Shift+D to toggle'); })(); } } catch(__e) { console.warn('[Userscript:Universal Dark Mode]', __e); } })(); })(); Fix: Twitch requests time out in the first minutes of a game (BufferedHTTPClient) by GustavoLR548 · Pull Request #130 · kanimaru/twitcher · GitHub
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
ContributorAuthor

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 freeto 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

@GustavoLR548@kanimaru