Giter Site home page Giter Site logo

Comments (6)

olix0r avatar olix0r commented on May 8, 2024

This is the last I see in the logs before all work stops.

1505169637.246497 TRACE h2::proto::streams::prioritize pop_frame                                                                                                                                  [0/1961]
1505169637.246500 TRACE h2::codec::framed_write flush
1505169637.246507 TRACE h2::codec::framed_write flushing buffer
1505169637.246510 TRACE h2::proto::streams::prioritize try reclaim frame
1505169637.246527 TRACE h2::proto::settings send_pending_ack; pending=None
1505169637.246534 TRACE h2::codec::framed_read poll
1505169637.246553 TRACE h2::codec::framed_read poll; bytes=13B
1505169637.246557 TRACE h2::codec::framed_read decoding frame from 13B
1505169637.246563 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505169637.246568 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(149), size_increment: 16384 }
1505169637.246574 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(149); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 491
51, available: 0 }
1505169637.246583 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505169637.246586 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=818805
1505169637.246590 TRACE h2::proto::settings send_pending_ack; pending=None
1505169637.246595 TRACE h2::codec::framed_read poll
1505169637.246597 TRACE h2::codec::framed_read poll; bytes=13B
1505169637.246601 TRACE h2::codec::framed_read decoding frame from 13B
1505169637.246603 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505169637.246607 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(151), size_increment: 16384 }
1505169637.246610 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(151); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 491
51, available: 0 }
1505169637.246617 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505169637.246619 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=818805
1505169637.246623 TRACE h2::proto::settings send_pending_ack; pending=None
1505169637.246625 TRACE h2::codec::framed_read poll
1505169637.246629 TRACE h2::codec::framed_read poll; bytes=13B
1505169637.246631 TRACE h2::codec::framed_read decoding frame from 13B
1505169637.246634 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505169637.246636 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(153), size_increment: 16384 }
1505169637.246643 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(153); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 491
51, available: 0 }
1505169637.246648 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505169637.246655 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=818805
1505169637.246659 TRACE h2::proto::settings send_pending_ack; pending=None
1505169637.246662 TRACE h2::codec::framed_read poll
1505169637.246675 TRACE h2::codec::framed_read poll; bytes=13B
1505169637.246681 TRACE h2::codec::framed_read decoding frame from 13B
1505169637.246684 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505169637.246687 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(155), size_increment: 16383 }
1505169637.246705 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(155); state=State { inner: HalfClosedRemote(Streaming) }; inc=16383; flow=FlowControl { window_size: 491
52, available: 0 }
1505169637.246711 TRACE h2::proto::streams::flow_control inc_window; sz=16383; old=49152; new=65535
1505169637.246714 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=818805
1505169637.246718 TRACE h2::proto::settings send_pending_ack; pending=None
1505169637.246721 TRACE h2::codec::framed_read poll
1505169637.246728 TRACE h2::proto::streams::prioritize try reclaim frame
1505169637.246732 TRACE h2::proto::streams::prioritize poll_complete
1505169637.246734 TRACE h2::proto::streams::prioritize pop_frame
1505169637.246737 TRACE h2::codec::framed_write flush
1505169637.246738 TRACE h2::codec::framed_write flushing buffer
1505169637.246740 TRACE h2::proto::streams::prioritize try reclaim frame

No evidence that this is actually related to connection-level flow control.

from h2.

olix0r avatar olix0r commented on May 8, 2024

Here's a fuller accounting of the final set of streams when the process hangs:

