Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 2ee530d5 authored by Mike Yu's avatar Mike Yu
Browse files

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
parent 6eb31445

doh/connection/driver.rs

+14 −14
Original line number Diff line number Diff line
@@ -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,

doh/network/driver.rs

+13 −8
Original line number Diff line number Diff line
@@ -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 });