ProxyMapService: логирование HTTP/2

Теперь ProxyMapService логирует HTTP/2-трафик так же, как HTTP/1.1: заголовки, тела и завершение каждого запроса видны в тех же логах и мониторе, ничего дополнительно настраивать не нужно.

Что изменилось

Раньше в логе и мониторе был виден только HTTP/1.1-трафик. Если и клиент, и сервер говорили на HTTP/2, туннель просто пересылал байты, и в логе ничего не оставалось. Теперь трафик по-прежнему идёт без изменений, но прокси читает его копию и передаёт в те же логгеры.

Сценарий	Раньше	Теперь
Клиент HTTP/1.1, сервер HTTP/1.1	логируется	логируется
Клиент HTTP/1.1, сервер HTTP/2 (трансляция)	логируется	логируется
Клиент HTTP/2, сервер HTTP/2	не видно	логируется
Файлы из RootDir по HTTP/2	клиент получал мусор	отдаётся корректно

Вкладка HTTP Traffic: клиент и сервер говорят на HTTP/2, ответ разбирается в Transaction Inspector.

Отдельно отмечу исправление, которое касается всех протоколов: событие «запрос завершён» теперь приходит на каждый запрос, а не один раз за сессию. Раньше, если по одному соединению шло несколько запросов (keep-alive, тем более HTTP/2), монитор мог получить завершение только для последнего.

Что попадает в лог

Для каждого HTTP/2-запроса прокси передаёт логгерам то же, что и для HTTP/1.1:

• заголовки запроса и ответа;
• тела запроса и ответа, если включён логгер тел (без него тела не накапливаются);
• завершение запроса — отдельно для каждого, даже если по одному соединению идут параллельно десятки запросов;
• совпадения по адресу для подписок (NotifyIfRequestUrlMatches).

Для чтения лога HTTP/2-заголовки показаны в привычном виде: запрос — как GET /path HTTP/2, ответ — как HTTP/2 200 OK. Адрес сервера берётся из :authority и показывается как host, а несколько заголовков cookie склеиваются в один.

В мониторе видно, на каком протоколе говорит клиент (колонка Client Proto) и на каком — сервер (Target Proto). При трансляции это HTTP/1.1 → HTTP/2, при прозрачном h2 — HTTP/2 → HTTP/2:

Рядом с этим на уровне Debug пишется одна строка итога на каждый запрос:

[h2 stream 5] GET /api/items -> 200, request 0 B, response 4821 B, 37 ms

Помимо этого, на уровне Debug видно обрывы отдельных запросов (RST_STREAM) и закрытие соединения (GOAWAY) с кодом ошибки.

Как включить

Отдельной настройки нет: наблюдение включается само, когда сессия работает на HTTP/2 с обеих сторон. Для этого нужно три условия:

1. Включена расшифровка TLS (DecryptSSL). Без неё прокси видит только зашифрованные байты, и разбирать нечего.
2. В SslClientOptions.ApplicationProtocols (что прокси предлагает серверу) указан h2.
3. В SslServerOptions.ApplicationProtocols (что прокси разрешает клиенту) тоже указан h2.

Если клиент умеет h2 и сервер выбрал h2, сессия идёт как прозрачный HTTP/2, и прокси сам начинает наблюдение. Как именно согласуются протоколы в каждой комбинации настроек, есть в посте про трансляцию HTTP/1.1 → HTTP/2: там таблица сценариев.

Рекомендуемый старт: http/1.1,h2 и в SslClientOptions, и в SslServerOptions. Браузер будет на h2, клиенты вроде curl останутся на HTTP/1.1, а логирование будет работать в обоих случаях.

Для FileRequestHandler (когда прокси сам отдаёт файлы из RootDir) тоже достаточно указать h2 в SslServerOptions.ApplicationProtocols: браузер согласует HTTP/2, и файлы будут отдаваться по нему.

Кэш и подмена Host

Наблюдение ничего не меняет в трафике, а кэш и подмена Host требуют вмешательства: отдать готовый ответ или переписать адрес в запросе. Пока такое умеет только работа с HTTP/1.1, поэтому для таких сессий прокси по умолчанию предлагает клиенту HTTP/1.1, даже если он умеет h2. С сервером прокси говорит на h2, если включена трансляция, и на HTTP/1.1, если нет. Оба понижения включены по умолчанию, и каждое можно отключить отдельной настройкой в разделе HTTP:

• DisableDowngradeToHttp1ForOverwrittenHost — подмена Host. По умолчанию (false) клиент понижается до HTTP/1.1, когда для хоста задана подмена, и подмена работает. Если поставить true, клиент останется на h2, а подмена Host в такой сессии не сработает.
• DisableDowngradeToHttp1ForCache — кэш. По умолчанию (false) понижение включено, и кэш работает даже для браузерного h2-трафика. Если поставить true, клиент продолжит работать по h2, а кэш в таких сессиях не сработает.

{
  "HTTP": {
    "DisableDowngradeToHttp1ForCache": false,
    "DisableDowngradeToHttp1ForOverwrittenHost": false
  }
}

При понижении в логе появляется запись о том, что клиенту предложен HTTP/1.1. Если клиент HTTP/1.1 не умеет или настройки ALPN этого не допускают, прокси пишет предупреждение, что понизить нельзя.

Если что-то пошло не так

Сломать трафик наблюдение не может: байты всегда отправляются адресату первыми, а анализ идёт после них. Если прокси не смог разобрать что-то нестандартное, страдает только лог, не сессия. В логе при этом могут появиться два предупреждения:

Сообщение	Что это значит
[h2] traffic analysis stopped for …	Разбор одного направления (запросы или ответы) прекратился до конца сессии. Трафик идёт как идёт, но это направление больше не логируется. Обычно это некорректный поток от клиента или сервера.
cannot build an HTTP header for logging	Для одного запроса не удалось собрать заголовок для лога (например, неверный статус). Этот запрос не запишется, остальные работают как обычно.

Если первое сообщение появляется часто для одного и того же хоста, смотрите в логе сообщения причины: они ведут к конкретному нарушению протокола и помогут найти проблемный сервер.

Ограничения

• Наблюдение только смотрит: кэш и подмена Host в прозрачном h2→h2 не работают (см. выше про понижение до HTTP/1.1).
• Тела накапливаются в памяти целиком до конца запроса, так что большие загрузки с включённым логгером тел будут занимать столько же памяти.
• Отдельные служебные фреймы (PING, WINDOW_UPDATE, SETTINGS) в лог не попадают: видны только запросы и ответы, а также RST_STREAM и GOAWAY на уровне Debug.
• После сбоя разбора направления остаток сессии в этом направлении не логируется.
• На одном соединении отслеживается не более 2048 одновременных запросов; этот лимит защищает память от пира, который открывает потоки без конца.