Using tracing crate to generate more compatible log

Cargo.toml

@@ -25,7 +25,15 @@ default = ["openssl"]
 # The reason we do this is because doctests don't get cfg(test)
 # See: https://github.com/rust-lang/cargo/issues/4669
 integration = []
-mstsc-rs = ["hex", "winapi", "minifb", "clap", "libc", "openssl", "futures"]
+mstsc-rs = ["hex",
+            "winapi",
+            "minifb",
+            "clap",
+            "libc",
+            "openssl",
+            "futures",
+            "tracing-subscriber"
+        ]
 openssl = ["async-native-tls"]
 
 [dependencies]
@@ -42,6 +50,7 @@ rand = "^0.8"
 num-bigint = "^0.4"
 x509-parser = "^0.12"
 num_enum = "^0.5"
+tracing = { version = "^0.1", features = ["log"] }
 
 # for mtsc-rs
 hex = { version = "^0.4", optional = true }
@@ -50,6 +59,7 @@ minifb = { version = "^0.15", optional = true }
 clap = { version = "^2.33", optional = true}
 libc = { version = "^0.2", optional = true}
 futures = { version = "0.3", optional = true }
+tracing-subscriber = { version = "^0.3", optional = true }
 
 [target.'cfg(not(target_arch = "wasm32"))'.dependencies]
 tokio = { version = "^1", features = ["full"] }

src/bin/mstsc-rs.rs

@@ -25,6 +25,7 @@ use tokio::{
     net::TcpStream,
     sync::Mutex,
 };
+use tracing::{event, Level};
 #[cfg(target_os = "windows")]
 use winapi::um::winsock2::{fd_set, select};
 
@@ -398,15 +399,19 @@ fn launch_rdp_thread<S: 'static + AsyncRead + AsyncWrite + Unpin + Send>(
                         RdpEvent::Bitmap(bitmap) => {
                             bitmap_channel.send(bitmap).unwrap();
                         }
-                        _ => println!("{}: ignore event", APPLICATION_NAME),
+                        _ => event!(Level::WARN, "{}: ignore event", APPLICATION_NAME),
                     })
                     .await
                 {
                     match e.kind() {
                         RdpErrorKind::Disconnect => {
-                            println!("{}: Server ask for disconnect", APPLICATION_NAME);
+                            event!(
+                                Level::WARN,
+                                "{}: Server ask for disconnect",
+                                APPLICATION_NAME
+                            );
                         }
-                        _ => println!("{}: {:?}", APPLICATION_NAME, e),
+                        _ => event!(Level::WARN, "{}: {:?}", APPLICATION_NAME, e),
                     }
                     break;
                 }
@@ -622,6 +627,15 @@ async fn main() {
         )
         .get_matches();
 
+    // Create tracing subscriber
+    let subscriber = tracing_subscriber::FmtSubscriber::builder()
+        // all spans/events with a level higher than TRACE (e.g, debug, info, warn, etc.)
+        // will be written to stdout.
+        .with_max_level(Level::INFO)
+        // completes the builder.
+        .finish();
+    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");
+
     // Create a tcp stream from args
     let tcp = tcp_from_args(&matches).await.unwrap();
 

src/core/gcc.rs

@@ -6,6 +6,7 @@ use crate::model::error::{Error, RdpError, RdpErrorKind, RdpResult};
 use crate::model::unicode::Unicode;
 use std::collections::HashMap;
 use std::io::{Cursor, Read};
+use tracing::{event, Level};
 
 const T124_02_98_OID: [u8; 6] = [0, 0, 20, 124, 0, 1];
 const H221_CS_KEY: [u8; 4] = *b"Duca";
@@ -371,7 +372,8 @@ pub fn read_conference_create_response(cc_response: &mut dyn Read) -> RdpResult<
                 server_net.read(&mut Cursor::new(buffer))?;
                 result.insert(MessageType::ScNet, server_net);
             }
