Свой формат: время, бэкенд, request_id

Если пара rt/urt и escape=json знакомы - листай до «Теперь сам».

Сначала ответь сам

Строка из лога, формат свой:

127.0.0.1 - - [10/Sep/2026:19:58:52 +0000] "GET /pair/report HTTP/1.1" 200 3 "-" "curl/8.22.0" host=localhost rt=0.000 upstream=127.0.0.1:9, 127.0.0.1:8080 us=502, 200 urt=0.001, 0.000 uct=-, 0.000 uht=-, 0.000 rid=a308ceb1dbf4e5caad5e76c0415d5766

Формат этой строки разобран ниже в уроке. Два адреса в upstream= взялись из группы серверов, куда nginx отправляет запрос (группы разбираются в разделе про балансировкуРазбирается в разделе 8, глава «Методы балансировки»: Группа серверов вместо адреса). В логе есть 502. Что увидел пользователь?

Успех. 502 стоит в $upstream_status - это ответ первой попытки: сервер 127.0.0.1:9 соединение отверг, nginx пошёл на второй адрес, тот ответил, и клиенту ушёл код 200 из $status. Запятая в этих полях всегда значит одно: попыток было больше одной.

Считать 502 по grep " 502 " в таком логе - значит считать поломки, которых пользователь не заметил. И наоборот: если считать только по $status, скрытые отказы бэкендов не увидит никто.

На что это похоже

Ты заказал еду и ждал сорок минут. Сорок минут - это $request_time. Кухня готовила восемь минут - это $upstream_response_time. Остальные тридцать две курьер вёз.

Пока у тебя одно число «сорок», разговор с рестораном бессмысленный: они клянутся, что готовят быстро, и по своим записям правы. Как только рядом встают два числа, спорить не о чем - видно, чья это половина.

Вся настройка формата сводится к тому, чтобы в каждой строке было два числа вместо одного.

Механизм: где кончается одно время и начинается другое

Правило

Читай эти числа парами, а не по одному. Разность rt и urt - это всё, что не бэкенд: чтение запроса, ожидание в очереди, отдача клиенту.

• rt большой, urt маленький - канал до клиента или медленная загрузка тела;
• оба большие - тормозит бэкенд;
• заметный uct при быстром остальном - бэкенду не хватает воркеров, соединения ждут приёма;
• uht почти равен urt - бэкенд долго думает и быстро отдаёт: тяжёлый запрос к базе.

Разбор: клиент на медленном канале

Замер на стенде. Бэкенд отдаёт 20 000 000 байт, клиент читает их через curl --limit-rate 2M - это 2 МиБ, 2 097 152 байта в секунду. Со стороны клиента загрузка заняла 9,5 секунды, ровно 20 000 000 / 2 097 152. В логе:

127.0.0.1 - - [10/Sep/2026:19:58:56 +0000] "GET /huge HTTP/1.1" 200 20000000 "-" "curl/8.22.0" host=localhost rt=4.239 upstream=127.0.0.1:8080 us=200 urt=0.064 uct=0.000 uht=0.001 rid=986cd9438ba973a33aeb627d8034fe05

Бэкенд отработал за 64 миллисекунды, nginx потратил 4,2 секунды. Виноват канал - и это видно из одной строки, не заходя ни на один сервер.

Но обрати внимание: 4,2 против 9,5 у клиента. $request_time заканчивается, когда nginx записал последний байт в сокет, а не когда клиент его получил. Часть данных лежала в буферах ядра, пока nginx уже считал запрос завершённым. На том же стенде ответ в 2 000 000 байт целиком уместился в буфер, и rt вышел 0.003 при почти секунде загрузки у клиента.

Практический вывод: rt - нижняя оценка того, сколько ждал человек. Если он большой, канал точно плохой; если маленький, это ещё ничего не доказывает.

Разбор: где наивное правило подводит

Прочерк - это не ноль. У запроса, не дошедшего до бэкенда, все upstream_* пусты: в обычном формате пустое значение печатается прочерком -, а с escape=json - пустотой. У 499 картина хитрее: us=- и uht=- (заголовков не было), а urt=1.001 - столько nginx прождал до того, как клиент ушёл. Складывать такие значения в среднее нельзя.

Кавычки в JSON - не косметика. Вот формат, где $upstream_response_time записан числом без кавычек:

log_format jsonbad escape=json '{"uri":"$uri","urt":$upstream_response_time,"ua":"$http_user_agent"}';

Он ломает строку на каждом запросе, который не ушёл на бэкенд, - на статике, на редиректе, на 404, - и на каждой повторной попытке:

