From 0eb4495a481665bf482de43662a8986935f7b2dc Mon Sep 17 00:00:00 2001 From: Hasan Date: Fri, 10 Jan 2025 17:53:47 +0100 Subject: [PATCH] Sprinkle log prints --- Cargo.lock | 31 ------------------- .../server_harness/mut_message_client.rs | 1 + crates/client/src/client/async_client.rs | 5 ++- .../client/src/client/async_secure_client.rs | 1 + crates/client/src/client/client.rs | 1 + crates/proto/src/xfer/dns_exchange.rs | 1 + crates/proto/src/xfer/dns_handle.rs | 4 ++- crates/proto/src/xfer/dns_request.rs | 1 + crates/proto/src/xfer/mod.rs | 1 + crates/proto/src/xfer/retry_dns_handle.rs | 12 +++++-- crates/resolver/src/lookup.rs | 7 +++-- .../src/name_server/connection_provider.rs | 1 + .../resolver/src/name_server/name_server.rs | 1 + .../src/name_server/name_server_pool.rs | 1 + 14 files changed, 31 insertions(+), 37 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 84bd979310..55e1684533 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -499,29 +499,6 @@ dependencies = [ "syn 2.0.90", ] -[[package]] -name = "env_filter" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4f2c92ceda6ceec50f43169f9ee8424fe2db276791afde7b2cd8bc084cb376ab" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e13fa619b91fb2381732789fc5de83b45675e882f66623b7d8cb4f643017018d" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "humantime", - "log", -] - [[package]] name = "equivalent" version = "1.0.1" @@ -875,7 +852,6 @@ name = "hickory-dns" version = "0.24.0" dependencies = [ "clap", - "env_logger", "futures-util", "hickory-client", "hickory-proto", @@ -896,7 +872,6 @@ name = "hickory-integration" version = "0.24.0" dependencies = [ "async-trait", - "env_logger", "futures", "hickory-client", "hickory-proto", @@ -1082,12 +1057,6 @@ dependencies = [ "itoa", ] -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "icu_collections" version = "1.5.0" diff --git a/bin/tests/server_harness/mut_message_client.rs b/bin/tests/server_harness/mut_message_client.rs index b9cdb6781d..9c0e17deea 100644 --- a/bin/tests/server_harness/mut_message_client.rs +++ b/bin/tests/server_harness/mut_message_client.rs @@ -30,6 +30,7 @@ impl DnsHandle for MutMessageHandle { #[allow(unused_mut)] fn send + Unpin>(&self, request: R) -> Self::Response { + tracing::debug!("Sending request"); let mut request = request.into(); #[cfg(feature = "dnssec")] diff --git a/crates/client/src/client/async_client.rs b/crates/client/src/client/async_client.rs index f619c6ade2..ac73f867c4 100644 --- a/crates/client/src/client/async_client.rs +++ b/crates/client/src/client/async_client.rs @@ -148,7 +148,10 @@ impl DnsHandle for AsyncClient { type Error = ProtoError; fn send + 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 { diff --git a/crates/client/src/client/async_secure_client.rs b/crates/client/src/client/async_secure_client.rs index 4ce64083bc..1a65bb7043 100644 --- a/crates/client/src/client/async_secure_client.rs +++ b/crates/client/src/client/async_secure_client.rs @@ -72,6 +72,7 @@ impl DnsHandle for AsyncDnssecClient { type Error = ProtoError; fn send + Unpin + Send + 'static>(&self, request: R) -> Self::Response { + tracing::debug!("Sending request"); self.client.send(request) } } diff --git a/crates/client/src/client/client.rs b/crates/client/src/client/client.rs index c307866eea..46a62a7978 100644 --- a/crates/client/src/client/client.rs +++ b/crates/client/src/client/client.rs @@ -99,6 +99,7 @@ pub trait Client { &self, msg: R, ) -> Vec> { + tracing::debug!("Sending request"); let (client, runtime) = match self.spawn_client() { Ok(c_r) => c_r, Err(e) => return vec![Err(e)], diff --git a/crates/proto/src/xfer/dns_exchange.rs b/crates/proto/src/xfer/dns_exchange.rs index c3c2d8dbd3..4ec805e219 100644 --- a/crates/proto/src/xfer/dns_exchange.rs +++ b/crates/proto/src/xfer/dns_exchange.rs @@ -108,6 +108,7 @@ impl DnsHandle for DnsExchange { type Error = ProtoError; fn send + 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 diff --git a/crates/proto/src/xfer/dns_handle.rs b/crates/proto/src/xfer/dns_handle.rs index f3dcbfad02..380ce3fc96 100644 --- a/crates/proto/src/xfer/dns_handle.rs +++ b/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 } } diff --git a/crates/proto/src/xfer/dns_request.rs b/crates/proto/src/xfer/dns_request.rs index 2d93c9b981..4413764ea6 100644 --- a/crates/proto/src/xfer/dns_request.rs +++ b/crates/proto/src/xfer/dns_request.rs @@ -84,6 +84,7 @@ impl DerefMut for DnsRequest { impl From for DnsRequest { fn from(message: Message) -> Self { + tracing::debug!("Converting to DnsRequest"); Self::new(message, DnsRequestOptions::default()) } } diff --git a/crates/proto/src/xfer/mod.rs b/crates/proto/src/xfer/mod.rs index 3fae41d82e..4ef6412d7d 100644 --- a/crates/proto/src/xfer/mod.rs +++ b/crates/proto/src/xfer/mod.rs @@ -168,6 +168,7 @@ impl DnsHandle for BufDnsRequestStreamHandle { type Error = ProtoError; fn send>(&self, request: R) -> Self::Response { + tracing::debug!("Sending request"); let request: DnsRequest = request.into(); debug!( "enqueueing message:{}:{:?}", diff --git a/crates/proto/src/xfer/retry_dns_handle.rs b/crates/proto/src/xfer/retry_dns_handle.rs index b24c55a516..79d69ba9c8 100644 --- a/crates/proto/src/xfer/retry_dns_handle.rs +++ b/crates/proto/src/xfer/retry_dns_handle.rs @@ -64,8 +64,9 @@ where type Error = ::Error; fn send>(&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> { // 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; + } } } } diff --git a/crates/resolver/src/lookup.rs b/crates/resolver/src/lookup.rs index a3649f65cd..783df86c5e 100644 --- a/crates/resolver/src/lookup.rs +++ b/crates/resolver/src/lookup.rs @@ -205,11 +205,14 @@ impl DnsHandle for LookupEither

{ } fn send + 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 } } diff --git a/crates/resolver/src/name_server/connection_provider.rs b/crates/resolver/src/name_server/connection_provider.rs index 32750b0137..b6642fa888 100644 --- a/crates/resolver/src/name_server/connection_provider.rs +++ b/crates/resolver/src/name_server/connection_provider.rs @@ -244,6 +244,7 @@ impl DnsHandle for GenericConnection { type Error = ResolveError; fn send + Unpin + Send + 'static>(&self, request: R) -> Self::Response { + tracing::debug!("Sending request"); ConnectionResponse(self.0.send(request)) } } diff --git a/crates/resolver/src/name_server/name_server.rs b/crates/resolver/src/name_server/name_server.rs index 4708f90166..cf7ef97c1b 100644 --- a/crates/resolver/src/name_server/name_server.rs +++ b/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 + 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))) } diff --git a/crates/resolver/src/name_server/name_server_pool.rs b/crates/resolver/src/name_server/name_server_pool.rs index ba832799a1..d2e0093122 100644 --- a/crates/resolver/src/name_server/name_server_pool.rs +++ b/crates/resolver/src/name_server/name_server_pool.rs @@ -230,6 +230,7 @@ where type Error = ResolveError; fn send>(&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);