From 0e9fbe4a90627f663671932e6aa487e707c01bf4 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Mon, 17 Jun 2019 14:14:40 -0700 Subject: [PATCH] Log protocol error causes at debug (#371) Currently, there are many cases where `h2` will fail a connection or stream with a PROTOCOL_ERROR, without recording why the protocol error occurred. Since protocol errors may result from a bug in `h2` or from a misbehaving peer, it is important to be able to debug the cause of protocol errors. This branch adds a log line to almost all cases where a protocol error occurs. I've tried to make the new log lines consistent with the existing logging, and in some cases, changed existing log lines to make them internally consistent with other log lines in that module. All receive-side errors that would send a reset are now logged at the debug level, using a formatting based on the format used in `framed_read`. Signed-off-by: Eliza Weisman --- src/codec/framed_read.rs | 56 +++++++++++++++++++++-------------- src/lib.rs | 9 ++++++ src/proto/peer.rs | 4 +-- src/proto/streams/recv.rs | 57 +++++++++++++++++++++++++++++------- src/proto/streams/state.rs | 15 +++++++--- src/proto/streams/streams.rs | 13 ++++++-- src/server.rs | 5 +++- 7 files changed, 117 insertions(+), 42 deletions(-) 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,