Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log protocol errors #371

Merged
merged 7 commits into from Jun 17, 2019
Merged

Log protocol errors #371

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
23df6ed
Log on invalid state transitions
hawkw Jun 12, 2019
ad6940f
log all protocol errors
hawkw Jun 12, 2019
7aeb856
log unexpected transitions at trace
hawkw Jun 12, 2019
acacf45
log proto errors at debug, use a consistent style
hawkw Jun 16, 2019
ca2e631
use proto_err in framed_read
hawkw Jun 17, 2019
36fcf81
log all recv errors identically
hawkw Jun 17, 2019
0f04539
syntax fixes
hawkw Jun 17, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
56 changes: 34 additions & 22 deletions src/codec/framed_read.rs
View file
Open in desktop
Expand Up @@ -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));
}

Expand All @@ -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`.
Expand All @@ -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));
}
};
Expand All @@ -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));
}
}
Expand All @@ -136,23 +136,23 @@ 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()
},
Kind::Ping => {
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()
},
Kind::WindowUpdate => {
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()
},
Expand All @@ -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()
},
Expand All @@ -171,18 +171,25 @@ 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)
},
Kind::Priority => {
if head.stream_id() == 0 {
// Invalid stream identifier
proto_err!(conn: "invalid stream ID 0");
return Err(Connection(Reason::PROTOCOL_ERROR));
}

Expand All @@ -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 => {
Expand All @@ -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));
}

Expand All @@ -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));
}
}
Expand All @@ -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));
},
}
Expand Down
9 changes: 9 additions & 0 deletions src/lib.rs
View file
Open in desktop
Expand Up @@ -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;
Expand Down
4 changes: 2 additions & 2 deletions src/proto/peer.rs
View file
Open in desktop
Expand Up @@ -70,15 +70,15 @@ 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));
}

Ok(())
} 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));
}

Expand Down
57 changes: 46 additions & 11 deletions src/proto/streams/recv.rs
View file
Open in desktop
Expand Up @@ -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));
}

Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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));
}

Expand All @@ -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
Expand Down Expand Up @@ -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,
Expand All @@ -556,15 +567,19 @@ 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,
});
}

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

Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -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);
}
}
Expand Down Expand Up @@ -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));
}

Expand Down