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.

Sign up for GitHub

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

Jump to bottom

Receiving FRAME_SIZE_ERROR in complex setup #644

Open
dmeijboom opened this issue Oct 26, 2022 · 1 comment
Open

Receiving FRAME_SIZE_ERROR in complex setup #644

dmeijboom opened this issue Oct 26, 2022 · 1 comment

Comments

@dmeijboom
Copy link

dmeijboom commented Oct 26, 2022 •
edited
Loading

I'm building an alternative implementation of a (mostly) decentralised networking protocol. This protocol consists of the following services:

  • Client (any HTTP client, could be curl or an application in any programming language)
  • Outway (plain HTTP server, acts as a reverse proxy to the Inway)
  • Inway (mTls HTTPS server, acts as a reverse proxy to a service)
  • Service (any HTTP/HTTPS endpoint)

The traffic flow is like this (going both ways):

flowchart LR
  Client --plain HTTP 1.1--> Outway --HTTP 2 mTLS--> Inway --> Service
Loading

Both the Outway/Inway use warp for the server implementation and reqwest for the client in the reverse proxy. The configuration of reqwest is as follows:

Outway

        ClientBuilder::new()
            .use_rustls_tls()
            .build()?;

Inway

        ClientBuilder::new()
            .use_rustls_tls()
            .tls_built_in_root_certs(false)
            .add_root_certificate(ca_cert)
            .identity(identity)
            .https_only(true)
            .build()?;

I tried to verify this is not an issue with my reverse proxy implementation (which is very basic). To check this I used curl (with TLS client authentication) directly with the Inway. This works fine. So the following flow seems to work:

flowchart LR
  Client --HTTP2 mTLS--> Inway --> Service
Loading

So it seems that this is an issue between the Outway and the Inway, although I'm not 100% sure.

The error I'm getting is BrokenPipe in hyper. This doesn't seem to happen when I either force http1 in the reqwest::ClientBuilder of the Outway or remove the request body stream. Not sure if it's relevant but this is how I stream the request body in the reverse proxy:

let stream = self
            .body
            .map(|buf| buf.map(|mut buf| buf.copy_to_bytes(buf.remaining())));

