hyperium / hyper

An HTTP library for Rust
https://hyper.rs
MIT License
14.42k stars 1.59k forks source link

It cause error when I use http client to do the http2 request #3675

Closed lsk569937453 closed 4 months ago

lsk569937453 commented 4 months ago

Version List the version(s) of hyper, and any relevant hyper dependency (such as h2 if this is related to HTTP/2). hyper = { version = "1.3.1", features = ["full"] } hyper-util = { version = "0.1.4", features = ["full"] } [[package]] name = "h2" version = "0.4.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "816ec7294445779408f36fe57bc5b7fc1cf59664059096c65f905c1c61f58069" dependencies = [ "bytes", "fnv", "futures-core", "futures-sink", "futures-util", "http", "indexmap", "slab", "tokio", "tokio-util", "tracing", ]

Platform The output of uname -a (UNIX), or version and 32 or 64-bit (Windows) windows and linux

Description I use the client of hyper_util to do the request of http2,and it cause error.But it works well for curl to do the same request .

One way to structure the description:

[short summary of the bug]

> POST /api/token HTTP/1.1
> content-type: application/x-www-form-urlencoded
> accept: */*
> host: accounts.spotify.com
> user-agent: rcur/0.0.24
> Content-Length: 119
2024-05-27T02:26:55.230065Z TRACE Rcurl: rcurl::http::handler: Start request
2024-05-27T02:26:55.230200Z TRACE Rcurl: hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", accounts.spotify.com:443)
2024-05-27T02:26:55.230289Z TRACE Rcurl: hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("accounts.spotify.com"), port=Some(Port(443))
2024-05-27T02:26:55.230397Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="accounts.spotify.com"
2024-05-27T02:26:55.277795Z DEBUG Rcurl: hyper_util::client::legacy::connect::http: connecting to [2600:1901:1:c36::]:443
2024-05-27T02:26:55.364683Z DEBUG Rcurl: hyper_util::client::legacy::connect::http: connected to [2600:1901:1:c36::]:443
2024-05-27T02:26:55.445365Z TRACE Rcurl: hyper_util::client::legacy::client: ALPN negotiated h2, updating pool
2024-05-27T02:26:55.445851Z DEBUG Rcurl: h2::client: binding client connection
2024-05-27T02:26:55.446127Z DEBUG Rcurl: h2::client: client connection bound
2024-05-27T02:26:55.446486Z DEBUG Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }
2024-05-27T02:26:55.446755Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::frame::settings: encoding SETTINGS; len=24
2024-05-27T02:26:55.447034Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::frame::settings: encoding setting; val=EnablePush(0)
2024-05-27T02:26:55.447185Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::frame::settings: encoding setting; val=InitialWindowSize(2097152)
2024-05-27T02:26:55.447514Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::frame::settings: encoding setting; val=MaxFrameSize(16384)
2024-05-27T02:26:55.447753Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::frame::settings: encoding setting; val=MaxHeaderListSize(16384)
2024-05-27T02:26:55.447901Z TRACE Rcurl:FramedWrite::buffer{frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }}: h2::codec::framed_write: encoded settings rem=33
2024-05-27T02:26:55.448160Z TRACE Rcurl: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
2024-05-27T02:26:55.448492Z TRACE Rcurl: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
2024-05-27T02:26:55.448641Z TRACE Rcurl: h2::proto::streams::prioritize: Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }
2024-05-27T02:26:55.448888Z TRACE Rcurl: h2::proto::streams::recv: set_target_connection_window; target=5242880; available=65535, reserved=0
2024-05-27T02:26:55.449127Z TRACE Rcurl: hyper_util::client::legacy::client: http2 handshake complete, spawning background dispatcher task
2024-05-27T02:26:55.449231Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: connection.state=Open
2024-05-27T02:26:55.449340Z TRACE Rcurl: hyper_util::client::legacy::pool: put; add idle connection for ("https", accounts.spotify.com:443)
2024-05-27T02:26:55.449698Z DEBUG Rcurl: hyper_util::client::legacy::pool: pooling idle connection for ("https", accounts.spotify.com:443)
2024-05-27T02:26:55.449562Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.449840Z TRACE Rcurl: hyper_util::client::legacy::pool: checkout dropped for ("https", accounts.spotify.com:443)
2024-05-27T02:26:55.450040Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-05-27T02:26:55.450565Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }}: h2::frame::window_update: encoding WINDOW_UPDATE; id=StreamId(0)
2024-05-27T02:26:55.451105Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }}: h2::codec::framed_write: encoded window_update rem=46
2024-05-27T02:26:55.451359Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::flow_control: inc_window; sz=5177345; old=65535; new=5242880
2024-05-27T02:26:55.451586Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: poll_complete
2024-05-27T02:26:55.451838Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2024-05-27T02:26:55.452167Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
2024-05-27T02:26:55.452469Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
2024-05-27T02:26:55.452703Z TRACE h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
2024-05-27T02:26:55.452864Z TRACE h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
2024-05-27T02:26:55.453047Z TRACE h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=65535
2024-05-27T02:26:55.453211Z TRACE h2::proto::streams::store: Queue::push_back
2024-05-27T02:26:55.453310Z TRACE h2::proto::streams::store:  -> first entry
2024-05-27T02:26:55.453681Z TRACE reserve_capacity{stream.id=StreamId(1) requested=1 effective=1 curr=0}:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: requested=1 additional=1 buffered=0 window=65535 conn=65535
2024-05-27T02:26:55.454004Z TRACE reserve_capacity{stream.id=StreamId(1) requested=1 effective=1 curr=0}:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: assigning capacity=1
2024-05-27T02:26:55.454123Z TRACE reserve_capacity{stream.id=StreamId(1) requested=1 effective=1 curr=0}:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::stream:   assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576 prev=0
2024-05-27T02:26:55.454229Z TRACE reserve_capacity{stream.id=StreamId(1) requested=1 effective=1 curr=0}:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::stream:   notifying task
2024-05-27T02:26:55.454325Z TRACE reserve_capacity{stream.id=StreamId(1) requested=1 effective=1 curr=0}:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: available=1 requested=1 buffered=0 has_unavailable=true
2024-05-27T02:26:55.454458Z TRACE send_data{sz=119 requested=1}: h2::proto::streams::prioritize: buffered=119
2024-05-27T02:26:55.454535Z TRACE send_data{sz=119 requested=1}: h2::proto::streams::state: send_close: Open => HalfClosedLocal(AwaitingHeaders)
2024-05-27T02:26:55.454654Z TRACE send_data{sz=119 requested=1}: h2::proto::streams::prioritize: available=1 buffered=119
2024-05-27T02:26:55.454774Z 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=119; num_recv=0; num_send=0
2024-05-27T02:26:55.454859Z TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65535), available: Window(1) }, requested_send_capacity: 119, buffered_send_data: 119, send_task: Some(Waker { data: 0x1760fdd8300, vtable: 0x7ff6f9361440 }), 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: true, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(65535), available: Window(65535) }, 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 }, is_recv: true, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream::NextAccept> }, content_length: Omitted }
2024-05-27T02:26:55.455084Z 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=119; num_recv=0; num_send=0
2024-05-27T02:26:55.455176Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: connection.state=Open
2024-05-27T02:26:55.455285Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.455407Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: poll_complete
2024-05-27T02:26:55.455500Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2024-05-27T02:26:55.455596Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open; stream=StreamId(1)
2024-05-27T02:26:55.455771Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::store: Queue::push_front
2024-05-27T02:26:55.455888Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::store:  -> first entry
2024-05-27T02:26:55.455958Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: requested=119 additional=118 buffered=119 window=65535 conn=65534
2024-05-27T02:26:55.456053Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: assigning capacity=118
2024-05-27T02:26:55.456155Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::stream:   assigned capacity to stream; available=119; buffered=119; id=StreamId(1); max_buffer_size=1048576 prev=0
2024-05-27T02:26:55.456241Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::prioritize: available=119 requested=119 buffered=119 has_unavailable=true
2024-05-27T02:26:55.456375Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::store: Queue::push_back
2024-05-27T02:26:55.456496Z TRACE Rcurl:Connection{peer=Client}:poll:try_assign_capacity{stream.id=StreamId(1)}: h2::proto::streams::store:  -> already queued
2024-05-27T02:26:55.456580Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: is_pending_reset=false
2024-05-27T02:26:55.456683Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2024-05-27T02:26:55.456807Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::store: Queue::push_back
2024-05-27T02:26:55.456916Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::store:  -> first entry
2024-05-27T02:26:55.457015Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=119; num_recv=0; num_send=1
2024-05-27T02:26:55.457189Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: writing frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2024-05-27T02:26:55.457382Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedWrite::buffer{frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2024-05-27T02:26:55.457513Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2024-05-27T02:26:55.457612Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: is_pending_reset=false
2024-05-27T02:26:55.457697Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: data frame sz=119 eos=true window=119 available=119 requested=119 buffered=119
2024-05-27T02:26:55.457781Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: sending data frame len=119
2024-05-27T02:26:55.457848Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}:updating stream flow: h2::proto::streams::flow_control: send_data; sz=119; window=65535; available=119
2024-05-27T02:26:55.457916Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}:updating stream flow: h2::proto::streams::stream:   sent stream data; available=0; buffered=0; id=StreamId(1); max_buffer_size=1048576 prev=0
2024-05-27T02:26:55.457986Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}:updating connection flow: h2::proto::streams::flow_control: send_data; sz=119; window=65535; available=65535
2024-05-27T02:26:55.458055Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: h2::proto::streams::prioritize: pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2024-05-27T02:26:55.458121Z TRACE Rcurl:Connection{peer=Client}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }}: 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
2024-05-27T02:26:55.458193Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: writing frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2024-05-27T02:26:55.458250Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedWrite::buffer{frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2024-05-27T02:26:55.458324Z TRACE Rcurl:Connection{peer=Client}:poll:try_reclaim_frame: h2::proto::streams::prioritize: reclaimed frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } sz=0
2024-05-27T02:26:55.458388Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2024-05-27T02:26:55.458436Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
2024-05-27T02:26:55.458510Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
2024-05-27T02:26:55.560566Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: connection.state=Open
2024-05-27T02:26:55.561031Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.561516Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=27
2024-05-27T02:26:55.561782Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: decoding frame from 27B
2024-05-27T02:26:55.562152Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: frame.kind=Settings
2024-05-27T02:26:55.562507Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 1048576, max_header_list_size: 65536 }
2024-05-27T02:26:55.562811Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 1048576, max_header_list_size: 65536 }
2024-05-27T02:26:55.563036Z DEBUG Rcurl:Connection{peer=Client}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
2024-05-27T02:26:55.563314Z TRACE Rcurl:Connection{peer=Client}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::frame::settings: encoding SETTINGS; len=0
2024-05-27T02:26:55.563637Z TRACE Rcurl:Connection{peer=Client}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: encoded settings rem=9
2024-05-27T02:26:55.563906Z TRACE Rcurl:Connection{peer=Client}:poll:poll_ready: h2::proto::settings: ACK sent; applying settings
2024-05-27T02:26:55.564163Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.564381Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=13
2024-05-27T02:26:55.564593Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: decoding frame from 13B
2024-05-27T02:26:55.564820Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: frame.kind=WindowUpdate
2024-05-27T02:26:55.565055Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
2024-05-27T02:26:55.565277Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
2024-05-27T02:26:55.565507Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::flow_control: inc_window; sz=983041; old=65416; new=1048457
2024-05-27T02:26:55.565713Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.565908Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=9
2024-05-27T02:26:55.566107Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: decoding frame from 9B
2024-05-27T02:26:55.566365Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: frame.kind=Settings
2024-05-27T02:26:55.566677Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
2024-05-27T02:26:55.566908Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x1: ACK) }
2024-05-27T02:26:55.567113Z DEBUG Rcurl:Connection{peer=Client}:poll: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }
2024-05-27T02:26:55.567322Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::recv: update_initial_window_size; new=2097152; old=65535
2024-05-27T02:26:55.567510Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::recv: incrementing all windows; inc=2031617
2024-05-27T02:26:55.567689Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::flow_control: inc_window; sz=2031617; old=65535; new=2097152
2024-05-27T02:26:55.567873Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.568059Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=13
2024-05-27T02:26:55.568239Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: decoding frame from 13B
2024-05-27T02:26:55.568431Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: frame.kind=Reset
2024-05-27T02:26:55.568650Z DEBUG Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Reset { stream_id: StreamId(1), error_code: PROTOCOL_ERROR }
2024-05-27T02:26:55.568830Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::connection: recv RST_STREAM frame=Reset { stream_id: StreamId(1), error_code: PROTOCOL_ERROR }
2024-05-27T02:26:55.569007Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::state: recv_reset; frame=Reset { stream_id: StreamId(1), error_code: PROTOCOL_ERROR }; state=HalfClosedLocal(AwaitingHeaders); queued=false
2024-05-27T02:26:55.569299Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), PROTOCOL_ERROR, Remote))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
2024-05-27T02:26:55.569487Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::counts: dec_num_streams; stream=StreamId(1)
2024-05-27T02:26:55.569681Z TRACE Rcurl:Connection{peer=Client}:poll:FramedRead::poll_next: h2::codec::framed_read: poll
2024-05-27T02:26:55.569842Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: poll_complete
2024-05-27T02:26:55.569972Z TRACE Rcurl:Connection{peer=Client}:poll: h2::proto::streams::prioritize: schedule_pending_open
2024-05-27T02:26:55.570105Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false
2024-05-27T02:26:55.570352Z TRACE Rcurl:Connection{peer=Client}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer
2024-05-27T02:26:55.570497Z TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(Error(Reset(StreamId(1), PROTOCOL_ERROR, Remote))) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65416), 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 }, is_recv: true, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData<h2::proto::streams::stream::NextAccept> }, content_length: Omitted }
client error (SendRequest)
2024-05-27T02:26:55.570765Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), PROTOCOL_ERROR, Remote))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
2024-05-27T02:26:55.571133Z TRACE h2::proto::streams::streams: Streams::recv_eof

I tried this code: [code sample that causes the bug]

    let https = hyper_rustls::HttpsConnectorBuilder::new()
                .with_tls_config(tls_config)
                .https_only()
                .enable_all_versions()
                .build();
            let https_clientt: Client<_, Full<Bytes>> =
                Client::builder(TokioExecutor::new()).build(https);

I expected to see this happen: [explanation] The curl log is in the following:

* Uses proxy env variable ALL_PROXY == 'http://192.168.16.1:7890'
*   Trying 192.168.16.1:7890...
* TCP_NODELAY set
* Connected to 192.168.16.1 (192.168.16.1) port 7890 (#0)
* allocate connect buffer!
* Establish HTTP proxy tunnel to accounts.spotify.com:443
> CONNECT accounts.spotify.com:443 HTTP/1.1
> Host: accounts.spotify.com:443
> User-Agent: curl/7.68.0
> Proxy-Connection: Keep-Alive
>
< HTTP/1.1 200 Connection established
<
* Proxy replied 200 to CONNECT request
* CONNECT phase completed!
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* CONNECT phase completed!
* CONNECT phase completed!
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=SE; L=Stockholm; O=Spotify AB; CN=*.spotify.com
*  start date: Feb  5 00:00:00 2024 GMT
*  expire date: Feb  4 23:59:59 2025 GMT
*  subjectAltName: host "accounts.spotify.com" matched cert's "*.spotify.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert Global G2 TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55cf6d81a0e0)
> POST /api/token HTTP/2
> Host: accounts.spotify.com
> user-agent: curl/7.68.0
> accept: */*
> content-type: application/x-www-form-urlencoded
> content-length: 119
>
* We are completely uploaded and fine
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
< HTTP/2 200
< date: Mon, 27 May 2024 02:24:44 GMT
< content-type: application/json
< content-length: 174
< set-cookie: __Host-device_id=AQCtL4pJdwBfaIMVkB1eZEgsZn2CMUhku2N_owEul0yVAoHzmrKAolnwhWKJihOm-u9aFPpk-hGe8SW68nCqurfUHJc3YgSOiNc;Version=1;Path=/;Max-Age=2147483647;Secure;HttpOnly;SameSite=Lax
< set-cookie: sp_tr=false;Version=1;Domain=accounts.spotify.com;Path=/;Secure;SameSite=Lax
< sp-trace-id: 03d85bb14ad4748b
< x-envoy-upstream-service-time: 11
< server: envoy
< strict-transport-security: max-age=31536000
< x-content-type-options: nosniff
< vary: Accept-Encoding
< via: HTTP/2 edgeproxy, 1.1 google
< alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
<

