Upgrade some DoH logs from DEBUG to INFO

On userdebug builds, these logs give us some basic insight into
what's going on in DoH, such as connection close, timeout, etc.

[A successful DoH query]
resolv  : res_nmkquery: (QUERY, IN, AAAA)
doh::connection::driver: Handling DNS request on network 100, stats=[recv=54 sent=67 lost=0 rtt=13.788958ms cwnd=12000], peer_streams_left_bidi=83, peer_streams_left_uni=99
doh::connection::driver: Handled DNS request: stream ID 68, network 100, stream_capacity=Ok(11829)
doh::connection::driver: optional_timeout: timeout=Some(92.13807ms), network 100
doh::connection::driver: optional_timeout: timeout=Some(54.99981307s), network 100
doh::connection::driver: Got 468 bytes of response data from stream ID 68 on network 100
doh::connection::driver: optional_timeout: timeout=Some(54.999612183s), network 100
doh::connection::driver: optional_timeout: timeout=Some(54.999871378s), network 100
resolv  : res_doh_send: Https query result: 468, netid=100

[A timed out DoH query]
resolv  : res_nmkquery: (QUERY, IN, AAAA)
doh::connection::driver: Handling DNS request on network 100, stats=[recv=59 sent=73 lost=0 rtt=18.998596ms cwnd=12000], peer_streams_left_bidi=81, peer_streams_left_uni=99
doh::connection::driver: Handled DNS request: stream ID 76, network 100, stream_capacity=Ok(11826)
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(251.711065ms), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(503.921438ms), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(1.007884907s), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(2.015910358s), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(4.02994002s), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(8.064315099s), network 100
doh::connection::driver: H3Driver: Timer expired on network 100
doh::connection::driver: optional_timeout: timeout=Some(16.1287871s), network 100
resolv  : res_doh_send: Https query result: -255, netid=100

Bug: N/A
Test: built; checked the logcat
Change-Id: Ie356576a8b5123f3a6a89fddbd3afb3e269a4cfe

2 files changed, 27 insertions, 22 deletions

diff --git a/doh/connection/driver.rs b/doh/connection/driver.rs
index 7eab52cd..1ba8faa7 100644
--- a/doh/connection/driver.rs
+++ b/doh/connection/driver.rs
@@ -17,7 +17,7 @@
 
 use crate::boot_time;
 use crate::boot_time::BootTime;
-use log::{debug, warn};
+use log::{debug, info, warn};
 use quiche::h3;
 use std::collections::HashMap;
 use std::default::Default;