Trace logs (in the Inway with https://httpbin.org/anything as the service endpoint):

 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
 DEBUG h2::codec::framed_write          > send frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
 TRACE h2::frame::settings              > encoding SETTINGS; len=18
 TRACE h2::frame::settings              > encoding setting; val=InitialWindowSize(1048576)
 TRACE h2::frame::settings              > encoding setting; val=MaxFrameSize(16384)
 TRACE h2::frame::settings              > encoding setting; val=MaxHeaderListSize(16777216)
 TRACE h2::codec::framed_write          > encoded settings rem=27
 TRACE h2::server                       > state=Flushing(_)
 TRACE h2::codec::framed_write          > queued_data_frame=false
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::server                       > flush.poll=Ready
 TRACE h2::proto::streams::flow_control > inc_window; sz=65535; old=0; new=65535
 TRACE h2::proto::streams::flow_control > inc_window; sz=65535; old=0; new=65535
 TRACE h2::proto::streams::prioritize   > Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }
 DEBUG h2::proto::connection            > Connection; peer=Server
 TRACE h2::server                       > connection established!
 TRACE h2::proto::streams::recv         > set_target_connection_window; target=1048576; available=65535, reserved=0
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
 DEBUG h2::codec::framed_write          > send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
 TRACE h2::frame::window_update         > encoding WINDOW_UPDATE; id=StreamId(0)
 TRACE h2::codec::framed_write          > encoded window_update rem=13
 TRACE h2::proto::streams::flow_control > inc_window; sz=983041; old=65535; new=1048576
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > queued_data_frame=false
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=27
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=27
 TRACE h2::codec::framed_read           > decoding frame from 27B
 TRACE h2::codec::framed_read           > frame.kind=Settings
 DEBUG h2::codec::framed_read           > received frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
 TRACE h2::proto::connection            > recv SETTINGS frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Settings { flags: (0x1: ACK) }
 DEBUG h2::codec::framed_write          > send frame=Settings { flags: (0x1: ACK) }
 TRACE h2::frame::settings              > encoding SETTINGS; len=0
 TRACE h2::codec::framed_write          > encoded settings rem=9
 TRACE h2::proto::settings              > ACK sent; applying settings
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=13
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=13
 TRACE h2::codec::framed_read           > decoding frame from 13B
 TRACE h2::codec::framed_read           > frame.kind=WindowUpdate
 DEBUG h2::codec::framed_read           > received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
 TRACE h2::proto::connection            > recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
 TRACE h2::proto::streams::flow_control > inc_window; sz=5177345; old=65535; new=5242880
 TRACE h2::proto::streams::prioritize   > assign_connection_capacity; inc=5177345
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=63
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=63
 TRACE h2::codec::framed_read           > decoding frame from 63B
 TRACE h2::codec::framed_read           > frame.kind=Headers
 TRACE h2::frame::headers               > loading headers; flags=(0x4: END_HEADERS)
 TRACE h2::hpack::decoder               > decode
 TRACE h2::hpack::decoder               > rem=54 kind=Indexed
 TRACE h2::hpack::decoder               > rem=53 kind=Indexed
 TRACE h2::hpack::decoder               > rem=52 kind=LiteralWithIndexing
 TRACE h2::hpack::decoder               > rem=37 kind=LiteralWithoutIndexing
 TRACE h2::hpack::decoder               > rem=30 kind=LiteralWithIndexing
 TRACE h2::hpack::decoder               > rem=25 kind=LiteralWithIndexing
 TRACE h2::hpack::decoder               > rem=15 kind=LiteralWithIndexing
 DEBUG h2::codec::framed_read           > received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::connection            > recv HEADERS frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::streams::flow_control > inc_window; sz=1048576; old=0; new=1048576
 TRACE h2::proto::streams::flow_control > inc_window; sz=2097152; old=0; new=2097152
 TRACE h2::proto::streams::streams      > recv_headers; stream=StreamId(1); state=State { inner: Idle }
 TRACE h2::proto::streams::recv         > opening stream; init_window=1048576
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Open { local: AwaitingHeaders, remote: Streaming } }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=9
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=9
 TRACE h2::codec::framed_read           > decoding frame from 9B
 TRACE h2::codec::framed_read           > frame.kind=Data
 DEBUG h2::codec::framed_read           > received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::proto::connection            > recv DATA frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::proto::streams::recv         > recv_data; size=0; connection=1048576; stream=1048576
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=1048576; available=1048576
 TRACE h2::proto::streams::state        > recv_close: Open => HalfClosedRemote(AwaitingHeaders)
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=1048576; available=1048576
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=9
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=9
 TRACE h2::codec::framed_read           > decoding frame from 9B
 TRACE h2::codec::framed_read           > frame.kind=Settings
 DEBUG h2::codec::framed_read           > received frame=Settings { flags: (0x1: ACK) }
 TRACE h2::proto::connection            > recv SETTINGS frame=Settings { flags: (0x1: ACK) }
 DEBUG h2::proto::settings              > received settings ACK; applying Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
 TRACE h2::proto::streams::recv         > update_initial_window_size; new=1048576; old=1048576
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > queued_data_frame=false
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::streams::streams      > next_incoming; id=StreamId(1), state=State { inner: HalfClosedRemote(AwaitingHeaders) }
 TRACE h2::server                       > received incoming
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > flushing buffer
 DEBUG h2::client                       > binding client connection
 DEBUG h2::client                       > client connection bound
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
 DEBUG h2::codec::framed_write          > send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
 TRACE h2::frame::settings              > encoding SETTINGS; len=18
 TRACE h2::frame::settings              > encoding setting; val=EnablePush(0)
 TRACE h2::frame::settings              > encoding setting; val=InitialWindowSize(2097152)
 TRACE h2::frame::settings              > encoding setting; val=MaxFrameSize(16384)
 TRACE h2::codec::framed_write          > encoded settings rem=27
 TRACE h2::proto::streams::flow_control > inc_window; sz=65535; old=0; new=65535
 TRACE h2::proto::streams::flow_control > inc_window; sz=65535; old=0; new=65535
 TRACE h2::proto::streams::prioritize   > Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }
 DEBUG h2::proto::connection            > Connection; peer=Client
 TRACE h2::proto::streams::recv         > set_target_connection_window; target=5242880; available=65535, reserved=0
 TRACE h2::proto::streams::flow_control > inc_window; sz=2097152; old=0; new=2097152
 TRACE h2::proto::streams::flow_control > inc_window; sz=65535; old=0; new=65535
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::proto::streams::send         > send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=65535
 TRACE h2::proto::streams::prioritize   > Prioritize::queue_frame; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > schedule_send stream.id=StreamId(1)
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=1 effective=1 curr=0
 TRACE h2::proto::streams::prioritize   > try_assign_capacity; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > requested=1 additional=1 buffered=0 window=65535 conn=65535
 TRACE h2::proto::streams::prioritize   > assigning capacity=1
 TRACE h2::proto::streams::stream       >   assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576
 TRACE h2::proto::streams::stream       >   notifying task
 TRACE h2::proto::streams::prioritize   > available=1 requested=1 buffered=0 has_unavailable=true
 TRACE h2::proto::streams::recv         > release_capacity; size=0
 TRACE h2::proto::streams::recv         > release_connection_capacity; size=0, connection in_flight_data=0
 TRACE h2::proto::streams::prioritize   > send_data; sz=0 requested=1
 TRACE h2::proto::streams::prioritize   > buffered=0
 TRACE h2::proto::streams::prioritize   > available=1 buffered=0
 TRACE h2::proto::streams::prioritize   > Prioritize::queue_frame; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > schedule_send stream.id=StreamId(1)
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> already queued
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Open { local: Streaming, remote: AwaitingHeaders } }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=1 effective=1 curr=1
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=0 effective=0 curr=1
 TRACE h2::proto::streams::prioritize   > assign_connection_capacity; inc=1
 TRACE h2::proto::streams::prioritize   > send_data; sz=0 requested=0
 TRACE h2::proto::streams::prioritize   > buffered=0
 TRACE h2::proto::streams::state        > send_close: Open => HalfClosedLocal(AwaitingHeaders)
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=0 effective=0 curr=0
 TRACE h2::proto::streams::prioritize   > available=0 buffered=0
 TRACE h2::proto::streams::prioritize   > Prioritize::queue_frame; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > schedule_send stream.id=StreamId(1)
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> already queued
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::streams      > drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x133508020, vtable: 0x102bf9240 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 2 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097152), available: Window(2097152) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::streams      > drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedRemote(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(2097152), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x134813000, vtable: 0x102bcc300 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048576), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=27
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=27
 TRACE h2::codec::framed_read           > decoding frame from 27B
 TRACE h2::codec::framed_read           > frame.kind=Settings
 DEBUG h2::codec::framed_read           > received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 }
 TRACE h2::proto::connection            > recv SETTINGS frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Settings { flags: (0x1: ACK) }
 DEBUG h2::codec::framed_write          > send frame=Settings { flags: (0x1: ACK) }
 TRACE h2::frame::settings              > encoding SETTINGS; len=0
 TRACE h2::codec::framed_write          > encoded settings rem=36
 TRACE h2::proto::settings              > ACK sent; applying settings
 TRACE h2::proto::streams::prioritize   > recv_stream_window_update; stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) } inc=1 flow=FlowControl { window_size: Window(65535), available: Window(0) }
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=13
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=13
 TRACE h2::codec::framed_read           > decoding frame from 13B
 TRACE h2::codec::framed_read           > frame.kind=WindowUpdate
 DEBUG h2::codec::framed_read           > received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 }
 TRACE h2::proto::connection            > recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 }
 TRACE h2::proto::streams::flow_control > inc_window; sz=2147418112; old=65535; new=2147483647
 TRACE h2::proto::streams::prioritize   > assign_connection_capacity; inc=2147418112
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
 DEBUG h2::codec::framed_write          > send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
 TRACE h2::frame::window_update         > encoding WINDOW_UPDATE; id=StreamId(0)
 TRACE h2::codec::framed_write          > encoded window_update rem=49
 TRACE h2::proto::streams::flow_control > inc_window; sz=5177345; old=65535; new=5242880
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::proto::streams::prioritize   > popped; stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
 TRACE h2::proto::streams::prioritize   > is_pending_reset=false
 TRACE h2::proto::streams::prioritize   > pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::prioritize   > writing frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 DEBUG h2::codec::framed_write          > send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::proto::streams::prioritize   > popped; stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
 TRACE h2::proto::streams::prioritize   > is_pending_reset=false
 TRACE h2::proto::streams::prioritize   > data frame sz=0 eos=false window=0 available=0 requested=0 buffered=0
 TRACE h2::proto::streams::prioritize   > sending data frame len=0
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=65535; available=0
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=2147483647; available=2147483647
 TRACE h2::proto::streams::prioritize   > pop_frame; frame=Data { stream_id: StreamId(1) }
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::prioritize   > writing frame=Data { stream_id: StreamId(1) }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Data { stream_id: StreamId(1) }
 DEBUG h2::codec::framed_write          > send frame=Data { stream_id: StreamId(1) }
 TRACE h2::proto::streams::prioritize   > reclaimed frame=Data { stream_id: StreamId(1) } sz=0
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::proto::streams::prioritize   > popped; stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
 TRACE h2::proto::streams::prioritize   > is_pending_reset=false
 TRACE h2::proto::streams::prioritize   > data frame sz=0 eos=true window=0 available=0 requested=0 buffered=0
 TRACE h2::proto::streams::prioritize   > sending data frame len=0
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=65535; available=0
 TRACE h2::proto::streams::flow_control > send_data; sz=0; window=2147483647; available=2147483647
 TRACE h2::proto::streams::prioritize   > pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::prioritize   > writing frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 DEBUG h2::codec::framed_write          > send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::proto::streams::prioritize   > reclaimed frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } sz=0
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > queued_data_frame=false
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=9
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=9
 TRACE h2::codec::framed_read           > decoding frame from 9B
 TRACE h2::codec::framed_read           > frame.kind=Settings
 DEBUG h2::codec::framed_read           > received frame=Settings { flags: (0x1: ACK) }
 TRACE h2::proto::connection            > recv SETTINGS frame=Settings { flags: (0x1: ACK) }
 DEBUG h2::proto::settings              > received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
 TRACE h2::proto::streams::recv         > update_initial_window_size; new=2097152; old=2097152
 TRACE h2::codec::framed_read           > poll
 TRACE h2::codec::framed_read           > read.bytes=17
 TRACE h2::codec::framed_read           > FramedRead::decode_frame; offset=17
 TRACE h2::codec::framed_read           > decoding frame from 17B
 TRACE h2::codec::framed_read           > frame.kind=GoAway
 DEBUG h2::codec::framed_read           > received frame=GoAway { error_code: FRAME_SIZE_ERROR, last_stream_id: StreamId(1) }
 TRACE h2::proto::connection            > recv GOAWAY frame=GoAway { error_code: FRAME_SIZE_ERROR, last_stream_id: StreamId(1) }
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::connection            > codec closed
 TRACE h2::proto::streams::streams      > Streams::recv_eof
 TRACE h2::proto::streams::state        > recv_eof; state=HalfClosedLocal(AwaitingHeaders)
 TRACE h2::proto::streams::prioritize   > clear_queue; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > assign_connection_capacity; inc=0
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Io(BrokenPipe, None))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
 TRACE h2::proto::streams::counts       > dec_num_streams; stream=StreamId(1)
 TRACE h2::proto::connection            > connection.state=Closing(NO_ERROR, Library)
 TRACE h2::proto::connection            > connection closing after flush
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::connection            > connection.state=Closed(NO_ERROR, Library)
 TRACE h2::proto::streams::streams      > Streams::recv_eof
 TRACE h2::proto::streams::streams      > drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(Error(Io(BrokenPipe, None))) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097152), available: Window(2097152) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Io(BrokenPipe, None))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
 TRACE h2::proto::streams::send         > send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=2097152
 TRACE h2::proto::streams::prioritize   > Prioritize::queue_frame; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > schedule_send stream.id=StreamId(1)
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: HalfClosedRemote(Streaming) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=1 effective=1 curr=0
 TRACE h2::proto::streams::prioritize   > try_assign_capacity; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > requested=1 additional=1 buffered=0 window=2097152 conn=5242880
 TRACE h2::proto::streams::prioritize   > assigning capacity=1
 TRACE h2::proto::streams::stream       >   assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=409600
 TRACE h2::proto::streams::stream       >   notifying task
 TRACE h2::proto::streams::prioritize   > available=1 requested=1 buffered=0 has_unavailable=true
 TRACE h2::proto::streams::prioritize   > send_data; sz=291 requested=1
 TRACE h2::proto::streams::prioritize   > buffered=291
 TRACE h2::proto::streams::prioritize   > try_assign_capacity; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > requested=291 additional=290 buffered=291 window=2097152 conn=5242879
 TRACE h2::proto::streams::prioritize   > assigning capacity=290
 TRACE h2::proto::streams::stream       >   assigned capacity to stream; available=291; buffered=291; id=StreamId(1); max_buffer_size=409600
 TRACE h2::proto::streams::prioritize   > available=291 requested=291 buffered=291 has_unavailable=true
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> already queued
 TRACE h2::proto::streams::state        > send_close: HalfClosedRemote => Closed
 TRACE h2::proto::streams::prioritize   > reserve_capacity; stream.id=StreamId(1) requested=0 effective=291 curr=291
 TRACE h2::proto::streams::prioritize   > available=291 buffered=291
 TRACE h2::proto::streams::prioritize   > Prioritize::queue_frame; stream.id=StreamId(1)
 TRACE h2::proto::streams::prioritize   > schedule_send stream.id=StreamId(1)
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> already queued
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=291; num_recv=1; num_send=0
 TRACE h2::proto::streams::streams      > drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(2097152), available: Window(291) }, requested_send_capacity: 291, buffered_send_data: 291, send_task: Some(Waker { data: 0x134813000, vtable: 0x102bcc300 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 1 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048576), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=291; num_recv=1; num_send=0
 TRACE h2::proto::streams::streams      > drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 1, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(2097152), available: Window(291) }, requested_send_capacity: 291, buffered_send_data: 291, send_task: Some(Waker { data: 0x134813000, vtable: 0x102bcc300 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 1 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048576), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=291; num_recv=1; num_send=0
 TRACE h2::proto::connection            > connection.state=Open
 TRACE h2::codec::framed_read           > poll
 TRACE h2::proto::streams::prioritize   > poll_complete
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::proto::streams::prioritize   > popped; stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }
 TRACE h2::proto::streams::prioritize   > is_pending_reset=false
 TRACE h2::proto::streams::prioritize   > pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::streams::store        > Queue::push
 TRACE h2::proto::streams::store        >  -> first entry
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=291; num_recv=1; num_send=0
 TRACE h2::proto::streams::prioritize   > writing frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 DEBUG h2::codec::framed_write          > send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::proto::streams::prioritize   > popped; stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }
 TRACE h2::proto::streams::prioritize   > is_pending_reset=false
 TRACE h2::proto::streams::prioritize   > data frame sz=291 eos=true window=291 available=291 requested=291 buffered=291
 TRACE h2::proto::streams::prioritize   > sending data frame len=291
 TRACE h2::proto::streams::flow_control > send_data; sz=291; window=2097152; available=291
 TRACE h2::proto::streams::flow_control > send_data; sz=291; window=5242880; available=5242880
 TRACE h2::proto::streams::prioritize   > pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::proto::streams::counts       > transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
 TRACE h2::proto::streams::counts       > dec_num_streams; stream=StreamId(1)
 TRACE h2::proto::streams::prioritize   > writing frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::codec::framed_write          > FramedWrite::buffer; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 DEBUG h2::codec::framed_write          > send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
 TRACE h2::codec::framed_write          > queued_data_frame=true
 TRACE h2::codec::framed_write          > queued_data_frame=true
 TRACE h2::codec::framed_write          > flushing buffer
 TRACE h2::proto::streams::prioritize   > reclaimed frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } sz=0
 TRACE h2::proto::streams::prioritize   > schedule_pending_open
 TRACE h2::codec::framed_write          > flushing buffer
@dmeijboom dmeijboom changed the title Receiving FRAME_SIZE_ERROR for some servers Receiving FRAME_SIZE_ERROR in complex setup Oct 26, 2022
@dmeijboom
Copy link
Author

dmeijboom commented Oct 26, 2022 •
edited
Loading

I'm not sure but could hyperium/hyper#2855 be related? The reverse proxy uses Body::wrap_stream for input data.

Snippet:

let stream = self
            .body
            .map(|buf| buf.map(|mut buf| buf.copy_to_bytes(buf.remaining())));

request.body_mut().replace(Body::wrap_stream(stream));

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@dmeijboom