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
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
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