Instead, this happened: [explanation]

lsk569937453 commented 4 months ago

The following is the log of curl without proxy.

*   Trying 35.186.224.25:443...
* TCP_NODELAY set
*   Trying 2600:1901:1:c36:::443...
* TCP_NODELAY set
* Immediate connect fail for 2600:1901:1:c36::: Network is unreachable
* Connected to accounts.spotify.com (35.186.224.25) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=SE; L=Stockholm; O=Spotify AB; CN=*.spotify.com
*  start date: Feb  5 00:00:00 2024 GMT
*  expire date: Feb  4 23:59:59 2025 GMT
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert Global G2 TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x5563e5a350e0)
> POST /api/token HTTP/2
> Host: accounts.spotify.com
> user-agent: curl/7.68.0
> accept: */*
> content-type: application/x-www-form-urlencoded
> content-length: 119
>
* We are completely uploaded and fine
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
< HTTP/2 200
< date: Mon, 27 May 2024 03:32:23 GMT
< content-type: application/json
< content-length: 174
< set-cookie: __Host-device_id=AQBR4lDgDz5T3oHzlZeJVWP5D-JrulsPC1UWyvASBWCjD_0Vvh9mcM1VTQuW-qZ68TM8vp6Ik27ylMBccSiy_FS4Gdhf0Rp8v0U;Version=1;Path=/;Max-Age=2147483647;Secure;HttpOnly;SameSite=Lax
< set-cookie: sp_tr=false;Version=1;Domain=accounts.spotify.com;Path=/;Secure;SameSite=Lax
< sp-trace-id: 62fb13682b6b3e1b
< x-envoy-upstream-service-time: 11
< server: envoy
< strict-transport-security: max-age=31536000
< x-content-type-options: nosniff
< vary: Accept-Encoding
< via: HTTP/2 edgeproxy, 1.1 google
< alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
<