1505174326.679400 TRACE h2::codec::framed_read poll
1505174326.679405 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679408 TRACE h2::proto::streams::prioritize poll_complete
1505174326.679411 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679414 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8231)
1505174326.679418 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Headers(Headers { stream_id: StreamId(8231), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679422 TRACE h2::proto::streams::store Queue::push
1505174326.679425 TRACE h2::proto::streams::store  -> existing entries
1505174326.679429 TRACE h2::proto::streams::prioritize writing frame=Frame::Headers(Headers { stream_id: StreamId(8231), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679433 DEBUG h2::codec::framed_write send; frame=Frame::Headers(Headers { stream_id: StreamId(8231), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679439 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679442 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679445 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8237)
1505174326.679448 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Headers(Headers { stream_id: StreamId(8237), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679452 TRACE h2::proto::streams::store Queue::push
1505174326.679455 TRACE h2::proto::streams::store  -> existing entries
1505174326.679459 TRACE h2::proto::streams::prioritize writing frame=Frame::Headers(Headers { stream_id: StreamId(8237), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679463 DEBUG h2::codec::framed_write send; frame=Frame::Headers(Headers { stream_id: StreamId(8237), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679467 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679470 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679473 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8233)
1505174326.679477 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Headers(Headers { stream_id: StreamId(8233), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679481 TRACE h2::proto::streams::store Queue::push
1505174326.679484 TRACE h2::proto::streams::store  -> existing entries
1505174326.679487 TRACE h2::proto::streams::prioritize writing frame=Frame::Headers(Headers { stream_id: StreamId(8233), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679491 DEBUG h2::codec::framed_write send; frame=Frame::Headers(Headers { stream_id: StreamId(8233), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679495 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679498 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679501 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8235)
1505174326.679505 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Headers(Headers { stream_id: StreamId(8235), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679509 TRACE h2::proto::streams::store Queue::push
1505174326.679515 TRACE h2::proto::streams::store  -> existing entries
1505174326.679518 TRACE h2::proto::streams::prioritize writing frame=Frame::Headers(Headers { stream_id: StreamId(8235), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679522 DEBUG h2::codec::framed_write send; frame=Frame::Headers(Headers { stream_id: StreamId(8235), stream_dep: None, flags: HeadersFlag { end_stream: false, end_headers: true, padded: false, priority: false } })
1505174326.679527 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679530 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679533 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8231)
1505174326.679536 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8231); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679540 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679543 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679546 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679549 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679552 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=950011; available=900860
1505174326.679555 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Data(Data { stream_id: StreamId(8231), flags: DataFlags, pad_len: None })
1505174326.679559 TRACE h2::proto::streams::prioritize writing frame=Frame::Data(Data { stream_id: StreamId(8231), flags: DataFlags, pad_len: None })
1505174326.679570 DEBUG h2::codec::framed_write send; frame=Frame::Data(Data { stream_id: StreamId(8231), flags: DataFlags, pad_len: None })
1505174326.679575 TRACE h2::codec::framed_write flush
1505174326.679603 TRACE h2::proto::streams::recv release_capacity; size=16384
1505174326.679609 TRACE h2::codec::framed_write flushing buffer
1505174326.679612 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679615 TRACE h2::proto::streams::prioritize   -> reclaimed; frame=Data { stream_id: StreamId(8231), flags: DataFlags, pad_len: None }; sz=0
1505174326.679619 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679622 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8237)
1505174326.679626 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8237); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679629 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679632 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679635 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679639 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679642 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=933627; available=900860
1505174326.679645 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Data(Data { stream_id: StreamId(8237), flags: DataFlags, pad_len: None })
1505174326.679649 TRACE h2::proto::streams::prioritize writing frame=Frame::Data(Data { stream_id: StreamId(8237), flags: DataFlags, pad_len: None })
1505174326.679652 DEBUG h2::codec::framed_write send; frame=Frame::Data(Data { stream_id: StreamId(8237), flags: DataFlags, pad_len: None })
1505174326.679656 TRACE h2::codec::framed_write flush
1505174326.679671 TRACE h2::proto::streams::recv release_capacity; size=16384
1505174326.679676 TRACE h2::codec::framed_write flushing buffer
1505174326.679679 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679682 TRACE h2::proto::streams::prioritize   -> reclaimed; frame=Data { stream_id: StreamId(8237), flags: DataFlags, pad_len: None }; sz=0
1505174326.679686 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679689 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8233)
1505174326.679692 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8233); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679720 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679724 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679727 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679731 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679734 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=917243; available=900860
1505174326.679737 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Data(Data { stream_id: StreamId(8233), flags: DataFlags, pad_len: None })
1505174326.679741 TRACE h2::proto::streams::prioritize writing frame=Frame::Data(Data { stream_id: StreamId(8233), flags: DataFlags, pad_len: None })
1505174326.679745 DEBUG h2::codec::framed_write send; frame=Frame::Data(Data { stream_id: StreamId(8233), flags: DataFlags, pad_len: None })
1505174326.679749 TRACE h2::codec::framed_write flush
1505174326.679763 TRACE h2::proto::streams::recv release_capacity; size=16384
1505174326.679768 TRACE h2::codec::framed_write flushing buffer
1505174326.679771 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679774 TRACE h2::proto::streams::prioritize   -> reclaimed; frame=Data { stream_id: StreamId(8233), flags: DataFlags, pad_len: None }; sz=0
1505174326.679778 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679781 TRACE h2::proto::streams::prioritize pop_frame; stream=StreamId(8235)
1505174326.679784 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8235); sz=16383; eos=false; window=16383; available=16383; requested=16383
1505174326.679788 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16383
1505174326.679791 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679794 TRACE h2::proto::streams::flow_control send_data; sz=16383; window=65535; available=16383
1505174326.679797 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679800 TRACE h2::proto::streams::flow_control send_data; sz=16383; window=900859; available=900859
1505174326.679803 TRACE h2::proto::streams::prioritize pop_frame; frame=Frame::Data(Data { stream_id: StreamId(8235), flags: DataFlags, pad_len: None })
1505174326.679807 TRACE h2::proto::streams::prioritize writing frame=Frame::Data(Data { stream_id: StreamId(8235), flags: DataFlags, pad_len: None })
1505174326.679811 DEBUG h2::codec::framed_write send; frame=Frame::Data(Data { stream_id: StreamId(8235), flags: DataFlags, pad_len: None })
1505174326.679815 TRACE h2::codec::framed_write flush
1505174326.679826 TRACE h2::proto::streams::recv release_capacity; size=16383
1505174326.679830 TRACE h2::codec::framed_write flushing buffer
1505174326.679833 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679836 TRACE h2::proto::streams::prioritize   -> reclaimed; frame=Data { stream_id: StreamId(8235), flags: DataFlags, pad_len: None }; sz=0
1505174326.679840 TRACE h2::proto::streams::prioritize pop_frame
1505174326.679843 TRACE h2::codec::framed_write flush
1505174326.679846 TRACE h2::codec::framed_write flushing buffer
1505174326.679849 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.679856 TRACE h2::proto::settings send_pending_ack; pending=None
1505174326.679860 TRACE h2::codec::framed_read poll
1505174326.679866 TRACE h2::codec::framed_read poll; bytes=13B
1505174326.679870 TRACE h2::codec::framed_read decoding frame from 13B
1505174326.679873 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505174326.679876 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8231), size_increment: 16384 }
1505174326.679881 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8231); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679898 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679902 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679905 TRACE h2::proto::settings send_pending_ack; pending=None
1505174326.679908 TRACE h2::codec::framed_read poll
1505174326.679912 TRACE h2::codec::framed_read poll; bytes=13B
1505174326.679915 TRACE h2::codec::framed_read decoding frame from 13B
1505174326.679918 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505174326.679921 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8237), size_increment: 16384 }
1505174326.679925 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8237); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679929 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679932 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679936 TRACE h2::proto::settings send_pending_ack; pending=None
1505174326.679939 TRACE h2::codec::framed_read poll
1505174326.679952 TRACE h2::codec::framed_read poll; bytes=13B
1505174326.679957 TRACE h2::codec::framed_read decoding frame from 13B
1505174326.679960 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505174326.679963 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8233), size_increment: 16384 }
1505174326.679967 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8233); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679971 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679974 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679977 TRACE h2::proto::settings send_pending_ack; pending=None
1505174326.679980 TRACE h2::codec::framed_read poll
1505174326.679984 TRACE h2::codec::framed_read poll; bytes=13B
1505174326.679987 TRACE h2::codec::framed_read decoding frame from 13B
1505174326.679990 TRACE h2::codec::framed_read     -> kind=WindowUpdate
1505174326.679993 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8235), size_increment: 16383 }
1505174326.679996 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8235); state=State { inner: HalfClosedRemote(Streaming) }; inc=16383; flow=FlowControl { window_size: 49152, available: 0 }
1505174326.680000 TRACE h2::proto::streams::flow_control inc_window; sz=16383; old=49152; new=65535
1505174326.680004 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.680015 TRACE h2::proto::settings send_pending_ack; pending=None
1505174326.680019 TRACE h2::codec::framed_read poll
1505174326.680025 TRACE h2::proto::streams::prioritize try reclaim frame
1505174326.680028 TRACE h2::proto::streams::prioritize poll_complete
1505174326.680031 TRACE h2::proto::streams::prioritize pop_frame
1505174326.680034 TRACE h2::codec::framed_write flush
1505174326.680037 TRACE h2::codec::framed_write flushing buffer
1505174326.680040 TRACE h2::proto::streams::prioritize try reclaim frame

