302 response with a header size of 4k+ triggers 502 error

[Bryan Martin]

We experienced a great deal of 502 errors when we added App Dynamics user monitoring to our application.

The workaround for us was to change the proxy_buffer_size to 8k, but the behavior we experienced seems like a bug.

If the header is too large, I'd expect to see a 431 Request Header Fields Too Large error, or something of the sort. Troubleshooting the 502 was quite painful. It seems like the cause was ultimately the Content-Length being set to 0.

Here's the debug output:

==> edm.test-a.2016.applicationname.company.ca_access.log <==
10.1.68.131 - - [23/Aug/2017:19:57:47 +0000] "GET /signin?from=timeout HTTP/1.1" 502 568 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.78 Safari/537.36" "xxx.16.140.27"

==> edm.test-a.2016.applicationname.company.ca_error.log <==
2017/08/23 19:57:47 [debug] 24833#24833: *57 http upstream request: "/signin?from=timeout"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http upstream process header
2017/08/23 19:57:47 [debug] 24833#24833: *57 malloc: 00007FF5DAEA2190:4096
2017/08/23 19:57:47 [debug] 24833#24833: *57 recv: eof:1, avail:1
2017/08/23 19:57:47 [debug] 24833#24833: *57 recv: fd:41 4096 of 4096
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy status 302 "302 Found"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Server: Apache-Coyote/1.1"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: ADRUM_BTa="R:0|g:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx"; Version=1; Max-Age=30; Expires=Wed, 23-Aug-2017 19:58:17 GMT; Path=/"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: ADRUM_BTa="R:0|g:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx|n:company-ss-dev_3b662425-b849-4961-afd2-xxxxxxxx"; Version=1; Max-Age=30; Expires=Wed, 23-Aug-2017 19:58:17 GMT; Path=/"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "X-XSS-Protection: 1; mode=block"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "X-FRAME-OPTIONS: SAMEORIGIN"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: ADRUM_BT1="R:0|i:21168"; Version=1; Max-Age=30; Expires=Wed, 23-Aug-2017 19:58:17 GMT; Path=/"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: ADRUM_BT1="R:0|i:21168|e:522"; Version=1; Max-Age=30; Expires=Wed, 23-Aug-2017 19:58:17 GMT; Path=/"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: JSESSIONID=3A38B1A00E86673D99A09336BE25F3CF; Path=/; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken="eyJhbGciOiJIUzI1NiJ9.eyJkb21haW4iOiJlZG0udGVzdC1hLmZlLnR1cmJvdGF4b25saW5lLmludHVpdC5jYSIsImlkIjoiM0EzOEIxQTAwRTg2NjczRDk5QTA5MzM2QkUyNUYzQ0YiLCJoYXNoSWQiOiJ1eFhEd0lJZDJQSUtOQUJMTDNZZGRldGdxLzgtIiwigarbagedatacjxE"; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=sessionToken"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=app_login_session"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=123146593655779|V1-24-b3l6tdfysxxxcoous8; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=sessionToken"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=eyJhbGciOiJIUzI1NiJ9.eyJkb21haW4iOiJlZG0udGVzdC1hLmZlLnR1cmJvdGF4b25saW5lLmludHVpdC5jYSIsImlkIjoiM0EzOEIxQTAwRTg2NjczRDk5QTA5MzM2QkUyNUYzQ0YiLCJoYXNoSWQiOiJ1eFhEd0lJZDJQSUtOQUJMTDNZZGRldGdxLzgtIiwigarbagedatacjxE; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.authid=123146593655779; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.agentid=123146593655779; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 posix_memalign: 00007FF5DAFC6A50:4096 @16
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.parentid=50000003; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.ticket=V1-24-b3l6tdfygarbageous8; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.gauthid=123146593655779; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: qbn.ptc.tkt=V1-24-b3l6tdfygarbageous8; Path=/; Domain=.company.ca; Secure; HttpOnly"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=app_login_session"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=123146593655779|V1-24-b3l6tdfygarbageous8; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=sessionToken"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=eyJhbGciOiJIUzI1NiJ9.eyJkb21haW4iOiJlZG0udGVzdC1hLmZlLnR1cmJvdGF4b25saW5lLmludHVpdC5jYSIsImlkIjoiM0EzOEIxQTAwRTg2NjczRDk5QTA5MzM2QkUyNUYzQ0YiLCJoYXNoSWQiOiJ1eFhEd0lJZDJQSUtOQUJMTDNZZGRldGdxLzgtIiwigarbagedatacjxE; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: application_signin_lastproduct=6; Path=/; Expires=Sat, 21-Aug-2027 19:57:47 GMT; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: application_signin_lastdate=1503518267547; Path=/; Expires=Sat, 21-Aug-2027 19:57:47 GMT; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=app_login_session"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: app_login_session=123146593655779|V1-24-b3l6tdfygarbageous8; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=""; Domain=.company.ca; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Path=sessionToken"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Set-Cookie: sessionToken=eyJhbGciOiJIUzI1NiJ9.eyJkb21haW4iOiJlZG0udGVzdC1hLmZlLnR1cmJvdGF4b25saW5lLmludHVpdC5jYSIsImlkIjoiM0EzOEIxQTAwRTg2NjczRDk5QTA5MzM2QkUyNUYzQ0YiLCJoYXNoSWQiOiJ1eFhEd0lJZDJQSUtOQUJMTDNZZGRldGdxLzgtIiwigarbagedatacjxE; Domain=.company.ca; Secure"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Location: https://xxx.test-a.fe.applicationname.company.ca/returnmanager/new?swlg=en&brand=company&ty=2016"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Content-Length: 0"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http proxy header: "Date: Wed, 23 Aug 2017 19:57:47 GMT"
2017/08/23 19:57:47 [error] 24833#24833: *57 upstream sent too big header while reading response header from upstream, client: 10.1.68.131, server: edm.test-a.2016.applicationname.company.ca, request: "GET /signin?from=timeout HTTP/1.1", upstream: "http://10.1.xx.xxx:80/signin?from=timeout", host: "edm.test-a.2016.applicationname.company.ca"
2017/08/23 19:57:47 [debug] 24833#24833: *57 http next upstream, 8
2017/08/23 19:57:47 [debug] 24833#24833: *57 free rr peer 1 4
2017/08/23 19:57:47 [debug] 24833#24833: *57 finalize http upstream request: 502
2017/08/23 19:57:47 [debug] 24833#24833: *57 finalize http proxy request
2017/08/23 19:57:47 [debug] 24833#24833: *57 close http upstream connection: 41
2017/08/23 19:57:47 [debug] 24833#24833: *57 free: 00007FF5DAE9AC70, unused: 48
2017/08/23 19:57:47 [debug] 24833#24833: *57 event timer del: 41: 1503518387034
2017/08/23 19:57:47 [debug] 24833#24833: *57 reusable connection: 0
2017/08/23 19:57:47 [debug] 24833#24833: *57 http finalize request: 502, "/signin?from=timeout" a:1, c:1
2017/08/23 19:57:47 [debug] 24833#24833: *57 http special response: 502, "/signin?from=timeout"
2017/08/23 19:57:47 [debug] 24833#24833: *57 HTTP/1.1 502 Bad Gateway
Server: nginx
Date: Wed, 23 Aug 2017 19:57:47 GMT
Content-Type: text/html
Content-Length: 568
Connection: keep-alive