Sprinkle send request prints

bin/tests/server_harness/mut_message_client.rs

@@ -30,6 +30,7 @@ impl<C: ClientHandle + Unpin> DnsHandle for MutMessageHandle<C> {
 
     #[allow(unused_mut)]
     fn send<R: Into<DnsRequest> + Unpin>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         let mut request = request.into();
 
         #[cfg(feature = "dnssec")]

crates/client/src/client/async_client.rs

@@ -148,7 +148,10 @@ impl DnsHandle for AsyncClient {
     type Error = ProtoError;
 
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
-        self.exchange.send(request)
+        debug!("Sending dns request");
+        let res = self.exchange.send(request);
+        debug!("Dns response recieved");
+        res
     }
 
     fn is_using_edns(&self) -> bool {

crates/client/src/client/async_secure_client.rs

@@ -72,6 +72,7 @@ impl DnsHandle for AsyncDnssecClient {
     type Error = ProtoError;
 
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         self.client.send(request)
     }
 }

crates/client/src/client/client.rs

@@ -99,6 +99,7 @@ pub trait Client {
         &self,
         msg: R,
     ) -> Vec<ClientResult<DnsResponse>> {
+        tracing::debug!("Sending request");
         let (client, runtime) = match self.spawn_client() {
             Ok(c_r) => c_r,
             Err(e) => return vec![Err(e)],

crates/proto/src/xfer/dns_exchange.rs

@@ -108,6 +108,7 @@ impl DnsHandle for DnsExchange {
     type Error = ProtoError;
 
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         DnsExchangeSend {
             result: self.sender.send(request),
             _sender: self.sender.clone(), // TODO: this shouldn't be necessary, currently the presence of Senders is what allows the background to track current users, it generally is dropped right after send, this makes sure that there is at least one active after send

crates/proto/src/xfer/dns_handle.rs

@@ -65,7 +65,9 @@ pub trait DnsHandle: 'static + Clone + Send + Sync + Unpin {
     /// * `options` - options to use when constructing the message
     fn lookup(&self, query: Query, options: DnsRequestOptions) -> Self::Response {
         debug!("querying: {} {:?}", query.name(), query.query_type());
-        self.send(DnsRequest::new(build_message(query, options), options))
+        let r = self.send(DnsRequest::new(build_message(query, options), options));
+        tracing::debug!("lookup return");
+        r
     }
 }
 

crates/proto/src/xfer/dns_request.rs

@@ -84,6 +84,7 @@ impl DerefMut for DnsRequest {
 
 impl From<Message> for DnsRequest {
     fn from(message: Message) -> Self {
+        tracing::debug!("Converting to DnsRequest");
         Self::new(message, DnsRequestOptions::default())
     }
 }

crates/proto/src/xfer/mod.rs

@@ -168,6 +168,7 @@ impl DnsHandle for BufDnsRequestStreamHandle {
     type Error = ProtoError;
 
     fn send<R: Into<DnsRequest>>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         let request: DnsRequest = request.into();
         debug!(
             "enqueueing message:{}:{:?}",

crates/proto/src/xfer/retry_dns_handle.rs

@@ -64,8 +64,9 @@ where
     type Error = <H as DnsHandle>::Error;
 
     fn send<R: Into<DnsRequest>>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         let request = request.into();
-
+        tracing::debug!("Request obj converted");
         // need to clone here so that the retry can resend if necessary...
         //  obviously it would be nice to be lazy about this...
         let stream = self.handle.send(request.clone());
@@ -99,23 +100,30 @@ where
     fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Option<Self::Item>> {
         // loop over the stream, on errors, spawn a new stream
         //  on ready and not ready return.
+        tracing::debug!("poll_next");
         loop {
             match self.stream.poll_next_unpin(cx) {
                 Poll::Ready(Some(Err(e))) => {
+                    tracing::debug!("poll ready error {e}");
                     if self.remaining_attempts == 0 || !e.should_retry() {
                         return Poll::Ready(Some(Err(e)));
                     }
 
                     if e.attempted() {
+                        tracing::debug!("poll attempted");
                         self.remaining_attempts -= 1;
                     }
 
                     // TODO: if the "sent" Message is part of the error result,
                     //  then we can just reuse it... and no clone necessary
                     let request = self.request.clone();
+                    tracing::debug!("sending ready");
                     self.stream = self.handle.send(request);
                 }
-                poll => return poll,
+                poll => {
+                    tracing::debug!("poll return {:?}", poll);
+                    return poll;
+                }
             }
         }
     }

crates/resolver/src/lookup.rs

@@ -205,11 +205,14 @@ impl<P: ConnectionProvider> DnsHandle for LookupEither<P> {
     }
 
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
-        match *self {
+        tracing::debug!("Sending request");
+        let r = match *self {
             Self::Retry(ref c) => c.send(request),
             #[cfg(feature = "dnssec")]
             Self::Secure(ref c) => c.send(request),
-        }
+        };
+        tracing::debug!("reply");
+        r
     }
 }
 

crates/resolver/src/name_server/connection_provider.rs

@@ -244,6 +244,7 @@ impl DnsHandle for GenericConnection {
     type Error = ResolveError;
 
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         ConnectionResponse(self.0.send(request))
     }
 }

crates/resolver/src/name_server/name_server.rs

@@ -185,6 +185,7 @@ where
     // TODO: there needs to be some way of customizing the connection based on EDNS options from the server side...
     fn send<R: Into<DnsRequest> + Unpin + Send + 'static>(&self, request: R) -> Self::Response {
         let this = self.clone();
+        tracing::debug!("Sending request");
         // if state is failed, return future::err(), unless retry delay expired..
         Box::pin(once(this.inner_send(request)))
     }

crates/resolver/src/name_server/name_server_pool.rs

@@ -230,6 +230,7 @@ where
     type Error = ResolveError;
 
     fn send<R: Into<DnsRequest>>(&self, request: R) -> Self::Response {
+        tracing::debug!("Sending request");
         let opts = self.options.clone();
         let request = request.into();
         let datagram_conns = Arc::clone(&self.datagram_conns);