Update tquic tools (Tencent#151)

- use millisecond precision for log timestamp
- change the `qlog-log` option to the `qlog-dir` option
- change the `dump-path` option to the `dump-dir` option
- update run_endpoint.sh and enable qlog

interop/run_endpoint.sh

@@ -42,6 +42,7 @@ TQUIC_SERVER="tquic_server"
 ROOT_DIR="/www"
 DOWNLOAD_DIR="/downloads"
 LOG_DIR="/logs"
+QLOG_DIR="/logs/qlog"
 
 CC_ALGOR="CUBIC"
 case ${CONGESTION^^} in
@@ -58,15 +59,15 @@ COPA)
     ;;
 esac
 
-COMMON_ARGS="--keylog-file $SSLKEYLOGFILE --log-level TRACE --idle-timeout 30000 --handshake-timeout 30000 --congestion-control-algor $CC_ALGOR"
+COMMON_ARGS="--keylog-file $SSLKEYLOGFILE --qlog-dir $QLOG_DIR --log-level TRACE --idle-timeout 30000 --handshake-timeout 30000 --congestion-control-algor $CC_ALGOR"
 
 if [ "$ROLE" == "client" ]; then
     # Wait for the simulator to start up.
     /wait-for-it.sh sim:57832 -s -t 30
 
     REQS=($REQUESTS)
 
-    CLIENT_ARGS="$COMMON_ARGS --dump-path ${DOWNLOAD_DIR} --max-concurrent-requests ${#REQS[@]}"
+    CLIENT_ARGS="$COMMON_ARGS --dump-dir ${DOWNLOAD_DIR} --max-concurrent-requests ${#REQS[@]}"
     CLIENT_ALPN="--alpn hq-interop"
     case $TESTCASE in
     resumption)

src/lib.rs

@@ -875,6 +875,7 @@ mod tests {
     fn init() {
         env_logger::builder()
             .filter_level(log::LevelFilter::Trace)
+            .format_timestamp_millis()
             .is_test(true)
             .init();
     }

tools/src/bin/tquic_client.rs

@@ -24,6 +24,7 @@ use std::net::Ipv4Addr;
 use std::net::Ipv6Addr;
 use std::net::SocketAddr;
 use std::net::ToSocketAddrs;
+use std::path::Path;
 use std::rc::Rc;
 use std::sync::atomic::AtomicBool;
 use std::sync::atomic::Ordering;
@@ -137,7 +138,7 @@ pub struct ClientOpt {
     /// Dump response body into the given directory.
     /// If the specified directory does not exist, a new directory will be created.
     #[clap(long, value_name = "DIR")]
-    pub dump_path: Option<String>,
+    pub dump_dir: Option<String>,
 
     /// File used for session resumption.
     #[clap(short, long, value_name = "FILE")]
@@ -208,9 +209,9 @@ pub struct ClientOpt {
     #[clap(short, long, value_name = "FILE")]
     pub keylog_file: Option<String>,
 
-    /// Save QUIC qlog into the given file.
-    #[clap(long, value_name = "FILE")]
-    pub qlog_file: Option<String>,
+    /// Save qlog file (<trace_id>.qlog) into the given directory.
+    #[clap(long, value_name = "DIR")]
+    pub qlog_dir: Option<String>,
 
     /// Length of connection id in bytes.
     #[clap(long, default_value = "8", value_name = "NUM")]
@@ -755,7 +756,7 @@ impl Request {
     }
 
     // TODO: support custom headers.
-    fn new(method: &str, url: &Url, body: &Option<Vec<u8>>, dump_path: &Option<String>) -> Self {
+    fn new(method: &str, url: &Url, body: &Option<Vec<u8>>, dump_dir: &Option<String>) -> Self {
         let authority = match url.port() {
             Some(port) => format!("{}:{}", url.host_str().unwrap(), port),
             None => url.host_str().unwrap().to_string(),
@@ -778,7 +779,7 @@ impl Request {
             url: url.clone(),
             line: format!("GET {}\r\n", url.path()),
             headers,
-            response_writer: Self::make_response_writer(url, dump_path),
+            response_writer: Self::make_response_writer(url, dump_dir),
             start_time: None,
         }
     }
@@ -891,7 +892,7 @@ impl RequestSender {
 
     fn send_request(&mut self, conn: &mut Connection) -> Result<()> {
         let url = &self.option.urls[self.current_url_idx];
-        let mut request = Request::new("GET", url, &None, &self.option.dump_path);
+        let mut request = Request::new("GET", url, &None, &self.option.dump_dir);
         debug!(
             "{} send request {} current index {}",
             conn.trace_id(),
@@ -1220,19 +1221,21 @@ impl TransportHandler for WorkerHandler {
             }
         }
 
-        if let Some(qlog_file) = &self.option.qlog_file {
+        if let Some(qlog_dir) = &self.option.qlog_dir {
+            let qlog_file = format!("{}.qlog", conn.trace_id());
+            let qlog_file = Path::new(qlog_dir).join(qlog_file);
             if let Ok(qlog) = std::fs::OpenOptions::new()
                 .create(true)
                 .append(true)
-                .open(qlog_file)
+                .open(qlog_file.as_path())
             {
                 conn.set_qlog(
                     Box::new(qlog),
                     "client qlog".into(),
                     format!("id={}", conn.trace_id()),
                 );
             } else {
-                error!("{} set qlog failed", conn.trace_id());
+                error!("{} set qlog {:?} failed", conn.trace_id(), qlog_file);
             }
         }
     }
@@ -1392,20 +1395,28 @@ fn parse_option() -> std::result::Result<ClientOpt, clap::error::Error> {
     Ok(option)
 }
 
-fn process_option(option: &mut ClientOpt) {
-    env_logger::builder().filter_level(option.log_level).init();
+fn process_option(option: &mut ClientOpt) -> Result<()> {
+    env_logger::builder()
+        .filter_level(option.log_level)
+        .format_timestamp_millis()
+        .init();
 
-    if let Some(dump_path) = &option.dump_path {
-        if let Err(e) = create_dir_all(dump_path) {
-            warn!(
-                "create dump path directory error: {:?}, can't dump response body",
-                e
-            );
-            option.dump_path = None;
+    if let Some(dump_dir) = &option.dump_dir {
+        if let Err(e) = create_dir_all(dump_dir) {
+            warn!("create dump directory {} error: {:?}", dump_dir, e);
+            return Err(Box::new(e));
+        }
+    }
+
+    if let Some(qlog_dir) = &option.qlog_dir {
+        if let Err(e) = create_dir_all(qlog_dir) {
+            warn!("create qlog directory {} error: {:?}", qlog_dir, e);
+            return Err(Box::new(e));
         }
     }
 
     process_connect_address(option);
+    Ok(())
 }
 
 fn main() -> Result<()> {
@@ -1416,7 +1427,7 @@ fn main() -> Result<()> {
     };
 
     // Process client option.
-    process_option(&mut option);
+    process_option(&mut option)?;
 
     // Create client.
     let mut client = Client::new(option)?;

tools/src/bin/tquic_server.rs

@@ -16,16 +16,17 @@
 
 use std::cmp;
 use std::collections::HashMap;
+use std::fs::create_dir_all;
 use std::fs::File;
 use std::net::SocketAddr;
 use std::path;
+use std::path::Path;
 use std::rc::Rc;
 use std::time::Instant;
 
 use bytes::Bytes;
 use clap::Parser;
-use log::debug;
-use log::error;
+use log::*;
 use mio::event::Event;
 use rustc_hash::FxHashMap;
 
@@ -146,9 +147,9 @@ pub struct ServerOpt {
     #[clap(long, value_name = "FILE")]
     pub keylog_file: Option<String>,
 
-    /// Save QUIC qlog into the given file.
-    #[clap(long, value_name = "FILE")]
-    pub qlog_file: Option<String>,
+    /// Save qlog file (<trace_id>.qlog) into the given directory.
+    #[clap(long, value_name = "DIR")]
+    pub qlog_dir: Option<String>,
 
     /// Length of connection id in bytes.
     #[clap(long, default_value = "8", value_name = "NUM")]
@@ -632,8 +633,8 @@ struct ServerHandler {
     /// SSL key logger
     keylog: Option<File>,
 
-    /// Qlog file
-    qlog: Option<File>,
+    /// Qlog directory
+    qlog_dir: Option<String>,
 }
 
 impl ServerHandler {
@@ -648,22 +649,12 @@ impl ServerHandler {
             None => None,
         };
 
-        let qlog = match &option.qlog_file {
-            Some(qlog_file) => Some(
-                std::fs::OpenOptions::new()
-                    .create(true)
-                    .append(true)
-                    .open(qlog_file)?,
-            ),
-            None => None,
-        };
-
         Ok(Self {
             root: option.root.clone(),
             buf: vec![0; MAX_BUF_SIZE],
             conns: FxHashMap::default(),
             keylog,
-            qlog,
+            qlog_dir: option.qlog_dir.clone(),
         })
     }
 
@@ -699,13 +690,28 @@ impl TransportHandler for ServerHandler {
             }
         }
 
-        if let Some(qlog) = &mut self.qlog {
-            if let Ok(qlog) = qlog.try_clone() {
+        // The qlog of each server connection is written to a different log file
+        // in JSON-SEQ format.
+        //
+        // Note: The server qlogs can also be written to the same file, with a
+        // recommended prefix for each line of logs that includes the trace id.
+        // The qlog of each connection can be then extracted by offline log
+        // processing.
+        if let Some(qlog_dir) = &self.qlog_dir {
+            let qlog_file = format!("{}.qlog", conn.trace_id());
+            let qlog_file = Path::new(qlog_dir).join(qlog_file);
+            if let Ok(qlog) = std::fs::OpenOptions::new()
+                .create(true)
+                .append(true)
+                .open(qlog_file.as_path())
+            {
                 conn.set_qlog(
                     Box::new(qlog),
                     "server qlog".into(),
                     format!("id={}", conn.trace_id()),
                 );
+            } else {
+                error!("{} set qlog {:?} failed", conn.trace_id(), qlog_file);
             }
         }
     }
@@ -758,11 +764,25 @@ impl TransportHandler for ServerHandler {
     fn on_new_token(&mut self, _conn: &mut Connection, _token: Vec<u8>) {}
 }
 
-fn main() -> Result<()> {
-    let option = ServerOpt::parse();
+fn process_option(option: &mut ServerOpt) -> Result<()> {
+    env_logger::builder()
+        .filter_level(option.log_level)
+        .format_timestamp_millis()
+        .init();
+
+    if let Some(qlog_dir) = &option.qlog_dir {
+        if let Err(e) = create_dir_all(qlog_dir) {
+            warn!("create qlog directory {} error: {:?}", qlog_dir, e);
+            return Err(Box::new(e));
+        }
+    }
+    Ok(())
+}
 
-    // Initialize logging.
-    env_logger::builder().filter_level(option.log_level).init();
+fn main() -> Result<()> {
+    // Parse and process server option
+    let mut option = ServerOpt::parse();
+    process_option(&mut option)?;
 
     // Initialize HTTP file server.
     let mut server = Server::new(&option)?;