truncated responses with H2C (via AWS Application Load Balancer)

[paulswartz]

I recently tried running a Bandit-based Phoenix application with H2C, behind an AWS Application Load Balancer. In this mode, I would almost never receive a full response, even for static files served by Plug.Static.

Some alternatives which did work, making me thing that the issue is with Bandit's H2C implementation:

• Bandit via HTTP/1.1
• Cowboy 2.12 via H2C

I don't have much in the way of logs at the moment, but if there's anything that would be helpful, I'm happy to give it a shot!

[mtrudel]

I'd love a repro case here, not of the application itself, but of the configuration it took within AWS to get here! I'm willing to bet it rhymes with #306 and/or #338; likely a bug in who / how content-length headers get set.

[paulswartz]

For us, it's:

• Phoenix 1.7 app
• Debian bookworm Docker container
• AWS ECS Fargate runner
• AWS Application Load Balancer
• AWS Target group configured with the HTTP2 target version to talk to the ECS Fargate tasks

Good response:

Bad response:

Server logs:

023cd54e6718 22:47:13.750 [info] state=sent method=GET path=/assets/app-b49524acc1698e2440c53a73d41aec25.js params=[UNFETCHED] status=200 headers={"user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:129.0) Gecko/20100101 Firefox/129.0"} duration=0.248
023cd54e6718 22:47:14.649 [info] state=sent method=GET path=/assets/app-b49524acc1698e2440c53a73d41aec25.js params=[UNFETCHED] status=200 headers={"user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:129.0) Gecko/20100101 Firefox/129.0"} duration=0.234

[paulswartz]

From cURL:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Host XXX:443 was resolved.
* IPv6: (none)
* IPv4: XXX, XXX, XXX
*   Trying XXX:443...
* Connected to XXX (XXX) port 443
* ALPN: curl offers h2,http/1.1
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [104 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [4959 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [333 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [70 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256 / secp256r1 / rsaEncryption
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=XXX
*  start date: Mar 27 00:00:00 2024 GMT
*  expire date: Apr 25 23:59:59 2025 GMT
*  subjectAltName: host "XXX" matched cert's "XXX"
*  issuer: C=US; O=Amazon; CN=Amazon RSA 2048 M03
*  SSL certificate verify ok.
*   Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 2: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
{ [5 bytes data]
* using HTTP/2
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* [HTTP/2] [1] OPENED stream for XXX/assets/app-b49524acc1698e2440c53a73d41aec25.js?vsn=d
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: XXX]
* [HTTP/2] [1] [:path: /assets/app-b49524acc1698e2440c53a73d41aec25.js?vsn=d]
* [HTTP/2] [1] [user-agent: curl/8.9.1]
* [HTTP/2] [1] [accept: */*]
} [5 bytes data]
> GET /assets/app-b49524acc1698e2440c53a73d41aec25.js?vsn=d HTTP/2
> Host: XXX
> User-Agent: curl/8.9.1
> Accept: */*
>
* Request completely sent off
{ [5 bytes data]
< HTTP/2 200
< server: awselb/2.0
< date: Tue, 20 Aug 2024 22:59:26 GMT
< content-type: text/javascript
< content-length: 270919
< vary: Accept-Encoding
< cache-control: public, max-age=31536000, immutable
< accept-ranges: bytes
<
{ [8192 bytes data]
* HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)
 90  264k   90  238k    0     0   870k      0 --:--:-- --:--:-- --:--:--  870k
* Connection #0 to host XXX left intact
curl: (92) HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)

[mtrudel]

Thanks! That's super helpful. Any notable logs on the bandit side?

[paulswartz]

Nope, nothing from Bandit other than the two request logs. If it's helpful, they're from Logster.Plug and run as a Plug.Conn.register_before_send/2 callback.