Envoy Large http2_protocol_options initial_stream_window_size вызывает тайм-аут отправки/чтения на ALB/nginx upstream при больших откликах и медленных клиентах

Мы используем Envoy в качестве пограничного прокси-сервера перед AWS ALB со значением idle_timeout.timeout_seconds по умолчанию, равным 60 секундам, и у нас были отчеты о том, что загрузка клиентов в браузере завершалась с ошибкой около 150 МБ.

К сожалению, журналы посланников только что показали: response_duration: - response_ttfb: - flags: -

и 200 ОК

Нам удалось воссоздать проблему в браузерах, ограничив скорость соединения до ~1 МБ/с.

Мы отметили, что проблема возникла только с HTTP2.

Глядя на Firefox about:networking traces, мы заметили, что отправляется HTTP2 rst_stream с кодом ошибки 0:

2019-08-29 22:09:46.217000 UTC - [Parent 12304: Socket Thread]: I/nsHttp Http2Session::RecvRstStream 0000019A3D1FB000 RST_STREAM Reason Code 0 ID 11

Мы включили трассировку для посланника и увидели, что поток начинался с паузы и возобновлялся вот так:

{"time": "2019-08-30 09:30:48.432", "level": "debug", "type": "http2", "message": "[source/common/http/http2/codec_impl.cc:200] [C213] send buffer under limit "}
{"time": "2019-08-30 09:30:48.432", "level": "debug", "type": "http", "message": "[source/common/http/conn_manager_impl.cc:1607] [C213][] Enabling upstream stream due to downstream stream watermark."}

Мы сделали захват пакета на envoy и обнаружили, что около 250 МБ было прочитано из ALB, после чего последовала 60-секундная пауза, когда envoy установил окно получения на 0, в то время как клиент продолжал читать медленно:

09:29:45.795071 IP alb.443 > envoy.61682: Flags [.], seq 331920955:331922379, ack 1670, win 118, options [nop,nop,TS val 58414411 ecr 2277140227], length 1424
09:29:45.795088 IP alb.443 > envoy.61682: Flags [.], seq 331922379:331924715, ack 1670, win 118, options [nop,nop,TS val 58414411 ecr 2277140227], length 2336
09:29:45.834615 IP envoy.61682 > alb.443: Flags [.], ack 331924715, win 2, options [nop,nop,TS val 2277140419 ecr 58414410], length 0
09:29:46.356500 IP alb.443 > envoy.61682: Flags [P.], seq 331924715:331925739, ack 1670, win 118, options [nop,nop,TS val 58414552 ecr 2277140419], length 1024
09:29:46.356523 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277140941 ecr 58414552], length 0
09:29:46.900379 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58414688 ecr 2277140941], length 0
09:29:46.900397 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277141485 ecr 58414552], length 0
09:29:47.796392 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58414912 ecr 2277141485], length 0
09:29:47.796413 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277142381 ecr 58414552], length 0
09:29:49.428395 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58415320 ecr 2277142381], length 0
09:29:49.428410 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277144013 ecr 58414552], length 0
09:29:52.660486 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58416128 ecr 2277144013], length 0
09:29:52.660501 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277147245 ecr 58414552], length 0
09:29:58.804579 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58417664 ecr 2277147245], length 0
09:29:58.804596 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277153389 ecr 58414552], length 0
09:30:10.836578 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58420672 ecr 2277153389], length 0
09:30:10.836601 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277165421 ecr 58414552], length 0
09:30:35.668812 IP alb.443 > envoy.61682: Flags [.], ack 1670, win 118, options [nop,nop,TS val 58426880 ecr 2277165421], length 0
09:30:35.668827 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 0, options [nop,nop,TS val 2277190253 ecr 58414552], length 0
09:30:48.436329 IP envoy.61682 > alb.443: Flags [.], ack 331925739, win 1265, options [nop,nop,TS val 2277203020 ecr 58414552], length 0
09:30:48.586141 IP alb.443 > envoy.61682: Flags [.], seq 331925739:331927163, ack 1670, win 118, options [nop,nop,TS val 58430109 ecr 2277203020], length 1424
09:30:48.586164 IP envoy.61682 > alb.443: Flags [.], ack 331927163, win 1270, options [nop,nop,TS val 2277203170 ecr 58430109], length 0

Как только envoy снова начнет чтение, как только клиент достаточно прочтет буфер, от nginx/ALB придет небольшой ответ (мы предполагаем, частичная полезная нагрузка http), а затем либо envoy обнаружит соединение, либо ALB.

Мы наблюдали следующие сообщения:

{"time": "2019-08-30 08:23:09.557", "level": "debug", "type": "client", "message": "[source/common/http/codec_client.cc:118] [C157] protocol error: http/1.1 protocol error: HPE_INVALID_EOF_STATE"}
{"time": "2019-08-30 08:23:09.557", "level": "debug", "type": "client", "message": "[source/common/http/codec_client.cc:82] [C157] disconnect. resetting 1 pending requests"}

В любом случае, это слишком многословный способ сказать: большой initial_stream_window_size для HTTP2 https://github.com/envoyproxy/envoy/blob/master/api/envoy/api/v2/core/protocol.proto вызывает довольно сложную диагностику проблема в сочетании с медленным клиентом и значением по умолчанию read_timeout AWS ALB.

Мы подозреваем, что это также может вызвать проблемы со значениями по умолчанию, такими как http://nginx.org/en/docs/http/ngx_http_core_module.html#send_timeout, что также равно 60.

Мы бы предложили охватить максимальное количество клиентов, чтобы значение по умолчанию было снижено до 16 МБ, на чем мы и остановились. :) Или, по крайней мере, мы могли бы помочь ввести некоторые флаги в журналы, чтобы объяснить, что соединение было завершено из-за частичного/поврежденного HTTP-ответа с точки зрения Envoy.


envoyproxy
person Benjamin McAlary    schedule 02.09.2019    source источник

Ответы (1)


arrow_upward
0
arrow_downward

Initial_stream_window_size описан здесь https://www.envoyproxy.io/docs/envoy/latest/api-v2/api/v2/core/protocol.proto#envoy-api-field-core-http2protocoloptions-initial-connection-window-size и соответствующий размер по умолчанию здесь https://github.com/envoyproxy/envoy/blob/master/api/envoy/api/v2/core/protocol.proto

  // `Initial stream-level flow-control window
  // <https://httpwg.org/specs/rfc7540.html#rfc.section.6.9.2>`_ size. Valid values range from 65535
  // (2^16 - 1, HTTP/2 default) to 2147483647 (2^31 - 1, HTTP/2 maximum) and defaults to 268435456
  // (256 * 1024 * 1024).

Мы решили эту проблему двумя способами, которые можно использовать независимо или вместе:

  1. Мы увеличили тайм-аут ALB (или nginx, если вы говорите с каким-то другим типом прокси) с 60 по умолчанию до 300+, в течение которого клиенты с большей вероятностью будут считывать достаточно данных, чтобы буфер Envoy упал ниже водяного знака, необходимого для дальнейшего срабатывания. читать события и, таким образом, сбрасывать тайм-аут чтения кластера/восходящих потоков.

  2. Мы уменьшили initial_stream_window_size до чего-то более разумного, например

            http2_protocol_options:
              initial_stream_window_size: 16777216

Дополнительным преимуществом здесь является то, что мы наблюдаем более последовательное и меньшее использование памяти, в то время как мы не наблюдали снижения производительности даже на высокоскоростных клиентах.

person Benjamin McAlary    schedule 02.09.2019