@@ -107,7 +107,7 @@ struct H3Driver {
 }
 
 async fn optional_timeout(timeout: Option<boot_time::Duration>, net_id: u32) {
-    debug!("optional_timeout: timeout={:?}, network {}", timeout, net_id);
+    info!("optional_timeout: timeout={:?}, network {}", timeout, net_id);
     match timeout {
         Some(timeout) => boot_time::sleep(timeout).await,
         None => future::pending().await,
@@ -156,7 +156,7 @@ impl Driver {
     fn handle_closed(&self) -> Result<()> {
         if self.quiche_conn.is_closed() {
             // TODO: Also log local_error() once Quiche 0.10.0 is available.
-            debug!(
+            info!(
                 "Connection {} closed on network {}, peer_error={:x?}",
                 self.quiche_conn.trace_id(),
                 self.net_id,
@@ -173,7 +173,7 @@ impl Driver {
     fn handle_draining(&mut self) {
         if self.quiche_conn.is_draining() && !self.closing {
             // TODO: Also log local_error() once Quiche 0.10.0 is available.
-            debug!(
+            info!(
                 "Connection {} is draining on network {}, peer_error={:x?}",
                 self.quiche_conn.trace_id(),
                 self.net_id,
@@ -198,7 +198,7 @@ impl Driver {
         select! {
             // If a quiche timer would fire, call their callback
             _ = timer => {
-                debug!("Driver: Timer expired on network {}", self.net_id);
+                info!("Driver: Timer expired on network {}", self.net_id);
                 self.quiche_conn.on_timeout()
             }
             // If we got packets from our peer, pass them to quiche
@@ -212,7 +212,7 @@ impl Driver {
 
         // If the QUIC connection is live, but the HTTP/3 is not, try to bring it up
         if self.quiche_conn.is_established() {
-            debug!(
+            info!(
                 "Connection {} established on network {}",
                 self.quiche_conn.trace_id(),
                 self.net_id
@@ -269,7 +269,7 @@ impl H3Driver {
                     .driver
                     .status_tx
                     .send(Status::Dead { session: self.driver.quiche_conn.session() });
-                return Err(e)
+                return Err(e);
             }
         }
     }
@@ -294,7 +294,7 @@ impl H3Driver {
             },
             // If a quiche timer would fire, call their callback
             _ = timer => {
-                debug!("H3Driver: Timer expired on network {}", self.driver.net_id);
+                info!("H3Driver: Timer expired on network {}", self.driver.net_id);
                 self.driver.quiche_conn.on_timeout()
             }
             // If we got packets from our peer, pass them to quiche
@@ -321,7 +321,7 @@ impl H3Driver {
     }
 
     fn handle_request(&mut self, request: Request) -> Result<()> {
-        debug!("Handling DNS request on network {}, stats={:?}, peer_streams_left_bidi={}, peer_streams_left_uni={}",
+        info!("Handling DNS request on network {}, stats=[{:?}], peer_streams_left_bidi={}, peer_streams_left_uni={}",
                 self.driver.net_id, self.driver.quiche_conn.stats(), self.driver.quiche_conn.peer_streams_left_bidi(), self.driver.quiche_conn.peer_streams_left_uni());
         // If the request has already timed out, don't issue it to the server.
         if let Some(expiry) = request.expiry {
@@ -339,14 +339,14 @@ impl H3Driver {
                     // buffered_request, or when buffered_request is empty. This assert just
                     // validates that we don't break that assumption later, as it could result in
                     // requests being dropped on the floor under high load.
-                    debug!("Stream has become blocked, buffering one request.");
+                    info!("Stream has become blocked, buffering one request.");
                     assert!(self.buffered_request.is_none());
                     self.buffered_request = Some(request);
                     return Ok(())
                 }
                 result => result?,
             };
-        debug!(
+        info!(
             "Handled DNS request: stream ID {}, network {}, stream_capacity={:?}",
             stream_id,
             self.driver.net_id,
@@ -372,13 +372,13 @@ impl H3Driver {
                         return Ok(());
                     }
                     Err(e) => {
-                        debug!("recv_body: Error={:?}", e);
+                        info!("recv_body: Error={:?}", e);
                         stream.data.truncate(base_len);
                         return Err(e.into());
                     }
                     Ok(recvd) => {
                         stream.data.truncate(base_len + recvd);
-                        debug!(
+                        info!(
                             "Got {} bytes of response data from stream ID {} on network {}",
                             recvd, stream_id, self.driver.net_id
                         );
@@ -461,7 +461,7 @@ impl H3Driver {
     }
 
     async fn shutdown(&mut self, send_goaway: bool, msg: &[u8]) -> Result<()> {
-        debug!(
+        info!(
             "Closing connection {} on network {} with msg {:?}",
             self.driver.quiche_conn.trace_id(),
             self.driver.net_id,
diff --git a/doh/network/driver.rs b/doh/network/driver.rs
index b0f59392..118e5758 100644
--- a/doh/network/driver.rs
+++ b/doh/network/driver.rs
@@ -22,14 +22,13 @@ use crate::connection::Connection;
 use crate::dispatcher::{QueryError, Response};
 use crate::encoding;
 use anyhow::{anyhow, bail, Result};
+use log::{debug, info};
 use std::sync::Arc;
 use tokio::sync::{mpsc, watch};
 use tokio::task;
 
 use super::{Query, ServerInfo, SocketTagger, ValidationReporter};
 
-use log::debug;
-
 pub struct Driver {
     info: ServerInfo,
     config: Config,
@@ -113,10 +112,16 @@ impl Driver {
     pub async fn drive(mut self) -> Result<()> {
         while let Some(cmd) = self.command_rx.recv().await {
             match cmd {
-                Command::Probe(duration) =>
-                    if let Err(e) = self.probe(duration).await { self.status_tx.send(Status::Failed(Arc::new(e)))? },
-                Command::Query(query) =>
-                    if let Err(e) = self.send_query(query).await { debug!("Unable to send query: {:?}", e) },
+                Command::Probe(duration) => {
+                    if let Err(e) = self.probe(duration).await {
+                        self.status_tx.send(Status::Failed(Arc::new(e)))?
+                    }
+                }
+                Command::Query(query) => {
+                    if let Err(e) = self.send_query(query).await {
+                        info!("Unable to send query: {:?}", e)
+                    }
+                }
             };
         }
         Ok(())
@@ -140,7 +145,7 @@ impl Driver {
     }
 
     async fn force_probe(&mut self, probe_timeout: Duration) -> Result<()> {
-        debug!("Sending probe to server {} on Network {}", self.info.peer_addr, self.info.net_id);
+        info!("Sending probe to server {} on Network {}", self.info.peer_addr, self.info.net_id);
         let probe = encoding::probe_query()?;
         let dns_request = encoding::dns_request(&probe, &self.info.url)?;
         let expiry = BootTime::now().checked_add(probe_timeout);
@@ -193,7 +198,7 @@ impl Driver {
             let stream = match stream_fut.await {
                 Some(stream) => stream,
                 None => {
-                    debug!("Connection died while processing request");
+                    info!("Connection died while processing request");
                     // We don't care if the response is gone
                     let _ =
                         query.response.send(Response::Error { error: QueryError::ConnectionError });