Skip to content

Instantly share code, notes, and snippets.

@edrevo

edrevo/h2 trace.log

Created August 30, 2020 07:50
Show Gist options
  • Save edrevo/853fe19a3593cfd724fa779332310c0a to your computer and use it in GitHub Desktop.
Save edrevo/853fe19a3593cfd724fa779332310c0a to your computer and use it in GitHub Desktop.
Download ZIP
Raw
h2 trace.log
[2020-08-30T07:34:38Z TRACE tower_buffer::service] sending request to buffer worker
[2020-08-30T07:34:38Z TRACE tower_buffer::worker] worker polling for next message
[2020-08-30T07:34:38Z TRACE tower_buffer::worker] processing new request
[2020-08-30T07:34:38Z TRACE tower_buffer::worker] resumed=false worker received request; waiting for service readiness
[2020-08-30T07:34:38Z TRACE tonic::transport::service::reconnect] poll_ready; connected
[2020-08-30T07:34:38Z TRACE want] poll_want: taker wants!
[2020-08-30T07:34:38Z TRACE tonic::transport::service::reconnect] poll_ready; ready
[2020-08-30T07:34:38Z DEBUG tower_buffer::worker] service.ready=true processing request
[2020-08-30T07:34:38Z TRACE tower_buffer::worker] returning response future
[2020-08-30T07:34:38Z TRACE tower_buffer::worker] worker polling for next message
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] inc_window; sz=2097152; old=0; new=2097152
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] inc_window; sz=1048576; old=0; new=1048576
[2020-08-30T07:34:38Z TRACE h2::proto::streams::send] send_headers; frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }; init_window=1048576
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(9); requested=1; effective=1; curr=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(9), requested=1; additional=1; buffered=0; window=1048576; conn=1048576
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(9), capacity=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=1; buffered=0; id=StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] notifying task
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=1; requested=1; buffered=0; has_unavailable=true
[2020-08-30T07:34:38Z TRACE hyper::proto::h2] send body chunk: 2604 bytes, eos=false
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data; sz=2604; buffered=2604; requested=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(9), requested=2604; additional=2603; buffered=2604; window=1048576; conn=1048575
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(9), capacity=2603
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=2604; buffered=2604; id=StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=2604; requested=2604; buffered=2604; has_unavailable=true
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data (2); available=2604; buffered=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: Open { local: Streaming, remote: AwaitingHeaders } }; is_closed=false; pending_send_empty=false; buffered_send_data=2604; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(9); requested=1; effective=2605; curr=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(9), requested=2605; additional=1; buffered=2604; window=1048576; conn=1045972
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(9), capacity=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=2605; buffered=2604; id=StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] notifying task
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=2605; requested=2605; buffered=2604; has_unavailable=true
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(9); requested=0; effective=2604; curr=2605
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assign_connection_capacity; inc=1
[2020-08-30T07:34:38Z TRACE hyper::proto::h2] send body eos
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data; sz=0; buffered=2604; requested=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::state] send_close: Open => HalfClosedLocal(AwaitingHeaders)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(9); requested=0; effective=2604; curr=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data (2); available=2604; buffered=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=2604; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(9), 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(2604) }, requested_send_capacity: 2604, buffered_send_data: 2604, send_task: Some(Waker { data: 0x1d351a0, vtable: 0xa869f0 }), 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 }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=2604; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE want] signal: Want
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(9); stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(9); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=2604; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(9); stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(9); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> data frame; stream=StreamId(9); sz=2604; eos=false; window=2604; available=2604; requested=2604; buffered=2604;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> sending data frame; len=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating stream flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=2604; window=1048576; available=2604
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating connection flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=2604; window=1048576; available=1048576
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Data { stream_id: StreamId(9) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Data { stream_id: StreamId(9) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Data { stream_id: StreamId(9) }
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flush
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] -> queued data frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] -> queued data frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flushing buffer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -> reclaimed; frame=Data { stream_id: StreamId(9) }; sz=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(9); stream.state=State { inner: HalfClosedLocal(AwaitingHeaders) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(9); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> data frame; stream=StreamId(9); sz=0; eos=true; window=0; available=0; requested=0; buffered=0;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> sending data frame; len=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating stream flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=0; window=1045972; available=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating connection flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=0; window=1045972; available=1045972
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Data { stream_id: StreamId(9), flags: (0x1: END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Data { stream_id: StreamId(9), flags: (0x1: END_STREAM) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Data { stream_id: StreamId(9), flags: (0x1: END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -> reclaimed; frame=Data { stream_id: StreamId(9), flags: (0x1: END_STREAM) }; sz=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flush
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flushing buffer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE want] signal: Want
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] frame decoded from buffer
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll; bytes=13B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] decoding frame from 13B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] -> kind=WindowUpdate
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_read] received; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2604 }
[2020-08-30T07:34:38Z TRACE h2::proto::connection] recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2604 }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] inc_window; sz=2604; old=1045972; new=1048576
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assign_connection_capacity; inc=2604
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] frame decoded from buffer
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll; bytes=13B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] decoding frame from 13B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] -> kind=WindowUpdate
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_read] received; frame=WindowUpdate { stream_id: StreamId(9), size_increment: 2604 }
[2020-08-30T07:34:38Z TRACE h2::proto::connection] recv WINDOW_UPDATE; frame=WindowUpdate { stream_id: StreamId(9), size_increment: 2604 }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] recv_stream_window_update; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }; inc=2604; flow=FlowControl { window_size: Window(1045972), available: Window(0) }
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] frame decoded from buffer
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll; bytes=14B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] decoding frame from 14B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] -> kind=Headers
[2020-08-30T07:34:38Z TRACE h2::frame::headers] loading headers; flags=(0x4: END_HEADERS)
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] decode
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=5
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=4
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=3
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=2
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=1
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_read] received; frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::connection] recv HEADERS; frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] recv_headers; stream=StreamId(9); state=State { inner: HalfClosedLocal(AwaitingHeaders) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::recv] opening stream; init_window=2097152
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] frame decoded from buffer
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll; bytes=14B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] decoding frame from 14B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] -> kind=Data
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_read] received; frame=Data { stream_id: StreamId(9) }
[2020-08-30T07:34:38Z TRACE h2::proto::connection] recv DATA; frame=Data { stream_id: StreamId(9) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::recv] recv_data; size=5; connection=5241234; stream=2097152
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=5; window=5241234; available=5242880
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=5; window=2097152; available=2097152
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: HalfClosedLocal(Streaming) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] frame decoded from buffer
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll; bytes=10B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] decoding frame from 10B
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] -> kind=Headers
[2020-08-30T07:34:38Z TRACE h2::frame::headers] loading headers; flags=(0x5: END_HEADERS | END_STREAM)
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] decode
[2020-08-30T07:34:38Z TRACE h2::hpack::decoder] Indexed; rem=1
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_read] received; frame=Headers { stream_id: StreamId(9), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::connection] recv HEADERS; frame=Headers { stream_id: StreamId(9), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] recv_headers; stream=StreamId(9); state=State { inner: HalfClosedLocal(Streaming) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::state] recv_close: HalfClosedLocal => Closed
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] dec_num_streams; stream=StreamId(9)
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE tokio_util::codec::framed_read] attempting to decode a frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flush
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flushing buffer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(9), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(1045972), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x1d351a0, vtable: 0xa869f0 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097147), available: Window(2097147) }, in_flight_recv_data: 5, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: Some(Indices { head: 1, tail: 2 }) }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::recv] release_capacity; size=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::recv] release_connection_capacity; size=5, connection in_flight_data=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(9), state: State { inner: Closed(EndStream) }, is_counted: false, ref_count: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(1045972), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x1d351a0, vtable: 0xa869f0 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097147), 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 }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(9); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
[2020-08-30T07:34:38Z WARN hyper::proto::h2] Connection header illegal in HTTP/2: trailer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::send] send_headers; frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }; init_window=65535
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: HalfClosedRemote(Streaming) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(5); requested=1; effective=1; curr=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(5), requested=1; additional=1; buffered=0; window=65535; conn=65535
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(5), capacity=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=1; buffered=0; id=StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] notifying task
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=1; requested=1; buffered=0; has_unavailable=true
[2020-08-30T07:34:38Z TRACE hyper::proto::h2] send body chunk: 5 bytes, eos=false
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data; sz=5; buffered=5; requested=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(5), requested=5; additional=4; buffered=5; window=65535; conn=65534
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(5), capacity=4
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=5; buffered=5; id=StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=5; requested=5; buffered=5; has_unavailable=true
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] send_data (2); available=5; buffered=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: HalfClosedRemote(Streaming) }; is_closed=false; pending_send_empty=false; buffered_send_data=5; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(5); requested=1; effective=6; curr=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity; stream=StreamId(5), requested=6; additional=1; buffered=5; window=65535; conn=65530
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assigning; stream=StreamId(5), capacity=1
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] assigned capacity to stream; available=6; buffered=5; id=StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::stream] notifying task
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try_assign_capacity(2); available=6; requested=6; buffered=5; has_unavailable=true
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(5); requested=0; effective=5; curr=6
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] assign_connection_capacity; inc=1
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flush
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flushing buffer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::state] send_close: HalfClosedRemote => Closed
[2020-08-30T07:34:38Z TRACE h2::proto::streams::send] send_trailers -- queuing; frame=Headers { stream_id: StreamId(5), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_send; StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> already queued
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] reserve_capacity; stream=StreamId(5); requested=0; effective=5; curr=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=5; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(5), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(65535), available: Window(5) }, requested_send_capacity: 5, buffered_send_data: 5, send_task: Some(Waker { data: 0x1d3a6c0, vtable: 0xa869b0 }), pending_send: Deque { indices: Some(Indices { head: 2, tail: 0 }) }, 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(1045972), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=5; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::streams] drop_stream_ref; stream=Stream { id: StreamId(5), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 1, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(65535), available: Window(5) }, requested_send_capacity: 5, buffered_send_data: 5, send_task: Some(Waker { data: 0x1d3a6c0, vtable: 0xa869b0 }), pending_send: Deque { indices: Some(Indices { head: 2, tail: 0 }) }, 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(1045972), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=5; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] poll_complete
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(5); stream.state=State { inner: Closed(EndStream) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(5); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=5; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(5); stream.state=State { inner: Closed(EndStream) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(5); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> data frame; stream=StreamId(5); sz=5; eos=false; window=5; available=5; requested=5; buffered=5;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> sending data frame; len=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating stream flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=5; window=65535; available=5
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -- updating connection flow --
[2020-08-30T07:34:38Z TRACE h2::proto::streams::flow_control] send_data; sz=5; window=65535; available=65535
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Data { stream_id: StreamId(5) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] Queue::push
[2020-08-30T07:34:38Z TRACE h2::proto::streams::store] -> first entry
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Data { stream_id: StreamId(5) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Data { stream_id: StreamId(5) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] -> reclaimed; frame=Data { stream_id: StreamId(5) }; sz=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; stream=StreamId(5); stream.state=State { inner: Closed(EndStream) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] --> stream=StreamId(5); is_pending_reset=false;
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame; frame=Headers { stream_id: StreamId(5), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] transition_after; stream=StreamId(5); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0
[2020-08-30T07:34:38Z TRACE h2::proto::streams::counts] dec_num_streams; stream=StreamId(5)
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] writing frame=Headers { stream_id: StreamId(5), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z DEBUG h2::codec::framed_write] send; frame=Headers { stream_id: StreamId(5), flags: (0x5: END_HEADERS | END_STREAM) }
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] schedule_pending_open
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] pop_frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flush
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] -> not a queued data frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_write] flushing buffer
[2020-08-30T07:34:38Z TRACE h2::proto::streams::prioritize] try reclaim frame
[2020-08-30T07:34:38Z TRACE h2::codec::framed_read] poll
time="2020-08-30T07:34:38Z" level=error msg="fatal error: rpc error: code = Unknown desc = OK: HTTP status code 200; transport: missing content-type field\ngithub.com/moby/buildkit/util/stack.Enable\n\t/src/util/stack/stack.go:56\ngithub.com/moby/buildkit/util/grpcerrors.FromGRPC\n\t/src/util/grpcerrors/grpcerrors.go:177\ngithub.com/moby/buildkit/util/grpcerrors.UnaryClientInterceptor\n\t/src/util/grpcerrors/intercept.go:22\ngoogle.golang.org/grpc.(*ClientConn).Invoke\n\t/src/vendor/google.golang.org/grpc/call.go:35\ngithub.com/moby/buildkit/frontend/gateway/pb.(*lLBBridgeClient).Inputs\n\t/src/frontend/gateway/pb/gateway.pb.go:1554\ngithub.com/moby/buildkit/frontend/gateway/grpcclient.(*grpcClient).Inputs\n\t/src/frontend/gateway/grpcclient/client.go:412\ngithub.com/moby/buildkit/frontend/dockerfile/builder.Build\n\t/src/frontend/dockerfile/builder/build.go:202\ngithub.com/moby/buildkit/frontend/gateway/grpcclient.(*grpcClient).Run\n\t/src/frontend/gateway/grpcclient/client.go:170\ngithub.com/moby/buildkit/frontend/gateway/grpcclient.RunFromEnvironment\n\t/src/frontend/gateway/grpcclient/client.go:91\nmain.main\n\t/src/frontend/dockerfile/cmd/dockerfile-frontend/main.go:29\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:203\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357\nfailed to get frontend inputs\ngithub.com/moby/buildkit/frontend/dockerfile/builder.Build\n\t/src/frontend/dockerfile/builder/build.go:204\ngithub.com/moby/buildkit/frontend/gateway/grpcclient.(*grpcClient).Run\n\t/src/frontend/gateway/grpcclient/client.go:170\ngithub.com/moby/buildkit/frontend/gateway/grpcclient.RunFromEnvironment\n\t/src/frontend/gateway/grpcclient/client.go:91\nmain.main\n\t/src/frontend/dockerfile/cmd/dockerfile-frontend/main.go:29\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:203\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357"
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment