forked/h2
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Log protocol error causes at debug (#371)

Browse Source 
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 <eliza@buoyant.io>
This commit is contained in:
Eliza Weisman
2019-06-17 14:14:40 -07:00
committed by GitHub
parent 383593a01e
commit 0e9fbe4a90
7 changed files with 117 additions and 42 deletions
Download Patch File Download Diff File Expand all files Collapse all files

56
src/codec/framed_read.rs
View File

@@ -63,7 +63,7 @@ impl<T> FramedRead<T> {
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<T> FramedRead<T> {
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<T> FramedRead<T> {
});
},
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<T> FramedRead<T> {
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<T> FramedRead<T> {
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<T> FramedRead<T> {
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<T> FramedRead<T> {
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<T> FramedRead<T> {
// 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<T> FramedRead<T> {
},
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<T> FramedRead<T> {
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<T> FramedRead<T> {
// 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<T> FramedRead<T> {
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<T> FramedRead<T> {
// 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<T> FramedRead<T> {
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));
},
}

9
src/lib.rs
View File

@@ -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;

4
src/proto/peer.rs
View File

@@ -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));
}

57
src/proto/streams/recv.rs
View File

@@ -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));
}

15
src/proto/streams/state.rs
View File

@@ -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),
}
}

13
src/proto/streams/streams.rs
View File

@@ -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

5
src/server.rs
View File

@@ -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,