Merge pull request #1115 from NordSecurity/more_dns_logs

Add more DNS logs
NordSecurity · Feb 7, 2025 · fa8b0a2 · fa8b0a2
2 parents 894e4e0 + d996524
commit fa8b0a2
Show file tree

Hide file tree

Showing 2 changed files with 42 additions and 11 deletions.
diff --git a/.unreleased/more_dns_logs b/.unreleased/more_dns_logs
diff --git a/crates/telio-dns/src/nameserver.rs b/crates/telio-dns/src/nameserver.rs
@@ -161,14 +161,19 @@ impl LocalNameServer {
                         telio_log_debug!("Write2Tun");
 
                         let nameserver = nameserver.clone();
-                        let length = match LocalNameServer::process_packet(
+                        let length = match Box::pin(LocalNameServer::process_packet(
                             nameserver,
                             packet,
                             &mut receiving_buffer,
-                        )
+                        ))
                         .await
                         {
-                            Ok(length) => length,
+                            Ok(length) => {
+                                telio_log_debug!(
+                                    "Finished processing dns request with length: {length}"
+                                );
+                                length
+                            }
                             Err(e) => {
                                 telio_log_error!(
                                     "[DNS] {}. Offending request packet: {:?}",
@@ -199,10 +204,14 @@ impl LocalNameServer {
                                     e
                                 )
                             }
-                            _ => {}
+                            res => {
+                                telio_log_debug!("Took ignored path for TunnResult: {:?}", res);
+                            }
                         }
                     }
-                    _ => {}
+                    res => {
+                        telio_log_debug!("Took ignored path for TunnResult: {:?}", res);
+                    }
                 }
             });
         }
@@ -213,30 +222,52 @@ impl LocalNameServer {
         request_info: &mut RequestInfo,
     ) -> Result<Vec<u8>, String> {
         telio_log_debug!("Resolving dns");
+        let ts = std::time::Instant::now();
         let resolver = Resolver::new();
-        telio_log_debug!("Getting DNS zones");
+        telio_log_debug!("Getting DNS zones. Time taken: {:?}", ts.elapsed());
+        let ts = std::time::Instant::now();
         let zones = nameserver.zones().await;
 
-        telio_log_debug!("Preparing DNS request");
+        telio_log_debug!("Preparing DNS request. Time taken: {:?}", ts.elapsed());
+        let ts = std::time::Instant::now();
         let dns_request = match &mut request_info.payload {
             PayloadRequestInfo::Udp {
                 ref mut dns_request,
                 ..
             } => dns_request
                 .take()
-                .ok_or_else(|| String::from("Inexistent DNS request"))?,
-            _ => return Ok(Vec::new()),
+                .ok_or_else(|| String::from("Nonexistent DNS request"))?,
+            _ => {
+                telio_log_debug!("Found DNS request with wrong protocol");
+                return Ok(Vec::new());
+            }
         };
+        telio_log_debug!(
+            "Exctraced dns request: {dns_request:?}. Time taken: {:?}",
+            ts.elapsed()
+        );
+        let ts = std::time::Instant::now();
         let dns_request = Request::new(dns_request, request_info.dns_source(), Protocol::Udp);
-        telio_log_debug!("DNS request: {:?}", &dns_request);
+        telio_log_debug!(
+            "DNS request: {:?}. Time taken: {:?}",
+            &dns_request,
+            ts.elapsed()
+        );
+        let ts = std::time::Instant::now();
 
         zones
             .lookup(&dns_request, resolver.clone())
             .await
             .map_err(|e| format!("Lookup failed {}", e))?;
+        telio_log_debug!("Finished zone lookup. Time taken: {:?}", ts.elapsed());
+        let ts = std::time::Instant::now();
 
         let dns_response = resolver.0.lock().await;
-        telio_log_debug!("Nameserver response: {:?}", &dns_response);
+        telio_log_debug!(
+            "Nameserver response: {:?}. Time taken: {:?}",
+            &dns_response,
+            ts.elapsed()
+        );
         Ok(dns_response.to_vec())
     }