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 HTTP2 racing / DownStreamProtocolError / codec_error:The_user_callback_function_failed #30882

Closed
pgeler opened this issue Nov 14, 2023 · 10 comments
Labels
area/http bug stale stalebot believes this issue/PR has not been touched recently

Comments

@pgeler
Copy link

pgeler commented Nov 14, 2023

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 Nov 14, 2023
@pgeler pgeler changed the title envoy-1.28 critical HTTP2 racing / DownStreamProtoroclError / codec_error:The_user_callback_function_failed envoy-1.28 critical HTTP2 racing / DownStreamProtocolError / codec_error:The_user_callback_function_failed Nov 14, 2023
@pgeler
Copy link
Author

pgeler commented Nov 14, 2023

affected branches are main and release/v1.28

the only close behavior change documented in releases notes which could affect the is the connections that prematurely reset streams, was turned off by setting, without any observable differences in the results:

layered_runtime:
  layers:
  - name: "static-runtime-0"
    static_layer: { "envoy.restart_features.send_goaway_for_premature_rst_streams": false }

@pgeler
Copy link
Author

pgeler commented Nov 15, 2023

by digging deeper the problem with particular behavior introduced in release/v1.27 somewhere after 1.27.2 and in release/v1.28 somewhere after 1.28.0.

@pgeler pgeler changed the title envoy-1.28 critical HTTP2 racing / DownStreamProtocolError / codec_error:The_user_callback_function_failed envoy HTTP2 racing / DownStreamProtocolError / codec_error:The_user_callback_function_failed Nov 15, 2023
@htuch htuch added area/http and removed triage Issue requires triage labels Nov 16, 2023
@htuch
Copy link
Member

htuch commented Nov 16, 2023

@yanavlasov thoughts?

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 Dec 16, 2023
Copy link

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted" or "no stalebot". Thank you for your contributions.

@pgeler
Copy link
Author

pgeler commented Mar 10, 2024

@htuch, is it possible to reopen? this issue came back as part of 1.29.2(envoy.reloadable_features.http2_use_oghttp2==false) while 1.29.1 or/and 1.29.2(envoy.reloadable_features.http2_use_oghttp2==true) is working fine

@htuch htuch reopened this Mar 11, 2024
@github-actions github-actions bot removed the stale stalebot believes this issue/PR has not been touched recently label Mar 11, 2024
@abscondment
Copy link

abscondment commented Mar 14, 2024

We're seeing this behavior with some clients, and like the reporter couldn't alter the behavior by setting envoy.restart_features.send_goaway_for_premature_rst_streams=false.

I see in the same envoy releases that we pulled in new versions of nghttp2, and they added similar RST_STREAM rate limit protection (https://github.com/nghttp2/nghttp2/pull/1961/files#diff-db6479b280b556cf648f72b490eda1aee2a2c38ccb34874e819022549701bd87) -- this is for CVE-2023-44487 just like #30055.

So, my naive questions - totally realize I could be barking up the wrong tree:

Does envoy now have two different RST_STREAM rate limiting behaviors?

Do we have any options for configuring nghttp2 from envoy, e.g. specifically the new nghttp2_option_set_stream_reset_rate_limit option that controls this feature?


Edit: just now processing what @pgeler said above...

1.29.2(envoy.reloadable_features.http2_use_oghttp2==false) while 1.29.1 or/and
1.29.2(envoy.reloadable_features.http2_use_oghttp2==true) is working fine

So if envoy.reloadable_features.http2_use_oghttp2==true succeeds and gets us off of nghttp2, this corroborates my theory.

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 Apr 14, 2024
Copy link

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted" or "no stalebot". Thank you for your contributions.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Apr 21, 2024
@pgeler
Copy link
Author

pgeler commented Sep 21, 2024

@htuch since oghttp2 implementation still having problems and envoy switching back to default nghttp2 as of 1.31.2 due to stability concerns, is it possible to re-open this issue as default nghttp2 implementation continue to have this unaddressed behavior?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/http bug stale stalebot believes this issue/PR has not been touched recently
Projects
None yet
Development

No branches or pull requests

3 participants