受欢迎的博客标签

How to Debugging a HTTP 400 Bad Request error in Nginx

Published
Created: 2020年4月12日星期日 上午8:53:14 Latest updated:2022年4月27日星期三 下午4:29:52 views(3325)

Table of Contents

Today I came across an interesting issue: A client got a http error 400 (bad request) when accessing certain pages of a website.

This website's architecture is built redundantly around a couple of load balancers. Here's an example drawing of such an architecture:

 

 

This means the traffic needs to run through multiple hosts including Nginx and HAProxy servers until finally reaching the application itself on the application server or container.

Debugging in Nginx

Debug Log for Selected IPs.

Once the client's IP address was identified I enabled the "debug mode" for this particular IP. Nginx allows to set a certain IP address or range into debug mode by using the "debug_connection" parameter in the events context. This context is usually found in /etc/nginx/nginx.conf:

error_log /path/to/log;
...
events {
    # Debugging a certain IP
    debug_connection 192.168.55.12; # client getting http 400 errors
   debug_connection 192.168.10.0/24;
  debug_connection 172.70.210.81/24;

  # Debugging cloudflare IP
  debug_connection 172.70.210.81/24;
  debug_connection 172.69.210.81/24;
   
 
}
When this client accesses the website, there will be a lot of debug information written into the defined error log of the requested virtual host. So if you have a virtual host (server) config with a dedicated error log, this debugged connection will be logged there:
server {
  listen 80;
  server_name www.example.com;
  access_log  /var/log/nginx/www.example.com.access.log;
  error_log  /var/log/nginx/www.example.com.error.log;
[...]

The log entries appearing in /var/log/nginx/www.example.com.error.log will contain A LOT of information, don't be shocked.

When I asked the client to access the website again and reproduce the http 400 error, this request was logged in detail and I was able to analyze it. Here's the (almost) full data of that request:

/var/log/nginx/error.log 

2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http args: ""
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http exten: "1482353"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http process request header line
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Host: www.example.com"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Connection: keep-alive"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Upgrade-Insecure-Requests: 1"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Referer: https://www.example.com/"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Accept-Encoding: gzip, deflate, br"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 posix_memalign: 00000000031BBA00:4096 @16
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Accept-Language: en-US,en;q=0.9,de;q=0.8"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http alloc large header buffer
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 malloc: 00000000031EDD50:8192
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http large header alloc: 00000000031EDD50 8192
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http large header copy: 464
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_read: 7140
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_read: -1
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_get_error: 2
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e3d2d2-4567-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7b5f6f548274; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_cntpwmt=5; ens_ueid_624612360_513=1559034320820; POPUPCHE
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header done
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 generic phase: 0
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 rewrite phase: 1
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 test location: "/"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 test location: "sitemap"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 using configuration "/"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http cl:-1 max:104857600
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 rewrite phase: 3
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post rewrite phase: 4
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 generic phase: 5
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 generic phase: 6
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 generic phase: 7
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 generic phase: 8
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 access phase: 9
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 access phase: 10
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post access phase: 11
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http init upstream, client timer: 0
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 malloc: 0000000003207030:8282
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "Host: "
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script var: "www.example.com"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "
"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "X-Real-IP: "
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script var: "192.168.55.12"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "
"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "X-Forwarded-For: "
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script var: "192.168.55.12"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "
"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "X-Forwarded-Proto: https
"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: "Connection: close
"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: ""
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: ""
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: ""
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http script copy: ""
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Upgrade-Insecure-Requests: 1"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Referer: https://www.example.com/"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Accept-Encoding: gzip, deflate, br"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Accept-Language: en-US,en;q=0.9,de;q=0.8"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e3d2d2-4567-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7b5f6f548274; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_cntpwmt=5; ens_ueid_624612360_513=1559034320820; PO
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header:
"GET /news/article-1234.1482353 HTTP/1.0
Host: www.example.com
X-Real-IP: 192.168.55.12
X-Forwarded-For: 192.168.55.12
X-Forwarded-Proto: https
Connection: close
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3
Referer: https://www.example.com/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9,de;q=0.8
Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e3d2d2-4567-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7b5f6f548274; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http cleanup add: 00000000031BC128
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 get rr peer, try: 1
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 stream socket 1514
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 epoll add connection: fd:1514 ev:80002005
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 connect to 127.0.0.1:8080, fd:1514 #1706804565
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream connect: -2
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 posix_memalign: 00000000021EF490:128 @16
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 event timer add: 1514: 6000000:1559039102955
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http finalize request: -4, "/news/article-1234.1482353?" a:1, c:2
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http request count:2 blk:0
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 delete posted event 00007F5DB055BA50
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http run request: "/news/article-1234.1482353?"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream check client, write event:1, "/news/article-1234.1482353"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream recv(): -1 (11: Resource temporarily unavailable)
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post event 00007F5DB055BA50
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post event 00007F5DB055B210
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 delete posted event 00007F5DB055BA50
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http run request: "/news/article-1234.1482353?"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream check client, write event:1, "/news/article-1234.1482353"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream recv(): -1 (11: Resource temporarily unavailable)
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 delete posted event 00007F5DB055B210
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream request: "/news/article-1234.1482353?"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream send request handler
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream send request
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream send request body
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 chain writer buf fl:1 s:8243
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 chain writer in: 00000000031BC160
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 writev: 8243 of 8243
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 chain writer out: 0000000000000000
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 event timer del: 1514: 1559039102955
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 event timer add: 1514: 6000000:1559039102959
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post event 00007F5DB064C210
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 post event 00007F5DB055B210
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 delete posted event 00007F5DB064C210
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream request: "/news/article-1234.1482353?"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream process header
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 malloc: 000000000318A3F0:4096
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 recv: fd:1514 187 of 4096
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy status 400 "400 Bad request"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Cache-Control: no-cache"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Connection: close"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Content-Type: text/html"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header done
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 HTTP/1.1 400 Bad request
Server: nginx/1.10.2
Date: Tue, 28 May 2019 08:45:02 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: keep-alive
Cache-Control: no-cache

There's obviously a lot of data and it's not easy to find the relevant part. I try to cherry-pick the relevant lines:

2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Accept-Language: en-US,en;q=0.9,de;q=0.8"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http alloc large header buffer
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 malloc: 00000000031EDD50:8192
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http large header alloc: 00000000031EDD50 8192
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http large header copy: 464
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_read: 7140
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_read: -1
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 SSL_get_error: 2
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e3d2d2-4567-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7b5f6f548274; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_cntpwmt=5; ens_ueid_624612360_513=1559034320820; POPUPCHE
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http header done

Nginx detected a large HTTP header and allocated a buffer for it.  Especially the "Cookie" header is huge and contains a lot of cookies and their session data.

A bit further down, the same headers are sent to the upstream server (the next hop in the data flow) using the "proxy" module:

2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Accept-Language: en-US,en;q=0.9,de;q=0.8"
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e3d2d2-4567-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7b5f6f548274; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_cntpwmt=5; ens_ueid_624612360_513=1559034320820; PO
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy header:
"GET /news/article-1234.1482353 HTTP/1.0

Finally the upstream server returned a HTTP 400 error when the proxied http headers were parsed:

2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http upstream process header
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 malloc: 000000000318A3F0:4096
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 recv: fd:1514 187 of 4096
2019/05/28 10:45:02 [debug] 14311#0: *1706803906 http proxy status 400 "400 Bad request"

By taking a closer look at the "Cookie" header from the http request, the data seems to be cut. It ends with "POPUPCHE" and does not contain a value.

Furthermore the Cookie header was even more cut when the request was forwarded to the upstream server; it ends with just "PO".

Obviously these request headers are too big to handle for Nginx and they are cut to a default size. The default header size limit in Nginx is 8K.

Adjust Nginx to allow larger http headers

The HTTP protocol itself does not define a size limit of the headers, but for security and performance reasons these limits are (usually) set in the web servers. These default limits can be changed, of course.

In Nginx this default size can be changed using the option "large_client_header_buffers". You can set this either globally in the "http" context or in a "server" context for a specific vhost. In this example I set a new limit of 64K in the "http" context:

http {
    include       /etc/nginx/mime.types;
    default_type  application/octet-stream;

    # Allow larger than normal headers
    large_client_header_buffers 4 64k;
[...]

Followed by a Nginx reload, the new http header size limit should be activated.

Testing and failing again

SSL_read

ret=SSL_read(ssl, line, sizeof (line));
err=SSL_get_error(ssl,ret); //观察返回值的情况，err=2时ret=-1, err=0时l=实际读取字节数
返回err=SSL_ERROR_WANT_READ时即err=2;
SSL_ERROR_WANT_READ的宏定义值就是2

Now that Nginx was told to accept the larger headers, I asked the client to reproduce the error. And the http 400 error occurred again. Once more, I checked the debug logs:

2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http large header alloc: 00000000036E84F0 65536
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http large header copy: 499
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 SSL_read: 7257
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 SSL_read: -1
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 SSL_get_error: 2
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 posix_memalign: 00000000036A2010:4096 @16
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e094fdb-0241-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7bf803883d4c; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_ueid_624612360_513=1559034320820; POPUPCHECK=155911712556
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http header done

This time the received "Cookie" header was complete!

Also the full "Cookie" header was sent to the upstream server:

2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http proxy header: "Cookie: bcjsck=defeb988-4e62-4971-b692-a0cab3e1aa15; bcjsmh=d41d8cd98f00b204e9800998ecf8427e; _ga=GA1.2.121262398.1500964581; conveyVisitorId=783533216391128700; _cb=DVtTO0D1nxaxqltf-; creid=1587323204948210394; ens_subscrptst=registered%3BTue%20Feb%2020%202018%2011%3A42%3A01%20GMT%2B0100%20(CET); _v__chartbeat3=CEFK3zDBkUfmBwsJ9l; _cb_ls=1; ivbsdid={"id":"qsg6vkb6sb78"}; mbox=PC#9dc594f60e3f4c358006c402a9d0d73e.26_21#1604146991|session#61a773b682474005a1ba24467c023012#1542273057; _fbp=fb.1.1549266199618.647410032; __gads=ID=6456a71ef275ba00:T=1551781894:S=ALNI_MaKQ4DMVT2F6IMzm4G1dOcUA9koOg; ens_c1pid=8e094fdb-0241-4074-abaf-2e6e5dc7c188; cresid_platform1234=cb81a3b283a9d208b04f7bf803883d4c; bclk=3704698032204732; cresid=6a7497a5ab3d809e8fb19644ad92e710; service=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjlmYzY2Zjg5LTdiM2ItNDBiYy04NDJhLTQzODNjMzZmMDJmYSJ9.eyJzZXJ2aWNlX2lkIjoibnp6IiwibG9naW4iOiJrYXRyaW4uaHV0aEBnbWFpbC5jb20iLCJsYXN0X25hbWUiOiJIdXRoIiwiZmlyc3RfbmFtZSI6IkthdHJpbiIsInNlc3Npb25faWQiOiJhYjU2YTYxMzg3MzYzYzZjNDM0NzIwODgxYzJjOGVkOCJ9.ZpC4f4fDN7yJT-QrsOj7CRFMxmmmZx-J08Vw8qHCpxCMlE5DJ97gn1vPmMomJhdU0JPrkHdJiAP5y-GRPRToz-1RUDhdeTmrZKHI6u9XrNDrDKUzWPxF553w2_O_TfD8ioTwLihn3sHhRpvAS7kLqbJCgMt5n3wB2Jbzz2mCVpfvFpyyMJoVDUTdeQ4Lefti-37wbwFHzZ-idt9rc3vYbK2iw0YTe-s7M3hsNRQ-2wFYSWjC4mAy8qtySa7Jb801eLSEqO2-W3603UkbcvjW9829-qn6kGrFjkEQ314I82HLgMX6Siy74BCVpPrOD-XLVNIwC_HX-6fknWkiXxR-Yg; ens_cntpvabo=383; ens_subscrst=subscriber%3BWed%20Jun%2026%202019%2009%3A48%3A49%20GMT%2B0200%20(Mitteleurop%C3%A4ische%20Sommerzeit); _gid=GA1.2.131606941.1558944578; ens_kavz=0986-0050-01-010; _fbc=fb.1.1558951120515.IwAR1vSVauTbRT1sO397XEXVmRHTSbC3dL08dZ9WSMVLGSoS4T9m8QRgHv6Js; p4m_snot=1318; s_vdnum=1559080800290%26vn%3D1; s_dinvisit=true; s_vwnum=1559426400501%26vn%3D7; s_winvisit=true; s_vmnum=1559340000345%26vn%3D56; s_minvisit=true; s_dslv_s=Less%20than%201%20day; ens_ueid_3425441984_513=1559034247693; ens_ueid_624612360_513=1559034320820; POPUPCHECK=155911

But the upstream server still sent back a 400 error:

2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http upstream process header
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 malloc: 00000000034EB2E0:4096
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 recv: fd:379 187 of 4096
2019/05/28 11:00:57 [debug] 20067#0: *1707128584 http proxy status 400 "400 Bad request"

Why would that be?

When you look at the architecture drawing at the begin, you see that after the Nginx web server, the next hop of the dataflow is HAProxy. And because HAProxy is also (kind of) a HTTP server, there are also some defaults and limits to be considered.

Adjust HAProxy to allow larger http headers

HAProxy has a lot of fine tuning settings. And to allow larger http headers, we need to exactly tune these.

The relevant settings are tune.bufsize and tune.maxrewrite. It's important to set both of these, as the documentation says:

tune.bufsize sets the buffer size to this size (in bytes). The default value is 16384 and can be changed at build time. [...] If HTTP request is larger than (tune.bufsize - tune.maxrewrite), haproxy will return HTTP 400 (Bad Request) error. Similarly if an HTTP response is larger than this size, haproxy will return HTTP 502 (Bad Gateway).

Both of these options need to be set in the "global" section of your HAProxy config:

#---------------------------------------------------------------------
# Global settings
#---------------------------------------------------------------------
global
    log /dev/log    local0
    log /dev/log    local1 notice
    chroot /var/lib/haproxy
    stats socket /run/haproxy/admin.sock mode 660 level admin
    stats timeout 30s
    user haproxy
    group haproxy
    daemon

    # Default SSL material locations
    ca-base /etc/ssl/certs
    crt-base /etc/ssl/private

    # Default ciphers to use on SSL-enabled listening sockets.
    # For more information, see ciphers(1SSL). This list is from:
    #  https://hynek.me/articles/hardening-your-web-servers-ssl-ciphers/
    ssl-default-bind-ciphers ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:ECDH+3DES:DH+3DES:RSA+AESGCM:RSA+AES:RSA+3DES:!aNULL:!MD5:!DSS
    ssl-default-bind-options no-sslv3

    # Large Buffer Sizes (to allow larger http headers/requests)
    tune.maxrewrite 16384
    tune.bufsize 65535

In this case a buffer size of 64K and a max rewrite size of 16K is defined. Which leaves us with a limit size of 48K.

Let's see if this is enough for our client.

After reloading HAProxy, the new limits are in place.

Party time

The next request came in shortly and this time the response was a successful HTTP 200:

2019/05/28 11:42:35 [debug] 20067#0: *1708050081 http upstream process header
2019/05/28 11:42:35 [debug] 20067#0: *1708050081 malloc: 00000000031B8E50:4096
2019/05/28 11:42:35 [debug] 20067#0: *1708050081 recv: fd:884 4096 of 4096
2019/05/28 11:42:35 [debug] 20067#0: *1708050081 http proxy status 200 "200 OK"

Finally the 400 errors are gone and it was all due to a larger than usual http request, because of the large http headers (damn cookies!).

If you need to increase the request/header limits, it's important to do this in the whole chain of dataflow. Every http/application server this request goes through must be checked and if necessary adjusted.

A handy comparison of defaults

To finalize this posts, here are the default values for request/header size limits of some http servers, as of May 2019:

 

 HTTP Server   Setting / Option name  Default value 
 Apache 2.2LimitRequestFieldSize 8190
 Apache 2.4LimitRequestFieldSize 8190
 HAProxytune.bufsize / tune.maxrewrite 16384 / half of bufsize
 IIS 4.xMaxClientRequestBuffer 2M
 IIS 5.xMaxClientRequestBuffer 128K
 IIS 5.x w Win 2000 SP4MaxClientRequestBuffer 16K
 IIS 6.x and laterMaxRequestBytes 16K
 Lighttpdserver.max-request-field-size unknown
 LiteSpeedmaxReqHeaderSize 16380
 Nginxlarge_client_header_buffers 4 8k
 Tomcat 5.5maxHttpHeaderSize 4096
 Tomcat 6 and latermaxHttpHeaderSize 8192
 Wildfly 10 and latermax-header-size 1048576

 

Origin server

.Net 6.x

blazor server

appsettings.json
{
  "DetailedErrors": true,
  "Logging": {
    "LogLevel": {
      "Default": "Trace",
      "Microsoft.AspNetCore": "Trace"
    }
  }
}

 

 

 

Useful links

Capture the SSL Handshake with tcpdump