Intermittent 502

[mstaudinger]

I am using nghttpx to proxy http/2 requests to a load balancer, using plaintext (no-tls specified on the frontend), with TLS handled upstream.

This is a FreeBSD-11-p2 system with nghttp2 package installed via "pkg". I was running version 1.18.0_1, but I see the same results on the latest pkg version 1.21.0.

I'm seeing requests getting 502 errors intermittently in the nghttpx log. After setting the log level to INFO I can see this for an example of a failed request.

HTTP parser failure: (HPE_CB_headers_complete) the on_headers_complete callback failed

Some additional context from the log is below.

Any advice on tracking this down?

Best,
Mark

2017-04-05T02:48:42.632Z 50440 50439 fd29a9f4 INFO (shrpx_connection_handler.cc:366) [LISTEN:0x7fffffffa5a0] Accepted connection from 10.11.0.110, fd=37
2017-04-05T02:48:42.632Z 50440 50439 fd29a9f4 INFO (shrpx_connection_handler.cc:410) Dispatch connection to worker #1
2017-04-05T02:48:42.632Z 50440 50441 ee0d0fa1 INFO (shrpx_worker.cc:355) [WORKER:0x80378cc00] WorkerEvent: client_fd=37, addrlen=16
2017-04-05T02:48:42.632Z 50440 50441 ee0d0fa1 INFO (shrpx_worker.cc:382) [WORKER:0x80378cc00] CLIENT_HANDLER:0x803a1b500 created
2017-04-05T02:48:42.632Z 50440 50441 ee0d0fa1 INFO (shrpx_client_handler.cc:1290) [CLIENT_HANDLER:0x803a1b500] PROXY-protocol: Started
2017-04-05T02:48:42.632Z 50440 50441 ee0d0fa1 INFO (shrpx_client_handler.cc:1461) [CLIENT_HANDLER:0x803a1b500] PROXY-protocol-v1: Finished, 49 bytes read
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_client_handler.cc:369) [CLIENT_HANDLER:0x803a1b500] direct HTTP/2 connection
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_http2_upstream.cc:270) [UPSTREAM:0x803a31280] Received upstream request HEADERS stream_id=1
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_http2_upstream.cc:326) [UPSTREAM:0x803a31280] HTTP request headers. stream_id=1
....
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_client_handler.cc:1012) [CLIENT_HANDLER:0x803a1b500] Downstream address group_idx: 0
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_client_handler.cc:1126) [CLIENT_HANDLER:0x803a1b500] Reuse downstream connection DCONN:0x803a40000 from pool
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:236) [DCONN:0x803a40000] Attaching to DOWNSTREAM:0x803b00700
2017-04-05T02:48:42.637Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:674) [DCONN:0x803a40000] HTTP request headers. stream_id=1
...
2017-04-05T02:48:42.960Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:236) [DCONN:0x803a40000] Attaching to DOWNSTREAM:0x803b00700
2017-04-05T02:48:42.960Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:674) [DCONN:0x803a40000] HTTP request headers. stream_id=3
...
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:1368) [DCONN:0x803a40000] HTTP parser failure: (HPE_CB_headers_complete) the on_headers_complete callback failed
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_http2_upstream.cc:1232) [DCONN:0x803a40000] HTTP parser failure
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_http2_upstream.cc:1305) [DCONN:0x803a40000] Downstream network/general error
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_http_downstream_connection.cc:223) [DCONN:0x803a40000] Deleted
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_http2_upstream.cc:63) [UPSTREAM:0x803a31280] Stream stream_id=3 is being closed
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_downstream.cc:164) [DOWNSTREAM:0x803b00700] Deleting
2017-04-05T02:48:42.966Z 50440 50441 ee0d0fa1 INFO (shrpx_downstream.cc:194) [DOWNSTREAM:0x803b00700] Deleted

[tatsuhiro-t]

The error means that nghttpx found an error while processing response header fields from upstream server.

Unfortunately, nghttpx does not log which header field caused this error.
There are several cases it fails:

1. HTTP version is neither 1.1 nor 1.0
2. HTTP status code is 204, but transfer-encodng header field is used
3. HTTP status code is 204, but there is content-length header field with nonzero value
4. HTTP status code is 1xx or 200 (for CONNECT request), and content-length or transfer-encoding header field appears.
5. content-length cannot be parsed as integer

[mstaudinger]

Thanks, that's a great concise list of things to check for. I cannot report that any of those are occurring. Here's a lightly redacted request header and response header. The log line from nghttpx indicates a $request_time of 0.003 ms to process this request, whereas the backend took 72ms to reply. So there's no indication that the headers are even available that fast. tcpdump capture indicates approximately 71ms between request and response packets.

REQ:
GET /login-admin HTTP/1.1
Host: www.test.com
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 10_2_1 like Mac OS X) AppleWebKit/602.4.6 (KHTML, like Gecko) Version/10.0 Mobile/14D27 Safari/602.1
Accept-Language: en-us
Accept-Encoding: gzip, deflate
Cookie: VisitorStatus=11060449968
X-Forwarded-For: 7.1.2.3
X-Forwarded-Proto: https
X-Transport: h2
GeoIP-CC: US

RESP:
HTTP/1.1 200 OK
Cache-Control: private, no-store, must-revalidate
Content-Type: text/html; charset=utf-8
Content-Encoding: deflate
Vary: Accept-Encoding
Server: Microsoft-IIS/8.5
X-Frame-Options: SAMEORIGIN
X-UA-Compatible: IE=Edge
X-AspNet-Version: 4.0.30319
Set-Cookie: CMSString=; expires=Thu, 07-Apr-2016 00:55:43 GMT; path=/; HttpOnly
X-Powered-By: ASP.NET
Date: Fri, 07 Apr 2017 00:25:42 GMT
Content-Length: 10733

[mstaudinger]

I am also able to reliably trigger a 502 response from nghttpx every time with a request that results in a 204 response from the backend, like this one.

HTTP/1.1 204 No Content
Date: Fri, 07 Apr 2017 04:14:42 GMT
Server: Apache/2.4.17 (FreeBSD) OpenSSL/1.0.1l-freebsd PHP/5.6.14
X-Powered-By: PHP/5.6.14
Access-Control-Allow-Origin: *
X-Cache: MISS
Vary: Accept-Encoding
Age: 0

[tatsuhiro-t]

Thank you for additional information. It turns out to be a bug of nghttpx. #876 fixes this issue.