-            _ => println!(
+            _ => event!(
+                Level::WARN,
                 "GCC: Unknown server block {:?}",
                 cast!(DataType::U16, header["type"])?
             ),

src/core/global.rs

@@ -12,6 +12,7 @@ use num_enum::TryFromPrimitive;
 use std::convert::TryFrom;
 use std::io::{Cursor, Read};
 use tokio::io::*;
+use tracing::{event, Level};
 
 /// Raw PDU type use by the protocol
 #[repr(u16)]
@@ -644,7 +645,7 @@ impl Client {
             for capability_set in cast!(DataType::Trame, pdu.message["capabilitySets"])?.iter() {
                 match Capability::from_capability_set(cast!(DataType::Component, capability_set)?) {
                     Ok(capability) => self.server_capabilities.push(capability),
-                    Err(e) => println!("GLOBAL: {:?}", e),
+                    Err(e) => event!(Level::WARN, "GLOBAL: {:?}", e),
                 }
             }
             self.share_id = Some(cast!(DataType::U32, pdu.message["shareId"])?);
@@ -719,24 +720,29 @@ impl Client {
 
             // Ask for a new handshake
             if pdu.pdu_type == PduType::Deactivateallpdu {
-                println!("GLOBAL: deactive/reactive sequence initiated");
+                event!(Level::WARN, "GLOBAL: deactive/reactive sequence initiated");
                 self.state = ClientState::DemandActivePDU;
                 continue;
             }
             if pdu.pdu_type != PduType::Datapdu {
-                println!("GLOBAL: Ignore PDU {:?}", pdu.pdu_type);
+                event!(Level::WARN, "GLOBAL: Ignore PDU {:?}", pdu.pdu_type);
                 continue;
             }
 
             match DataPDU::from_pdu(&pdu) {
                 Ok(data_pdu) => match data_pdu.pdu_type {
-                    PDUType2::Pdutype2SetErrorInfoPdu => println!(
+                    PDUType2::Pdutype2SetErrorInfoPdu => event!(
+                        Level::WARN,
                         "GLOBAL: Receive error PDU from server {:?}",
                         cast!(DataType::U32, data_pdu.message["errorInfo"])?
                     ),
-                    _ => println!("GLOBAL: Data PDU not handle {:?}", data_pdu.pdu_type),
+                    _ => event!(
+                        Level::WARN,
+                        "GLOBAL: Data PDU not handle {:?}",
+                        data_pdu.pdu_type
+                    ),
                 },
-                Err(e) => println!("GLOBAL: Parsing data PDU error {:?}", e),
+                Err(e) => event!(Level::WARN, "GLOBAL: Parsing data PDU error {:?}", e),
             };
         }
         Ok(())
@@ -780,10 +786,14 @@ impl Client {
                         FastPathUpdateType::FastpathUpdatetypeColor
                         | FastPathUpdateType::FastpathUpdatetypePtrNull
                         | FastPathUpdateType::FastpathUpdatetypeSynchronize => (),
-                        _ => println!("GLOBAL: Fast Path order not handled {:?}", order.fp_type),
+                        _ => event!(
+                            Level::WARN,
+                            "GLOBAL: Fast Path order not handled {:?}",
+                            order.fp_type
+                        ),
                     }
                 }
-                Err(e) => println!("GLOBAL: Unknown Fast Path order {:?}", e),
+                Err(e) => event!(Level::WARN, "GLOBAL: Unknown Fast Path order {:?}", e),
             };
         }
 

src/core/mcs.rs

@@ -14,6 +14,7 @@ use crate::nla::asn1::{
 use std::collections::HashMap;
 use std::io::{BufRead, Cursor, Read};
 use tokio::io::*;
+use tracing::{event, Level};
 use yasna::Tag;
 
 #[allow(dead_code)]
@@ -327,7 +328,7 @@ impl<S: AsyncRead + AsyncWrite + Unpin> Client<S> {
                 *channel_id,
                 &mut try_let!(tpkt::Payload::Raw, self.x224.read().await?)?,
             )? {
-                println!("Server reject channel id {:?}", channel_id);
+                event!(Level::WARN, "Server reject channel id {:?}", channel_id);
             }
         }
 

src/core/tpkt.rs

@@ -138,7 +138,11 @@ impl<S: AsyncRead + AsyncWrite + Unpin> Client<S> {
             if size.inner() < 4 {
                 Err(Error::RdpError(RdpError::new(
                     RdpErrorKind::InvalidSize,
-                    "Invalid minimal size for TPKT",
+                    &format!(
+                        "Invalid minimal size for TPKT #1 ({}, {})",
+                        action,
+                        size.inner()
+                    ),
                 )))
             } else {
                 // now wait for body
@@ -159,7 +163,7 @@ impl<S: AsyncRead + AsyncWrite + Unpin> Client<S> {
                 if length < 3 {
                     Err(Error::RdpError(RdpError::new(
                         RdpErrorKind::InvalidSize,
-                        "Invalid minimal size for TPKT",
+                        &format!("Invalid minimal size for TPKT #2 ({}, {})", action, length),
                     )))
                 } else {
                     Ok(Payload::FastPath(
@@ -170,7 +174,10 @@ impl<S: AsyncRead + AsyncWrite + Unpin> Client<S> {
             } else if short_length < 2 {
                 Err(Error::RdpError(RdpError::new(
                     RdpErrorKind::InvalidSize,
-                    "Invalid minimal size for TPKT",
+                    &format!(
+                        "Invalid minimal size for TPKT #3 ({}, {})",
+                        action, short_length
+                    ),
                 )))
             } else {
                 Ok(Payload::FastPath(