Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Wire in recv flow control #26

Merged
merged 3 commits into from
Aug 23, 2017
Merged

Wire in recv flow control #26

merged 3 commits into from
Aug 23, 2017

Conversation

carllerche
Copy link
Collaborator

No description provided.

Copy link
Collaborator

@olix0r olix0r left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this panics in my test application.

TRACE:h2::proto::streams::flow_control: assign capacity: window=65388 available=65388 capacity=147
thread 'main' panicked at 'assertion failed: self.window_size() >= self.available + capacity', /.../h2/src/proto/streams/flow_control.rs:53:8
stack backtrace:

   5:        0x1071de316 - h2::proto::streams::flow_control::FlowControl::assign_capacity::hb50875cf8dbffb8c

It looks like both window_size AND available are decremented when receiving a frame. When assign_capacity is called, the assertion fails because window_size == available

@olix0r
Copy link
Collaborator

olix0r commented Aug 23, 2017

:; cargo build && cargo build --example proxy && env RUST_LOG=h2::proto=trace RUST_BACKTRACE=full target/debug/examples/proxy
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
DEBUG:h2::proto::framed_write: send; frame=Frame::Settings(Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None })
TRACE:h2::proto::framed_write: encoded settings; rem=9
TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535
TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=65535
TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535
TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=65535
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=15B
TRACE:h2::proto::framed_read: decoding frame from 15B
TRACE:h2::proto::framed_read:     -> kind=Settings
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Settings(Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: Some(100), initial_window_size: None, max_frame_size: None, max_header_list_size: None }))
TRACE:h2::proto::connection: recv SETTINGS; frame=Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: Some(100), initial_window_size: None, max_frame_size: None, max_header_list_size: None }
DEBUG:h2::proto::framed_write: send; frame=Frame::Settings(Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None })
TRACE:h2::proto::framed_write: encoded settings; rem=18
TRACE:h2::proto::settings: ACK sent
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: poll_complete
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=9B
TRACE:h2::proto::framed_read: decoding frame from 9B
TRACE:h2::proto::framed_read:     -> kind=Settings
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Settings(Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None }))
TRACE:h2::proto::connection: recv SETTINGS; frame=Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None }
DEBUG:h2::proto::settings: received remote settings ack
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: poll_complete
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::prioritize: try reclaim frame
DEBUG:h2::proto::framed_write: send; frame=Frame::Settings(Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None })
TRACE:h2::proto::framed_write: encoded settings; rem=9
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535
TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=65535
TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535
TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=65535
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=21B
TRACE:h2::proto::framed_read: decoding frame from 21B
TRACE:h2::proto::framed_read:     -> kind=Settings
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Settings(Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: Some(100), initial_window_size: Some(65535), max_frame_size: None, max_header_list_size: None }))
TRACE:h2::proto::connection: recv SETTINGS; frame=Settings { flags: SettingsFlags(0), header_table_size: None, enable_push: None, max_concurrent_streams: Some(100), initial_window_size: Some(65535), max_frame_size: None, max_header_list_size: None }
DEBUG:h2::proto::framed_write: send; frame=Frame::Settings(Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None })
TRACE:h2::proto::framed_write: encoded settings; rem=9
TRACE:h2::proto::settings: ACK sent
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=14B
TRACE:h2::proto::framed_read: decoding frame from 14B
TRACE:h2::proto::framed_read:     -> kind=Priority
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Priority(Priority { stream_id: StreamId(3), dependency: StreamDependency { dependency_id: StreamId(0), weight: 200, is_exclusive: false } }))
TRACE:h2::proto::connection: recv PRIORITY; frame=Priority { stream_id: StreamId(3), dependency: StreamDependency { dependency_id: StreamId(0), weight: 200, is_exclusive: false } }
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=14B
TRACE:h2::proto::framed_read: decoding frame from 14B
TRACE:h2::proto::framed_read:     -> kind=Priority
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Priority(Priority { stream_id: StreamId(5), dependency: StreamDependency { dependency_id: StreamId(0), weight: 100, is_exclusive: false } }))
TRACE:h2::proto::connection: recv PRIORITY; frame=Priority { stream_id: StreamId(5), dependency: StreamDependency { dependency_id: StreamId(0), weight: 100, is_exclusive: false } }
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=14B
TRACE:h2::proto::framed_read: decoding frame from 14B
TRACE:h2::proto::framed_read:     -> kind=Priority
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Priority(Priority { stream_id: StreamId(7), dependency: StreamDependency { dependency_id: StreamId(0), weight: 0, is_exclusive: false } }))
TRACE:h2::proto::connection: recv PRIORITY; frame=Priority { stream_id: StreamId(7), dependency: StreamDependency { dependency_id: StreamId(0), weight: 0, is_exclusive: false } }
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=14B
TRACE:h2::proto::framed_read: decoding frame from 14B
TRACE:h2::proto::framed_read:     -> kind=Priority
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Priority(Priority { stream_id: StreamId(9), dependency: StreamDependency { dependency_id: StreamId(7), weight: 0, is_exclusive: false } }))
TRACE:h2::proto::connection: recv PRIORITY; frame=Priority { stream_id: StreamId(9), dependency: StreamDependency { dependency_id: StreamId(7), weight: 0, is_exclusive: false } }
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=14B
TRACE:h2::proto::framed_read: decoding frame from 14B
TRACE:h2::proto::framed_read:     -> kind=Priority
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Priority(Priority { stream_id: StreamId(11), dependency: StreamDependency { dependency_id: StreamId(3), weight: 0, is_exclusive: false } }))
TRACE:h2::proto::connection: recv PRIORITY; frame=Priority { stream_id: StreamId(11), dependency: StreamDependency { dependency_id: StreamId(3), weight: 0, is_exclusive: false } }
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=47B
TRACE:h2::proto::framed_read: decoding frame from 47B
TRACE:h2::proto::framed_read:     -> kind=Headers
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Headers(Headers { stream_id: StreamId(13), stream_dep: Some(StreamDependency { dependency_id: StreamId(11), weight: 15, is_exclusive: false }), fields: {"accept": HeaderValue { value: */*, is_sensitive: false }, "accept-encoding": HeaderValue { value: gzip, deflate, is_sensitive: false }, "user-agent": HeaderValue { value: nghttp2/1.23.1, is_sensitive: false }}, pseudo: Pseudo { method: Some(GET), scheme: Some("http"), authority: Some("localhost:7777"), path: Some("/"), status: None }, flags: HeadersFlag { end_stream: true, end_headers: true, padded: false, priority: true } }))
TRACE:h2::proto::connection: recv HEADERS; frame=Headers { stream_id: StreamId(13), stream_dep: Some(StreamDependency { dependency_id: StreamId(11), weight: 15, is_exclusive: false }), fields: {"accept": HeaderValue { value: */*, is_sensitive: false }, "accept-encoding": HeaderValue { value: gzip, deflate, is_sensitive: false }, "user-agent": HeaderValue { value: nghttp2/1.23.1, is_sensitive: false }}, pseudo: Pseudo { method: Some(GET), scheme: Some("http"), authority: Some("localhost:7777"), path: Some("/"), status: None }, flags: HeadersFlag { end_stream: true, end_headers: true, padded: false, priority: true } }
TRACE:h2::proto::streams::recv: opening stream; init_window=65535
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=9B
TRACE:h2::proto::framed_read: decoding frame from 9B
TRACE:h2::proto::framed_read:     -> kind=Settings
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Settings(Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None }))
TRACE:h2::proto::connection: recv SETTINGS; frame=Settings { flags: SettingsFlags(1), header_table_size: None, enable_push: None, max_concurrent_streams: None, initial_window_size: None, max_frame_size: None, max_header_list_size: None }
DEBUG:h2::proto::settings: received remote settings ack
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: poll_complete
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: poll_complete
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(1), stream_dep: None, fields: {"accept": HeaderValue { value: */*, is_sensitive: false }, "accept-encoding": HeaderValue { value: gzip, deflate, is_sensitive: false }, "user-agent": HeaderValue { value: nghttp2/1.23.1, is_sensitive: false }}, pseudo: Pseudo { method: Some(GET), scheme: Some("http"), authority: Some("localhost:7777"), path: Some("/"), status: None }, flags: HeadersFlag { end_stream: true, end_headers: true, padded: false, priority: false } }; init_window=65535
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: poll_complete
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::streams::prioritize: writing frame=Frame::Headers(Headers { stream_id: StreamId(1), stream_dep: None, fields: {"accept": HeaderValue { value: */*, is_sensitive: false }, "accept-encoding": HeaderValue { value: gzip, deflate, is_sensitive: false }, "user-agent": HeaderValue { value: nghttp2/1.23.1, is_sensitive: false }}, pseudo: Pseudo { method: Some(GET), scheme: Some("http"), authority: Some("localhost:7777"), path: Some("/"), status: None }, flags: HeadersFlag { end_stream: true, end_headers: true, padded: false, priority: false } })
DEBUG:h2::proto::framed_write: send; frame=Frame::Headers(Headers { stream_id: StreamId(1), stream_dep: None, fields: {"accept": HeaderValue { value: */*, is_sensitive: false }, "accept-encoding": HeaderValue { value: gzip, deflate, is_sensitive: false }, "user-agent": HeaderValue { value: nghttp2/1.23.1, is_sensitive: false }}, pseudo: Pseudo { method: Some(GET), scheme: Some("http"), authority: Some("localhost:7777"), path: Some("/"), status: None }, flags: HeadersFlag { end_stream: true, end_headers: true, padded: false, priority: false } })
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::framed_write: poll_complete
TRACE:h2::proto::framed_write: flushing buffer
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=78B
TRACE:h2::proto::framed_read: decoding frame from 78B
TRACE:h2::proto::framed_read:     -> kind=Headers
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Headers(Headers { stream_id: StreamId(1), stream_dep: None, fields: {"server": HeaderValue { value: nghttpd nghttp2/1.23.1, is_sensitive: false }, "date": HeaderValue { value: Wed, 23 Aug 2017 03:11:52 GMT, is_sensitive: false }, "content-type": HeaderValue { value: text/html; charset=UTF-8, is_sensitive: false }, "content-length": HeaderValue { value: 147, is_sensitive: false }}, pseudo: Pseudo { method: None, scheme: None, authority: None, path: None, status: Some(404) }, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } }))
TRACE:h2::proto::connection: recv HEADERS; frame=Headers { stream_id: StreamId(1), stream_dep: None, fields: {"server": HeaderValue { value: nghttpd nghttp2/1.23.1, is_sensitive: false }, "date": HeaderValue { value: Wed, 23 Aug 2017 03:11:52 GMT, is_sensitive: false }, "content-type": HeaderValue { value: text/html; charset=UTF-8, is_sensitive: false }, "content-length": HeaderValue { value: 147, is_sensitive: false }}, pseudo: Pseudo { method: None, scheme: None, authority: None, path: None, status: Some(404) }, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } }
TRACE:h2::proto::streams::recv: opening stream; init_window=65535
TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535
TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=65535
TRACE:h2::proto::connection: polling codec
TRACE:h2::proto::framed_read: poll
TRACE:h2::proto::framed_read: poll; bytes=156B
TRACE:h2::proto::framed_read: decoding frame from 156B
TRACE:h2::proto::framed_read:     -> kind=Data
DEBUG:h2::proto::connection: recv; frame=Some(Frame::Data(..))
TRACE:h2::proto::connection: recv DATA; frame=Data { stream_id: StreamId(1), data: b"<title>404\x20Not\x20Found</title>

404\x20Not\x20Found


nghttpd\x20nghttp2/1.23.1\x20at\x20port\x208888", flags: DataFlag(1), pad_len: None } TRACE:h2::proto::streams::recv: recv_data; size=147; connection=65535; stream=65535 TRACE:h2::proto::streams::flow_control: send_data; sz=147; window=65535; available=65535 TRACE:h2::proto::streams::flow_control: send_data; sz=147; window=65535; available=65535 TRACE:h2::proto::streams::state: recv_close: HalfClosedLocal => Closed TRACE:h2::proto::connection: polling codec TRACE:h2::proto::framed_read: poll TRACE:h2::proto::streams::prioritize: try reclaim frame TRACE:h2::proto::streams::prioritize: poll_complete TRACE:h2::proto::streams::prioritize: pop frame TRACE:h2::proto::framed_write: poll_complete TRACE:h2::proto::framed_write: flushing buffer TRACE:h2::proto::streams::prioritize: try reclaim frame TRACE:h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(13), stream_dep: None, fields: {"server": HeaderValue { value: nghttpd nghttp2/1.23.1, is_sensitive: false }, "date": HeaderValue { value: Wed, 23 Aug 2017 03:11:52 GMT, is_sensitive: false }, "content-type": HeaderValue { value: text/html; charset=UTF-8, is_sensitive: false }, "content-length": HeaderValue { value: 147, is_sensitive: false }}, pseudo: Pseudo { method: None, scheme: None, authority: None, path: None, status: Some(404) }, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } }; init_window=65535 TRACE:h2::proto::streams::flow_control: inc_window: window=0 available=0 sz=65535 TRACE:h2::proto::streams::prioritize: try_assign_capacity; requested=147; additional=147; conn=65535 TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=0 capacity=147 TRACE:h2::proto::streams::flow_control: claim capacity: window=65535 available=65535 capacity=147 TRACE:h2::proto::streams::state: send_close: HalfClosedRemote => Closed TRACE:h2::proto::connection: polling codec TRACE:h2::proto::framed_read: poll TRACE:h2::proto::streams::prioritize: try reclaim frame TRACE:h2::proto::streams::prioritize: poll_complete TRACE:h2::proto::streams::prioritize: pop frame TRACE:h2::proto::streams::prioritize: writing frame=Frame::Headers(Headers { stream_id: StreamId(13), stream_dep: None, fields: {"server": HeaderValue { value: nghttpd nghttp2/1.23.1, is_sensitive: false }, "date": HeaderValue { value: Wed, 23 Aug 2017 03:11:52 GMT, is_sensitive: false }, "content-type": HeaderValue { value: text/html; charset=UTF-8, is_sensitive: false }, "content-length": HeaderValue { value: 147, is_sensitive: false }}, pseudo: Pseudo { method: None, scheme: None, authority: None, path: None, status: Some(404) }, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } }) DEBUG:h2::proto::framed_write: send; frame=Frame::Headers(Headers { stream_id: StreamId(13), stream_dep: None, fields: {"server": HeaderValue { value: nghttpd nghttp2/1.23.1, is_sensitive: false }, "date": HeaderValue { value: Wed, 23 Aug 2017 03:11:52 GMT, is_sensitive: false }, "content-type": HeaderValue { value: text/html; charset=UTF-8, is_sensitive: false }, "content-length": HeaderValue { value: 147, is_sensitive: false }}, pseudo: Pseudo { method: None, scheme: None, authority: None, path: None, status: Some(404) }, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } }) TRACE:h2::proto::streams::prioritize: try reclaim frame TRACE:h2::proto::streams::prioritize: pop frame TRACE:h2::proto::streams::prioritize: --> data frame TRACE:h2::proto::streams::prioritize: -- updating stream flow -- TRACE:h2::proto::streams::flow_control: send_data; sz=147; window=65535; available=147 TRACE:h2::proto::streams::flow_control: assign capacity: window=65535 available=65388 capacity=147 TRACE:h2::proto::streams::prioritize: -- updating connection flow -- TRACE:h2::proto::streams::flow_control: send_data; sz=147; window=65535; available=65535 TRACE:h2::proto::streams::prioritize: writing frame=Frame::Data(..) DEBUG:h2::proto::framed_write: send; frame=Frame::Data(..) TRACE:h2::proto::streams::flow_control: assign capacity: window=65388 available=65388 capacity=147 thread 'main' panicked at 'assertion failed: self.window_size() >= self.available + capacity', /Users/ver/b/rs/h2/src/proto/streams/flow_control.rs:54:8 stack backtrace: 0: 0x10a4d8893 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::ha7e300af98739b0a 1: 0x10a4d9fca - std::panicking::default_hook::{{closure}}::hf87bad6075b566a9 2: 0x10a4d9c82 - std::panicking::default_hook::hf2545c692bf4b891 3: 0x10a4dc242 - std::panicking::rust_panic_with_hook::h89c2ff4bac8586ab 4: 0x10a4238e6 - std::panicking::begin_panic::h891808a8678a6255 5: 0x10a45c076 - h2::proto::streams::flow_control::FlowControl::assign_capacity::hb50875cf8dbffb8c 6: 0x10a1d164e - >::release_capacity::hddc382b5ba0b3edb 7: 0x10a20a673 - >::release_capacity::h74ab612428a0f754 8: 0x10a1aa807 - >::release_capacity::hd3b15277ae6e7495 9: 0x10a236063 - as tower_h2::recv_body::InnerRecvBody>::release::h90ea26a6d091c722 10: 0x10a3b3a36 - tower_h2::recv_body::RecvBody::release_capacity::h83b1d16c0709c78c 11: 0x10a258039 - ::advance::hca15ab6fdef28757 12: 0x10a237ce6 - as bytes::buf::buf::Buf>::advance::h4753a4f4c95a1c52 13: 0x10a235e4d - as bytes::buf::buf::Buf>::advance::h83938478c909381e 14: 0x10a24c4cc - as bytes::buf::buf::Buf>::advance::hb0346c90f3f823d5 15: 0x10a221f0f - <&'a mut T as bytes::buf::buf::Buf>::advance::hd1d1b06dc8c2491f 16: 0x10a21304a - bytes::buf::buf_mut::BufMut::put::h34cc85f0d13e0d2d 17: 0x10a1bacc3 - >::encode_chunk::h48e280e5a5fd19a0 18: 0x10a24e51f - as futures::sink::Sink>::start_send::h1764c00d2324ef65 19: 0x10a24361c - as futures::sink::Sink>::start_send::h5d523b33599da4b0 20: 0x10a2424ec - as futures::sink::Sink>::start_send::hb42bc31ec4da7535 21: 0x10a215aaf - >::poll_complete::h9a6732599840b050 22: 0x10a1d87a2 - >::poll_complete::h9abd11206757f605 23: 0x10a206619 - >::poll_complete::h81242e01bc3ec124 24: 0x10a22d309 - >::poll_complete::h0b32b9899cfa260e 25: 0x10a231a72 - >::poll2::hb95ce607dc6bf616 26: 0x10a22dde6 - >::poll::hbdb21106e14508ca 27: 0x10a1c4c83 - >::poll_close::h81fc8b99d076ff02 28: 0x10a2416e0 - as futures::stream::Stream>::poll::h3929160779d1f579 29: 0x10a1a7829 - as futures::future::Future>::poll::h3a8c7d75aa16c295 30: 0x10a24d54a - as futures::future::Future>::poll::hed4cb428c55d333a 31: 0x10a2240bb - >::poll::ha62d08cfd936843c 32: 0x10a1a5dc3 - as futures::future::Future>::poll::h858994181ccb6a42 33: 0x10a222c2b - >::poll::h4cfb19d46eb047e0 34: 0x10a1a5d63 - as futures::future::Future>::poll::h61193b43ce44f1c7 35: 0x10a3b39d6 - as futures::future::Future>::poll::h2588b44d1f3ccb30 36: 0x10a3b4033 - ::poll::hc5b42bad4f205ec1 37: 0x10a24cab9 - as futures::future::Future>::poll::h92f7aa38f5dcba72 38: 0x10a3df29f - as futures::future::Future>::poll::hc5141e1e8c84552e 39: 0x10a3c2b5c - >::poll_future_notify::{{closure}}::ha1b01d2581d38eab 40: 0x10a3c30af - >::enter::{{closure}}::h8e338b2fcab7f5d7 41: 0x10a3e08e8 - futures::task_impl::std::set::he82801d94729eb2c 42: 0x10a3c2e3e - >::enter::h6ce0f8bf3c8fa719 43: 0x10a3c2b24 - >::poll_future_notify::hd22a55ddb1e48b14 44: 0x10a3ee45f - tokio_core::reactor::Core::dispatch_task::{{closure}}::h33935b92c2aa101d 45: 0x10a3bf757 - >::set::h016f0a7a03a6ad0c 46: 0x10a3edcc1 - tokio_core::reactor::Core::dispatch_task::hec420a4cc0835980 47: 0x10a3ece85 - tokio_core::reactor::Core::dispatch::h86db0f04538f0a06 48: 0x10a3ec98b - tokio_core::reactor::Core::poll::hf8802d23cd4950c2 49: 0x10a1a91e3 - tokio_core::reactor::Core::run::he19e22032a1a0e7c 50: 0x10a258598 - proxy::main::h223a7c6d382e6912 51: 0x10a4dd47c - __rust_maybe_catch_panic 52: 0x10a4dc698 - std::rt::lang_start::h2d56a2c32f7d543f 53: 0x10a259749 - main

:; nghttp -vv http://localhost:7777/
[  0.003] Connected
[  0.003] send SETTINGS frame 
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.003] send PRIORITY frame 
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.003] send PRIORITY frame 
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.003] send PRIORITY frame 
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.003] send PRIORITY frame 
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.003] send PRIORITY frame 
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.003] send HEADERS frame 
          ; END_STREAM | END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: GET
          :path: /
          :scheme: http
          :authority: localhost:7777
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.23.1
[  0.003] recv SETTINGS frame 
          (niv=0)
[  0.003] send SETTINGS frame 
          ; ACK
          (niv=0)
[  0.005] recv SETTINGS frame 
          ; ACK
          (niv=0)
Some requests were not processed. total=1, processed=0

:; nghttpd -v --no-tls 8888
[id=15] [6112.823] send SETTINGS frame 
          (niv=1)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
[id=15] [6112.825] recv SETTINGS frame 
          (niv=0)
[id=15] [6112.825] recv SETTINGS frame 
          ; ACK
          (niv=0)
[id=15] [6112.825] send SETTINGS frame 
          ; ACK
          (niv=0)
[id=15] [6114.327] recv (stream_id=1) :method: GET
[id=15] [6114.327] recv (stream_id=1) :scheme: http
[id=15] [6114.327] recv (stream_id=1) :authority: localhost:7777
[id=15] [6114.327] recv (stream_id=1) :path: /
[id=15] [6114.327] recv (stream_id=1) accept: */*
[id=15] [6114.327] recv (stream_id=1) accept-encoding: gzip, deflate
[id=15] [6114.327] recv (stream_id=1) user-agent: nghttp2/1.23.1
[id=15] [6114.327] recv HEADERS frame 
          ; END_STREAM | END_HEADERS
          (padlen=0)
          ; Open new stream
[id=15] [6114.327] send HEADERS frame 
          ; END_HEADERS
          (padlen=0)
          ; First response header
          :status: 404
          server: nghttpd nghttp2/1.23.1
          date: Wed, 23 Aug 2017 03:20:58 GMT
          content-type: text/html; charset=UTF-8
          content-length: 147
[id=15] [6114.327] send DATA frame 
          ; END_STREAM
[id=15] [6114.327] stream_id=1 closed
[id=15] [6114.344] closed

@carllerche
Copy link
Collaborator Author

Ah yes. That assertion isn't correct. I had it for send but it is expected to not be the case for recv

@olix0r
Copy link
Collaborator

olix0r commented Aug 23, 2017

Removing that assertion triggers another panic, this time after 400 requests (so most likely on the connection flow controller)

TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::streams::prioritize:  --> data frame
TRACE:h2::proto::streams::prioritize:  -- updating stream flow --
TRACE:h2::proto::streams::flow_control: send_data: window=65535 available=147 sz=147
TRACE:h2::proto::streams::flow_control: send_data: window=65388; available=0
TRACE:h2::proto::streams::flow_control: assign capacity: window=33048 available=0 capacity=147
TRACE:h2::proto::streams::flow_control: assign capacity: window=33048 available=147
TRACE:h2::proto::streams::prioritize:  -- updating connection flow --
TRACE:h2::proto::streams::flow_control: send_data: window=33048 available=147 sz=147
TRACE:h2::proto::streams::flow_control: send_data: window=32901; available=0
TRACE:h2::proto::streams::prioritize: writing frame=Frame::Data(..)
DEBUG:h2::proto::framed_write: send; frame=Frame::Data(..)
TRACE:h2::proto::streams::flow_control: assign capacity: window=50835 available=57303 capacity=147
TRACE:h2::proto::streams::flow_control: assign capacity: window=50835 available=57450
TRACE:h2::proto::streams::flow_control: assign capacity: window=65388 available=65388 capacity=147
TRACE:h2::proto::streams::flow_control: assign capacity: window=65388 available=65535
TRACE:h2::proto::streams::prioritize: try reclaim frame
TRACE:h2::proto::streams::prioritize:   -> reclaimed; frame=Data { stream_id: StreamId(901), data: Prioritized { remaining: 0, end_of_stream: false, stream: Key(444) }, flags: DataFlag(0), pad_len: None }
TRACE:h2::proto::streams::prioritize: pop frame
TRACE:h2::proto::streams::prioritize:  --> data frame
TRACE:h2::proto::streams::prioritize:  -- updating stream flow --
TRACE:h2::proto::streams::flow_control: send_data: window=65535 available=120 sz=147
thread 'main' panicked at 'attempt to subtract with overflow', /Users/ver/b/rs/h2/src/proto/streams/flow_control.rs:106:9
stack backtrace:
   0:        0x1101a88d3 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::ha7e300af98739b0a
   1:        0x1101aa00a - std::panicking::default_hook::{{closure}}::hf87bad6075b566a9
   2:        0x1101a9cc2 - std::panicking::default_hook::hf2545c692bf4b891
   3:        0x1101ac282 - std::panicking::rust_panic_with_hook::h89c2ff4bac8586ab
   4:        0x1101ac0e4 - std::panicking::begin_panic::h624277f74f45eb29
   5:        0x1101ac032 - std::panicking::begin_panic_fmt::ha453ab564ee65d9d
   6:        0x1101abf9a - rust_begin_unwind
   7:        0x1101d0b53 - core::panicking::panic_fmt::h70f80d2989621b59
   8:        0x1101d0a56 - core::panicking::panic::h26c4c1ccdfa09abb
   9:        0x11012c7be - h2::proto::streams::flow_control::FlowControl::send_data::he95599c04238a21e

@carllerche carllerche merged commit 807d2b7 into master Aug 23, 2017
@carllerche carllerche deleted the recv-flow branch August 23, 2017 18:23
cxw620 pushed a commit to hanyu-dev/miku-h2 that referenced this pull request Jan 20, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants