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

Commit 0f13e595 authored by Mike Yu's avatar Mike Yu
Browse files

Add more debugging logs for DoH 

Bug: 203314532
Test: built dnsresolver
Change-Id: I7232eb15ff4a02976fcbfeba676906638e9f7a4f
parent e34efd08

doh/connection/driver.rs

+63 −10
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, trace, warn};

use quiche::h3;

use std::collections::HashMap;

use std::default::Default;
@@ -86,6 +86,7 @@ struct Driver { 
    // off the stack and prevent it being copied during

    // moves of the driver.

    buffer: Box<[u8; MAX_UDP_PACKET_SIZE]>,

    net_id: u32,

}



struct H3Driver {
@@ -103,7 +104,8 @@ struct H3Driver { 
    streams: HashMap<u64, Stream>,

}



async fn optional_timeout(timeout: Option<boot_time::Duration>) {

async fn optional_timeout(timeout: Option<boot_time::Duration>, net_id: u32) {

    trace!("optional_timeout: timeout={:?}, network {}", timeout, net_id);

    match timeout {

        Some(timeout) => boot_time::sleep(timeout).await,

        None => future::pending().await,
@@ -117,8 +119,9 @@ pub async fn drive( 
    status_tx: watch::Sender<Status>,

    quiche_conn: Pin<Box<quiche::Connection>>,

    socket: UdpSocket,

    net_id: u32,

) -> Result<()> {

    Driver::new(request_rx, status_tx, quiche_conn, socket).drive().await

    Driver::new(request_rx, status_tx, quiche_conn, socket, net_id).drive().await

}



impl Driver {
@@ -127,6 +130,7 @@ impl Driver { 
        status_tx: watch::Sender<Status>,

        quiche_conn: Pin<Box<quiche::Connection>>,

        socket: UdpSocket,

        net_id: u32,

    ) -> Self {

        Self {

            request_rx,
@@ -134,6 +138,7 @@ impl Driver { 
            quiche_conn,

            socket,

            buffer: Box::new([0; MAX_UDP_PACKET_SIZE]),

            net_id,

        }

    }
@@ -147,6 +152,12 @@ 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!(

                "Connection closed on network {}, peer_error={:?}",

                self.net_id,

                self.quiche_conn.peer_error()

            );

            // We don't care if the receiver has hung up

            let _ = self.status_tx.send(Status::Dead);

            Err(Error::Closed)
@@ -156,15 +167,17 @@ impl Driver { 
    }



    async fn drive_once(mut self) -> Result<Self> {

        let timer = optional_timeout(self.quiche_conn.timeout());

        let timer = optional_timeout(self.quiche_conn.timeout(), self.net_id);

        select! {

            // If a quiche timer would fire, call their callback

            _ = timer => {

                debug!("Driver: Timer expired on network {}", self.net_id);

                self.quiche_conn.on_timeout()

            }

            // If we got packets from our peer, pass them to quiche

            Ok((size, from)) = self.socket.recv_from(self.buffer.as_mut()) => {

                self.quiche_conn.recv(&mut self.buffer[..size], quiche::RecvInfo { from })?;

                debug!("Received {} bytes on network {}", size, self.net_id);

            }

        };

        // Any of the actions in the select could require us to send packets to the peer
@@ -192,6 +205,7 @@ impl Driver { 
                Err(e) => return Err(e.into()),

                Ok((valid_len, send_info)) => {

                    self.socket.send_to(&send_buf[..valid_len], send_info.to).await?;

                    debug!("Sent {} bytes on network {}", valid_len, self.net_id);

                }

            }

        }
@@ -226,7 +240,7 @@ impl H3Driver { 
    async fn drive_once(&mut self) -> Result<()> {

        // We can't call self.driver.drive_once at the same time as

        // self.driver.request_rx.recv() due to ownership

        let timer = optional_timeout(self.driver.quiche_conn.timeout());

        let timer = optional_timeout(self.driver.quiche_conn.timeout(), self.driver.net_id);

        // If we've buffered a request (due to the connection being full)

        // try to resend that first

        if let Some(request) = self.buffered_request.take() {
@@ -243,11 +257,14 @@ impl H3Driver { 
            },

            // If a quiche timer would fire, call their callback

            _ = timer => {

                debug!("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

            Ok((size, from)) = self.driver.socket.recv_from(self.driver.buffer.as_mut()) =>

                self.driver.quiche_conn.recv(&mut self.driver.buffer[..size], quiche::RecvInfo { from }).map(|_| ())?,

            Ok((size, from)) = self.driver.socket.recv_from(self.driver.buffer.as_mut()) => {

                self.driver.quiche_conn.recv(&mut self.driver.buffer[..size], quiche::RecvInfo { from }).map(|_| ())?;

                debug!("Received {} bytes on network {}", size, self.driver.net_id);

            }

        };



        // Any of the actions in the select could require us to send packets to the peer
@@ -261,6 +278,8 @@ 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={}",

                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 {

            if BootTime::now() > expiry {
@@ -283,6 +302,12 @@ impl H3Driver { 
                }

                result => result?,

            };

        debug!(

            "Handled DNS request: stream ID {}, network {}, stream_capacity={:?}",

            stream_id,

            self.driver.net_id,

            self.driver.quiche_conn.stream_capacity(stream_id)

        );

        self.requests.insert(stream_id, request);

        Ok(())

    }
@@ -303,10 +328,17 @@ impl H3Driver { 
                        return Ok(());

                    }

                    Err(e) => {

                        debug!("recv_body: Error={:?}", e);

                        stream.data.truncate(base_len);

                        return Err(e.into());

                    }

                    Ok(recvd) => stream.data.truncate(base_len + recvd),

                    Ok(recvd) => {

                        stream.data.truncate(base_len + recvd);

                        debug!(

                            "Got {} bytes of response data from stream ID {} on network {}",

                            recvd, stream_id, self.driver.net_id

                        );

                    }

                }

            }

        } else {
@@ -342,6 +374,10 @@ impl H3Driver { 
        }

        match event {

            h3::Event::Headers { list, has_body } => {

                debug!(

                    "process_h3_event: h3::Event::Headers on stream ID {}, network {}",

                    stream_id, self.driver.net_id

                );

                let stream = Stream::new(list);

                if self.streams.insert(stream_id, stream).is_some() {

                    warn!("Re-using stream ID {} before it was completed.", stream_id)
@@ -350,8 +386,20 @@ impl H3Driver { 
                    self.respond(stream_id);

                }

            }

            h3::Event::Data => self.recv_body(stream_id).await?,

            h3::Event::Finished => self.respond(stream_id),

            h3::Event::Data => {

                debug!(

                    "process_h3_event: h3::Event::Data on stream ID {}, network {}",

                    stream_id, self.driver.net_id

                );

                self.recv_body(stream_id).await?;

            }

            h3::Event::Finished => {

                debug!(

                    "process_h3_event: h3::Event::Finished on stream ID {}, network {}",

                    stream_id, self.driver.net_id

                );

                self.respond(stream_id)

            }

            // This clause is for quiche 0.10.x, we're still on 0.9.x

            //h3::Event::Reset(e) => {

            //    self.streams.get_mut(&stream_id).map(|stream| stream.error = Some(e));
@@ -369,6 +417,7 @@ impl H3Driver { 
    }



    async fn shutdown(&mut self, send_goaway: bool, msg: &[u8]) -> Result<()> {

        debug!("Closing connection on network {} with msg {:?}", self.driver.net_id, msg);

        self.driver.request_rx.close();

        while self.driver.request_rx.recv().await.is_some() {}

        self.closing = true;
@@ -384,6 +433,10 @@ impl H3Driver { 
    fn respond(&mut self, stream_id: u64) {

        match (self.streams.remove(&stream_id), self.requests.remove(&stream_id)) {

            (Some(stream), Some(request)) => {

                debug!(

                    "Sending answer back to resolv, stream ID: {}, network {}",

                    stream_id, self.driver.net_id

                );

                // We don't care about the error, because it means the requestor has left.

                let _ = request.response_tx.send(stream);

            }

doh/connection/mod.rs

+5 −4
Original line number Diff line number Diff line
@@ -17,7 +17,7 @@ 


use crate::boot_time::BootTime;

use crate::network::SocketTagger;

use log::error;

use log::{error, warn};

use quiche::h3;

use std::future::Future;

use std::io;
@@ -129,6 +129,7 @@ impl Connection { 
        server_name: Option<&str>,

        to: SocketAddr,

        socket_mark: u32,

        net_id: u32,

        tag_socket: &SocketTagger,

        config: &mut quiche::Config,

    ) -> Result<Self> {
@@ -138,10 +139,10 @@ impl Connection { 
        let quiche_conn =

            quiche::connect(server_name, &quiche::ConnectionId::from_ref(&scid), to, config)?;

        let socket = build_socket(to, socket_mark, tag_socket).await?;

        let driver = async {

            let result = drive(request_rx, status_tx, quiche_conn, socket).await;

        let driver = async move {

            let result = drive(request_rx, status_tx, quiche_conn, socket, net_id).await;

            if let Err(ref e) = result {

                error!("Connection driver failed: {:?}", e);

                warn!("Connection driver returns some Err: {:?}", e);

            }

            result

        };

doh/dispatcher/driver.rs

+1 −1
Original line number Diff line number Diff line
@@ -107,7 +107,7 @@ impl Driver { 
            // If we have a network registered to the provided net_id, but the server info doesn't

            // match, our API has been used incorrectly. Attempt to recover by deleting the old

            // network and recreating it according to the probe request.

            warn!("Probing net_id={} with mismatched server info", info.net_id);

            warn!("Probing net_id={} with mismatched server info {:?}", info.net_id, info);

            self.networks.remove(&info.net_id);

        }

        // Can't use or_insert_with because creating a network may fail

doh/network/driver.rs

+2 −0
Original line number Diff line number Diff line
@@ -82,6 +82,7 @@ async fn build_connection( 
        info.domain.as_deref(),

        info.peer_addr,

        info.sk_mark,

        info.net_id,

        tag_socket,

        config.take().await.deref_mut(),

    )
@@ -141,6 +142,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);

        let probe = encoding::probe_query()?;

        let dns_request = encoding::dns_request(&probe, &self.info.url)?;

        let expiry = BootTime::now().checked_add(probe_timeout);

res_send.cpp

+1 −1
Original line number Diff line number Diff line
@@ -1398,7 +1398,7 @@ ssize_t res_doh_send(ResState* statp, const Slice query, const Slice answer, int 
        queryTimeout = 1000;

    }

    ssize_t result = privateDnsConfiguration.dohQuery(netId, query, answer, queryTimeout);

    LOG(INFO) << __func__ << ": Https query result: " << result;

    LOG(INFO) << __func__ << ": Https query result: " << result << ", netid=" << netId;



    if (result == DOH_RESULT_CAN_NOT_SEND) return DOH_RESULT_CAN_NOT_SEND;