"upstream sent invalid chunked response while reading upstream" when responding a stream.

[basti.lamberto@…]

A detailed log is available at ​https://github.com/ktorio/ktor/issues/1933

It seems that nginx closes the proxy way before my Ktor actually starts responding.

It only happens when responding using a stream, otherwise everything works.

[Maxim Dounin]

I don't see any nginx-related details in the issue linked except the error message itself, "upstream sent invalid chunked response while reading upstream". The message suggests that backend returned a broken response, with invalid chunked encoding. That is, your backend started returning a response, but the response contained invalid chunked encoding framing. Details, if needed, can be found in nginx ​debugging log.

Could you please elaborate what makes you think this is a bug in nginx rather than a broken response from backend server, as the message suggests?

[basti.lamberto@…]

Hi, Thank you for your time. Indeed I am very new into web protocols and I am practically flying blind. The endpoint works when exposing it directly.

I've attached the log! It seems that somehow the client closes the connection. But why?

[Maxim Dounin]

Relevant part from the log:

2020/06/08 20:29:15 [debug] 29#29: *4 http upstream request: "/sql/wordClouds/tweets/hope?"
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream process header
2020/06/08 20:29:15 [debug] 29#29: *4 malloc: 0172C040:4096
2020/06/08 20:29:15 [debug] 29#29: *4 recv: eof:0, avail:-1
2020/06/08 20:29:15 [debug] 29#29: *4 recv: fd:3 154 of 4096
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy status 200 "200 "
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header: "Cache-Control: max-age=600"
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header: "Transfer-Encoding: chunked"
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header: "Connection: close"
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header: "Content-Type: image/png"
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header: "Date: Mon, 08 Jun 2020 20:29:15 GMT"
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy header done
2020/06/08 20:29:15 [debug] 29#29: *4 HTTP/1.1 200 
Server: nginx/1.19.0
Date: Mon, 08 Jun 2020 20:29:15 GMT
Content-Type: image/png
Transfer-Encoding: chunked
Connection: keep-alive
Cache-Control: max-age=600

2020/06/08 20:29:15 [debug] 29#29: *4 write new buf t:1 f:0 0172E320, pos 0172E320, size: 181 file: 0, size: 0
2020/06/08 20:29:15 [debug] 29#29: *4 http write filter: l:0 f:0 s:181
2020/06/08 20:29:15 [debug] 29#29: *4 http cacheable: 0
2020/06/08 20:29:15 [debug] 29#29: *4 http proxy filter init s:200 h:0 c:1 l:-1
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream process upstream
2020/06/08 20:29:15 [debug] 29#29: *4 pipe read upstream: 0
2020/06/08 20:29:15 [debug] 29#29: *4 pipe preread: 0
2020/06/08 20:29:15 [debug] 29#29: *4 pipe buf free s:0 t:1 f:0 0172C040, pos 0172C0DA, size: 0 file: 0, size: 0
2020/06/08 20:29:15 [debug] 29#29: *4 pipe length: 3
2020/06/08 20:29:15 [debug] 29#29: *4 event timer del: 3: 573678
2020/06/08 20:29:15 [debug] 29#29: *4 event timer add: 3: 60000:575076
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream request: "/sql/wordClouds/tweets/hope?"
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream dummy handler
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream request: "/sql/wordClouds/tweets/hope?"
2020/06/08 20:29:15 [debug] 29#29: *4 http upstream process upstream
2020/06/08 20:29:15 [debug] 29#29: *4 pipe read upstream: 1
2020/06/08 20:29:15 [debug] 29#29: *4 readv: eof:0, avail:-1
2020/06/08 20:29:15 [debug] 29#29: *4 readv: 1, last:3942
2020/06/08 20:29:15 [debug] 29#29: *4 pipe recv chain: 33
2020/06/08 20:29:15 [debug] 29#29: *4 pipe buf free s:0 t:1 f:0 0172C040, pos 0172C0DA, size: 33 file: 0, size: 0
2020/06/08 20:29:15 [debug] 29#29: *4 pipe length: 3
2020/06/08 20:29:15 [debug] 29#29: *4 http chunked byte: 89 s:0
2020/06/08 20:29:15 [error] 29#29: *4 upstream sent invalid chunked response while reading upstream, client: 10.0.0.2, server: , request: "GET /sql/wordClouds/tweets/hope HTTP/1.1", upstream: "http://10.0.2.5:80/wordClouds/tweets/hope", host: "192.168.1.158"

So the upstream server returns a response with "Transfer-Encoding: chunked", and the first byte of the response body is 0x89. This character is outside of the ASCII range and clearly is not a hexadecimal number as required by the ​chunked encoding.

Clearly this is an incorrect response from the backend. Depending on how the framework you are using is expected to work, this may either indicate a bug in the framework, or you are using the framework incorrectly.

[basti.lamberto@…]

Thank you very much :) I've updated the issue on the Ktor board. Just one question tho, why Chrome and other clients correctly handles the request when not proxied?

[Maxim Dounin]

Just one question tho, why Chrome and other clients correctly handles the request when not proxied?

My best guess that's because Chrome is using HTTP/2 when talking to your backend directly, and the backend works correctly via HTTP/2.

[lamba92@…]

I was using the IntelliJ HTTP tool and noticed that the request is served using HTTP/1.1:

GET http://localhost/wordClouds/tweets/anger

HTTP/1.1 200 
Cache-Control: max-age=600
Transfer-Encoding: chunked
Connection: keep-alive, keep-alive
Content-Type: image/png
Transfer-Encoding: chunked
Date: Sat, 13 Jun 2020 14:33:02 GMT
Keep-Alive: timeout=60

It actually works. Indeed reading the RFC you linked, it states:

Page 19

A recipient MUST parse an HTTP message as a sequence of octets in an
   encoding that is a superset of US-ASCII [USASCII].

0x89 is indeed outside the range of ASCII but what a superset of US-ASCII means? And why 0x89 is not in the range of a superset?

[Maxim Dounin]

The first byte of the message body encoded with chunked encoding must be a HEXDIG ("hexadecimal 0-9/A-F/a-f"), and a character outside of the ASCII range certainly doesn't fit. See above for the normative reference.