Skip to content

Conversation

@camshaft
Copy link
Contributor

@camshaft camshaft commented Dec 7, 2023

Description of changes:

This change adds a branch-tracing feature to s2n-quic-core which hooks into the ensure! macro and logs each decision point with the outcome and the action it took in case of a failure. This is really useful for debugging why something happened or how often a check occurred.

Here's an example output:

0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="self.max_recv_offset <= final_offset" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=212
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="excess.is_empty()" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=238
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="!request.is_empty()" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=241
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="!request.is_empty()" result=false outcome="return" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=522
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="!request.is_empty()" result=false outcome="return" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=522
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(offset)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=492
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(offset)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=492
0:00:00.300000 s2n_quic:client:conn: rx_stream_progress: bytes=710 id=0
0:00:00.300000 s2n_quic:client: platform_event_loop_sleep: timeout=Some(25ms) processing_duration=1µs
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.start_offset)" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=452
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="watermark > 0" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=390
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="len > 0" result=true file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=460
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(offset)" result=false outcome="return offset" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=492
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=false outcome="return None" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=false outcome="return None" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682
0:00:00.300000 s2n_quic_core::buffer::receive_buffer: branch="slot.is_occupied(self.prev_end)" result=false outcome="return None" file="quic/s2n-quic-core/src/buffer/receive_buffer.rs" line=682

Testing:

I've enabled the feature on the integration tests to make it easy to debug. Note that you do need to pass S2N_LOG=trace to get the output.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

@camshaft camshaft force-pushed the camshaft/branch-trace branch from 4573a87 to d53b01d Compare December 7, 2023 18:45
@camshaft camshaft marked this pull request as ready for review December 7, 2023 18:46
}
}

let level = if std::env::var("TRACE").is_ok() {
Copy link
Contributor

@jmayclin jmayclin Dec 7, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: I think the tracing subscriber can handle this logic for you: default_directive

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah probably worth switching to that i guess

@camshaft camshaft requested a review from jmayclin December 7, 2023 19:01
@camshaft camshaft merged commit ac53c60 into main Dec 7, 2023
@camshaft camshaft deleted the camshaft/branch-trace branch December 7, 2023 19:37
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants