"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? If you believe the error is due to the backend, could you please pin point me the error with some keywords so I may Google up!

[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.