search

hyperium / h2

HTTP 2.0 client & server implementation for Rust.
MIT License
1.34k stars 269 forks source link

FlowControl problem when the initial_stream_window_size is smller than 65535 #630

Closed Chengwch closed 6 months ago

Chengwch commented 2 years ago

If I start an HTTP2 service as follows, the local_init_window_sz will be set to 32767 when a new connection is established. Before client receive the server initial settings frame of connection preface, it sends the data frame using the default window size 65535. In this case, the data received by the service may exceed the tream window size.

let server_fut = Builder::new().initial_window_size(32767);

Here set the initial value to custom window size when connection established in src/proto/connections.rs

pub fn new(codec: Codec<T, Prioritized<B>>, config: Config) -> Connection<T, P, B> {
        fn streams_config(config: &Config) -> streams::Config {
            streams::Config {
                local_init_window_sz: config
                    .settings
                    .initial_window_size()
                    .unwrap_or(DEFAULT_INITIAL_WINDOW_SIZE),
                initial_max_send_streams: config.initial_max_send_streams,
                local_max_buffer_size: config.max_send_buffer_size,
                local_next_stream_id: config.next_stream_id,
                local_push_enabled: config.settings.is_push_enabled().unwrap_or(true),
                extended_connect_protocol_enabled: config
                    .settings
                    .is_extended_connect_protocol_enabled()
                    .unwrap_or(false),
                local_reset_duration: config.reset_stream_duration,
                local_reset_max: config.reset_stream_max,
                remote_init_window_sz: DEFAULT_INITIAL_WINDOW_SIZE,
                remote_max_initiated: config
                    .settings
                    .max_concurrent_streams()
                    .map(|max| max as usize),
            }
        }
        let streams = Streams::new(streams_config(&config));
        Connection {
            codec,
            inner: ConnectionInner {
                state: State::Open,
                error: None,
                go_away: GoAway::new(),
                ping_pong: PingPong::new(),
                settings: Settings::new(config.settings),
                streams,
                span: tracing::debug_span!("Connection", peer = %P::NAME),
                _phantom: PhantomData,
            },
        }
    }

The default value should probably be used when the connection is established and updated to the custom value after the ACK settings frame is received. Another way is to limit the custom size to no less than 65535.

logs as follow

