From: AngeloR Date: Fri, 13 Dec 2024 16:48:28 +0000 (-0500) Subject: update content for chrome-stalled-request post X-Git-Url: https://git.xangelo.ca/?a=commitdiff_plain;h=187ddac208b550a30927ebc619a9f362fc0123fb;p=xangelo.ca.git update content for chrome-stalled-request post --- diff --git a/content/posts/Chrome HTTP Request stuck in a Stalled State.md b/content/posts/Chrome HTTP Request stuck in a Stalled State.md index 8a6a6a5..8bc5b34 100644 --- a/content/posts/Chrome HTTP Request stuck in a Stalled State.md +++ b/content/posts/Chrome HTTP Request stuck in a Stalled State.md @@ -8,7 +8,7 @@ tags: - publish draft: false date: 2023-06-20T12:30:56.105-04:00 -lastmod: 2024-12-10T19:47:36.987Z +lastmod: 2024-12-13T16:47:37.707Z --- # Chrome HTTP Request stuck in a "Stalled" State @@ -16,7 +16,7 @@ I got the chance to investigate a really odd bug where randomly network requests The first thing I did was attempt to replicate it and capture a `.har` file that I could share with anyone else that was interested. This part was easy - just popping open the network tab, navigating to the app on a test env, and then clicking every link that would trigger a network request. After about 30-40 seconds I had replicated the event -![Stuck Stalled...](/img/http2/wait-queue.png) +![wait-queue.png](/wait-queue.png) So we can clearly see here that the request took 2 minutes and the entirety of that time the connection was stuck in the `stalled` state. That indicates one of two things: @@ -30,7 +30,7 @@ I did a bit more testing to figure out the scope of the issue. On/Off VPN with m One tool that chrome has to diagnose networking issues is hidden away at `chrome://net-export`. It generates a very VERY detailed log of everything network related that chrome is aware of.  -![Chrome Net Export](/img/http2/net-export.png) +![net-export.png](/net-export.png) I unchecked the `strip private information` option and told it to include cookies + credentials and started logging it to disk. Then I swapped back to my tab and replicated the issue. Waited a few seconds, and then went back and ended the capture session. @@ -38,15 +38,15 @@ Once you get that capture file, you have to head over to https://netlog-viewer.a There will likely be a lot of events. The "filter" at the top never worked for me given the sheer size of the events.. but scrolling through them all was just fine and eventually I found the URL request that caused the issue. If you click on the event it will display a bunch of debug information about the request.  -![Event 168281](/img/http2/event-169281.png) +![event-169281.png](/event-169281.png) As you can see.. suddenly there's a HUGE jump in time from `66807` to `187631`. We've confirmed now that this is a problem that's occurring within the CORS preflight request specifically, and it's just getting rolled into the `stalled` state. The log viewer makes it trivial to dig down into the events and if you click on the details of the `HTTP_STREAM_JOB_CONTROLLER` event you can see some more details.  -![Event 169283](/img/http2/event-169284.png) +![event-169283.png](/event-169283.png) Here again, we see that there is a definitely delay when it attempts to call `HTTP_STREAM_REQUEST_STARTED_JOB`  -![Event 169284](/img/http2/event-169284.png) +![event-169284.png](/event-169284.png) And now we can easily see the problem: `SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP` @@ -56,7 +56,7 @@ In HTTP1.1 each tab in your browser is configured to only make a certain number We can dig even further! Since we know that this is happening on an HTTP2 call, we can filter our events to only show us the http2 connections and that paints a more serious picture!  -![GOAWAY](/img/http2/goaway.png) +![goaway.png](/goaway.png) Every one of our http2 sockets is getting sent a `GOAWAY` frame by the server.. but notice that it says `NO_ERROR`. This generally indicates that the server is telling the client that it will be shutting down this socket and. The `GOAWAY` frame also tells the client what the last stream that it processed was. This is so that the client can resend any data that it needs to on a new connection. What should happen is that after this frame, the connection is ended by both parties and we move on to a new one. In practice, it happens after a following `GOAWAY` frame that indicates the connection is now dead. Except that final disconnect frame is never sent. So as far as chrome is concerned, we're still happily connected so it returns the connection to the pool. But the server has disconnected. diff --git a/static/event-169281.png b/static/event-169281.png new file mode 100644 index 0000000..eeebbf2 Binary files /dev/null and b/static/event-169281.png differ diff --git a/static/event-169283.png b/static/event-169283.png new file mode 100644 index 0000000..d91f4b7 Binary files /dev/null and b/static/event-169283.png differ diff --git a/static/event-169284.png b/static/event-169284.png new file mode 100644 index 0000000..6fe2b5e Binary files /dev/null and b/static/event-169284.png differ diff --git a/static/goaway.png b/static/goaway.png new file mode 100644 index 0000000..d32d28e Binary files /dev/null and b/static/goaway.png differ diff --git a/static/net-export.png b/static/net-export.png new file mode 100644 index 0000000..fb34c1f Binary files /dev/null and b/static/net-export.png differ diff --git a/static/wait-queue.png b/static/wait-queue.png new file mode 100644 index 0000000..d4a32cb Binary files /dev/null and b/static/wait-queue.png differ