Of course we cannot always share details about our work with customers, but nevertheless it is nice to show our technical achievements and share some of our implemented solutions.
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.
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:
events {
# Debugging a certain IP
debug_connection 192.168.55.12; # client getting http 400 errors
}
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:
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.
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.
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.
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.
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.
To finalize this posts, here are the default values for request/header size limits of some http servers, as of February 2021 (last updated):
| HTTP Server |
Setting / Option name |
Default value |
| Apache 2.2 |
LimitRequestFieldSize | 8190 |
| Apache 2.4 |
LimitRequestFieldSize |
8190 |
| HAProxy |
tune.bufsize / tune.maxrewrite |
16384 / half of bufsize |
| IIS 4.x |
MaxClientRequestBuffer |
2M |
| IIS 5.x |
MaxClientRequestBuffer | 128K |
| IIS 5.x w Win 2000 SP4 |
MaxClientRequestBuffer | 16K |
| IIS 6.x and later |
MaxRequestBytes |
16K |
| Lighttpd |
server.max-request-field-size |
none |
| LiteSpeed |
maxReqHeaderSize |
16380 |
| Nginx |
large_client_header_buffers |
4 8k |
| Node.js < v13.13.0 |
--max-http-header-size | 8KB |
| Node.js >= v13.13.0 |
--max-http-header-size |
16KB |
| Tomcat 5.5 |
maxHttpHeaderSize |
4096 |
| Tomcat 6 and later |
maxHttpHeaderSize | 8192 |
| Wildfly 10 and later |
max-header-size |
1048576 |
Meanwhile Geeker's Digest also published an up to date list of HTTP request header limits.