Client receives `unexpected end of file` randomly

Question

Client receives `unexpected end of file` randomly

Nehliin opened this issue 2 years ago · 5 comments

I have been investigating an issue on one of our servcies where a tonic client seemingly at random errors out on client response error: unexpected end of file". Both to outgoing traffic to a grpc servcie written in go as well as to another tonic server. Other services communicating to the same services does not seem to run into the same problem.

I'm not super familiar with the grpc implementation details on top of h2 so I'm bit stuck staring at the logs. From what I can tell the client stream is waiting for headers from the remote and eventually the client sends an frame END_STREAM which afaik should close the stream and that'd be the end of it.

However right after flushing the buffer I see a log mentioning connect.state = Open and a framed read which polls the connection. That poll is what eventually results in the UnexpectedEof. I'm a bit confused why it would set the connection state to open after seemingly closing the stream? Perhaps the logs are for two separate streams and the open one is another one just opening up?

Here is a snippet of the tracing logs starting from the error, let me know if you need more of them. It's tricky to exactly pin point the relevant info since this is grabbed from a server (but with very little load):

Logs

s=2022-08-19T06:45:28.65144369Z level=debug target=hyper::proto::h2::client message="connection error: unexpected end of file"
ts=2022-08-19T06:45:28.651334159Z level=trace target=h2::proto::streams::streams message=Streams::recv_eof
ts=2022-08-19T06:45:28.651313981Z level=trace target=h2::proto::streams::counts message="dec_num_streams; stream=StreamId(1)" peer=Client
ts=2022-08-19T06:45:28.651291709Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Io(UnexpectedEof, None))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1" peer=Client
ts=2022-08-19T06:45:28.651246943Z level=trace target=h2::proto::streams::state message="handle_error; err=Io(UnexpectedEof, None)" peer=Client
ts=2022-08-19T06:45:28.651209418Z level=debug target=h2::proto::connection message="Connection::poll; IO error" error=UnexpectedEof peer=Client
ts=2022-08-19T06:45:28.651174583Z level=trace target=h2::codec::framed_read message=poll peer=Client
ts=2022-08-19T06:45:28.651132359Z level=trace target=h2::proto::connection connection.state=Open peer=Client
ts=2022-08-19T06:45:28.649306454Z level=trace target=h2::codec::framed_write message="flushing buffer" peer=Client
ts=2022-08-19T06:45:28.649254552Z level=trace target=h2::codec::framed_write queued_data_frame=false peer=Client
ts=2022-08-19T06:45:28.649230034Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.649205082Z level=trace target=h2::proto::streams::prioritize message=reclaimed frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" sz=0 peer=Client
ts=2022-08-19T06:45:28.64915352Z level=debug target=h2::codec::framed_write message=send frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"
ts=2022-08-19T06:45:28.649124589Z level=trace target=h2::proto::streams::prioritize message=writing frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client
ts=2022-08-19T06:45:28.64907251Z level=trace target=h2::proto::streams::counts message="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" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.649048201Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.649028933Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=0; window=1048170; available=1048170" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.64900355Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=0; window=1048170; available=0" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.64898749Z level=trace target=h2::proto::streams::prioritize message="sending data frame" len=0 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648947305Z level=trace target=h2::proto::streams::prioritize message="data frame" sz=0 eos=true window=0 available=0 requested=0 buffered=0 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648936169Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648905675Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.648879221Z level=trace target=h2::proto::streams::prioritize message=reclaimed frame="Data { stream_id: StreamId(1) }" sz=0 peer=Client
ts=2022-08-19T06:45:28.648850075Z level=trace target=h2::codec::framed_write message="flushing buffer" peer=Client
ts=2022-08-19T06:45:28.648814175Z level=trace target=h2::codec::framed_write queued_data_frame=true peer=Client
ts=2022-08-19T06:45:28.648750232Z level=trace target=h2::codec::framed_write queued_data_frame=true peer=Client
ts=2022-08-19T06:45:28.648699442Z level=debug target=h2::codec::framed_write message=send frame="Data { stream_id: StreamId(1) }" peer=Client frame="Data { stream_id: StreamId(1) }"
ts=2022-08-19T06:45:28.648672125Z level=trace target=h2::proto::streams::prioritize message=writing frame="Data { stream_id: StreamId(1) }" peer=Client
ts=2022-08-19T06:45:28.648637709Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648628635Z level=trace target=h2::proto::streams::store message=" -> first entry" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648619461Z level=trace target=h2::proto::streams::store message=Queue::push peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648605187Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Data { stream_id: StreamId(1) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648582981Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=406; window=1048576; available=1048576" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648553853Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=406; window=1048576; available=406" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648537358Z level=trace target=h2::proto::streams::prioritize message="sending data frame" len=406 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648518625Z level=trace target=h2::proto::streams::prioritize message="data frame" sz=406 eos=false window=406 available=406 requested=406 buffered=406 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648506173Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648476352Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.648340382Z level=debug target=h2::codec::framed_write message=send frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"
ts=2022-08-19T06:45:28.648306457Z level=trace target=h2::proto::streams::prioritize message=writing frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client
ts=2022-08-19T06:45:28.648271645Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648260553Z level=trace target=h2::proto::streams::store message=" -> first entry" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648249173Z level=trace target=h2::proto::streams::store message=Queue::push peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648229178Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648217035Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.648185696Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.64817581Z level=trace target=h2::proto::streams::prioritize message=poll_complete peer=Client
ts=2022-08-19T06:45:28.648141571Z level=trace target=h2::codec::framed_read message=poll peer=Client
ts=2022-08-19T06:45:28.648107529Z level=trace target=h2::proto::connection connection.state=Open peer=Client
ts=2022-08-19T06:45:28.64783861Z level=trace target=h2::codec::framed_write message="flushing buffer" peer=Client
ts=2022-08-19T06:45:28.647796546Z level=trace target=h2::codec::framed_write queued_data_frame=false peer=Client
ts=2022-08-19T06:45:28.647773018Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.647748404Z level=trace target=h2::proto::streams::prioritize message=reclaimed frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" sz=0 peer=Client
ts=2022-08-19T06:45:28.647695417Z level=debug target=h2::codec::framed_write message=send frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }"
ts=2022-08-19T06:45:28.647664797Z level=trace target=h2::proto::streams::prioritize message=writing frame="Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client
ts=2022-08-19T06:45:28.647632521Z level=trace target=h2::proto::streams::counts message="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" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647617528Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647598547Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=0; window=1048170; available=1048170" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.64757535Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=0; window=1048170; available=0" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647560404Z level=trace target=h2::proto::streams::prioritize message="sending data frame" len=0 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647543471Z level=trace target=h2::proto::streams::prioritize message="data frame" sz=0 eos=true window=0 available=0 requested=0 buffered=0 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647533213Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.64750768Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.64748587Z level=trace target=h2::proto::streams::prioritize message=reclaimed frame="Data { stream_id: StreamId(1) }" sz=0 peer=Client
ts=2022-08-19T06:45:28.647461474Z level=trace target=h2::codec::framed_write message="flushing buffer" peer=Client
ts=2022-08-19T06:45:28.647432373Z level=trace target=h2::codec::framed_write queued_data_frame=true peer=Client
ts=2022-08-19T06:45:28.6473704Z level=trace target=h2::codec::framed_write queued_data_frame=true peer=Client
ts=2022-08-19T06:45:28.647322745Z level=debug target=h2::codec::framed_write message=send frame="Data { stream_id: StreamId(1) }" peer=Client frame="Data { stream_id: StreamId(1) }"
ts=2022-08-19T06:45:28.647300478Z level=trace target=h2::proto::streams::prioritize message=writing frame="Data { stream_id: StreamId(1) }" peer=Client
ts=2022-08-19T06:45:28.647269829Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647259853Z level=trace target=h2::proto::streams::store message=" -> first entry" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647250511Z level=trace target=h2::proto::streams::store message=Queue::push peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647236151Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Data { stream_id: StreamId(1) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647215687Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=406; window=1048576; available=1048576" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647190718Z level=trace target=h2::proto::streams::flow_control message="send_data; sz=406; window=1048576; available=406" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647174048Z level=trace target=h2::proto::streams::prioritize message="sending data frame" len=406 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647153916Z level=trace target=h2::proto::streams::prioritize message="data frame" sz=406 eos=false window=406 available=406 requested=406 buffered=406 peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647141579Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.647107048Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.64690629Z level=debug target=h2::codec::framed_write message=send frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }"
ts=2022-08-19T06:45:28.64687828Z level=trace target=h2::proto::streams::prioritize message=writing frame="Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client
ts=2022-08-19T06:45:28.646847244Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.646837758Z level=trace target=h2::proto::streams::store message=" -> first entry" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.646828001Z level=trace target=h2::proto::streams::store message=Queue::push peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.646811123Z level=trace target=h2::proto::streams::prioritize message="pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }" peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.646799853Z level=trace target=h2::proto::streams::prioritize is_pending_reset=false peer=Client stream.id=StreamId(1) stream.state="State { inner: HalfClosedLocal(AwaitingHeaders) }"
ts=2022-08-19T06:45:28.646771886Z level=trace target=h2::proto::streams::prioritize message=schedule_pending_open peer=Client
ts=2022-08-19T06:45:28.646761403Z level=trace target=h2::proto::streams::prioritize message=poll_complete peer=Client
ts=2022-08-19T06:45:28.646724933Z level=trace target=h2::codec::framed_read message=poll peer=Client
ts=2022-08-19T06:45:28.64668255Z level=trace target=h2::proto::connection connection.state=Open peer=Client
ts=2022-08-19T06:45:28.646643879Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.646597039Z level=trace target=h2::proto::streams::streams message="drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(1048576), available: Window(406) }, requested_send_capacity: 406, buffered_send_data: 406, send_task: Some(Waker { data: 0x555555922900, vtable: 0x7ff2f70196f0 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 2 }) }, 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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }"
ts=2022-08-19T06:45:28.646581236Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.646555828Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.64654557Z level=trace target=h2::proto::streams::store message=Queue::push sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646534369Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646516868Z level=trace target=h2::proto::streams::prioritize available=406 buffered=406 sz=0 requested=406
ts=2022-08-19T06:45:28.646487253Z level=trace target=h2::proto::streams::state message="send_close: Open => HalfClosedLocal(AwaitingHeaders)" sz=0 requested=406
ts=2022-08-19T06:45:28.646477183Z level=trace target=h2::proto::streams::prioritize buffered=406 sz=0 requested=406
ts=2022-08-19T06:45:28.646460932Z level=trace target=hyper::proto::h2 message="send body eos"
ts=2022-08-19T06:45:28.646400762Z level=trace target=h2::proto::streams::store message=" -> already queued" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646391165Z level=trace target=h2::proto::streams::store message=Queue::push stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646376359Z level=trace target=h2::proto::streams::prioritize available=407 requested=407 buffered=406 has_unavailable=true stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646365462Z level=trace target=h2::proto::streams::stream message="  notifying task" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646350697Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=407; buffered=406; id=StreamId(1); max_buffer_size=1048576" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646339768Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=1 stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646323451Z level=trace target=h2::proto::streams::prioritize requested=407 additional=1 buffered=406 window=1048576 conn=1048170 stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646288385Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: Open { local: Streaming, remote: AwaitingHeaders } }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.646263998Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646255259Z level=trace target=h2::proto::streams::store message=Queue::push sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646243516Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646224994Z level=trace target=h2::proto::streams::prioritize available=406 buffered=406 sz=406 requested=1
ts=2022-08-19T06:45:28.646206782Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646197544Z level=trace target=h2::proto::streams::store message=Queue::push sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646184193Z level=trace target=h2::proto::streams::prioritize available=406 requested=406 buffered=406 has_unavailable=true sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646169927Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=406; buffered=406; id=StreamId(1); max_buffer_size=1048576" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646159552Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=405 sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646144413Z level=trace target=h2::proto::streams::prioritize requested=406 additional=405 buffered=406 window=1048576 conn=1048575 sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646126011Z level=trace target=h2::proto::streams::prioritize buffered=406 sz=406 requested=1
ts=2022-08-19T06:45:28.646092285Z level=trace target=hyper::proto::h2 message="send body chunk: 406 bytes, eos=false"
ts=2022-08-19T06:45:28.646042239Z level=trace target=h2::proto::streams::prioritize available=1 requested=1 buffered=0 has_unavailable=true stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646032746Z level=trace target=h2::proto::streams::stream message="  notifying task" stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646018982Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576" stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.646007726Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=1 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645972855Z level=trace target=h2::proto::streams::prioritize requested=1 additional=1 buffered=0 window=1048576 conn=1048576 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645930368Z level=trace target=h2::proto::streams::store message=" -> first entry" stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645921505Z level=trace target=h2::proto::streams::store message=Queue::push stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645909706Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645882721Z level=trace target=h2::proto::streams::send message="send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=1048576"
ts=2022-08-19T06:45:28.645868207Z level=trace target=h2::proto::streams::flow_control message="inc_window; sz=1048576; old=0; new=1048576"
ts=2022-08-19T06:45:28.645858179Z level=trace target=h2::proto::streams::flow_control message="inc_window; sz=2097152; old=0; new=2097152"
ts=2022-08-19T06:45:28.645757723Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.645710742Z level=trace target=h2::proto::streams::streams message="drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedLocal(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(1048576), available: Window(406) }, requested_send_capacity: 406, buffered_send_data: 406, send_task: Some(Waker { data: 0x5555559083e0, vtable: 0x7ff2f70196f0 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 2 }) }, 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 }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }"
ts=2022-08-19T06:45:28.64569395Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.645670766Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645661314Z level=trace target=h2::proto::streams::store message=Queue::push sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645649318Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) sz=0 requested=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645630022Z level=trace target=h2::proto::streams::prioritize available=406 buffered=406 sz=0 requested=406
ts=2022-08-19T06:45:28.645595573Z level=trace target=h2::proto::streams::state message="send_close: Open => HalfClosedLocal(AwaitingHeaders)" sz=0 requested=406
ts=2022-08-19T06:45:28.645585482Z level=trace target=h2::proto::streams::prioritize buffered=406 sz=0 requested=406
ts=2022-08-19T06:45:28.645548319Z level=trace target=hyper::proto::h2 message="send body eos"
ts=2022-08-19T06:45:28.64546896Z level=trace target=h2::proto::streams::store message=" -> already queued" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645460287Z level=trace target=h2::proto::streams::store message=Queue::push stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645446089Z level=trace target=h2::proto::streams::prioritize available=407 requested=407 buffered=406 has_unavailable=true stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645435768Z level=trace target=h2::proto::streams::stream message="  notifying task" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645421084Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=407; buffered=406; id=StreamId(1); max_buffer_size=1048576" stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645410816Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=1 stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.64539549Z level=trace target=h2::proto::streams::prioritize requested=407 additional=1 buffered=406 window=1048576 conn=1048170 stream.id=StreamId(1) requested=1 effective=407 curr=406 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.64535889Z level=trace target=h2::proto::streams::counts message="transition_after; stream=StreamId(1); state=State { inner: Open { local: Streaming, remote: AwaitingHeaders } }; is_closed=false; pending_send_empty=false; buffered_send_data=406; num_recv=0; num_send=1"
ts=2022-08-19T06:45:28.645335089Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645326032Z level=trace target=h2::proto::streams::store message=Queue::push sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645314315Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.64529575Z level=trace target=h2::proto::streams::prioritize available=406 buffered=406 sz=406 requested=1
ts=2022-08-19T06:45:28.645276291Z level=trace target=h2::proto::streams::store message=" -> already queued" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645266285Z level=trace target=h2::proto::streams::store message=Queue::push sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645252395Z level=trace target=h2::proto::streams::prioritize available=406 requested=406 buffered=406 has_unavailable=true sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.64523616Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=406; buffered=406; id=StreamId(1); max_buffer_size=1048576" sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645226296Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=405 sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645212266Z level=trace target=h2::proto::streams::prioritize requested=406 additional=405 buffered=406 window=1048576 conn=1048575 sz=406 requested=1 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645195183Z level=trace target=h2::proto::streams::prioritize buffered=406 sz=406 requested=1
ts=2022-08-19T06:45:28.645175542Z level=trace target=hyper::proto::h2 message="send body chunk: 406 bytes, eos=false"
ts=2022-08-19T06:45:28.645130373Z level=trace target=h2::proto::streams::prioritize available=1 requested=1 buffered=0 has_unavailable=true stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645120066Z level=trace target=h2::proto::streams::stream message="  notifying task" stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645104394Z level=trace target=h2::proto::streams::stream message="  assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576" stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645091987Z level=trace target=h2::proto::streams::prioritize message=assigning capacity=1 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645072473Z level=trace target=h2::proto::streams::prioritize requested=1 additional=1 buffered=0 window=1048576 conn=1048576 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
ts=2022-08-19T06:45:28.645000562Z level=trace target=h2::proto::streams::store message=" -> first entry" stream.id=StreamId(1)
ts=2022-08-19T06:45:28.644988374Z level=trace target=h2::proto::streams::store message=Queue::push stream.id=StreamId(1)
ts=2022-08-19T06:45:28.644946845Z level=trace target=h2::proto::streams::prioritize message=schedule_send stream.id=StreamId(1) stream.id=StreamId(1)
ts=2022-08-19T06:45:28.644913624Z level=trace target=h2::proto::streams::send message="send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=1048576"
ts=2022-08-19T06:45:28.64489814Z level=trace target=h2::proto::streams::flow_control message="inc_window; sz=1048576; old=0; new=1048576"
ts=2022-08-19T06:45:28.64487859Z level=trace target=h2::proto::streams::flow_control message="inc_window; sz=2097152; old=0; new=2097152"

