Closed polc closed 4 years ago
So one of those unwrap
s in your code is panicking because the method returned an error. Can you find which one? For simple test cases, I find it easy to replace unwrap
with expect("name of previous operation")
.
Here is the code replaced with expect
:
use h2::server;
use http::uri;
use http::{Method, Request, Response, StatusCode};
use hyper::body::Bytes;
use std::error::Error;
use tokio::net::{TcpListener, TcpStream};
#[tokio::main]
async fn main() -> () {
let mut listener = TcpListener::bind("127.0.0.1:8080").await.expect("10: listener");
loop {
if let Ok((socket, _peer_addr)) = listener.accept().await {
tokio::spawn(async move {
handle(socket).await;
});
}
}
}
async fn handle(socket: TcpStream) {
let mut connection = server::handshake(socket).await.expect("22: connection");
while let Some(result) = connection.accept().await {
println!("Accept connection");
let (req, mut stream) = result.expect("25: result");
let res = Response::builder().status(StatusCode::OK).body(()).expect("26: response");
let push_uri = uri::Uri::from_static("/push");
let push_req = Request::builder().uri(push_uri).body(()).expect("29: push_req");
let push_res = http::Response::builder().status(200).body(()).expect("30: push_res");
let mut push_send = stream
.push_request(push_req)
.expect("34: push_request")
.send_response(push_res, false)
.expect("36: send_response");
let mut send = stream.send_response(res, false).expect("37: send");
push_send.send_data(Bytes::from_static(b"Push data!"), true).expect("39: send_data");
send.send_data(Bytes::from_static(b"Hello World"), true).expect("40: send_data");
}
}
And the result :
Finished dev [unoptimized + debuginfo] target(s) in 1.89s
Running `target/debug/examples/books`
Accept connection
Accept connection
thread 'main' panicked at '25: result: Error { kind: Proto(PROTOCOL_ERROR) }', examples/books/main.rs:27:33
Notice how Accept connection
is printed twice, even if I only call curl --http2-prior-knowledge --trace-ascii - http://localhost:8080/
once.
What if you add -v
to curl, to see what it logs?
Here is with -v
argument :
➜ ~ curl -v --http2-prior-knowledge http://localhost:8080/
* Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
* 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 0x55cf468598b0)
> GET / HTTP/2
> Host: localhost:8080
> user-agent: curl/7.70.0
> accept: */*
>
* Connection state changed (MAX_CONCURRENT_STREAMS == 4294967295)!
* Connection #0 to host localhost left intact
curl: (16) Error in the HTTP2 framing layer
And here is with --trace-ascii
which is a little bit more verbose :
➜ ~ curl --http2-prior-knowledge --trace-ascii - http://localhost:8080/
Warning: --trace-ascii overrides an earlier trace/verbose option
== Info: Trying 127.0.0.1:8080...
== Info: Connected to localhost (127.0.0.1) port 8080 (#0)
== Info: Using HTTP2, server supports multi-use
== Info: Connection state changed (HTTP/2 confirmed)
== Info: Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
== Info: Using Stream ID: 1 (easy handle 0x563d7613b8b0)
=> Send header, 76 bytes (0x4c)
0000: GET / HTTP/2
000e: Host: localhost:8080
0024: user-agent: curl/7.70.0
003d: accept: */*
004a:
== Info: Connection state changed (MAX_CONCURRENT_STREAMS == 4294967295)!
== Info: Connection #0 to host localhost left intact
curl: (16) Error in the HTTP2 framing layer
Can you also include env_logger
into the Rust program and run with RUST_LOG=h2
?
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Settings { flags: (0x0) }
[2020-06-26T14:25:41Z TRACE h2::frame::settings] encoding SETTINGS; len=0
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] encoded settings; rem=9
[2020-06-26T14:25:41Z TRACE h2::server] Handshake::poll(); state=Handshaking::Flushing(_);
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-06-26T14:25:41Z TRACE h2::server] Handshake::poll(); flush.poll()=Pending
[2020-06-26T14:25:41Z TRACE h2::server] Handshake::poll(); state=Handshaking::Flushing(_);
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flushing buffer
[2020-06-26T14:25:41Z TRACE h2::server] Handshake::poll(); flush.poll()=Ready
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=65535; old=0; new=65535
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=65535; old=0; new=65535
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) }
[2020-06-26T14:25:41Z TRACE h2::server] Handshake::poll(); connection established!
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll; bytes=27B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] decoding frame from 27B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] -> kind=Settings
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_read] received; frame=Settings { flags: (0x0), enable_push: 0, max_concurrent_streams: 100, initial_window_size: 33554432 }
[2020-06-26T14:25:41Z TRACE h2::proto::connection] recv SETTINGS; frame=Settings { flags: (0x0), enable_push: 0, max_concurrent_streams: 100, initial_window_size: 33554432 }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Settings { flags: (0x1: ACK) }
[2020-06-26T14:25:41Z TRACE h2::frame::settings] encoding SETTINGS; len=0
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] encoded settings; rem=9
[2020-06-26T14:25:41Z TRACE h2::proto::settings] ACK sent; applying settings
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll; bytes=13B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] decoding frame from 13B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] -> kind=WindowUpdate
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_read] received; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 33488897 }
[2020-06-26T14:25:41Z TRACE h2::proto::connection] recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 33488897 }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=33488897; old=65535; new=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] assign_connection_capacity; inc=33488897
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll; bytes=39B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] decoding frame from 39B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] -> kind=Headers
[2020-06-26T14:25:41Z TRACE h2::frame::headers] loading headers; flags=(0x5: END_HEADERS | END_STREAM)
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] decode
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] Indexed; rem=30
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] Indexed; rem=29
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] Indexed; rem=28
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] LiteralWithIndexing; rem=27
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] LiteralWithIndexing; rem=15
[2020-06-26T14:25:41Z TRACE h2::hpack::decoder] LiteralWithIndexing; rem=5
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_read] received; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-06-26T14:25:41Z TRACE h2::proto::connection] recv HEADERS; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=65535; old=0; new=65535
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=33554432; old=0; new=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] recv_headers; stream=StreamId(1); state=State { inner: Idle }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::recv] opening stream; init_window=65535
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> first entry
[2020-06-26T14:25:41Z 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
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll; bytes=9B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] decoding frame from 9B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] -> kind=Settings
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_read] received; frame=Settings { flags: (0x1: ACK) }
[2020-06-26T14:25:41Z TRACE h2::proto::connection] recv SETTINGS; frame=Settings { flags: (0x1: ACK) }
[2020-06-26T14:25:41Z DEBUG h2::proto::settings] received settings ACK; applying Settings { flags: (0x0) }
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flushing buffer
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] next_incoming; id=StreamId(1), state=State { inner: HalfClosedRemote(AwaitingHeaders) }
[2020-06-26T14:25:41Z TRACE h2::server] received incoming
Accept connection
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=65535; old=0; new=65535
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] inc_window; sz=33554432; old=0; new=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::send] send_push_promise; frame=PushPromise { stream_id: StreamId(1), promised_id: StreamId(2), flags: (0x4: END_HEADERS) }; init_window=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(1)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> first entry
[2020-06-26T14:25:41Z TRACE h2::proto::streams::send] send_headers; frame=Headers { stream_id: StreamId(2), flags: (0x4: END_HEADERS) }; init_window=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: HalfClosedRemote(Streaming) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(2), state: State { inner: HalfClosedRemote(Streaming) }, 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: None, pending_send: Deque { indices: Some(Indices { head: 1, tail: 1 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: true, 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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: HalfClosedRemote(Streaming) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::send] send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(1)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> already queued
[2020-06-26T14:25:41Z 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
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] send_data; sz=10; buffered=10; requested=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(2), requested=10; additional=10; buffered=10; window=33554432; conn=33554432
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(2), capacity=10
[2020-06-26T14:25:41Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=10; buffered=10; id=StreamId(2)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=10; requested=10; buffered=10; has_unavailable=true
[2020-06-26T14:25:41Z TRACE h2::proto::streams::state] send_close: HalfClosedRemote => Closed
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(2); requested=0; effective=10; curr=10
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] send_data (2); available=10; buffered=10
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=10; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] send_data; sz=11; buffered=11; requested=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(1), requested=11; additional=11; buffered=11; window=33554432; conn=33554422
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(1), capacity=11
[2020-06-26T14:25:41Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=11; buffered=11; id=StreamId(1)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=11; requested=11; buffered=11; has_unavailable=true
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> already queued
[2020-06-26T14:25:41Z TRACE h2::proto::streams::state] send_close: HalfClosedRemote => Closed
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(1); requested=0; effective=11; curr=11
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] send_data (2); available=11; buffered=11
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(1)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> already queued
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 3, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(33554432), available: Window(11) }, requested_send_capacity: 11, buffered_send_data: 11, send_task: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 4 }) }, 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(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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(2), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(33554432), available: Window(10) }, requested_send_capacity: 10, buffered_send_data: 10, send_task: None, pending_send: Deque { indices: Some(Indices { head: 1, tail: 3 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: true, 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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=10; num_recv=1; num_send=0
[2020-06-26T14:25:41Z 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(33554432), available: Window(11) }, requested_send_capacity: 11, buffered_send_data: 11, send_task: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 4 }) }, 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(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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=0
[2020-06-26T14:25:41Z 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(33554432), available: Window(11) }, requested_send_capacity: 11, buffered_send_data: 11, send_task: None, pending_send: Deque { indices: Some(Indices { head: 0, tail: 4 }) }, 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(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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=0
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(1); stream.state=State { inner: Closed(EndStream) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(1); is_pending_reset=false;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> first entry
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; frame=PushPromise { stream_id: StreamId(1), promised_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> existing entries
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=1
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] writing frame=PushPromise { stream_id: StreamId(1), promised_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=PushPromise { stream_id: StreamId(1), promised_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(2); stream.state=State { inner: Closed(EndStream) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(2); is_pending_reset=false;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> existing entries
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=10; num_recv=1; num_send=1
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Headers { stream_id: StreamId(2), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(1); stream.state=State { inner: Closed(EndStream) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(1); is_pending_reset=false;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] Queue::push
[2020-06-26T14:25:41Z TRACE h2::proto::streams::store] -> existing entries
[2020-06-26T14:25:41Z 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=11; num_recv=1; num_send=1
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(2); stream.state=State { inner: Closed(EndStream) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(2); is_pending_reset=false;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> data frame; stream=StreamId(2); sz=10; eos=true; window=10; available=10; requested=10; buffered=10;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> sending data frame; len=10
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -- updating stream flow --
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] send_data; sz=10; window=33554432; available=10
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -- updating connection flow --
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] send_data; sz=10; window=33554432; available=33554421
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Data { stream_id: StreamId(2), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(2); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=1
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] dec_num_streams; stream=StreamId(2)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] writing frame=Data { stream_id: StreamId(2), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Data { stream_id: StreamId(2), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -> reclaimed; frame=Data { stream_id: StreamId(2), flags: (0x1: END_STREAM) }; sz=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(1); stream.state=State { inner: Closed(EndStream) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(1); is_pending_reset=false;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> data frame; stream=StreamId(1); sz=11; eos=true; window=11; available=11; requested=11; buffered=11;
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] --> sending data frame; len=11
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -- updating stream flow --
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] send_data; sz=11; window=33554432; available=11
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -- updating connection flow --
[2020-06-26T14:25:41Z TRACE h2::proto::streams::flow_control] send_data; sz=11; window=33554422; available=33554422
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z 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
[2020-06-26T14:25:41Z TRACE h2::proto::streams::counts] dec_num_streams; stream=StreamId(1)
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] writing frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_write] send; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] -> reclaimed; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }; sz=0
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flushing buffer
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flushing buffer
[2020-06-26T14:25:41Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll; bytes=44B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] decoding frame from 44B
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] -> kind=GoAway
[2020-06-26T14:25:41Z DEBUG h2::codec::framed_read] received; frame=GoAway { error_code: PROTOCOL_ERROR, last_stream_id: StreamId(0), debug_data: b"PUSH_PROMISE: push disabled" }
[2020-06-26T14:25:41Z TRACE h2::proto::connection] recv GOAWAY; frame=GoAway { error_code: PROTOCOL_ERROR, last_stream_id: StreamId(0), debug_data: b"PUSH_PROMISE: push disabled" }
[2020-06-26T14:25:41Z TRACE h2::codec::framed_read] poll
[2020-06-26T14:25:41Z TRACE h2::proto::connection] codec closed
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] Streams::recv_eof
[2020-06-26T14:25:41Z TRACE h2::proto::connection] connection closing after flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flush
[2020-06-26T14:25:41Z TRACE h2::codec::framed_write] flushing buffer
Accept connection
thread 'main' panicked at '25: result: Error { kind: Proto(PROTOCOL_ERROR) }', examples/books/main.rs:28:33
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[2020-06-26T14:25:41Z TRACE h2::proto::streams::streams] Streams::recv_eof
These logs are the important ones. curl has disabled push, and then when the push is sent anyways, it sends a connection error.
recv SETTINGS; frame=Settings { flags: (0x0), enable_push: 0, max_concurrent_streams: 100, initial_window_size: 33554432 }
recv GOAWAY; frame=GoAway { error_code: PROTOCOL_ERROR, last_stream_id: StreamId(0), debug_data: b"PUSH_PROMISE: push disabled" }
oh that's my bad. Thanks a lot for the help !
I don't think this issue should be closed—the library is ignoring the remote peer's server push setting in contravention of the spec, which states in Section 6.6 PUSH_PROMISE:
PUSH_PROMISE MUST NOT be sent if the SETTINGS_ENABLE_PUSH setting of the peer endpoint is set to 0.
Indeed I've followed the src from proto::Settings::poll_send
and it appears that of the 6 settings defined in the spec, only 4 remote settings and 3 local settings are actually processed; the following are ignored:
Remote:
Local (library doesn't expose any method by which these can actually be updated after a connection has been established, so no contravention can occur here in practice—though perhaps an ability to update these settings is a feature users might wish to have):
Hi, thanks for the awesome library! I'm experimenting with
HTTP/2 Server Push
but without success, I get the following error :thread 'main' panicked at 'called 'Result::unwrap()' on an 'Err' value: Error { kind: Proto(PROTOCOL_ERROR) }',
First of all, to be noted that I'm using a fork with this PR merged : https://github.com/hyperium/h2/pull/425, to get around the
attempt to subtract with overflow
panic.Here is the source code of my test :
Here is how I'm calling the server :
curl --http2-prior-knowledge --trace-ascii - http://localhost:8080/
Here is the stack trace :