Specifically we send 4 data frames:

1505174326.679536 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8231); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679540 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679543 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679546 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679549 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679552 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=950011; available=900860

we release capacity back to the server so it may send more data:

1505174326.679603 TRACE h2::proto::streams::recv release_capacity; size=16384

and then we do that again a few more times:

1505174326.679626 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8237); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679629 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679632 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679635 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679639 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679642 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=933627; available=900860
1505174326.679671 TRACE h2::proto::streams::recv release_capacity; size=16384
...
1505174326.679692 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8233); sz=16384; eos=false; window=16384; available=16384; requested=16384
1505174326.679720 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16384
1505174326.679724 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679727 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=65535; available=16384
1505174326.679731 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679734 TRACE h2::proto::streams::flow_control send_data; sz=16384; window=917243; available=900860
1505174326.679763 TRACE h2::proto::streams::recv release_capacity; size=16384
...
1505174326.679784 TRACE h2::proto::streams::prioritize  --> data frame; stream=StreamId(8235); sz=16383; eos=false; window=16383; available=16383; requested=16383
1505174326.679788 TRACE h2::proto::streams::prioritize  --> sending data frame; len=16383
1505174326.679791 TRACE h2::proto::streams::prioritize  -- updating stream flow --
1505174326.679794 TRACE h2::proto::streams::flow_control send_data; sz=16383; window=65535; available=16383
1505174326.679797 TRACE h2::proto::streams::prioritize  -- updating connection flow --
1505174326.679800 TRACE h2::proto::streams::flow_control send_data; sz=16383; window=900859; available=900859
1505174326.679826 TRACE h2::proto::streams::recv release_capacity; size=16383