{"uri":"/pair/report","urt":0.001, 0.000,"ua":"curl/8.22.0"}
{"uri":"/logo.png","urt":,"ua":"curl/8.22.0"}
{"uri":"/huge","urt":0.064,"ua":"curl/8.22.0"}

Первые две строки не разберёт ни один парсер. То же с $upstream_addr и $upstream_status. С кавычками вокруг значения те же запросы дают "urt":"0.001, 0.000" и "urt":"" - корректный JSON.

escape=json обязателен. Без него nginx экранирует по своим правилам, а не по правилам JSON, и User-Agent с кавычкой превращается в \x22:

escape=json:     "ua":"Mozilla/5.0 \"hacked\" \\back"
по умолчанию:    "ua":"Mozilla/5.0 \x22hacked\x22 \x5Cback"

Вторая строка формально похожа на JSON и ломается на \x: такой последовательности в стандарте нет. Приёмная сторона начинает ронять записи пачками, причём именно те, что интереснее всего.

Формат под разбор инцидентов

log_format main '$remote_addr - $remote_user [$time_local] '
                '"$request" $status $body_bytes_sent '
                '"$http_referer" "$http_user_agent" '
                'host=$host rt=$request_time '
                'upstream=$upstream_addr us=$upstream_status '
                'urt=$upstream_response_time uct=$upstream_connect_time '
                'uht=$upstream_header_time rid=$request_id';

log_format json escape=json '{"uri":"$uri","urt":"$upstream_response_time","ua":"$http_user_agent"}';

Куски в кавычках склеиваются в одну строку формата, поэтому пробел в конце каждого нужен, а отступы между ними - нет. В официальном образе Docker в nginx.conf уже объявлен свой log_format main, и этот блок пишется вместо него: такой же в conf.d даст duplicate "log_format" name "main" - проверено.

log_format объявляется только в http. Попытка положить его в server даёт отказ ещё до старта:

nginx: [emerg] "log_format" directive is not allowed here in /etc/nginx/nginx.conf:32

:32 - номер строки в файле.

$request_id - 32 шестнадцатеричных символа, свои на каждый запрос. Передай их бэкенду, и строка nginx сошьётся с записями приложения:

proxy_set_header X-Request-Id $request_id;

proxy_set_header добавляет заголовок к запросу, уходящему бэкенду; имя заголовка выбираешь сам, X-Request-Id - общепринятое.

бэкенд:  X-Request-Id: 7ea37b4954250561d6d41a0ab9a3366f
в логе:  rid=7ea37b4954250561d6d41a0ab9a3366f

Дальше в разборе ты берёшь rid из строки с ошибкой и находишь по нему трассу в приложении. Без этого приходится сопоставлять по времени и URL, а под нагрузкой это гадание.

Что ломается без этого

Спор «виноват бэкенд» против «виноват nginx» идёт неделями, потому что у сторон разные числа и ни одно из них не общее. Появление rt и urt в одной строке заканчивает такой спор за минуту.

Второе: лог в JSON, который разваливается на трети записей. Сборщик молча отбрасывает нечитаемое, графики выглядят нормально, и никто не замечает, что пропали именно ошибки.

Зачем это в работе

Куда писать - решается тут же, рядом с форматом:

server {
    listen 80;
    server_name shop.local;
    access_log /var/log/nginx/shop.access.log main;

    # мониторинг стучится раз в секунду - в логе от этого только шум
    location = /health { access_log off; return 200 "ok\n"; }

    # трафик API уезжает в аналитику отдельным потоком
    location /api/ {
        access_log /var/log/nginx/api.access.log json;
        proxy_pass http://127.0.0.1:8080;
    }
}

На одном уровне можно объявить несколько access_log - запись уйдёт в каждый. \n в return - перевод строки в конце ответа. А access_log на уровне вытесняет унаследованный: объявишь в server свой формат, и общий access_log из http в этот сервер писать перестанет. Проверяется это за минуту и удивляет ровно один раз в жизни.

Ещё два параметра для нагруженного сайта:

access_log /var/log/nginx/shop.access.log main buffer=64k flush=5s;

Эту строку пишут вместо прежнего access_log, а не рядом - иначе запись уйдёт в оба. buffer копит строки в памяти, flush не даёт последним залежаться. Плата - твой запрос появится в логе не сразу: на стенде с flush=5s строка ждала своих пять секунд. При отладке это выглядит как «лог не пишется», а при жёстком падении процесса последние секунды теряются насовсем.

Теперь сам

В формате стоит rt=$request_time, и на графике 95-й процентиль по /api/search (время, быстрее которого обслужены 95% запросов) вырос с 0,3 до 2,5 секунды. urt при этом стоит на месте, около 0,2. Куда идти?