Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
pgeler opened this issue Sep 30, 2024 · 15 comments

Comments

@pgeler
Copy link

pgeler commented Sep 30, 2024

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
@pgeler pgeler added bug triage Issue requires triage labels Sep 30, 2024
@kyessenov
Copy link
Contributor

CC @alyssawilk @yanavlasov

@kyessenov kyessenov added area/http and removed triage Issue requires triage labels Sep 30, 2024
@kyessenov
Copy link
Contributor

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

@pgeler
Copy link
Author

pgeler commented Oct 3, 2024

@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
Copy link
Author

pgeler commented Oct 3, 2024

@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
Copy link
Contributor

kyessenov commented Oct 3, 2024

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

@pgeler
Copy link
Author

pgeler commented Oct 4, 2024

@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
Copy link
Author

pgeler commented Oct 11, 2024

@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
Copy link
Author

pgeler commented Oct 14, 2024

TLS didn't change anything

@pgeler
Copy link
Author

pgeler commented Oct 28, 2024

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

Copy link

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale stalebot believes this issue/PR has not been touched recently label Nov 27, 2024
@pgeler
Copy link
Author

pgeler commented Nov 27, 2024

@alyssawilk, @yanavlasov, any thoughts or suggestions where to look with this nghttp2 issue?

@github-actions github-actions bot removed the stale stalebot believes this issue/PR has not been touched recently label Nov 27, 2024
@zhouxiaobo1990
Copy link

To workaround with this, we forked envoy and triggered nghttp2_option_set_stream_reset_rate_limit in codec_impl.cc.

@pgeler
Copy link
Author

pgeler commented Dec 17, 2024

@alyssawilk any thought on disabling this nghttp2 rate limit? or make it configurable?

Copy link

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale stalebot believes this issue/PR has not been touched recently label Jan 17, 2025
@pgeler
Copy link
Author

pgeler commented Jan 21, 2025

I'll create a patch then...

@github-actions github-actions bot removed the stale stalebot believes this issue/PR has not been touched recently label Jan 22, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants