Logging elapse time for DNS resolving and ACL checking

fix #269

Author: zonyitoo

src/context.rs

@@ -13,7 +13,7 @@ use std::{
 use std::{net::IpAddr, time::Duration};
 
 use bloomfilter::Bloom;
-use log::warn;
+use log::{log_enabled, warn};
 #[cfg(feature = "local-dns-relay")]
 use lru_time_cache::LruCache;
 use spin::Mutex;
@@ -293,9 +293,36 @@ impl Context {
 
     /// Perform a DNS resolution
     pub async fn dns_resolve(&self, host: &str, port: u16) -> io::Result<Vec<SocketAddr>> {
-        #[cfg(feature = "local-dns-relay")]
-        return self.local_dns().lookup_ip(host, port).await;
-        #[cfg(not(feature = "local-dns-relay"))]
+        if log_enabled!(log::Level::Debug) {
+            use log::debug;
+            use std::time::Instant;
+
+            let start = Instant::now();
+            let result = self.dns_resolve_inner(host, port).await;
+            let elapsed = Instant::now() - start;
+            debug!(
+                "DNS resolved {}:{} elapsed: {}.{:03}s, {:?}",
+                host,
+                port,
+                elapsed.as_secs(),
+                elapsed.subsec_millis(),
+                result
+            );
+            result
+        } else {
+            self.dns_resolve_inner(host, port).await
+        }
+    }
+
+    #[cfg(feature = "local-dns-relay")]
+    #[inline(always)]
+    async fn dns_resolve_inner(&self, host: &str, port: u16) -> io::Result<Vec<SocketAddr>> {
+        self.local_dns().lookup_ip(host, port).await
+    }
+
+    #[cfg(not(feature = "local-dns-relay"))]
+    #[inline(always)]
+    async fn dns_resolve_inner(&self, host: &str, port: u16) -> io::Result<Vec<SocketAddr>> {
         resolve(self, host, port).await
     }
 
@@ -327,23 +354,23 @@ impl Context {
     pub fn check_client_blocked(&self, addr: &SocketAddr) -> bool {
         match self.acl() {
             None => false,
-            Some(ref a) => a.check_client_blocked(addr),
+            Some(a) => a.check_client_blocked(addr),
         }
     }
 
     /// Check outbound address ACL (for server)
     pub fn check_outbound_blocked(&self, addr: &Address) -> bool {
         match self.acl() {
             None => false,
-            Some(ref a) => a.check_outbound_blocked(addr),
+            Some(a) => a.check_outbound_blocked(addr),
         }
     }
 
     /// Check resolved outbound address ACL (for server)
     pub fn check_resolved_outbound_blocked(&self, addr: &SocketAddr) -> bool {
         match self.acl() {
             None => false,
-            Some(ref a) => a.check_resolved_outbound_blocked(addr),
+            Some(a) => a.check_resolved_outbound_blocked(addr),
         }
     }
 
@@ -354,7 +381,7 @@ impl Context {
             != match self.acl() {
                 // Proxy everything by default
                 None => true,
-                Some(ref a) => a.check_ip_in_proxy_list(addr),
+                Some(a) => a.check_ip_in_proxy_list(addr),
             };
         let mut reverse_lookup_cache = self.reverse_lookup_cache.lock();
         match reverse_lookup_cache.get_mut(addr) {
@@ -374,10 +401,12 @@ impl Context {
         }
     }
 
-    pub fn acl(&self) -> &Option<AccessControl> {
-        &self.config.acl
+    /// Get ACL control instance
+    pub fn acl(&self) -> Option<&AccessControl> {
+        self.config.acl.as_ref()
     }
 
+    /// Get local DNS connector
     #[cfg(feature = "local-dns-relay")]
     pub fn local_dns(&self) -> &LocalUpstream {
         &self.local_dns
@@ -388,21 +417,43 @@ impl Context {
         match self.acl() {
             // Proxy everything by default
             None => false,
-            Some(ref a) => {
-                #[cfg(feature = "local-dns-relay")]
-                {
-                    if let Address::SocketAddress(ref saddr) = target {
-                        // do the reverse lookup in our local cache
-                        let mut reverse_lookup_cache = self.reverse_lookup_cache.lock();
-                        // if a qname is found
-                        if let Some(forward) = reverse_lookup_cache.get(&saddr.ip()) {
-                            return !*forward;
-                        }
-                    }
+            Some(a) => {
+                if log_enabled!(log::Level::Debug) {
+                    use log::debug;
+                    use std::time::Instant;
+
+                    let start = Instant::now();
+                    let r = self.check_target_bypassed_with_acl(a, target).await;
+                    let elapsed = Instant::now() - start;
+                    debug!(
+                        "check bypassing {} elapsed {}.{:03}s, result: {}",
+                        target,
+                        elapsed.as_secs(),
+                        elapsed.subsec_millis(),
+                        if r { "bypassed" } else { "proxied" }
+                    );
+                    r
+                } else {
+                    self.check_target_bypassed_with_acl(a, target).await
+                }
+            }
+        }
+    }
+
+    #[inline(always)]
+    async fn check_target_bypassed_with_acl(&self, a: &AccessControl, target: &Address) -> bool {
+        #[cfg(feature = "local-dns-relay")]
+        {
+            if let Address::SocketAddress(ref saddr) = target {
+                // do the reverse lookup in our local cache
+                let mut reverse_lookup_cache = self.reverse_lookup_cache.lock();
+                // if a qname is found
+                if let Some(forward) = reverse_lookup_cache.get(&saddr.ip()) {
+                    return !*forward;
                 }
-                a.check_target_bypassed(self, target).await
             }
         }
+        a.check_target_bypassed(self, target).await
     }
 
     /// Get client flow statistics

src/relay/dns_resolver/tokio_dns_resolver.rs

@@ -4,7 +4,7 @@ use std::{
     sync::atomic::{AtomicBool, Ordering},
 };
 
-use log::warn;
+use log::{trace, warn};
 use tokio::net::lookup_host;
 
 use crate::context::Context;
@@ -16,6 +16,10 @@ pub async fn resolve(_: &Context, addr: &str, port: u16) -> io::Result<Vec<Socke
         warn!("Tokio resolver is used. Performance might deteriorate.");
     }
 
+    if cfg!(not(feature = "trust-dns")) {
+        trace!("DNS resolving {}:{} with tokio", addr, port);
+    }
+
     match lookup_host((addr, port)).await {
         Ok(v) => Ok(v.collect()),
         Err(err) => {

src/relay/dns_resolver/trust_dns_resolver.rs

@@ -84,17 +84,25 @@ pub async fn create_resolver(dns: Option<ResolverConfig>, ipv6_first: bool) -> i
 /// Perform a DNS resolution
 pub async fn resolve(context: &Context, addr: &str, port: u16) -> io::Result<Vec<SocketAddr>> {
     match context.dns_resolver() {
-        Some(resolver) => match resolver.lookup_ip(addr).await {
-            Ok(lookup_result) => Ok(lookup_result.iter().map(|ip| SocketAddr::new(ip, port)).collect()),
-            Err(err) => {
-                let err = Error::new(
-                    ErrorKind::Other,
-                    format!("dns resolve {}:{} error: {}", addr, port, err),
-                );
-                Err(err)
+        Some(resolver) => {
+            trace!("DNS resolving {}:{} with trust-dns", addr, port);
+
+            match resolver.lookup_ip(addr).await {
+                Ok(lookup_result) => Ok(lookup_result.iter().map(|ip| SocketAddr::new(ip, port)).collect()),
+                Err(err) => {
+                    let err = Error::new(
+                        ErrorKind::Other,
+                        format!("dns resolve {}:{} error: {}", addr, port, err),
+                    );
+                    Err(err)
+                }
             }
-        },
+        }
         // Fallback to tokio's DNS resolver
-        None => tokio_resolve(context, addr, port).await,
+        None => {
+            trace!("DNS resolving {}:{} with tokio (fallback)", addr, port);
+
+            tokio_resolve(context, addr, port).await
+        }
     }
 }

src/relay/dnsrelay/mod.rs

@@ -83,7 +83,7 @@ fn check_name_in_proxy_list(acl: &AccessControl, name: &Name) -> Option<bool> {
 }
 
 /// given the query, determine whether remote/local query should be used, or inconclusive
-fn should_forward_by_query(acl: &Option<AccessControl>, query: &Query) -> Option<bool> {
+fn should_forward_by_query(acl: Option<&AccessControl>, query: &Query) -> Option<bool> {
     if let Some(acl) = acl {
         if query.query_class() != DNSClass::IN {
             // unconditionally use default for all non-IN queries
@@ -105,7 +105,7 @@ fn should_forward_by_query(acl: &Option<AccessControl>, query: &Query) -> Option
 
 /// given the local response, determine whether remote response should be used instead
 fn should_forward_by_response(
-    acl: &Option<AccessControl>,
+    acl: Option<&AccessControl>,
     local_response: &io::Result<Message>,
     query: &Query,
 ) -> bool {