diff --git a/Cargo.toml b/Cargo.toml index ffd1443..e8e04ee 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -47,7 +47,7 @@ tokio-util = { version = "0.3.1", features = ["codec"] } tokio = { version = "0.2", features = ["io-util"] } bytes = "0.5.2" http = "0.2" -log = "0.4.1" +tracing = { version = "0.1.13", default-features = false, features = ["std", "log"] } fnv = "1.0.5" slab = "0.4.0" indexmap = "1.0" diff --git a/src/client.rs b/src/client.rs index 63514e3..597eb3d 100644 --- a/src/client.rs +++ b/src/client.rs @@ -1129,12 +1129,12 @@ where mut io: T, builder: Builder, ) -> Result<(SendRequest, Connection), crate::Error> { - log::debug!("binding client connection"); + tracing::debug!("binding client connection"); let msg: &'static [u8] = b"PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n"; io.write_all(msg).await.map_err(crate::Error::from_io)?; - log::debug!("client connection bound"); + tracing::debug!("client connection bound"); // Create the codec let mut codec = Codec::new(io); diff --git a/src/codec/framed_read.rs b/src/codec/framed_read.rs index 76a236e..2674e39 100644 --- a/src/codec/framed_read.rs +++ b/src/codec/framed_read.rs @@ -62,7 +62,7 @@ impl FramedRead { fn decode_frame(&mut self, mut bytes: BytesMut) -> Result, RecvError> { use self::RecvError::*; - log::trace!("decoding frame from {}B", bytes.len()); + tracing::trace!("decoding frame from {}B", bytes.len()); // Parse the head let head = frame::Head::parse(&bytes); @@ -74,7 +74,7 @@ impl FramedRead { let kind = head.kind(); - log::trace!(" -> kind={:?}", kind); + tracing::trace!(" -> kind={:?}", kind); macro_rules! header_block { ($frame:ident, $head:ident, $bytes:ident) => ({ @@ -124,7 +124,7 @@ impl FramedRead { if is_end_headers { frame.into() } else { - log::trace!("loaded partial header block"); + tracing::trace!("loaded partial header block"); // Defer returning the frame self.partial = Some(Partial { frame: Continuable::$frame(frame), @@ -339,16 +339,16 @@ where fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { loop { - log::trace!("poll"); + tracing::trace!("poll"); let bytes = match ready!(Pin::new(&mut self.inner).poll_next(cx)) { Some(Ok(bytes)) => bytes, Some(Err(e)) => return Poll::Ready(Some(Err(map_err(e)))), None => return Poll::Ready(None), }; - log::trace!("poll; bytes={}B", bytes.len()); + tracing::trace!("poll; bytes={}B", bytes.len()); if let Some(frame) = self.decode_frame(bytes)? { - log::debug!("received; frame={:?}", frame); + tracing::debug!("received; frame={:?}", frame); return Poll::Ready(Some(Ok(frame))); } } diff --git a/src/codec/framed_write.rs b/src/codec/framed_write.rs index c63f122..47ee592 100644 --- a/src/codec/framed_write.rs +++ b/src/codec/framed_write.rs @@ -106,7 +106,7 @@ where // Ensure that we have enough capacity to accept the write. assert!(self.has_capacity()); - log::debug!("send; frame={:?}", item); + tracing::debug!("send; frame={:?}", item); match item { Frame::Data(mut v) => { @@ -150,31 +150,31 @@ where } Frame::Settings(v) => { v.encode(self.buf.get_mut()); - log::trace!("encoded settings; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded settings; rem={:?}", self.buf.remaining()); } Frame::GoAway(v) => { v.encode(self.buf.get_mut()); - log::trace!("encoded go_away; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded go_away; rem={:?}", self.buf.remaining()); } Frame::Ping(v) => { v.encode(self.buf.get_mut()); - log::trace!("encoded ping; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded ping; rem={:?}", self.buf.remaining()); } Frame::WindowUpdate(v) => { v.encode(self.buf.get_mut()); - log::trace!("encoded window_update; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded window_update; rem={:?}", self.buf.remaining()); } Frame::Priority(_) => { /* v.encode(self.buf.get_mut()); - log::trace!("encoded priority; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded priority; rem={:?}", self.buf.remaining()); */ unimplemented!(); } Frame::Reset(v) => { v.encode(self.buf.get_mut()); - log::trace!("encoded reset; rem={:?}", self.buf.remaining()); + tracing::trace!("encoded reset; rem={:?}", self.buf.remaining()); } } @@ -183,18 +183,18 @@ where /// Flush buffered data to the wire pub fn flush(&mut self, cx: &mut Context) -> Poll> { - log::trace!("flush"); + tracing::trace!("flush"); loop { while !self.is_empty() { match self.next { Some(Next::Data(ref mut frame)) => { - log::trace!(" -> queued data frame"); + tracing::trace!(" -> queued data frame"); let mut buf = (&mut self.buf).chain(frame.payload_mut()); ready!(Pin::new(&mut self.inner).poll_write_buf(cx, &mut buf))?; } _ => { - log::trace!(" -> not a queued data frame"); + tracing::trace!(" -> not a queued data frame"); ready!(Pin::new(&mut self.inner).poll_write_buf(cx, &mut self.buf))?; } } @@ -234,7 +234,7 @@ where } } - log::trace!("flushing buffer"); + tracing::trace!("flushing buffer"); // Flush the upstream ready!(Pin::new(&mut self.inner).poll_flush(cx))?; diff --git a/src/frame/go_away.rs b/src/frame/go_away.rs index a46ba7a..52dd91d 100644 --- a/src/frame/go_away.rs +++ b/src/frame/go_away.rs @@ -51,7 +51,7 @@ impl GoAway { } pub fn encode(&self, dst: &mut B) { - log::trace!("encoding GO_AWAY; code={:?}", self.error_code); + tracing::trace!("encoding GO_AWAY; code={:?}", self.error_code); let head = Head::new(Kind::GoAway, 0, StreamId::zero()); head.encode(8, dst); dst.put_u32(self.last_stream_id.into()); diff --git a/src/frame/headers.rs b/src/frame/headers.rs index 2491d8d..0719f14 100644 --- a/src/frame/headers.rs +++ b/src/frame/headers.rs @@ -153,7 +153,7 @@ impl Headers { let flags = HeadersFlag(head.flag()); let mut pad = 0; - log::trace!("loading headers; flags={:?}", flags); + tracing::trace!("loading headers; flags={:?}", flags); // Read the padding length if flags.is_padded() { @@ -817,10 +817,10 @@ impl HeaderBlock { macro_rules! set_pseudo { ($field:ident, $val:expr) => {{ if reg { - log::trace!("load_hpack; header malformed -- pseudo not at head of block"); + tracing::trace!("load_hpack; header malformed -- pseudo not at head of block"); malformed = true; } else if self.pseudo.$field.is_some() { - log::trace!("load_hpack; header malformed -- repeated pseudo"); + tracing::trace!("load_hpack; header malformed -- repeated pseudo"); malformed = true; } else { let __val = $val; @@ -829,7 +829,7 @@ impl HeaderBlock { if headers_size < max_header_list_size { self.pseudo.$field = Some(__val); } else if !self.is_over_size { - log::trace!("load_hpack; header list size over max"); + tracing::trace!("load_hpack; header list size over max"); self.is_over_size = true; } } @@ -856,10 +856,13 @@ impl HeaderBlock { || name == "keep-alive" || name == "proxy-connection" { - log::trace!("load_hpack; connection level header"); + tracing::trace!("load_hpack; connection level header"); malformed = true; } else if name == header::TE && value != "trailers" { - log::trace!("load_hpack; TE header not set to trailers; val={:?}", value); + tracing::trace!( + "load_hpack; TE header not set to trailers; val={:?}", + value + ); malformed = true; } else { reg = true; @@ -868,7 +871,7 @@ impl HeaderBlock { if headers_size < max_header_list_size { self.fields.append(name, value); } else if !self.is_over_size { - log::trace!("load_hpack; header list size over max"); + tracing::trace!("load_hpack; header list size over max"); self.is_over_size = true; } } @@ -882,12 +885,12 @@ impl HeaderBlock { }); if let Err(e) = res { - log::trace!("hpack decoding error; err={:?}", e); + tracing::trace!("hpack decoding error; err={:?}", e); return Err(e.into()); } if malformed { - log::trace!("malformed message"); + tracing::trace!("malformed message"); return Err(Error::MalformedMessage); } diff --git a/src/frame/ping.rs b/src/frame/ping.rs index 1802ec1..241d06e 100644 --- a/src/frame/ping.rs +++ b/src/frame/ping.rs @@ -85,7 +85,7 @@ impl Ping { pub fn encode(&self, dst: &mut B) { let sz = self.payload.len(); - log::trace!("encoding PING; ack={} len={}", self.ack, sz); + tracing::trace!("encoding PING; ack={} len={}", self.ack, sz); let flags = if self.ack { ACK_FLAG } else { 0 }; let head = Head::new(Kind::Ping, flags, StreamId::zero()); diff --git a/src/frame/reset.rs b/src/frame/reset.rs index 6edecf1..b261302 100644 --- a/src/frame/reset.rs +++ b/src/frame/reset.rs @@ -38,7 +38,7 @@ impl Reset { } pub fn encode(&self, dst: &mut B) { - log::trace!( + tracing::trace!( "encoding RESET; id={:?} code={:?}", self.stream_id, self.error_code diff --git a/src/frame/settings.rs b/src/frame/settings.rs index c709381..06de9cf 100644 --- a/src/frame/settings.rs +++ b/src/frame/settings.rs @@ -141,7 +141,7 @@ impl Settings { // Ensure the payload length is correct, each setting is 6 bytes long. if payload.len() % 6 != 0 { - log::debug!("invalid settings payload length; len={:?}", payload.len()); + tracing::debug!("invalid settings payload length; len={:?}", payload.len()); return Err(Error::InvalidPayloadAckSettings); } @@ -199,13 +199,13 @@ impl Settings { let head = Head::new(Kind::Settings, self.flags.into(), StreamId::zero()); let payload_len = self.payload_len(); - log::trace!("encoding SETTINGS; len={}", payload_len); + tracing::trace!("encoding SETTINGS; len={}", payload_len); head.encode(payload_len, dst); // Encode the settings self.for_each(|setting| { - log::trace!("encoding setting; val={:?}", setting); + tracing::trace!("encoding setting; val={:?}", setting); setting.encode(dst) }); } diff --git a/src/frame/window_update.rs b/src/frame/window_update.rs index 72c1c25..eed2ce1 100644 --- a/src/frame/window_update.rs +++ b/src/frame/window_update.rs @@ -48,7 +48,7 @@ impl WindowUpdate { } pub fn encode(&self, dst: &mut B) { - log::trace!("encoding WINDOW_UPDATE; id={:?}", self.stream_id); + tracing::trace!("encoding WINDOW_UPDATE; id={:?}", self.stream_id); let head = Head::new(Kind::WindowUpdate, 0, self.stream_id); head.encode(4, dst); dst.put_u32(self.size_increment); diff --git a/src/hpack/decoder.rs b/src/hpack/decoder.rs index 4befa87..3009e30 100644 --- a/src/hpack/decoder.rs +++ b/src/hpack/decoder.rs @@ -183,7 +183,7 @@ impl Decoder { self.last_max_update = size; } - log::trace!("decode"); + tracing::trace!("decode"); while let Some(ty) = peek_u8(src) { // At this point we are always at the beginning of the next block @@ -191,14 +191,14 @@ impl Decoder { // determined from the first byte. match Representation::load(ty)? { Indexed => { - log::trace!(" Indexed; rem={:?}", src.remaining()); + tracing::trace!(" Indexed; rem={:?}", src.remaining()); can_resize = false; let entry = self.decode_indexed(src)?; consume(src); f(entry); } LiteralWithIndexing => { - log::trace!(" LiteralWithIndexing; rem={:?}", src.remaining()); + tracing::trace!(" LiteralWithIndexing; rem={:?}", src.remaining()); can_resize = false; let entry = self.decode_literal(src, true)?; @@ -209,14 +209,14 @@ impl Decoder { f(entry); } LiteralWithoutIndexing => { - log::trace!(" LiteralWithoutIndexing; rem={:?}", src.remaining()); + tracing::trace!(" LiteralWithoutIndexing; rem={:?}", src.remaining()); can_resize = false; let entry = self.decode_literal(src, false)?; consume(src); f(entry); } LiteralNeverIndexed => { - log::trace!(" LiteralNeverIndexed; rem={:?}", src.remaining()); + tracing::trace!(" LiteralNeverIndexed; rem={:?}", src.remaining()); can_resize = false; let entry = self.decode_literal(src, false)?; consume(src); @@ -226,7 +226,7 @@ impl Decoder { f(entry); } SizeUpdate => { - log::trace!(" SizeUpdate; rem={:?}", src.remaining()); + tracing::trace!(" SizeUpdate; rem={:?}", src.remaining()); if !can_resize { return Err(DecoderError::InvalidMaxDynamicSize); } @@ -248,7 +248,7 @@ impl Decoder { return Err(DecoderError::InvalidMaxDynamicSize); } - log::debug!( + tracing::debug!( "Decoder changed max table size from {} to {}", self.table.size(), new_size @@ -302,7 +302,7 @@ impl Decoder { let len = decode_int(buf, 7)?; if len > buf.remaining() { - log::trace!( + tracing::trace!( "decode_string underflow; len={}; remaining={}", len, buf.remaining() diff --git a/src/lib.rs b/src/lib.rs index 8fd77b3..e5e1f3c 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -84,10 +84,10 @@ macro_rules! proto_err { (conn: $($msg:tt)+) => { - log::debug!("connection error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + tracing::debug!("connection error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) }; (stream: $($msg:tt)+) => { - log::debug!("stream error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + tracing::debug!("stream error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) }; } diff --git a/src/proto/connection.rs b/src/proto/connection.rs index 49c123e..c9e33f4 100644 --- a/src/proto/connection.rs +++ b/src/proto/connection.rs @@ -230,13 +230,13 @@ where // error. This is handled by setting a GOAWAY frame followed by // terminating the connection. Poll::Ready(Err(Connection(e))) => { - log::debug!("Connection::poll; connection error={:?}", e); + tracing::debug!("Connection::poll; connection error={:?}", e); // We may have already sent a GOAWAY for this error, // if so, don't send another, just flush and close up. if let Some(reason) = self.go_away.going_away_reason() { if reason == e { - log::trace!(" -> already going away"); + tracing::trace!(" -> already going away"); self.state = State::Closing(e); continue; } @@ -250,7 +250,7 @@ where // This is handled by resetting the frame then trying to read // another frame. Poll::Ready(Err(Stream { id, reason })) => { - log::trace!("stream error; id={:?}; reason={:?}", id, reason); + tracing::trace!("stream error; id={:?}; reason={:?}", id, reason); self.streams.send_reset(id, reason); } // Attempting to read a frame resulted in an I/O error. All @@ -258,7 +258,7 @@ where // // TODO: Are I/O errors recoverable? Poll::Ready(Err(Io(e))) => { - log::debug!("Connection::poll; IO error={:?}", e); + tracing::debug!("Connection::poll; IO error={:?}", e); let e = e.into(); // Reset all active streams @@ -270,7 +270,7 @@ where } } State::Closing(reason) => { - log::trace!("connection closing after flush"); + tracing::trace!("connection closing after flush"); // Flush/shutdown the codec ready!(self.codec.shutdown(cx))?; @@ -317,28 +317,28 @@ where match ready!(Pin::new(&mut self.codec).poll_next(cx)?) { Some(Headers(frame)) => { - log::trace!("recv HEADERS; frame={:?}", frame); + tracing::trace!("recv HEADERS; frame={:?}", frame); self.streams.recv_headers(frame)?; } Some(Data(frame)) => { - log::trace!("recv DATA; frame={:?}", frame); + tracing::trace!("recv DATA; frame={:?}", frame); self.streams.recv_data(frame)?; } Some(Reset(frame)) => { - log::trace!("recv RST_STREAM; frame={:?}", frame); + tracing::trace!("recv RST_STREAM; frame={:?}", frame); self.streams.recv_reset(frame)?; } Some(PushPromise(frame)) => { - log::trace!("recv PUSH_PROMISE; frame={:?}", frame); + tracing::trace!("recv PUSH_PROMISE; frame={:?}", frame); self.streams.recv_push_promise(frame)?; } Some(Settings(frame)) => { - log::trace!("recv SETTINGS; frame={:?}", frame); + tracing::trace!("recv SETTINGS; frame={:?}", frame); self.settings .recv_settings(frame, &mut self.codec, &mut self.streams)?; } Some(GoAway(frame)) => { - log::trace!("recv GOAWAY; frame={:?}", frame); + tracing::trace!("recv GOAWAY; frame={:?}", frame); // This should prevent starting new streams, // but should allow continuing to process current streams // until they are all EOS. Once they are, State should @@ -347,7 +347,7 @@ where self.error = Some(frame.reason()); } Some(Ping(frame)) => { - log::trace!("recv PING; frame={:?}", frame); + tracing::trace!("recv PING; frame={:?}", frame); let status = self.ping_pong.recv_ping(frame); if status.is_shutdown() { assert!( @@ -360,15 +360,15 @@ where } } Some(WindowUpdate(frame)) => { - log::trace!("recv WINDOW_UPDATE; frame={:?}", frame); + tracing::trace!("recv WINDOW_UPDATE; frame={:?}", frame); self.streams.recv_window_update(frame)?; } Some(Priority(frame)) => { - log::trace!("recv PRIORITY; frame={:?}", frame); + tracing::trace!("recv PRIORITY; frame={:?}", frame); // TODO: handle } None => { - log::trace!("codec closed"); + tracing::trace!("codec closed"); self.streams.recv_eof(false).expect("mutex poisoned"); return Poll::Ready(Ok(())); } diff --git a/src/proto/ping_pong.rs b/src/proto/ping_pong.rs index 0022d4a..e0442c8 100644 --- a/src/proto/ping_pong.rs +++ b/src/proto/ping_pong.rs @@ -107,7 +107,7 @@ impl PingPong { &Ping::SHUTDOWN, "pending_ping should be for shutdown", ); - log::trace!("recv PING SHUTDOWN ack"); + tracing::trace!("recv PING SHUTDOWN ack"); return ReceivedPing::Shutdown; } @@ -117,7 +117,7 @@ impl PingPong { if let Some(ref users) = self.user_pings { if ping.payload() == &Ping::USER && users.receive_pong() { - log::trace!("recv PING USER ack"); + tracing::trace!("recv PING USER ack"); return ReceivedPing::Unknown; } } @@ -125,7 +125,7 @@ impl PingPong { // else we were acked a ping we didn't send? // The spec doesn't require us to do anything about this, // so for resiliency, just ignore it for now. - log::warn!("recv PING ack that we never sent: {:?}", ping); + tracing::warn!("recv PING ack that we never sent: {:?}", ping); ReceivedPing::Unknown } else { // Save the ping's payload to be sent as an acknowledgement. diff --git a/src/proto/settings.rs b/src/proto/settings.rs index b1d91e6..4532923 100644 --- a/src/proto/settings.rs +++ b/src/proto/settings.rs @@ -50,7 +50,7 @@ impl Settings { if frame.is_ack() { match &self.local { Local::WaitingAck(local) => { - log::debug!("received settings ACK; applying {:?}", local); + tracing::debug!("received settings ACK; applying {:?}", local); if let Some(max) = local.max_frame_size() { codec.set_max_recv_frame_size(max as usize); @@ -85,7 +85,7 @@ impl Settings { match &self.local { Local::ToSend(..) | Local::WaitingAck(..) => Err(UserError::SendSettingsWhilePending), Local::Synced => { - log::trace!("queue to send local settings: {:?}", frame); + tracing::trace!("queue to send local settings: {:?}", frame); self.local = Local::ToSend(frame); Ok(()) } @@ -115,7 +115,7 @@ impl Settings { // Buffer the settings frame dst.buffer(frame.into()).expect("invalid settings frame"); - log::trace!("ACK sent; applying settings"); + tracing::trace!("ACK sent; applying settings"); if let Some(val) = settings.header_table_size() { dst.set_send_header_table_size(val as usize); @@ -139,7 +139,7 @@ impl Settings { // Buffer the settings frame dst.buffer(settings.clone().into()) .expect("invalid settings frame"); - log::trace!("local settings sent; waiting for ack: {:?}", settings); + tracing::trace!("local settings sent; waiting for ack: {:?}", settings); self.local = Local::WaitingAck(settings.clone()); } diff --git a/src/proto/streams/counts.rs b/src/proto/streams/counts.rs index bcd07e8..a1b7c1d 100644 --- a/src/proto/streams/counts.rs +++ b/src/proto/streams/counts.rs @@ -133,7 +133,7 @@ impl Counts { // TODO: move this to macro? pub fn transition_after(&mut self, mut stream: store::Ptr, is_reset_counted: bool) { - log::trace!( + tracing::trace!( "transition_after; stream={:?}; state={:?}; is_closed={:?}; \ pending_send_empty={:?}; buffered_send_data={}; \ num_recv={}; num_send={}", @@ -155,7 +155,7 @@ impl Counts { } if stream.is_counted { - log::trace!("dec_num_streams; stream={:?}", stream.id); + tracing::trace!("dec_num_streams; stream={:?}", stream.id); // Decrement the number of active streams. self.dec_num_streams(&mut stream); } diff --git a/src/proto/streams/flow_control.rs b/src/proto/streams/flow_control.rs index f3cea16..bd0aadc 100644 --- a/src/proto/streams/flow_control.rs +++ b/src/proto/streams/flow_control.rs @@ -120,7 +120,7 @@ impl FlowControl { return Err(Reason::FLOW_CONTROL_ERROR); } - log::trace!( + tracing::trace!( "inc_window; sz={}; old={}; new={}", sz, self.window_size, @@ -136,7 +136,7 @@ impl FlowControl { /// This is called after receiving a SETTINGS frame with a lower /// INITIAL_WINDOW_SIZE value. pub fn dec_send_window(&mut self, sz: WindowSize) { - log::trace!( + tracing::trace!( "dec_window; sz={}; window={}, available={}", sz, self.window_size, @@ -151,7 +151,7 @@ impl FlowControl { /// This is called after receiving a SETTINGS ACK frame with a lower /// INITIAL_WINDOW_SIZE value. pub fn dec_recv_window(&mut self, sz: WindowSize) { - log::trace!( + tracing::trace!( "dec_recv_window; sz={}; window={}, available={}", sz, self.window_size, @@ -165,7 +165,7 @@ impl FlowControl { /// Decrements the window reflecting data has actually been sent. The caller /// must ensure that the window has capacity. pub fn send_data(&mut self, sz: WindowSize) { - log::trace!( + tracing::trace!( "send_data; sz={}; window={}; available={}", sz, self.window_size, diff --git a/src/proto/streams/prioritize.rs b/src/proto/streams/prioritize.rs index a133932..180d936 100644 --- a/src/proto/streams/prioritize.rs +++ b/src/proto/streams/prioritize.rs @@ -84,7 +84,7 @@ impl Prioritize { flow.assign_capacity(config.remote_init_window_sz); - log::trace!("Prioritize::new; flow={:?}", flow); + tracing::trace!("Prioritize::new; flow={:?}", flow); Prioritize { pending_send: store::Queue::new(), @@ -112,7 +112,7 @@ impl Prioritize { pub fn schedule_send(&mut self, stream: &mut store::Ptr, task: &mut Option) { // If the stream is waiting to be opened, nothing more to do. if stream.is_send_ready() { - log::trace!("schedule_send; {:?}", stream.id); + tracing::trace!("schedule_send; {:?}", stream.id); // Queue the stream self.pending_send.push(stream); @@ -158,7 +158,7 @@ impl Prioritize { // Update the buffered data counter stream.buffered_send_data += sz; - log::trace!( + tracing::trace!( "send_data; sz={}; buffered={}; requested={}", sz, stream.buffered_send_data, @@ -179,7 +179,7 @@ impl Prioritize { self.reserve_capacity(0, stream, counts); } - log::trace!( + tracing::trace!( "send_data (2); available={}; buffered={}", stream.send_flow.available(), stream.buffered_send_data @@ -214,7 +214,7 @@ impl Prioritize { stream: &mut store::Ptr, counts: &mut Counts, ) { - log::trace!( + tracing::trace!( "reserve_capacity; stream={:?}; requested={:?}; effective={:?}; curr={:?}", stream.id, capacity, @@ -266,7 +266,7 @@ impl Prioritize { inc: WindowSize, stream: &mut store::Ptr, ) -> Result<(), Reason> { - log::trace!( + tracing::trace!( "recv_stream_window_update; stream={:?}; state={:?}; inc={}; flow={:?}", stream.id, stream.state, @@ -326,7 +326,7 @@ impl Prioritize { pub fn clear_pending_capacity(&mut self, store: &mut Store, counts: &mut Counts) { while let Some(stream) = self.pending_capacity.pop(store) { counts.transition(stream, |_, stream| { - log::trace!("clear_pending_capacity; stream={:?}", stream.id); + tracing::trace!("clear_pending_capacity; stream={:?}", stream.id); }) } } @@ -339,7 +339,7 @@ impl Prioritize { ) where R: Resolve, { - log::trace!("assign_connection_capacity; inc={}", inc); + tracing::trace!("assign_connection_capacity; inc={}", inc); self.flow.assign_capacity(inc); @@ -383,7 +383,7 @@ impl Prioritize { stream.send_flow.window_size() - stream.send_flow.available().as_size(), ); - log::trace!( + tracing::trace!( "try_assign_capacity; stream={:?}, requested={}; additional={}; buffered={}; window={}; conn={}", stream.id, total_requested, @@ -416,7 +416,7 @@ impl Prioritize { // TODO: Should prioritization factor into this? let assign = cmp::min(conn_available, additional); - log::trace!(" assigning; stream={:?}, capacity={}", stream.id, assign,); + tracing::trace!(" assigning; stream={:?}, capacity={}", stream.id, assign,); // Assign the capacity to the stream stream.assign_capacity(assign); @@ -425,7 +425,7 @@ impl Prioritize { self.flow.claim_capacity(assign); } - log::trace!( + tracing::trace!( "try_assign_capacity(2); available={}; requested={}; buffered={}; has_unavailable={:?}", stream.send_flow.available(), stream.requested_send_capacity, @@ -485,14 +485,14 @@ impl Prioritize { // The max frame length let max_frame_len = dst.max_send_frame_size(); - log::trace!("poll_complete"); + tracing::trace!("poll_complete"); loop { self.schedule_pending_open(store, counts); match self.pop_frame(buffer, store, max_frame_len, counts) { Some(frame) => { - log::trace!("writing frame={:?}", frame); + tracing::trace!("writing frame={:?}", frame); debug_assert_eq!(self.in_flight_data_frame, InFlightData::Nothing); if let Frame::Data(ref frame) = frame { @@ -538,11 +538,11 @@ impl Prioritize { where B: Buf, { - log::trace!("try reclaim frame"); + tracing::trace!("try reclaim frame"); // First check if there are any data chunks to take back if let Some(frame) = dst.take_last_data_frame() { - log::trace!( + tracing::trace!( " -> reclaimed; frame={:?}; sz={}", frame, frame.payload().inner.get_ref().remaining() @@ -554,7 +554,7 @@ impl Prioritize { match mem::replace(&mut self.in_flight_data_frame, InFlightData::Nothing) { InFlightData::Nothing => panic!("wasn't expecting a frame to reclaim"), InFlightData::Drop => { - log::trace!("not reclaiming frame for cancelled stream"); + tracing::trace!("not reclaiming frame for cancelled stream"); return false; } InFlightData::DataFrame(k) => { @@ -603,11 +603,11 @@ impl Prioritize { } pub fn clear_queue(&mut self, buffer: &mut Buffer>, stream: &mut store::Ptr) { - log::trace!("clear_queue; stream={:?}", stream.id); + tracing::trace!("clear_queue; stream={:?}", stream.id); // TODO: make this more efficient? while let Some(frame) = stream.pending_send.pop_front(buffer) { - log::trace!("dropping; frame={:?}", frame); + tracing::trace!("dropping; frame={:?}", frame); } stream.buffered_send_data = 0; @@ -644,12 +644,12 @@ impl Prioritize { where B: Buf, { - log::trace!("pop_frame"); + tracing::trace!("pop_frame"); loop { match self.pending_send.pop(store) { Some(mut stream) => { - log::trace!( + tracing::trace!( "pop_frame; stream={:?}; stream.state={:?}", stream.id, stream.state @@ -662,7 +662,7 @@ impl Prioritize { // To be safe, we just always ask the stream. let is_pending_reset = stream.is_pending_reset_expiration(); - log::trace!( + tracing::trace!( " --> stream={:?}; is_pending_reset={:?};", stream.id, is_pending_reset @@ -675,7 +675,7 @@ impl Prioritize { let stream_capacity = stream.send_flow.available(); let sz = frame.payload().remaining(); - log::trace!( + tracing::trace!( " --> data frame; stream={:?}; sz={}; eos={:?}; window={}; \ available={}; requested={}; buffered={};", frame.stream_id(), @@ -690,7 +690,7 @@ impl Prioritize { // Zero length data frames always have capacity to // be sent. if sz > 0 && stream_capacity == 0 { - log::trace!( + tracing::trace!( " --> stream capacity is 0; requested={}", stream.requested_send_capacity ); @@ -721,10 +721,10 @@ impl Prioritize { // capacity at this point. debug_assert!(len <= self.flow.window_size()); - log::trace!(" --> sending data frame; len={}", len); + tracing::trace!(" --> sending data frame; len={}", len); // Update the flow control - log::trace!(" -- updating stream flow --"); + tracing::trace!(" -- updating stream flow --"); stream.send_flow.send_data(len); // Decrement the stream's buffered data counter @@ -737,7 +737,7 @@ impl Prioritize { // line. self.flow.assign_capacity(len); - log::trace!(" -- updating connection flow --"); + tracing::trace!(" -- updating connection flow --"); self.flow.send_data(len); // Wrap the frame's data payload to ensure that the @@ -789,7 +789,7 @@ impl Prioritize { // had data buffered to be sent, but all the frames are cleared // in clear_queue(). Instead of doing O(N) traversal through queue // to remove, lets just ignore the stream here. - log::trace!("removing dangling stream from pending_send"); + tracing::trace!("removing dangling stream from pending_send"); // Since this should only happen as a consequence of `clear_queue`, // we must be in a closed state of some kind. debug_assert!(stream.state.is_closed()); @@ -799,7 +799,7 @@ impl Prioritize { } }; - log::trace!("pop_frame; frame={:?}", frame); + tracing::trace!("pop_frame; frame={:?}", frame); if cfg!(debug_assertions) && stream.state.is_idle() { debug_assert!(stream.id > self.last_opened_id); @@ -824,11 +824,11 @@ impl Prioritize { } fn schedule_pending_open(&mut self, store: &mut Store, counts: &mut Counts) { - log::trace!("schedule_pending_open"); + tracing::trace!("schedule_pending_open"); // check for any pending open streams while counts.can_inc_num_send_streams() { if let Some(mut stream) = self.pending_open.pop(store) { - log::trace!("schedule_pending_open; stream={:?}", stream.id); + tracing::trace!("schedule_pending_open; stream={:?}", stream.id); counts.inc_num_send_streams(&mut stream); self.pending_send.push(&mut stream); diff --git a/src/proto/streams/recv.rs b/src/proto/streams/recv.rs index f0e23a4..682200d 100644 --- a/src/proto/streams/recv.rs +++ b/src/proto/streams/recv.rs @@ -160,7 +160,7 @@ impl Recv { stream: &mut store::Ptr, counts: &mut Counts, ) -> Result<(), RecvHeaderBlockError>> { - log::trace!("opening stream; init_window={}", self.init_window_sz); + tracing::trace!("opening stream; init_window={}", self.init_window_sz); let is_initial = stream.state.recv_open(frame.is_end_stream())?; if is_initial { @@ -206,7 +206,7 @@ impl Recv { // So, if peer is a server, we'll send a 431. In either case, // an error is recorded, which will send a REFUSED_STREAM, // since we don't want any of the data frames either. - log::debug!( + tracing::debug!( "stream error REQUEST_HEADER_FIELDS_TOO_LARGE -- \ recv_headers: frame is over size; stream={:?}", stream.id @@ -341,7 +341,7 @@ impl Recv { /// Releases capacity of the connection pub fn release_connection_capacity(&mut self, capacity: WindowSize, task: &mut Option) { - log::trace!( + tracing::trace!( "release_connection_capacity; size={}, connection in_flight_data={}", capacity, self.in_flight_data, @@ -367,7 +367,7 @@ impl Recv { stream: &mut store::Ptr, task: &mut Option, ) -> Result<(), UserError> { - log::trace!("release_capacity; size={}", capacity); + tracing::trace!("release_capacity; size={}", capacity); if capacity > stream.in_flight_recv_data { return Err(UserError::ReleaseCapacityTooBig); @@ -401,7 +401,7 @@ impl Recv { return; } - log::trace!( + tracing::trace!( "auto-release closed stream ({:?}) capacity: {:?}", stream.id, stream.in_flight_recv_data, @@ -426,7 +426,7 @@ impl Recv { /// The `task` is an optional parked task for the `Connection` that might /// be blocked on needing more window capacity. pub fn set_target_connection_window(&mut self, target: WindowSize, task: &mut Option) { - log::trace!( + tracing::trace!( "set_target_connection_window; target={}; available={}, reserved={}", target, self.flow.available(), @@ -469,7 +469,7 @@ impl Recv { let old_sz = self.init_window_sz; self.init_window_sz = target; - log::trace!("update_initial_window_size; new={}; old={}", target, old_sz,); + tracing::trace!("update_initial_window_size; new={}; old={}", target, old_sz,); // Per RFC 7540 ยง6.9.2: // @@ -490,7 +490,7 @@ impl Recv { if target < old_sz { // We must decrease the (local) window on every open stream. let dec = old_sz - target; - log::trace!("decrementing all windows; dec={}", dec); + tracing::trace!("decrementing all windows; dec={}", dec); store.for_each(|mut stream| { stream.recv_flow.dec_recv_window(dec); @@ -499,7 +499,7 @@ impl Recv { } else if target > old_sz { // We must increase the (local) window on every open stream. let inc = target - old_sz; - log::trace!("incrementing all windows; inc={}", inc); + tracing::trace!("incrementing all windows; inc={}", inc); store.for_each(|mut stream| { // XXX: Shouldn't the peer have already noticed our // overflow and sent us a GOAWAY? @@ -549,7 +549,7 @@ impl Recv { return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } - log::trace!( + tracing::trace!( "recv_data; size={}; connection={}; stream={}", sz, self.flow.window_size(), @@ -557,7 +557,7 @@ impl Recv { ); if is_ignoring_frame { - log::trace!( + tracing::trace!( "recv_data; frame ignored on locally reset {:?} for some time", stream.id, ); @@ -647,7 +647,7 @@ impl Recv { pub fn consume_connection_window(&mut self, sz: WindowSize) -> Result<(), RecvError> { if self.flow.window_size() < sz { - log::debug!( + tracing::debug!( "connection error FLOW_CONTROL_ERROR -- window_size ({:?}) < sz ({:?});", self.flow.window_size(), sz, @@ -681,7 +681,7 @@ impl Recv { // So, if peer is a server, we'll send a 431. In either case, // an error is recorded, which will send a REFUSED_STREAM, // since we don't want any of the data frames either. - log::debug!( + tracing::debug!( "stream error REFUSED_STREAM -- recv_push_promise: \ headers frame is over size; promised_id={:?};", frame.promised_id(), @@ -730,7 +730,7 @@ impl Recv { pub fn ensure_not_idle(&self, id: StreamId) -> Result<(), Reason> { if let Ok(next) = self.next_stream_id { if id >= next { - log::debug!( + tracing::debug!( "stream ID implicitly closed, PROTOCOL_ERROR; stream={:?}", id ); @@ -821,7 +821,7 @@ impl Recv { return; } - log::trace!("enqueue_reset_expiration; {:?}", stream.id); + tracing::trace!("enqueue_reset_expiration; {:?}", stream.id); if !counts.can_inc_num_reset_streams() { // try to evict 1 stream if possible @@ -891,7 +891,7 @@ impl Recv { fn clear_stream_window_update_queue(&mut self, store: &mut Store, counts: &mut Counts) { while let Some(stream) = self.pending_window_updates.pop(store) { counts.transition(stream, |_, stream| { - log::trace!("clear_stream_window_update_queue; stream={:?}", stream.id); + tracing::trace!("clear_stream_window_update_queue; stream={:?}", stream.id); }) } } @@ -981,7 +981,7 @@ impl Recv { }; counts.transition(stream, |_, stream| { - log::trace!("pending_window_updates -- pop; stream={:?}", stream.id); + tracing::trace!("pending_window_updates -- pop; stream={:?}", stream.id); debug_assert!(!stream.is_pending_window_update); if !stream.state.is_recv_streaming() { diff --git a/src/proto/streams/send.rs b/src/proto/streams/send.rs index 4d38593..220a8b4 100644 --- a/src/proto/streams/send.rs +++ b/src/proto/streams/send.rs @@ -77,11 +77,11 @@ impl Send { || fields.contains_key("keep-alive") || fields.contains_key("proxy-connection") { - log::debug!("illegal connection-specific headers found"); + tracing::debug!("illegal connection-specific headers found"); return Err(UserError::MalformedHeaders); } else if let Some(te) = fields.get(http::header::TE) { if te != "trailers" { - log::debug!("illegal connection-specific headers found"); + tracing::debug!("illegal connection-specific headers found"); return Err(UserError::MalformedHeaders); } } @@ -95,7 +95,7 @@ impl Send { stream: &mut store::Ptr, task: &mut Option, ) -> Result<(), UserError> { - log::trace!( + tracing::trace!( "send_push_promise; frame={:?}; init_window={:?}", frame, self.init_window_sz @@ -118,7 +118,7 @@ impl Send { counts: &mut Counts, task: &mut Option, ) -> Result<(), UserError> { - log::trace!( + tracing::trace!( "send_headers; frame={:?}; init_window={:?}", frame, self.init_window_sz @@ -167,7 +167,7 @@ impl Send { let is_closed = stream.state.is_closed(); let is_empty = stream.pending_send.is_empty(); - log::trace!( + tracing::trace!( "send_reset(..., reason={:?}, stream={:?}, ..., \ is_reset={:?}; is_closed={:?}; pending_send.is_empty={:?}; \ state={:?} \ @@ -182,7 +182,7 @@ impl Send { if is_reset { // Don't double reset - log::trace!( + tracing::trace!( " -> not sending RST_STREAM ({:?} is already reset)", stream.id ); @@ -195,7 +195,7 @@ impl Send { // If closed AND the send queue is flushed, then the stream cannot be // reset explicitly, either. Implicit resets can still be queued. if is_closed && is_empty { - log::trace!( + tracing::trace!( " -> not sending explicit RST_STREAM ({:?} was closed \ and send queue was flushed)", stream.id @@ -211,7 +211,7 @@ impl Send { let frame = frame::Reset::new(stream.id, reason); - log::trace!("send_reset -- queueing; frame={:?}", frame); + tracing::trace!("send_reset -- queueing; frame={:?}", frame); self.prioritize .queue_frame(frame.into(), buffer, stream, task); self.prioritize.reclaim_all_capacity(stream, counts); @@ -269,7 +269,7 @@ impl Send { stream.state.send_close(); - log::trace!("send_trailers -- queuing; frame={:?}", frame); + tracing::trace!("send_trailers -- queuing; frame={:?}", frame); self.prioritize .queue_frame(frame.into(), buffer, stream, task); @@ -370,7 +370,7 @@ impl Send { task: &mut Option, ) -> Result<(), Reason> { if let Err(e) = self.prioritize.recv_stream_window_update(sz, stream) { - log::debug!("recv_stream_window_update !!; err={:?}", e); + tracing::debug!("recv_stream_window_update !!; err={:?}", e); self.send_reset(Reason::FLOW_CONTROL_ERROR, buffer, stream, counts, task); @@ -443,7 +443,7 @@ impl Send { if val < old_val { // We must decrease the (remote) window on every open stream. let dec = old_val - val; - log::trace!("decrementing all windows; dec={}", dec); + tracing::trace!("decrementing all windows; dec={}", dec); let mut total_reclaimed = 0; store.for_each(|mut stream| { @@ -469,7 +469,7 @@ impl Send { 0 }; - log::trace!( + tracing::trace!( "decremented stream window; id={:?}; decr={}; reclaimed={}; flow={:?}", stream.id, dec, diff --git a/src/proto/streams/state.rs b/src/proto/streams/state.rs index 2632312..45ec82f 100644 --- a/src/proto/streams/state.rs +++ b/src/proto/streams/state.rs @@ -216,12 +216,12 @@ impl State { match self.inner { Open { local, .. } => { // The remote side will continue to receive data. - log::trace!("recv_close: Open => HalfClosedRemote({:?})", local); + tracing::trace!("recv_close: Open => HalfClosedRemote({:?})", local); self.inner = HalfClosedRemote(local); Ok(()) } HalfClosedLocal(..) => { - log::trace!("recv_close: HalfClosedLocal => Closed"); + tracing::trace!("recv_close: HalfClosedLocal => Closed"); self.inner = Closed(Cause::EndStream); Ok(()) } @@ -257,7 +257,7 @@ impl State { // previous state with the received RST_STREAM, so that the queue // will be cleared by `Prioritize::pop_frame`. state => { - log::trace!( + tracing::trace!( "recv_reset; reason={:?}; state={:?}; queued={:?}", reason, state, @@ -275,7 +275,7 @@ impl State { match self.inner { Closed(..) => {} _ => { - log::trace!("recv_err; err={:?}", err); + tracing::trace!("recv_err; err={:?}", err); self.inner = Closed(match *err { Proto(reason) => Cause::LocallyReset(reason), Io(..) => Cause::Io, @@ -288,7 +288,7 @@ impl State { match self.inner { Closed(..) => {} s => { - log::trace!("recv_eof; state={:?}", s); + tracing::trace!("recv_eof; state={:?}", s); self.inner = Closed(Cause::Io); } } @@ -299,11 +299,11 @@ impl State { match self.inner { Open { remote, .. } => { // The remote side will continue to receive data. - log::trace!("send_close: Open => HalfClosedLocal({:?})", remote); + tracing::trace!("send_close: Open => HalfClosedLocal({:?})", remote); self.inner = HalfClosedLocal(remote); } HalfClosedRemote(..) => { - log::trace!("send_close: HalfClosedRemote => Closed"); + tracing::trace!("send_close: HalfClosedRemote => Closed"); self.inner = Closed(Cause::EndStream); } state => panic!("send_close: unexpected state {:?}", state), diff --git a/src/proto/streams/store.rs b/src/proto/streams/store.rs index 09d8a64..9b66cf9 100644 --- a/src/proto/streams/store.rs +++ b/src/proto/streams/store.rs @@ -244,10 +244,10 @@ where /// /// If the stream is already contained by the list, return `false`. pub fn push(&mut self, stream: &mut store::Ptr) -> bool { - log::trace!("Queue::push"); + tracing::trace!("Queue::push"); if N::is_queued(stream) { - log::trace!(" -> already queued"); + tracing::trace!(" -> already queued"); return false; } @@ -259,7 +259,7 @@ where // Queue the stream match self.indices { Some(ref mut idxs) => { - log::trace!(" -> existing entries"); + tracing::trace!(" -> existing entries"); // Update the current tail node to point to `stream` let key = stream.key(); @@ -269,7 +269,7 @@ where idxs.tail = stream.key(); } None => { - log::trace!(" -> first entry"); + tracing::trace!(" -> first entry"); self.indices = Some(store::Indices { head: stream.key(), tail: stream.key(), diff --git a/src/proto/streams/stream.rs b/src/proto/streams/stream.rs index 3986720..c2b647c 100644 --- a/src/proto/streams/stream.rs +++ b/src/proto/streams/stream.rs @@ -265,7 +265,7 @@ impl Stream { self.send_capacity_inc = true; self.send_flow.assign_capacity(capacity); - log::trace!( + tracing::trace!( " assigned capacity to stream; available={}; buffered={}; id={:?}", self.send_flow.available(), self.buffered_send_data, @@ -274,7 +274,7 @@ impl Stream { // Only notify if the capacity exceeds the amount of buffered data if self.send_flow.available() > self.buffered_send_data { - log::trace!(" notifying task"); + tracing::trace!(" notifying task"); self.notify_send(); } } diff --git a/src/proto/streams/streams.rs b/src/proto/streams/streams.rs index 8f61861..26eabbe 100644 --- a/src/proto/streams/streams.rs +++ b/src/proto/streams/streams.rs @@ -135,7 +135,7 @@ where // The GOAWAY process has begun. All streams with a greater ID than // specified as part of GOAWAY should be ignored. if id > me.actions.recv.max_stream_id() { - log::trace!( + tracing::trace!( "id ({:?}) > max_stream_id ({:?}), ignoring HEADERS", id, me.actions.recv.max_stream_id() @@ -155,7 +155,7 @@ where // This may be response headers for a stream we've already // forgotten about... if me.actions.may_have_forgotten_stream::

(id) { - log::debug!( + tracing::debug!( "recv_headers for old stream={:?}, sending STREAM_CLOSED", id, ); @@ -187,7 +187,7 @@ where // Locally reset streams must ignore frames "for some time". // This is because the remote may have sent trailers before // receiving the RST_STREAM frame. - log::trace!("recv_headers; ignoring trailers on {:?}", stream.id); + tracing::trace!("recv_headers; ignoring trailers on {:?}", stream.id); return Ok(()); } @@ -196,7 +196,7 @@ where let send_buffer = &mut *send_buffer; me.counts.transition(stream, |counts, stream| { - log::trace!( + tracing::trace!( "recv_headers; stream={:?}; state={:?}", stream.id, stream.state @@ -259,7 +259,7 @@ where // The GOAWAY process has begun. All streams with a greater ID // than specified as part of GOAWAY should be ignored. if id > me.actions.recv.max_stream_id() { - log::trace!( + tracing::trace!( "id ({:?}) > max_stream_id ({:?}), ignoring DATA", id, me.actions.recv.max_stream_id() @@ -268,7 +268,7 @@ where } if me.actions.may_have_forgotten_stream::

(id) { - log::debug!("recv_data for old stream={:?}, sending STREAM_CLOSED", id,); + tracing::debug!("recv_data for old stream={:?}, sending STREAM_CLOSED", id,); let sz = frame.payload().len(); // This should have been enforced at the codec::FramedRead layer, so @@ -322,7 +322,7 @@ where // The GOAWAY process has begun. All streams with a greater ID than // specified as part of GOAWAY should be ignored. if id > me.actions.recv.max_stream_id() { - log::trace!( + tracing::trace!( "id ({:?}) > max_stream_id ({:?}), ignoring RST_STREAM", id, me.actions.recv.max_stream_id() @@ -470,7 +470,7 @@ where // The GOAWAY process has begun. All streams with a greater ID // than specified as part of GOAWAY should be ignored. if id > me.actions.recv.max_stream_id() { - log::trace!( + tracing::trace!( "id ({:?}) > max_stream_id ({:?}), ignoring PUSH_PROMISE", id, me.actions.recv.max_stream_id() @@ -563,7 +563,7 @@ where me.refs += 1; key.map(|key| { let stream = &mut me.store.resolve(key); - log::trace!( + tracing::trace!( "next_incoming; id={:?}, state={:?}", stream.id, stream.state @@ -788,7 +788,7 @@ where if let Some(pending) = pending { let mut stream = me.store.resolve(pending.key); - log::trace!("poll_pending_open; stream = {:?}", stream.is_pending_open); + tracing::trace!("poll_pending_open; stream = {:?}", stream.is_pending_open); if stream.is_pending_open { stream.wait_send(cx); return Poll::Pending; @@ -818,7 +818,7 @@ where actions.conn_error = Some(io::Error::from(io::ErrorKind::BrokenPipe).into()); } - log::trace!("Streams::recv_eof"); + tracing::trace!("Streams::recv_eof"); me.store .for_each(|stream| { @@ -1265,7 +1265,7 @@ fn drop_stream_ref(inner: &Mutex, key: store::Key) { Ok(inner) => inner, Err(_) => { if ::std::thread::panicking() { - log::trace!("StreamRef::drop; mutex poisoned"); + tracing::trace!("StreamRef::drop; mutex poisoned"); return; } else { panic!("StreamRef::drop; mutex poisoned"); @@ -1277,7 +1277,7 @@ fn drop_stream_ref(inner: &Mutex, key: store::Key) { me.refs -= 1; let mut stream = me.store.resolve(key); - log::trace!("drop_stream_ref; stream={:?}", stream); + tracing::trace!("drop_stream_ref; stream={:?}", stream); // decrement the stream's ref count by 1. stream.ref_dec(); diff --git a/src/server.rs b/src/server.rs index b6e7394..69ba16a 100644 --- a/src/server.rs +++ b/src/server.rs @@ -402,7 +402,7 @@ where } if let Some(inner) = self.connection.next_incoming() { - log::trace!("received incoming"); + tracing::trace!("received incoming"); let (head, _) = inner.take_request().into_parts(); let body = RecvStream::new(FlowControl::new(inner.clone_to_opaque())); @@ -1179,7 +1179,7 @@ where type Output = Result, crate::Error>; fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { - log::trace!("Handshake::poll(); state={:?};", self.state); + tracing::trace!("Handshake::poll(); state={:?};", self.state); use crate::server::Handshaking::*; self.state = if let Flushing(ref mut flush) = self.state { @@ -1188,11 +1188,11 @@ where // for the client preface. let codec = match Pin::new(flush).poll(cx)? { Poll::Pending => { - log::trace!("Handshake::poll(); flush.poll()=Pending"); + tracing::trace!("Handshake::poll(); flush.poll()=Pending"); return Poll::Pending; } Poll::Ready(flushed) => { - log::trace!("Handshake::poll(); flush.poll()=Ready"); + tracing::trace!("Handshake::poll(); flush.poll()=Ready"); flushed } }; @@ -1229,7 +1229,7 @@ where }, ); - log::trace!("Handshake::poll(); connection established!"); + tracing::trace!("Handshake::poll(); connection established!"); let mut c = Connection { connection }; if let Some(sz) = self.builder.initial_target_connection_window_size { c.set_target_window_size(sz); @@ -1289,12 +1289,12 @@ impl Peer { if let Err(e) = frame::PushPromise::validate_request(&request) { use PushPromiseHeaderError::*; match e { - NotSafeAndCacheable => log::debug!( + NotSafeAndCacheable => tracing::debug!( "convert_push_message: method {} is not safe and cacheable; promised_id={:?}", request.method(), promised_id, ), - InvalidContentLength(e) => log::debug!( + InvalidContentLength(e) => tracing::debug!( "convert_push_message; promised request has invalid content-length {:?}; promised_id={:?}", e, promised_id, @@ -1347,7 +1347,7 @@ impl proto::Peer for Peer { macro_rules! malformed { ($($arg:tt)*) => {{ - log::debug!($($arg)*); + tracing::debug!($($arg)*); return Err(RecvError::Stream { id: stream_id, reason: Reason::PROTOCOL_ERROR, @@ -1367,7 +1367,7 @@ impl proto::Peer for Peer { // Specifying :status for a request is a protocol error if pseudo.status.is_some() { - log::trace!("malformed headers: :status field on request; PROTOCOL_ERROR"); + tracing::trace!("malformed headers: :status field on request; PROTOCOL_ERROR"); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } diff --git a/tests/h2-tests/Cargo.toml b/tests/h2-tests/Cargo.toml index 3e9d130..4c711fe 100644 --- a/tests/h2-tests/Cargo.toml +++ b/tests/h2-tests/Cargo.toml @@ -9,6 +9,6 @@ edition = "2018" [dev-dependencies] h2-support = { path = "../h2-support" } -log = "0.4.1" +tracing = "0.1.13" futures = { version = "0.3", default-features = false, features = ["alloc"] } tokio = { version = "0.2", features = ["macros", "tcp"] } diff --git a/tests/h2-tests/tests/client_request.rs b/tests/h2-tests/tests/client_request.rs index b156d97..8175ce4 100644 --- a/tests/h2-tests/tests/client_request.rs +++ b/tests/h2-tests/tests/client_request.rs @@ -16,7 +16,7 @@ async fn handshake() { let (_client, h2) = client::handshake(mock).await.unwrap(); - log::trace!("hands have been shook"); + tracing::trace!("hands have been shook"); // At this point, the connection should be closed h2.await.unwrap(); @@ -84,7 +84,7 @@ async fn recv_invalid_server_stream_id() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, _) = client.send_request(request, true).unwrap(); // The connection errors diff --git a/tests/h2-tests/tests/stream_states.rs b/tests/h2-tests/tests/stream_states.rs index dd0316c..2082d5f 100644 --- a/tests/h2-tests/tests/stream_states.rs +++ b/tests/h2-tests/tests/stream_states.rs @@ -31,7 +31,7 @@ async fn send_recv_headers_only() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, _) = client.send_request(request, true).unwrap(); let resp = h2.run(response).await.unwrap(); @@ -72,7 +72,7 @@ async fn send_recv_data() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, mut stream) = client.send_request(request, false).unwrap(); // Reserve send capacity @@ -129,7 +129,7 @@ async fn send_headers_recv_data_single_frame() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, _) = client.send_request(request, true).unwrap(); let resp = h2.run(response).await.unwrap(); diff --git a/tests/h2-tests/tests/trailers.rs b/tests/h2-tests/tests/trailers.rs index 513b65d..0786655 100644 --- a/tests/h2-tests/tests/trailers.rs +++ b/tests/h2-tests/tests/trailers.rs @@ -28,7 +28,7 @@ async fn recv_trailers_only() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, _) = client.send_request(request, true).unwrap(); let response = h2.run(response).await.unwrap(); @@ -79,7 +79,7 @@ async fn send_trailers_immediately() { .body(()) .unwrap(); - log::info!("sending request"); + tracing::info!("sending request"); let (response, mut stream) = client.send_request(request, false).unwrap(); let mut trailers = HeaderMap::new();