diff --git a/src/codec/framed_read.rs b/src/codec/framed_read.rs index 2f7bdc0..baabfa6 100644 --- a/src/codec/framed_read.rs +++ b/src/codec/framed_read.rs @@ -63,7 +63,7 @@ impl FramedRead { let head = frame::Head::parse(&bytes); if self.partial.is_some() && head.kind() != Kind::Continuation { - trace!("connection error PROTOCOL_ERROR -- expected CONTINUATION, got {:?}", head.kind()); + proto_err!(conn: "expected CONTINUATION, got {:?}", head.kind()); return Err(Connection(Reason::PROTOCOL_ERROR)); } @@ -81,7 +81,7 @@ impl FramedRead { let (mut frame, mut payload) = match frame::$frame::load($head, $bytes) { Ok(res) => res, Err(frame::Error::InvalidDependencyId) => { - debug!("stream error PROTOCOL_ERROR -- invalid HEADERS dependency ID"); + proto_err!(stream: "invalid HEADERS dependency ID"); // A stream cannot depend on itself. An endpoint MUST // treat this as a stream error (Section 5.4.2) of type // `PROTOCOL_ERROR`. @@ -91,7 +91,7 @@ impl FramedRead { }); }, Err(e) => { - debug!("connection error PROTOCOL_ERROR -- failed to load frame; err={:?}", e); + proto_err!(conn: "failed to load frame; err={:?}", e); return Err(Connection(Reason::PROTOCOL_ERROR)); } }; @@ -103,15 +103,15 @@ impl FramedRead { Ok(_) => {}, Err(frame::Error::Hpack(hpack::DecoderError::NeedMore(_))) if !is_end_headers => {}, Err(frame::Error::MalformedMessage) => { - - debug!("stream error PROTOCOL_ERROR -- malformed header block"); + let id = $head.stream_id(); + proto_err!(stream: "malformed header block; stream={:?}", id); return Err(Stream { - id: $head.stream_id(), + id, reason: Reason::PROTOCOL_ERROR, }); }, Err(e) => { - debug!("connection error PROTOCOL_ERROR -- failed HPACK decoding; err={:?}", e); + proto_err!(conn: "failed HPACK decoding; err={:?}", e); return Err(Connection(Reason::PROTOCOL_ERROR)); } } @@ -136,7 +136,7 @@ impl FramedRead { let res = frame::Settings::load(head, &bytes[frame::HEADER_LEN..]); res.map_err(|e| { - debug!("connection error PROTOCOL_ERROR -- failed to load SETTINGS frame; err={:?}", e); + proto_err!(conn: "failed to load SETTINGS frame; err={:?}", e); Connection(Reason::PROTOCOL_ERROR) })?.into() }, @@ -144,7 +144,7 @@ impl FramedRead { let res = frame::Ping::load(head, &bytes[frame::HEADER_LEN..]); res.map_err(|e| { - debug!("connection error PROTOCOL_ERROR -- failed to load PING frame; err={:?}", e); + proto_err!(conn: "failed to load PING frame; err={:?}", e); Connection(Reason::PROTOCOL_ERROR) })?.into() }, @@ -152,7 +152,7 @@ impl FramedRead { let res = frame::WindowUpdate::load(head, &bytes[frame::HEADER_LEN..]); res.map_err(|e| { - debug!("connection error PROTOCOL_ERROR -- failed to load WINDOW_UPDATE frame; err={:?}", e); + proto_err!(conn: "failed to load WINDOW_UPDATE frame; err={:?}", e); Connection(Reason::PROTOCOL_ERROR) })?.into() }, @@ -162,7 +162,7 @@ impl FramedRead { // TODO: Should this always be connection level? Probably not... res.map_err(|e| { - debug!("connection error PROTOCOL_ERROR -- failed to load DATA frame; err={:?}", e); + proto_err!(conn: "failed to load DATA frame; err={:?}", e); Connection(Reason::PROTOCOL_ERROR) })?.into() }, @@ -171,11 +171,17 @@ impl FramedRead { }, Kind::Reset => { let res = frame::Reset::load(head, &bytes[frame::HEADER_LEN..]); - res.map_err(|_| Connection(Reason::PROTOCOL_ERROR))?.into() + res.map_err(|e| { + proto_err!(conn: "failed to load RESET frame; err={:?}", e); + Connection(Reason::PROTOCOL_ERROR) + })?.into() }, Kind::GoAway => { let res = frame::GoAway::load(&bytes[frame::HEADER_LEN..]); - res.map_err(|_| Connection(Reason::PROTOCOL_ERROR))?.into() + res.map_err(|e| { + proto_err!(conn: "failed to load GO_AWAY frame; err={:?}", e); + Connection(Reason::PROTOCOL_ERROR) + })?.into() }, Kind::PushPromise => { header_block!(PushPromise, head, bytes) @@ -183,6 +189,7 @@ impl FramedRead { Kind::Priority => { if head.stream_id() == 0 { // Invalid stream identifier + proto_err!(conn: "invalid stream ID 0"); return Err(Connection(Reason::PROTOCOL_ERROR)); } @@ -192,13 +199,17 @@ impl FramedRead { // A stream cannot depend on itself. An endpoint MUST // treat this as a stream error (Section 5.4.2) of type // `PROTOCOL_ERROR`. - debug!("stream error PROTOCOL_ERROR -- PRIORITY invalid dependency ID"); + let id = head.stream_id(); + proto_err!(stream: "PRIORITY invalid dependency ID; stream={:?}", id); return Err(Stream { - id: head.stream_id(), + id, reason: Reason::PROTOCOL_ERROR, }); }, - Err(_) => return Err(Connection(Reason::PROTOCOL_ERROR)), + Err(e) => { + proto_err!(conn: "failed to load PRIORITY frame; err={:?};", e); + return Err(Connection(Reason::PROTOCOL_ERROR)); + } } }, Kind::Continuation => { @@ -207,14 +218,14 @@ impl FramedRead { let mut partial = match self.partial.take() { Some(partial) => partial, None => { - debug!("connection error PROTOCOL_ERROR -- received unexpected CONTINUATION frame"); + proto_err!(conn: "received unexpected CONTINUATION frame"); return Err(Connection(Reason::PROTOCOL_ERROR)); } }; // The stream identifiers must match if partial.frame.stream_id() != head.stream_id() { - debug!("connection error PROTOCOL_ERROR -- CONTINUATION frame stream ID does not match previous frame stream ID"); + proto_err!(conn: "CONTINUATION frame stream ID does not match previous frame stream ID"); return Err(Connection(Reason::PROTOCOL_ERROR)); } @@ -239,7 +250,7 @@ impl FramedRead { // we should continue to ignore decoding, or to tell // the attacker to go away. if partial.buf.len() + bytes.len() > self.max_header_list_size { - debug!("connection error COMPRESSION_ERROR -- CONTINUATION frame header block size over ignorable limit"); + proto_err!(conn: "CONTINUATION frame header block size over ignorable limit"); return Err(Connection(Reason::COMPRESSION_ERROR)); } } @@ -250,14 +261,15 @@ impl FramedRead { Ok(_) => {}, Err(frame::Error::Hpack(hpack::DecoderError::NeedMore(_))) if !is_end_headers => {}, Err(frame::Error::MalformedMessage) => { - debug!("stream error PROTOCOL_ERROR -- malformed CONTINUATION frame"); + let id = head.stream_id(); + proto_err!(stream: "malformed CONTINUATION frame; stream={:?}", id); return Err(Stream { - id: head.stream_id(), + id, reason: Reason::PROTOCOL_ERROR, }); }, Err(e) => { - debug!("connection error PROTOCOL_ERROR -- failed HPACK decoding; err={:?}", e); + proto_err!(conn: "failed HPACK decoding; err={:?}", e); return Err(Connection(Reason::PROTOCOL_ERROR)); }, } diff --git a/src/lib.rs b/src/lib.rs index ab0ee88..e6ebb46 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -111,6 +111,15 @@ extern crate log; extern crate string; extern crate indexmap; +macro_rules! proto_err { + (conn: $($msg:tt)+) => { + debug!("connection error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + }; + (stream: $($msg:tt)+) => { + debug!("stream error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + }; +} + mod error; #[cfg_attr(feature = "unstable", allow(missing_docs))] mod codec; diff --git a/src/proto/peer.rs b/src/proto/peer.rs index bcc73b9..bcfc425 100644 --- a/src/proto/peer.rs +++ b/src/proto/peer.rs @@ -70,7 +70,7 @@ impl Dyn { if self.is_server() { // Ensure that the ID is a valid client initiated ID if mode.is_push_promise() || !id.is_client_initiated() { - trace!("Cannot open stream {:?} - not client initiated, PROTOCOL_ERROR", id); + proto_err!(conn: "cannot open stream {:?} - not client initiated", id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -78,7 +78,7 @@ impl Dyn { } else { // Ensure that the ID is a valid server initiated ID if !mode.is_push_promise() || !id.is_server_initiated() { - trace!("Cannot open stream {:?} - not server initiated, PROTOCOL_ERROR", id); + proto_err!(conn: "cannot open stream {:?} - not server initiated", id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } diff --git a/src/proto/streams/recv.rs b/src/proto/streams/recv.rs index 5955820..ed38cc1 100644 --- a/src/proto/streams/recv.rs +++ b/src/proto/streams/recv.rs @@ -135,7 +135,7 @@ impl Recv { let next_id = self.next_stream_id()?; if id < next_id { - trace!("id ({:?}) < next_id ({:?}), PROTOCOL_ERROR", id, next_id); + proto_err!(conn: "id ({:?}) < next_id ({:?})", id, next_id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -178,7 +178,8 @@ impl Recv { if let Some(content_length) = frame.fields().get(header::CONTENT_LENGTH) { let content_length = match parse_u64(content_length.as_bytes()) { Ok(v) => v, - Err(_) => { + Err(()) => { + proto_err!(stream: "could not parse content-length; stream={:?}", stream.id); return Err(RecvError::Stream { id: stream.id, reason: Reason::PROTOCOL_ERROR, @@ -202,7 +203,11 @@ 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. - trace!("recv_headers; frame for {:?} is over size", stream.id); + debug!( + "stream error REQUEST_HEADER_FIELDS_TOO_LARGE -- \ + recv_headers: frame is over size; stream={:?}", + stream.id + ); return if counts.peer().is_server() && is_initial { let mut res = frame::Headers::new( stream.id, @@ -311,6 +316,7 @@ impl Recv { stream.state.recv_close()?; if stream.ensure_content_length_zero().is_err() { + proto_err!(stream: "recv_trailers: content-length is not zero; stream={:?};", stream.id); return Err(RecvError::Stream { id: stream.id, reason: Reason::PROTOCOL_ERROR, @@ -499,6 +505,7 @@ impl Recv { // Receiving a DATA frame when not expecting one is a protocol // error. + proto_err!(conn: "unexpected DATA frame; stream={:?}", stream.id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -515,7 +522,7 @@ impl Recv { if is_ignoring_frame { trace!( - "recv_data frame ignored on locally reset {:?} for some time", + "recv_data; frame ignored on locally reset {:?} for some time", stream.id, ); // we just checked for enough connection window capacity, and @@ -547,7 +554,11 @@ impl Recv { } if stream.dec_content_length(frame.payload().len()).is_err() { - trace!("content-length overflow"); + proto_err!(stream: + "recv_data: content-length overflow; stream={:?}; len={:?}", + stream.id, + frame.payload().len(), + ); return Err(RecvError::Stream { id: stream.id, reason: Reason::PROTOCOL_ERROR, @@ -556,7 +567,11 @@ impl Recv { if frame.is_end_stream() { if stream.ensure_content_length_zero().is_err() { - trace!("content-length underflow"); + proto_err!(stream: + "recv_data: content-length underflow; stream={:?}; len={:?}", + stream.id, + frame.payload().len(), + ); return Err(RecvError::Stream { id: stream.id, reason: Reason::PROTOCOL_ERROR, @@ -564,7 +579,7 @@ impl Recv { } if stream.state.recv_close().is_err() { - trace!("failed to transition to closed state"); + proto_err!(conn: "recv_data: failed to transition to closed state; stream={:?}", stream.id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } } @@ -586,6 +601,11 @@ impl Recv { pub fn consume_connection_window(&mut self, sz: WindowSize) -> Result<(), RecvError> { if self.flow.window_size() < sz { + debug!( + "connection error FLOW_CONTROL_ERROR -- window_size ({:?}) < sz ({:?});", + self.flow.window_size(), + sz, + ); return Err(RecvError::Connection(Reason::FLOW_CONTROL_ERROR)); } @@ -615,7 +635,11 @@ 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. - trace!("recv_push_promise; frame for {:?} is over size", frame.promised_id()); + debug!( + "stream error REFUSED_STREAM -- recv_push_promise: \ + headers frame is over size; promised_id={:?};", + frame.promised_id(), + ); return Err(RecvError::Stream { id: frame.promised_id(), reason: Reason::REFUSED_STREAM, @@ -634,7 +658,12 @@ impl Recv { if let Some(content_length) = req.headers().get(header::CONTENT_LENGTH) { match parse_u64(content_length.as_bytes()) { Ok(0) => {}, - _ => { + otherwise => { + proto_err!(stream: + "recv_push_promise; promised request has content-length {:?}; promised_id={:?}", + otherwise, + promised_id, + ); return Err(RecvError::Stream { id: promised_id, reason: Reason::PROTOCOL_ERROR, @@ -645,6 +674,12 @@ impl Recv { // "The server MUST include a method in the :method pseudo-header field // that is safe and cacheable" if !Self::safe_and_cacheable(req.method()) { + proto_err!( + stream: + "recv_push_promise: method {} is not safe and cacheable; promised_id={:?}", + req.method(), + promised_id, + ); return Err(RecvError::Stream { id: promised_id, reason: Reason::PROTOCOL_ERROR, @@ -666,7 +701,7 @@ impl Recv { pub fn ensure_not_idle(&self, id: StreamId) -> Result<(), Reason> { if let Ok(next) = self.next_stream_id { if id >= next { - trace!("stream ID implicitly closed"); + debug!("stream ID implicitly closed, PROTOCOL_ERROR; stream={:?}", id); return Err(Reason::PROTOCOL_ERROR); } } @@ -731,7 +766,7 @@ impl Recv { -> Result<(), RecvError> { if !self.is_push_enabled { - trace!("recv_push_promise; error push is disabled"); + proto_err!(conn: "recv_push_promise: push is disabled"); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } diff --git a/src/proto/streams/state.rs b/src/proto/streams/state.rs index d8d3c6c..7e3879d 100644 --- a/src/proto/streams/state.rs +++ b/src/proto/streams/state.rs @@ -172,8 +172,9 @@ impl State { } else { HalfClosedLocal(remote) }, - _ => { + state => { // All other transitions result in a protocol error + proto_err!(conn: "recv_open: in unexpected state {:?}", state); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); }, }; @@ -188,7 +189,10 @@ impl State { self.inner = ReservedRemote; Ok(()) }, - _ => Err(RecvError::Connection(Reason::PROTOCOL_ERROR)), + state => { + proto_err!(conn: "reserve_remote: in unexpected state {:?}", state); + Err(RecvError::Connection(Reason::PROTOCOL_ERROR)) + } } } @@ -208,7 +212,10 @@ impl State { self.inner = Closed(Cause::EndStream); Ok(()) }, - _ => Err(RecvError::Connection(Reason::PROTOCOL_ERROR)), + state => { + proto_err!(conn: "recv_close: in unexpected state {:?}", state); + Err(RecvError::Connection(Reason::PROTOCOL_ERROR)) + } } } @@ -287,7 +294,7 @@ impl State { trace!("send_close: HalfClosedRemote => Closed"); self.inner = Closed(Cause::EndStream); }, - _ => panic!("transition send_close on unexpected state"), + state => panic!("send_close: unexpected state {:?}", state), } } diff --git a/src/proto/streams/streams.rs b/src/proto/streams/streams.rs index bc47b38..4f44edf 100644 --- a/src/proto/streams/streams.rs +++ b/src/proto/streams/streams.rs @@ -205,6 +205,7 @@ where } else { if !frame.is_end_stream() { // TODO: Is this the right error + proto_err!(conn: "recv_headers: trailers frame was not EOS; stream={:?}", stream.id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -231,7 +232,7 @@ where return Ok(()); } - trace!("recv_data; stream not found: {:?}", id); + proto_err!(conn: "recv_data: stream not found; id={:?}", id); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); }, }; @@ -261,6 +262,7 @@ where let id = frame.stream_id(); if id.is_zero() { + proto_err!(conn: "recv_reset: invalid stream ID 0"); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -343,6 +345,10 @@ where // the value they send in the last stream identifier, since the // peers might already have retried unprocessed requests on another // connection.") + proto_err!(conn: + "recv_go_away: last_stream_id ({:?}) > max_stream_id ({:?})", + last_stream_id, actions.recv.max_stream_id(), + ); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -427,7 +433,10 @@ where stream.state.ensure_recv_open()?; stream.key() } - None => return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)), + None => { + proto_err!(conn: "recv_push_promise: initiating stream is in an invalid state"); + return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)) + }, }; // TODO: Streams in the reserved states do not count towards the concurrency diff --git a/src/server.rs b/src/server.rs index 7cbb6df..7a0c390 100644 --- a/src/server.rs +++ b/src/server.rs @@ -1070,6 +1070,7 @@ where } if PREFACE[self.pos..self.pos + n] != buf[..n] { + proto_err!(conn: "read_preface: invalid preface"); // TODO: Should this just write the GO_AWAY frame directly? return Err(Reason::PROTOCOL_ERROR.into()); } @@ -1230,6 +1231,7 @@ impl proto::Peer for Peer { // Specifying :status for a request is a protocol error if pseudo.status.is_some() { + trace!("malformed headers: :status field on request; PROTOCOL_ERROR"); return Err(RecvError::Connection(Reason::PROTOCOL_ERROR)); } @@ -1280,9 +1282,10 @@ impl proto::Peer for Peer { let mut request = match b.body(()) { Ok(request) => request, - Err(_) => { + Err(e) => { // TODO: Should there be more specialized handling for different // kinds of errors + proto_err!(stream: "error building request: {}; stream={:?}", e, stream_id); return Err(RecvError::Stream { id: stream_id, reason: Reason::PROTOCOL_ERROR,