Yes changing the error_to debug level as Emmanuel Joubaud suggested worked out (edit /etc/nginx/sites-enabled/default ):
error_log /var/log/nginx/error.log debug;
Then after restarting nginx I got in the error log with my Python application using uwsgi:
2017/02/08 22:32:24 [debug] 1322#1322: *1 connect to unix:///run/uwsgi/app/socket, fd:20 #2
2017/02/08 22:32:24 [debug] 1322#1322: *1 connected
2017/02/08 22:32:24 [debug] 1322#1322: *1 http upstream connect: 0
2017/02/08 22:32:24 [debug] 1322#1322: *1 posix_memalign: 0000560E1F25A2A0:128 @16
2017/02/08 22:32:24 [debug] 1322#1322: *1 http upstream send request
2017/02/08 22:32:24 [debug] 1322#1322: *1 http upstream send request body
2017/02/08 22:32:24 [debug] 1322#1322: *1 chain writer buf fl:0 s:454
2017/02/08 22:32:24 [debug] 1322#1322: *1 chain writer in: 0000560E1F2A0928
2017/02/08 22:32:24 [debug] 1322#1322: *1 writev: 454 of 454
2017/02/08 22:32:24 [debug] 1322#1322: *1 chain writer out: 0000000000000000
2017/02/08 22:32:24 [debug] 1322#1322: *1 event timer add: 20: 60000:1486593204249
2017/02/08 22:32:24 [debug] 1322#1322: *1 http finalize request: -4, "/?" a:1, c:2
2017/02/08 22:32:24 [debug] 1322#1322: *1 http request count:2 blk:0
2017/02/08 22:32:24 [debug] 1322#1322: *1 post event 0000560E1F2E5DE0
2017/02/08 22:32:24 [debug] 1322#1322: *1 post event 0000560E1F2E5E40
2017/02/08 22:32:24 [debug] 1322#1322: *1 delete posted event 0000560E1F2E5DE0
2017/02/08 22:32:24 [debug] 1322#1322: *1 http run request: "/?"
2017/02/08 22:32:24 [debug] 1322#1322: *1 http upstream check client, write event:1, "/"
2017/02/08 22:32:24 [debug] 1322#1322: *1 http upstream recv(): -1 (11: Resource temporarily unavailable)
Then I took a look to my uwsgi log and found out that:
Invalid HTTP_HOST header: 'www.mysite.local'. You may need to add u'www.mysite.local' to ALLOWED_HOSTS.
[pid: 10903|app: 0|req: 2/4] 192.168.221.2 () {38 vars in 450 bytes} [Wed Feb 8 22:32:24 2017] GET / => generated 54098 bytes in 55 msecs (HTTP/1.1 400) 4 headers in 135 bytes (1 switches on core 0)
And adding www.mysite.local to the settings.py ALLOWED_HOSTS fixed the
issue 
ALLOWED_HOSTS = ['www.mysite.local']
Ошибка 400 bad request nginx означает, что сделан неверный запрос.
Ошибка может возникать по разным причинам, всё зависит от используемой конфигурации и приложения.
Если речь идет о запросах к базе данных или API — причина может быть в работе бэкенда. Например, недостаточное количество знаков в поле БД.
В случае если ошибка возникает при обращении к странице сайта — причина обычно в Nginx и размерах буферов, которые задаются в конфигурационных файлах.
Рассмотрим подробнее этот случай, он самый типичный.
Ошибка 400 bad request nginx
Объем заголовков в запросе может быть различным. Если он велик и лимит, установленный в конфигурации, не позволяет их обработать — возникнет ошибка.
Ошибка исправляется добавлением в секцию http конфигурационного файла nginx.conf следующей директивы:
large_client_header_buffers 2 12k;
Тестируем конфигурацию, убеждаемся в том, что ошибок в выводе нет
nginx -t
Затем перечитываем конфигурация веб-сервера чтобы он увидел новые директивы и значения паратетров.
nginx -s reload
Если параметры уже добавлены можно попробовать увеличить их значения, в 2, в 4 раза.
С каждой итерацией нужно тестировать конфигурацию с помощью nginx -t, перезапускать процесс nginx -s reload и проверять выполняя тот же запрос при котором была ошибка 400 bad request nginx.
Дополнительно можно проверить логи Nginx
less /var/log/nginx/error.log
Если ошибка возникает периодически — в логе доступа можно найти при помощи grep все случаи получения ответа 400 по уникальным характеристикам запроса: комбинации даты, времени, ip адреса клиента. Затем сопоставить данные с записями в error.log — логе ошибок.
В access.log будут запросы, которые выполнялись при обращении к сайту.
Пример запроса с кодом ответа 400 приведен на скриншоте:
Также есть другие буферы Nginx, на которые стоит обратить внимание (ссылка на статью про буферы была выше). Особенно если сервер обслуживает нагруженный проект.
Читайте про конфигурацию веб-сервера Nginx: структуру файлов с настройками и контексты.
How to solve 400 bad request error when using nginx as reverse proxy ?
Problem
The original nginx.conf file content
http {
upstream myserver {
server 127.0.0.1:8001;
server 127.0.0.1:8002;
server 127.0.0.1:8003;
}
server {
listen 8000;
server_name 127.0.0.1;
location / {
proxy_pass http://myserver;
}
}
}
I run three http server instances in one server, and I use nginx as reverse proxy to load balancing the request to backend http services.
When I start nginx, I got this:
HTTP/1.1 400 Bad Request =>
Server => nginx
I use curl to debug the http request and response:
curl -v http://127.0.0.1:8000/
* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8000 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1:8000
>
< HTTP/1.1 400 Bad Request
< Server: nginx
....
<
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN""http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Bad Request</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Bad Request</h2>
<hr><p>HTTP Error 400.</p>
</BODY></HTML>
Solution #1
When nginx returns 400 (Bad Request) it will log the reason into error log, at “info” level. Hence an obvious way to find out what’s going on is to configure error_log to log messages at “info” level and take a look into error log when testing.
You should open the debug log by adding this line to nginx.conf:
error_log /var/log/nginx/error.log debug;
Solution #2
Some server may require additional http headers to be set in the http request. You can add some useful http headers by using proxy_set_header like this:
proxy_set_header Host $host:$server_port;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
According to mozilla document:
The Host Header Specifies the domain name of the server (for virtual hosting), and (optionally) the TCP port number on which the server is listening.
X-Real-IP Let nginx pass the request to backend with real client IP address. You should know that:
This module is not built by default, it should be enabled with the
--with-http_realip_moduleconfiguration parameter.
X-Forwarded-For Identifies the originating IP addresses of a client connecting to a web server through an HTTP proxy or a load balancer.
The final nginx.conf
error_log /var/log/nginx/error.log debug;
http {
upstream myserver {
server 127.0.0.1:8001;
server 127.0.0.1:8002;
server 127.0.0.1:8003;
}
server {
listen 8000;
server_name 127.0.0.1;
location / {
proxy_pass http://myserver/;
proxy_set_header Host $host:$server_port;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
}
}
}
7 июня, 2022 12:03 пп
334 views
| Комментариев нет
LEMP Stack, Ubuntu
Nginx – это высокопроизводительный веб-сервер, способный гибко и качественно обслуживать контент. Оформляя страницы своего сайта, вы наверняка захотите создать пользовательский стиль для каждого его элемента, включая и страницы об ошибках, которые появляются, если контент недоступен. В этом руководстве мы покажем, как настроить такие страницы на Nginx.
Требования
- Виртуальный сервер с пользователем sudo (мы используем сервер Ubuntu 22.04, настроенный по этому мануалу).
- Предварительно установленный веб-сервер Nginx (инструкции по установке вы найдете здесь).
Создание пользовательской страницы об ошибке
Пользовательские страницы ошибок, которые мы используем здесь, предназначены для демонстрационных целей. Если у вас есть свои страницы, используйте их.
Поместите пользовательские страницы ошибок в каталог /usr/share/nginx/html, корневой каталог Nginx по умолчанию. Там мы создадим страницу для ошибки 404 под названием custom_404.html и для общих ошибок уровня 500 под названием custom_50x.html.
Примечание: Дальнейшие строки можно использовать, если вы тренируетесь на наших страницах. В противном случае не забудьте указать свои данные.
Сначала создайте HTML-файл для своей пользовательской страницы 404 с помощью nano или другого текстового редактора:
sudo nano /usr/share/nginx/html/custom_404.html
Вставьте туда код, который определяет пользовательскую страницу:
<h1 style='color:red'>Error 404: Not found :-(</h1> <p>I have no idea where that file is, sorry. Are you sure you typed in the correct URL?</p>
Сохраните и закройте файл.
Теперь создайте файл HTML для страницы 500:
sudo nano /usr/share/nginx/html/custom_50x.html
Вставьте в файл следующее:
<h1>Oops! Something went wrong...</h1> <p>We seem to be having some technical difficulties. Hang tight.</p>
Сохраните и закройте файл.
В данный момент у вас есть две пользовательские страницы ошибок, которые будут отображаться на сайте, когда запросы клиентов приводят к различным ошибкам.
Итак, пора сообщить Nginx, что он должен использовать эти страницы всякий раз, когда возникают соответствующие ошибки. Откройте тот файл server-блока в каталоге /etc/nginx/sites-enabled, который вы хотите настроить. Здесь мы используем стандартный файл по имени default. Если вы настраиваете свои собственные страницы, пожалуйста, убедитесь, что используете правильный файл:
sudo nano /etc/nginx/sites-enabled/default
Теперь нужно направить Nginx на соответствующие страницы.
Настройка пользовательской страницы 404
Используйте директиву error_page, чтобы при возникновении ошибки 404 (когда запрошенный файл не найден) обслуживалась созданная вами пользовательская страница. Создайте location-блок для вашего файла, где вы сможете установить его правильное расположение в файловой системе и указать, что файл доступен только через внутренние перенаправления Nginx (не запрашиваемые клиентами напрямую):
server {
listen 80 default_server;
. . .
error_page 404 /custom_404.html;
location = /custom_404.html {
root /usr/share/nginx/html;
internal;
}
}
Обычно устанавливать root в новом блоке location не нужно, так как он совпадает с root в блоке server. Однако здесь мы явно указываем, что страницы ошибок нужно обслуживать, даже если вы перемещаете свой обычный веб-контент и связанный с ним root в другое место.
Настройка страницы ошибок 50х
Затем добавьте новые директивы, чтобы Nginx, столкнувшись с ошибками уровня 500 (это проблемы, связанные с сервером), мог обслуживать другую пользовательскую страницу, которую вы создали. Здесь мы будем следовать той же формуле, которую вы использовали в предыдущем разделе. На этот раз мы насторим несколько ошибок уровня 500, чтобы все они использовали страницу custom_50x.html.
Внизу мы также добавим фиктивный FastCGI, чтобы вы могли протестировать свою страницу с ошибкой уровня 500. Это выдаст ошибку, потому что бэкэнд на самом деле не существует. Так вы можете убедиться, что ошибки уровня 500 обслуживают вашу пользовательскую страницу.
Отредактируйте файл /etc/nginx/sites-enabled/default следующим образом:
server {
listen 80 default_server;
. . .
error_page 404 /custom_404.html;
location = /custom_404.html {
root /usr/share/nginx/html;
internal;
}
error_page 500 502 503 504 /custom_50x.html;
location = /custom_50x.html {
root /usr/share/nginx/html;
internal;
}
location /testing {
fastcgi_pass unix:/does/not/exist;
}
}
Сохраните и закройте файл, когда закончите.
Перезапуск Nginx и тестирование
Чтобы проверить синтаксис ваших файлов, введите:
sudo nginx -t
Если команда обнаружила какие-либо ошибки, исправьте их, прежде чем продолжить. Перезапустите Nginx, если ошибок нет:
sudo systemctl restart nginx
Теперь, если вы перейдете на домен или IP-адрес вашего сервера и запросите несуществующий файл, вы должны увидеть настроенную вами страницу 404:
http://server_domain_or_IP/thiswillerror
Перейдите в расположение вашего FastCGI и вы получите ошибку 502 Bad Gateway, что является ошибкой уровня 50х:
http://server_domain_or_IP/testing
Вернитесь в конфигурационный файл и удалите фиктивный FastCGI.
Заключение
Теперь ваш веб-сервер может обслуживать пользовательские страницы ошибок. Это простой способ персонализировать ваш сайт и обеспечить лучший пользовательский опыт даже при возникновении ошибок. Один из способов оптимизировать эти страницы – разместить на них дополнительную информацию или полезные ссылки для пользователей. Если вы сделаете это, убедитесь, что ссылки доступны даже при возникновении соответствующих ошибок.
Tags: NGINX, Ubuntu 22.04
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
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.
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
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 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.
Add a comment
Show form to leave a comment
Comments (newest first)
Ali from India wrote on May 29th, 2022:
Thanks for detailed explanation. I like who share real outputs and explain each step-by-step. Solved my issue with this!!
Thank you!