Jul 30 17:07:25.457 TRACE hyper::server::conn: Trying to upgrade connection to h2
Jul 30 17:07:25.457 DEBUG server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::codec::framed_write: send frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::frame::settings: encoding SETTINGS; len=24
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::frame::settings: encoding setting; val=MaxConcurrentStreams(128)
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::frame::settings: encoding setting; val=InitialWindowSize(32767)
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::frame::settings: encoding setting; val=MaxFrameSize(16384)
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::frame::settings: encoding setting; val=MaxHeaderListSize(32768)
Jul 30 17:07:25.457 TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }}: h2::codec::framed_write: encoded settings rem=33
Jul 30 17:07:25.457 TRACE server_handshake: h2::server: state=Flushing(_)
Jul 30 17:07:25.457 TRACE server_handshake:flush:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
Jul 30 17:07:25.458 TRACE server_handshake:flush:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.458 TRACE server_handshake: h2::server: flush.poll=Ready
Jul 30 17:07:25.458 TRACE server_handshake: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
Jul 30 17:07:25.458 TRACE server_handshake: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
Jul 30 17:07:25.458 TRACE server_handshake: h2::proto::streams::prioritize: Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }
Jul 30 17:07:25.458 TRACE server_handshake: h2::server: connection established!
Jul 30 17:07:25.458 TRACE server_handshake: h2::proto::streams::recv: set_target_connection_window; target=409600; available=65535, reserved=0
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=27
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: decoding frame from 27B
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: frame.kind=Settings
Jul 30 17:07:25.458 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x0), enable_push: 0, max_concurrent_streams: 100, initial_window_size: 33554432 }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x0), enable_push: 0, max_concurrent_streams: 100, initial_window_size: 33554432 }
Jul 30 17:07:25.458 DEBUG server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::frame::settings: encoding SETTINGS; len=0
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: encoded settings rem=9
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:poll_ready: h2::proto::settings: ACK sent; applying settings
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=13
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: decoding frame from 13B
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: frame.kind=WindowUpdate
Jul 30 17:07:25.458 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 33488897 }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 33488897 }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=33488897; old=65535; new=33554432
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=69
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}: h2::codec::framed_read: decoding frame from 69B
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}: h2::codec::framed_read: frame.kind=Headers
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}: h2::frame::headers: loading headers; flags=(0x4: END_HEADERS)
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: decode
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=60 kind=Indexed
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=59 kind=LiteralWithoutIndexing
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=40 kind=Indexed
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=39 kind=LiteralWithIndexing
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=22 kind=LiteralWithIndexing
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=12 kind=LiteralWithIndexing
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=69}:hpack::decode: h2::hpack::decoder: rem=7 kind=LiteralWithoutIndexing
Jul 30 17:07:25.458 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv HEADERS frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=32767; old=0; new=32767
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=33554432; old=0; new=33554432
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::streams: recv_headers; stream=StreamId(1); state=State { inner: Idle }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: opening stream; init_window=32767
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::store: Queue::push
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::store:  -> first entry
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: 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
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.458 DEBUG server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 344065 }}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 344065 }
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 344065 }}: h2::frame::window_update: encoding WINDOW_UPDATE; id=StreamId(0)
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 344065 }}: h2::codec::framed_write: encoded window_update rem=22
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=344065; old=65535; new=409600
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.458 TRACE h2::proto::streams::streams: next_incoming; id=StreamId(1), state=State { inner: Open { local: AwaitingHeaders, remote: Streaming } }
Jul 30 17:07:25.458 TRACE h2::server: received incoming
Jul 30 17:07:25.458 TRACE hyper::proto::h2::server: incoming request
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.458 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.458 TRACE hyper::client::pool: checkout waiting for idle connection: ("https", 10.244.165.239:32018)
Jul 30 17:07:25.459 TRACE hyper::client::conn: client handshake Http1
Jul 30 17:07:25.460 TRACE hyper::client::client: handshake complete, spawning background dispatcher task
Jul 30 17:07:25.460 TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
Jul 30 17:07:25.460 TRACE hyper::client::pool: checkout dropped for ("https", 10.244.165.239:32018)
Jul 30 17:07:25.460 TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Unknown)
Jul 30 17:07:25.460 DEBUG hyper::proto::h1::io: flushed 555 bytes
Jul 30 17:07:25.460 TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Body(Encoder { kind: Length(100000), is_last: false }), keep_alive: Busy }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=16393
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: decoding frame from 16393B
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: frame.kind=Data
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=16384; connection=409600; stream=32767
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=16384; window=409600; available=409600
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=16384; window=32767; available=32767
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: 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
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=16393
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: decoding frame from 16393B
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: frame.kind=Data
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=16384; connection=393216; stream=16383
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=16384; window=393216; available=393216
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: release_connection_capacity; size=16384, connection in_flight_data=32768
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::send: send_reset(..., reason=FLOW_CONTROL_ERROR, initiator=Library, stream=StreamId(1), ..., is_reset=false; is_closed=false; pending_send.is_empty=true; state=State { inner: Open { local: AwaitingHeaders, remote: Streaming } } 
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::send: send_reset -- queueing; frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::prioritize: schedule_send stream.id=StreamId(1)
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::store: Queue::push
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::store:  -> first entry
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=16393
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: decoding frame from 16393B
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16393}: h2::codec::framed_read: frame.kind=Data
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=16384; connection=376832; stream=16383
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; frame ignored on locally reset StreamId(1) for some time
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=16384; window=376832; available=393216
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: release_connection_capacity; size=16384, connection in_flight_data=32768
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=16392
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16392}: h2::codec::framed_read: decoding frame from 16392B
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=16392}: h2::codec::framed_read: frame.kind=Data
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=16383; connection=360448; stream=16383
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; frame ignored on locally reset StreamId(1) for some time
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=16383; window=360448; available=393216
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: release_connection_capacity; size=16383, connection in_flight_data=32767
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: frame decoded from buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=9
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: decoding frame from 9B
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: frame.kind=Settings
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x1: ACK) }
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 32767, max_frame_size: 16384, max_header_list_size: 32768 }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: update_initial_window_size; new=32767; old=32767
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: tokio_util::codec::framed_impl: attempting to decode a frame
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }}: h2::proto::streams::prioritize: is_pending_reset=false
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }}: h2::proto::streams::prioritize: pop_frame; frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }}: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }}: h2::proto::streams::counts: dec_num_streams; stream=StreamId(1)
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: writing frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }
Jul 30 17:07:25.468 DEBUG server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }}: h2::codec::framed_write: send frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }}: h2::frame::reset: encoding RESET; id=StreamId(1) code=FLOW_CONTROL_ERROR
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=Reset { stream_id: StreamId(1), error_code: FLOW_CONTROL_ERROR }}: h2::codec::framed_write: encoded reset rem=13
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.468 TRACE hyper::proto::h1::conn: Conn::read_head
Jul 30 17:07:25.468 TRACE h2::proto::streams::recv: release_capacity; size=16384
Jul 30 17:07:25.468 TRACE h2::proto::streams::recv: release_connection_capacity; size=16384, connection in_flight_data=16384
Jul 30 17:07:25.468 TRACE h2::proto::streams::store: Queue::push
Jul 30 17:07:25.468 TRACE h2::proto::streams::store:  -> first entry
Jul 30 17:07:25.468 TRACE hyper::proto::h1::encode: sized write, len = 16384
Jul 30 17:07:25.468 TRACE hyper::proto::h1::io: buffer.flatten self.len=0 buf.len=16384
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(33554432), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x7fb31e296400, vtable: 0x562ad05300d0 }), 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(16383), available: Window(32767) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: true, 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: Remaining(83616) }
Jul 30 17:07:25.468 TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
read body 16384 bytes
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: pending_window_updates -- pop; stream=StreamId(1)
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open
Jul 30 17:07:25.468 TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
Jul 30 17:07:25.469  WARN hyper::proto::h2: Connection header illegal in HTTP/2: connection
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: codec closed
Jul 30 17:07:25.469 TRACE h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }; init_window=33554432
Jul 30 17:07:25.469 TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
Jul 30 17:07:25.469 DEBUG hyper::proto::h2::server: send response error: user error: unexpected frame type
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::streams: Streams::recv_eof
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Closing(NO_ERROR, Library)
Jul 30 17:07:25.469 TRACE h2::proto::streams::send: send_reset(..., reason=INTERNAL_ERROR, initiator=User, stream=StreamId(1), ..., is_reset=true; is_closed=true; pending_send.is_empty=true; state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) } 
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection closing after flush
Jul 30 17:07:25.469 TRACE h2::proto::streams::send:  -> not sending RST_STREAM (StreamId(1) is already reset)
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
Jul 30 17:07:25.469 TRACE h2::proto::streams::recv: enqueue_reset_expiration; StreamId(1)
Jul 30 17:07:25.469 TRACE h2::proto::streams::store: Queue::push
Jul 30 17:07:25.469 TRACE h2::proto::streams::store:  -> first entry
Jul 30 17:07:25.469 TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), FLOW_CONTROL_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
Jul 30 17:07:25.469 DEBUG hyper::proto::h2::server: stream error: http2 error: user error: unexpected frame type
Jul 30 17:07:25.469 TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Closed(NO_ERROR, Library)