search

envoyproxy / envoy

Cloud-native high-performance edge/middle/service proxy
https://www.envoyproxy.io
Apache License 2.0
24.98k stars 4.81k forks source link

envoy-1.31.2 nghttp2 racing / DownStreamProtocolError / codec_error:The_user_callback_function_failed #36387

Open pgeler opened 1 month ago

pgeler commented 1 month ago

This is to reiterate on the issue with nghttp2 implementation and envoy gRPC clusters #30882 which was closed due to inactivity and understanding that oghttp2 will replace it within a release or so. So as of 1.31.2, nghttp2 seem not going away any time soon as oghttp2 have some observable issues with general http2 implementation. So we are dead in the water right now and thinking to rollback before 1.27.2 or something...

Description: Overall it seem like racing condition on HTTP2, most of the time I was able it to reproduce with GRPC service., There is seem to be correlation on larger number of clients, however I have examples where similar issue happening with envoy to envoy HTTP path-through connectivity. This particular example was created after ~5min, 1000k RPS, execution on 50+ simultaneous clients, grpc is a ext_proc stream-based service, but I can confirm that the issue isolated to newer envoy not to the ext_proc filter as b-sidecar(by rollback to envoy-1.27):

client -> envoy(a router - ext_proc) -> envoy(b-sidecar) -> grpc service:

http2 specific clusters configuration:

          http2_protocol_options:
            override_stream_error_on_invalid_http_message: true

after period of time and high frequency requests: requests starts failing with DPE(b-sidecar):