Then we read four window updates from the receiver:

1505174326.679876 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8231), size_increment: 16384 }
1505174326.679881 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8231); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679898 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679902 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679921 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8237), size_increment: 16384 }
1505174326.679925 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8237); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679929 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679932 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679963 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8233), size_increment: 16384 }
1505174326.679967 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8233); state=State { inner: HalfClosedRemote(Streaming) }; inc=16384; flow=FlowControl { window_size: 49151, available: 0 }
1505174326.679971 TRACE h2::proto::streams::flow_control inc_window; sz=16384; old=49151; new=65535
1505174326.679974 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476
1505174326.679993 TRACE h2::proto::connection recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(8235), size_increment: 16383 }
1505174326.679996 TRACE h2::proto::streams::prioritize recv_stream_window_update; stream=StreamId(8235); state=State { inner: HalfClosedRemote(Streaming) }; inc=16383; flow=FlowControl { window_size: 49152, available: 0 }
1505174326.680000 TRACE h2::proto::streams::flow_control inc_window; sz=16383; old=49152; new=65535
1505174326.680004 TRACE h2::proto::streams::prioritize try_assign_capacity; requested=0; additional=0; buffered=0; window=65535; conn=884476

and then nothing happens... ;(

from h2.

olix0r avatar olix0r commented on May 8, 2024

I'm still trying to get a tighter narrative around what's happening, but I think the issue is likely caused by a receiver starving a remote sender by not sending window updates as needed. I'll try to narrow down this behavior.

from h2.

carllerche avatar carllerche commented on May 8, 2024

I'm pretty sure this was fixed by #86.

from h2.

seanmonstar avatar seanmonstar commented on May 8, 2024

Pretty sure enough that we can close?

from h2.

carllerche avatar carllerche commented on May 8, 2024

At this point, yeah.

from h2.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.