Answer 1 · 2024-01-22T11:06:40.000Z

I assume the UnexpectedEof you encountered is on a server. This should be fixed by #743.

eventually the client sends an frame END_STREAM which afaik should close the stream and that'd be the end of it.

From the log you posted, it seems the server never got an END_STREAM flag (server sent one, but never got one), causing it to remain open until the client closed the connection. The moment the server tries to poll, it hits an unexpected EOF.

Answer 2 · 2024-01-24T09:02:01.000Z

I assume the UnexpectedEof you encountered is on a server

It's not outgoing responses from a server that have this issue if that's what you mean. It's running on a server but is normal outgoing rpcs to various other services and is not responses to incoming requests.

Answer 3 · 2024-01-24T09:29:22.000Z

It's not outgoing responses from a server that have this issue if that's what you mean.

Thanks for the clarification. #743 won't fix this if this is the case.

I suspect it's a similar issue tho -- the connection is just closed by upstream servers without END_STREAM.

Would you happen to have a simplified version of the tonic/go server to reproduce this issue?

Answer 4 · 2024-01-24T15:23:02.000Z

not at the moment, we are trying to eliminate any other potential layer on top of hyper/tonic as causing problems (unlikely though). Those logs linked in the issue is the best we got for now

Answer 5 · 2024-02-15T13:37:45.000Z

not at the moment, we are trying to eliminate any other potential layer on top of hyper/tonic as causing problems (unlikely though). Those logs linked in the issue is the best we got for now

I'm experiencing the same error when connecting to Google API from rust using tonic. I haven't found specific conditions for that and have not created a minimal example but just wanted to say that I would also be grateful if you will be able to post your findings