{"line":{"xrid":"43a5f437-14b6-96d2-8330-a8ad286ef377","dtfr":null,"rx":2102,"tx":76,"path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","mthd":"POST","sid":"43a5f437-14b6-96d2-8330-a8ad286ef377","dur":155,"ra":"cluster","rf":"DPE","utime":null,"ua":null,"ctd":null,"rc":200,"id":233,"proto":"HTTP/2","utfr":null,"rcd":"codec_error:The_user_callback_function_failed","time":"2023-11-14T20:01:15.110Z"},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"ctd":null,"xrid":"d8f6005f-ed16-9638-90a5-6e7603c48d3d","path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","sid":"d8f6005f-ed16-9638-90a5-6e7603c48d3d","rcd":"codec_error:The_user_callback_function_failed","utfr":null,"tx":78,"ua":null,"rf":"DPE","utime":null,"time":"2023-11-14T20:01:15.186Z","proto":"HTTP/2","id":233,"mthd":"POST","rx":1290,"ra":"cluster","rc":200,"dur":80,"dtfr":null},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"xrid":"cf78183e-203e-95e7-bc45-efd564f58bc7","id":233,"rx":1253,"utime":null,"rcd":"codec_error:The_user_callback_function_failed","tx":0,"utfr":null,"rc":0,"dur":1,"time":"2023-11-14T20:01:15.265Z","sid":"cf78183e-203e-95e7-bc45-efd564f58bc7","rf":"DPE","ra":"cluster","mthd":"POST","ctd":null,"ua":null,"dtfr":null,"path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","proto":"HTTP/2"},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"utfr":null,"path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","tx":0,"rcd":"codec_error:The_user_callback_function_failed","time":"2023-11-14T20:01:15.265Z","ua":null,"rx":1286,"id":233,"rf":"DPE","ctd":null,"ra":"cluster","xrid":"7ec0e1a2-c896-9b46-b57d-08b9c55a307b","rc":0,"sid":"7ec0e1a2-c896-9b46-b57d-08b9c55a307b","mthd":"POST","dur":0,"utime":null,"dtfr":null,"proto":"HTTP/2"},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","ctd":null,"rx":1288,"mthd":"POST","time":"2023-11-14T20:01:15.265Z","rf":"DPE","rcd":"codec_error:The_user_callback_function_failed","proto":"HTTP/2","utime":null,"ra":"cluster","dur":0,"dtfr":null,"ua":null,"rc":0,"tx":0,"id":233,"utfr":null,"xrid":"8b078583-acce-9007-b43a-27b216c539aa","sid":"8b078583-acce-9007-b43a-27b216c539aa"},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"dur":0,"ra":"cluster","id":233,"rc":0,"time":"2023-11-14T20:01:15.265Z","path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","proto":"HTTP/2","mthd":"POST","utfr":null,"rcd":"codec_error:The_user_callback_function_failed","rf":"DPE","ua":null,"tx":0,"utime":null,"xrid":"fce995f4-7cd9-99f5-9eb5-0bfe54f7ce9f","ctd":null,"sid":"fce995f4-7cd9-99f5-9eb5-0bfe54f7ce9f","rx":1251,"dtfr":null},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"ctd":null,"id":233,"utime":null,"mthd":"POST","sid":"aee3e7fc-4ac7-9da2-85a4-af6008dd2b06","rf":"DPE","ra":"cluster","rc":0,"path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","tx":0,"time":"2023-11-14T20:01:15.265Z","dur":0,"proto":"HTTP/2","xrid":"aee3e7fc-4ac7-9da2-85a4-af6008dd2b06","rx":1257,"dtfr":null,"ua":null,"utfr":null,"rcd":"codec_error:The_user_callback_function_failed"},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
{"line":{"dur":0,"rc":0,"id":233,"ua":null,"mthd":"POST","ctd":null,"utfr":null,"time":"2023-11-14T20:01:15.265Z","ra":"cluster","dtfr":null,"proto":"HTTP/2","path":"/envoy.service.ext_proc.v3.ExternalProcessor/Process","rcd":"codec_error:The_user_callback_function_failed","tx":0,"xrid":"7acd0dcb-8294-9096-aa59-5c73432de879","sid":"7acd0dcb-8294-9096-aa59-5c73432de879","utime":null,"rf":"DPE","rx":1292},"source":"stdout","tag":"ece6485d1111","attrs":{"stack":"test"}}
all requests isolated to single connection and it seem that is happening on connection per-connection basis: tracelog last couple of seconds for the connection 233 (end of the life(b-sidecar) where issue occured): ``` [2023-11-14 20:01:16.298][29][trace][connection] [network/connection_impl.cc:469] raising connection event 1 [2023-11-14 20:01:16.298][29][debug][connection] [extensions/transport_sockets/tls/ssl_socket.cc:329] SSL shutdown: rc=0 [2023-11-14 20:01:16.298][29][debug][connection] [network/connection_impl.cc:278] closing socket: 1 [2023-11-14 20:01:16.298][29][debug][connection] [network/connection_impl_base.cc:69] triggered delayed close [2023-11-14 20:01:15.267][29][debug][connection] [network/connection_impl.cc:788] write flush complete [2023-11-14 20:01:15.267][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 17 [2023-11-14 20:01:15.267][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.267][29][trace][connection] [network/connection_impl.cc:614] socket event: 2 [2023-11-14 20:01:15.266][29][debug][connection] [network/connection_impl_base.cc:47] setting delayed close timer with timeout 1000 ms [2023-11-14 20:01:15.266][29][debug][connection] [network/connection_impl.cc:146] closing data_to_write=17 type=2 [2023-11-14 20:01:15.266][29][debug][http2] [http/http2/codec_impl.cc:1220] sent goaway code=2 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=7, stream_id=0, length=8 [2023-11-14 20:01:15.266][29][trace][connection] [network/connection_impl.cc:529] writing 17 bytes, end_stream false [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=17 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=7, flags=0 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 13 bytes [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10369 [2023-11-14 20:01:15.266][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 13 bytes [2023-11-14 20:01:15.266][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 13 bytes [2023-11-14 20:01:15.266][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.266][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.266][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 13 [2023-11-14 20:01:15.266][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.266][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.266][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.265][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.265][29][trace][connection] [network/connection_impl.cc:614] socket event: 2 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 9064 bytes [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1292 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10385 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10385 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1257 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10383 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10383 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1251 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10381 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10381 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1288 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10379 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10379 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=850 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10371 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1286 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10377 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10377 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1253 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10375 [2023-11-14 20:01:15.265][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10375 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10361 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10359 [2023-11-14 20:01:15.265][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 9064 bytes [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 9064 bytes [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1384 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1349 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1343 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1380 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 859 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1378 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1345 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 26 [2023-11-14 20:01:15.265][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.265][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 142 [2023-11-14 20:01:15.264][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.264][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10373, length=78 [2023-11-14 20:01:15.264][29][trace][connection] [network/connection_impl.cc:529] writing 87 bytes, end_stream false [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10373, length=5 [2023-11-14 20:01:15.264][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.264][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10369. [2023-11-14 20:01:15.264][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10369 closed: 0 [2023-11-14 20:01:15.264][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10369, length=4 [2023-11-14 20:01:15.264][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.264][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10369, length=1 [2023-11-14 20:01:15.263][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.263][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.263][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.263][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10369, length=9 [2023-11-14 20:01:15.263][29][trace][connection] [network/connection_impl.cc:529] writing 18 bytes, end_stream false [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 1956 bytes [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=513 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10369 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1290 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10373 [2023-11-14 20:01:15.186][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10373 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10367 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10363 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10365 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10357 [2023-11-14 20:01:15.186][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 1956 bytes [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 1956 bytes [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1904 [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 52 [2023-11-14 20:01:15.186][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.186][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 138 [2023-11-14 20:01:15.186][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.186][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10361. [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10361 closed: 0 [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10361, length=4 [2023-11-14 20:01:15.184][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10361, length=1 [2023-11-14 20:01:15.184][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10361, length=9 [2023-11-14 20:01:15.184][29][trace][connection] [network/connection_impl.cc:529] writing 18 bytes, end_stream false [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10359. [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10359 closed: 0 [2023-11-14 20:01:15.184][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10359, length=4 [2023-11-14 20:01:15.184][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10359, length=1 [2023-11-14 20:01:15.184][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.184][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10359, length=65 [2023-11-14 20:01:15.183][29][trace][connection] [network/connection_impl.cc:529] writing 74 bytes, end_stream false [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 13 bytes [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10355 [2023-11-14 20:01:15.183][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 13 bytes [2023-11-14 20:01:15.183][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 13 bytes [2023-11-14 20:01:15.183][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.183][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.183][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 13 [2023-11-14 20:01:15.183][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.183][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 375 [2023-11-14 20:01:15.183][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.183][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.183][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10367. [2023-11-14 20:01:15.183][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10367 closed: 0 [2023-11-14 20:01:15.183][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10367, length=4 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10367, length=1 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10367, length=65 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 74 bytes, end_stream false [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10363. [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10363 closed: 0 [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10363, length=4 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10363, length=1 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10363, length=9 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 18 bytes, end_stream false [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10365. [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10365 closed: 0 [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10365, length=4 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10365, length=1 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.182][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10365, length=9 [2023-11-14 20:01:15.182][29][trace][connection] [network/connection_impl.cc:529] writing 18 bytes, end_stream false [2023-11-14 20:01:15.182][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10357. [2023-11-14 20:01:15.181][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10357 closed: 0 [2023-11-14 20:01:15.181][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10357, length=4 [2023-11-14 20:01:15.181][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10357, length=1 [2023-11-14 20:01:15.181][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10357, length=65 [2023-11-14 20:01:15.181][29][trace][connection] [network/connection_impl.cc:529] writing 74 bytes, end_stream false [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10371, length=76 [2023-11-14 20:01:15.181][29][trace][connection] [network/connection_impl.cc:529] writing 85 bytes, end_stream false [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10371, length=5 [2023-11-14 20:01:15.181][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.181][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 4217 bytes [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=513 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10361 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=850 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10359 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=887 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10367 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=513 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10363 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=513 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10365 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=887 padding_length=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10357 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 4217 bytes [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 4217 bytes [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 522 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 859 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 896 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 522 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 522 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 896 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.180][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 191 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10369, length=104 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:529] writing 113 bytes, end_stream false [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10369, length=28 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:529] writing 37 bytes, end_stream false [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=37 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.180][29][debug][http2] [http/http2/codec_impl.cc:1426] Recouping 0 bytes of flow control window for stream 10355. [2023-11-14 20:01:15.180][29][debug][http2] [http/http2/codec_impl.cc:1362] stream 10355 closed: 0 [2023-11-14 20:01:15.180][29][debug][http2] [http/http2/codec_impl.cc:1237] sent reset code=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=3, stream_id=10355, length=4 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:529] writing 13 bytes, end_stream false [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=13 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=3, flags=0 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10355, length=1 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:529] writing 10 bytes, end_stream false [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=10 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=5 [2023-11-14 20:01:15.180][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10355, length=9 [2023-11-14 20:01:15.180][29][trace][connection] [network/connection_impl.cc:529] writing 18 bytes, end_stream false [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 522 bytes [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=513 padding_length=0 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10355 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 522 bytes [2023-11-14 20:01:15.111][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 522 bytes [2023-11-14 20:01:15.111][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.111][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.111][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 522 [2023-11-14 20:01:15.111][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.111][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.111][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 2761 bytes [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1252 padding_length=0 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.111][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10371 [2023-11-14 20:01:15.111][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=75 padding_length=0 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10371 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1252 padding_length=0 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10369 [2023-11-14 20:01:15.110][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=146 padding_length=0 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10369 [2023-11-14 20:01:15.110][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 2761 bytes [2023-11-14 20:01:15.110][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 2761 bytes [2023-11-14 20:01:15.110][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.110][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.110][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 2761 [2023-11-14 20:01:15.110][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.110][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.110][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.108][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 480 [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:614] socket event: 2 [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10365, length=104 [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:529] writing 113 bytes, end_stream false [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10365, length=5 [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10367, length=76 [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:529] writing 85 bytes, end_stream false [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10367, length=5 [2023-11-14 20:01:15.108][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.108][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10363, length=104 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:529] writing 113 bytes, end_stream false [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10363, length=5 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10361, length=104 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:529] writing 113 bytes, end_stream false [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10361, length=5 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 104 bytes [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10347 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10345 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10351 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10353 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10349 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10343 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10339 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=3 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=3 flags=0 length=4 padding_length=0 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=3, flags=0, stream_id=10341 [2023-11-14 20:01:15.107][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 104 bytes [2023-11-14 20:01:15.107][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 104 bytes [2023-11-14 20:01:15.107][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.107][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.107][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 104 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.107][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:989] dispatched 5461 bytes [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1290 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10367 [2023-11-14 20:01:15.105][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10367 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1252 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10365 [2023-11-14 20:01:15.105][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10365 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1259 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10363 [2023-11-14 20:01:15.105][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10363 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=0 flags=0 length=1292 padding_length=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=0 [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=0, flags=0, stream_id=10361 [2023-11-14 20:01:15.105][29][debug][connection] [network/connection_impl.h:98] current connecting state: false [2023-11-14 20:01:15.105][29][trace][http2] [http/http2/codec_impl.cc:1087] recv frame type=1 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:2138] track inbound frame type=1 flags=4 length=74 padding_length=0 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1061] about to recv frame type=1, flags=4, stream_id=10361 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:954] dispatching 5461 bytes [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:163] ssl read 5461 bytes [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:127] ssl error occurred while read: WANT_READ [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: -1 [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 4077 [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:87] ssl read returns: 1384 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:654] read ready. dispatch_buffered_data=0 [2023-11-14 20:01:15.104][29][trace][connection] [extensions/transport_sockets/tls/ssl_socket.cc:277] ssl write returns: 876 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:737] write ready [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:614] socket event: 3 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10359, length=76 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:529] writing 85 bytes, end_stream false [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10359, length=5 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=0, stream_id=10357, length=76 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:529] writing 85 bytes, end_stream false [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1208] sent frame type=1, stream_id=10357, length=5 [2023-11-14 20:01:15.104][29][trace][connection] [network/connection_impl.cc:529] writing 14 bytes, end_stream false [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1337] send data: bytes=14 [2023-11-14 20:01:15.104][29][trace][http2] [http/http2/codec_impl.cc:1315] about to send frame type=1, flags=4 ```

