From 492d5c976ea6a19630fcdb76f2786d6749f9c137 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Thu, 6 Jun 2024 07:50:30 +1000 Subject: [PATCH] test(connlib): improve assertion logs (#5223) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In #5207, I already added logs for which assertions we are performing on ICMP packets. This PR does the same thing for the DNS queries that are being to connlib. It also adds spans that add some more context to the messages. Here is an excerpt of what this looks like: ``` Applying transition 19/19: SendICMPPacketToResource { idx: Index(3210705382108961150), seq: 57053, identifier: 28234, src: TunnelIp6 } 2024-06-05T07:06:30.742455Z INFO assertions: ✅ Performed the expected 2 ICMP handshakes 2024-06-05T07:06:30.742459Z INFO icmp{seq=15543 identifier=63125}: assertions: ✅ dst IP of request matches src IP of response: 3fb8:a7b0:c912:a648:6c9:7910:92dc:8db 2024-06-05T07:06:30.742461Z INFO icmp{seq=15543 identifier=63125}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742464Z INFO icmp{seq=15543 identifier=63125}: assertions: ✅ 3fb8:a7b0:c912:a648:6c9:7910:92dc:8db is the correct resource 2024-06-05T07:06:30.742467Z INFO icmp{seq=57053 identifier=28234}: assertions: ✅ dst IP of request matches src IP of response: 3fb8:a7b0:c912:a648:6c9:7910:92dc:8d8 2024-06-05T07:06:30.742470Z INFO icmp{seq=57053 identifier=28234}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742473Z INFO icmp{seq=57053 identifier=28234}: assertions: ✅ 3fb8:a7b0:c912:a648:6c9:7910:92dc:8d8 is the correct resource 2024-06-05T07:06:30.742477Z INFO dns{query_id=58256}: assertions: ✅ dst IP of request matches src IP of response: fd00:2021:1111:8000:100:100:111:0 2024-06-05T07:06:30.742480Z INFO dns{query_id=58256}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742483Z INFO dns{query_id=58256}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742485Z INFO dns{query_id=58256}: assertions: ✅ src port of request matches dst port of response: 9999 2024-06-05T07:06:30.742488Z INFO dns{query_id=22568}: assertions: ✅ dst IP of request matches src IP of response: 100.100.111.1 2024-06-05T07:06:30.742491Z INFO dns{query_id=22568}: assertions: ✅ src IP of request matches dst IP of response: 100.75.34.66 2024-06-05T07:06:30.742494Z INFO dns{query_id=22568}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742497Z INFO dns{query_id=22568}: assertions: ✅ src port of request matches dst port of response: 9999 2024-06-05T07:06:30.742500Z INFO dns{query_id=58735}: assertions: ✅ dst IP of request matches src IP of response: fd00:2021:1111:8000:100:100:111:2 2024-06-05T07:06:30.742502Z INFO dns{query_id=58735}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742505Z INFO dns{query_id=58735}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742507Z INFO dns{query_id=58735}: assertions: ✅ src port of request matches dst port of response: 9999 2024-06-05T07:06:30.742512Z INFO dns{query_id=59096}: assertions: ✅ dst IP of request matches src IP of response: fd00:2021:1111:8000:100:100:111:1 2024-06-05T07:06:30.742514Z INFO dns{query_id=59096}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742517Z INFO dns{query_id=59096}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742519Z INFO dns{query_id=59096}: assertions: ✅ src port of request matches dst port of response: 9999 2024-06-05T07:06:30.742522Z INFO dns{query_id=41570}: assertions: ✅ dst IP of request matches src IP of response: fd00:2021:1111:8000:100:100:111:1 2024-06-05T07:06:30.742525Z INFO dns{query_id=41570}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742527Z INFO dns{query_id=41570}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742530Z INFO dns{query_id=41570}: assertions: ✅ src port of request matches dst port of response: 9999 2024-06-05T07:06:30.742533Z INFO dns{query_id=15028}: assertions: ✅ dst IP of request matches src IP of response: fd00:2021:1111:8000:100:100:111:1 2024-06-05T07:06:30.742536Z INFO dns{query_id=15028}: assertions: ✅ src IP of request matches dst IP of response: fd00:2021:1111::a:3531 2024-06-05T07:06:30.742538Z INFO dns{query_id=15028}: assertions: ✅ dst port of request matches src port of response: 53 2024-06-05T07:06:30.742541Z INFO dns{query_id=15028}: assertions: ✅ src port of request matches dst port of response: 9999 ``` It is a bit repetitive because all assertions always run on all state transition. Nevertheless I've found it useful to be able to look at the assertions and visually verify that they make sense. --- rust/connlib/tunnel/src/tests.rs | 73 ++++++++++++++++---------------- 1 file changed, 37 insertions(+), 36 deletions(-) diff --git a/rust/connlib/tunnel/src/tests.rs b/rust/connlib/tunnel/src/tests.rs index b714c425c..0ed983caa 100644 --- a/rust/connlib/tunnel/src/tests.rs +++ b/rust/connlib/tunnel/src/tests.rs @@ -2397,6 +2397,8 @@ fn assert_icmp_packets_properties(state: &mut TunnelTest, ref_state: &ReferenceS .iter() .zip(state.gateway_received_icmp_requests.iter()) { + let _guard = tracing::info_span!(target: "assertions", "icmp", %seq, %identifier).entered(); + let client_sent_request = &state .client_sent_icmp_requests .get(&(*seq, *identifier)) @@ -2406,7 +2408,7 @@ fn assert_icmp_packets_properties(state: &mut TunnelTest, ref_state: &ReferenceS .get(&(*seq, *identifier)) .expect("to have ICMP reply on client"); - assert_correct_src_and_dst_ips(client_sent_request, client_received_reply, seq, identifier); + assert_correct_src_and_dst_ips(client_sent_request, client_received_reply); assert_eq!( gateway_received_request.source(), @@ -2439,21 +2441,46 @@ fn assert_icmp_packets_properties(state: &mut TunnelTest, ref_state: &ReferenceS fn assert_correct_src_and_dst_ips( client_sent_request: &IpPacket<'_>, client_received_reply: &IpPacket<'_>, - seq: &IcmpSeq, - identifier: &IcmpIdentifier, ) { assert_eq!( client_sent_request.destination(), client_received_reply.source(), - "ICMP request destination == ICMP reply source" + "request destination == reply source" ); + + tracing::info!(target: "assertions", "✅ dst IP of request matches src IP of response: {}", client_sent_request.destination()); + assert_eq!( client_sent_request.source(), client_received_reply.destination(), - "ICMP request source == ICMP reply destination" + "request source == reply destination" ); - tracing::info!(target: "assertions", "✅ src and dst IP for ICMP request ({seq},{identifier}) are correct"); + tracing::info!(target: "assertions", "✅ src IP of request matches dst IP of response: {}", client_sent_request.source()); +} + +fn assert_correct_src_and_dst_udp_ports( + client_sent_request: &IpPacket<'_>, + client_received_reply: &IpPacket<'_>, +) { + let client_sent_request = client_sent_request.as_udp().expect("packet to be UDP"); + let client_received_reply = client_received_reply.as_udp().expect("packet to be UDP"); + + assert_eq!( + client_sent_request.get_destination(), + client_received_reply.get_source(), + "request destination == reply source" + ); + + tracing::info!(target: "assertions", "✅ dst port of request matches src port of response: {}", client_sent_request.get_destination()); + + assert_eq!( + client_sent_request.get_source(), + client_received_reply.get_destination(), + "request source == reply destination" + ); + + tracing::info!(target: "assertions", "✅ src port of request matches dst port of response: {}", client_sent_request.get_source()); } fn assert_destination_is_cdir_resource( @@ -2532,6 +2559,8 @@ fn assert_dns_packets_properties(state: &TunnelTest, ref_state: &ReferenceState) ); for query_id in ref_state.expected_dns_handshakes.iter() { + let _guard = tracing::info_span!(target: "assertions", "dns", %query_id).entered(); + let client_sent_query = state .client_sent_dns_queries .get(query_id) @@ -2541,36 +2570,8 @@ fn assert_dns_packets_properties(state: &TunnelTest, ref_state: &ReferenceState) .get(query_id) .expect("to have DNS response on client"); - assert_eq!( - client_sent_query.destination(), - client_received_response.source(), - "DNS query dIP == DNS response sIP" - ); - assert_eq!( - client_sent_query.source(), - client_received_response.destination(), - "DNS query sIP == DNS response dIP" - ); - - { - let client_sent_query = client_sent_query - .as_udp() - .expect("DNS query to be UDP packet"); - let client_received_response = client_received_response - .as_udp() - .expect("DNS response to be UDP packet"); - - assert_eq!( - client_sent_query.get_destination(), - client_received_response.get_source(), - "DNS query dport == DNS response sport" - ); - assert_eq!( - client_sent_query.get_source(), - client_received_response.get_destination(), - "DNS query sport == DNS response dport" - ); - } + assert_correct_src_and_dst_ips(client_sent_query, client_received_response); + assert_correct_src_and_dst_udp_ports(client_sent_query, client_received_response); } }