everything is working as expected with envoy-1.27

kyessenov commented 1 month ago

CC @alyssawilk @yanavlasov

kyessenov commented 1 month ago

It might be helpful to try this with ENVOY_NGHTTP2_TRACE to get detailed logging from the codec.

pgeler commented 1 month ago

@kyessenov do you know if it requires special build or something? Otherwise nothing additional is logged when I'm enabling ENVOY_NGHTTP2_TRACE with http2 tracing

pgeler commented 1 month ago

@kyessenov do you know if it requires special build or something? Otherwise nothing additional is logged when I'm enabling ENVOY_NGHTTP2_TRACE with http2 tracing

yeah, it sounds like nghttp2 needs to be build with DEBUGBUILD https://nghttp2.org/documentation/nghttp2_set_debug_vprintf_callback.html then a question how to pass it though all of those bazel levels 🤔

kyessenov commented 1 month ago

I think you are right, the trace nghttp2 logs seem to have disappeared on recent builds.

pgeler commented 1 month ago

@kyessenov, I end up patching v1.31.2

diff --git a/bazel/foreign_cc/BUILD b/bazel/foreign_cc/BUILD
index bf859db838..bffcbe4eee 100644
--- a/bazel/foreign_cc/BUILD
+++ b/bazel/foreign_cc/BUILD
@@ -352,6 +352,7 @@ envoy_cmake(
 envoy_cmake(
     name = "nghttp2",
     cache_entries = {
+        "ENABLE_DEBUG": "on",
         "ENABLE_LIB_ONLY": "on",
         "BUILD_SHARED_LIBS": "off",
         "BUILD_STATIC_LIBS": "on",

connection 77: I added few seconds before and after for nghttp2 as have no idea how to filter it:

trace log: https://github.com/pgeler/test/blob/main/grpc_connection_trace.txt access log: https://github.com/pgeler/test/blob/main/grpc_connection_access.txt

pgeler commented 4 weeks ago

@kyessenov any thoughts? Building envoy:main with nghttp2 1.58.0 where most of the instabilities with http2 originally started, but what I can tell it has very similar behavior with bunch of DPE at larger concurrency, if I have time will try to disable TLS

pgeler commented 3 weeks ago

TLS didn't change anything

pgeler commented 1 week ago

just as an observation, if somebody actually looking at this, it's working pretty stable when listener configured when max_requests_per_connection less than a 1000