From 22b261bbfc59c3294623b2ed2d1ddc5bf1c109bc Mon Sep 17 00:00:00 2001 From: Ketan Singh Date: Sun, 18 Aug 2024 12:15:47 +0200 Subject: [PATCH] use tracing crate --- Cargo.lock | 104 +++++++++++++++++++++++++++++++++++++-- Cargo.toml | 7 ++- cli/Cargo.toml | 2 + cli/src/main.rs | 66 ++++++++++++------------- src/core.rs | 7 ++- src/core/key.rs | 3 +- src/core/rendezvous.rs | 18 +++---- src/core/test.rs | 80 +++++++++++------------------- src/forwarding.rs | 44 ++++++++--------- src/transfer.rs | 1 - src/transfer/cancel.rs | 26 +++++----- src/transfer/offer.rs | 8 +-- src/transfer/v1.rs | 46 ++++++++--------- src/transfer/v2.rs | 2 +- src/transit.rs | 47 +++++++++--------- src/transit/transport.rs | 16 +++--- src/util.rs | 2 +- 17 files changed, 277 insertions(+), 202 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 79f9d98f..60009fa3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1713,7 +1713,6 @@ dependencies = [ "bytecodec", "crypto_secretbox", "derive_more", - "env_logger", "eyre", "futures", "getrandom", @@ -1736,8 +1735,10 @@ dependencies = [ "spake2", "stun_codec", "tar", + "test-log", "thiserror", "time", + "tracing", "url", "wasm-timer", "ws_stream_wasm", @@ -1766,10 +1767,21 @@ dependencies = [ "serde", "serde_derive", "serde_json", + "tracing", + "tracing-subscriber", "trycmd", "url", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "md5" version = "0.7.0" @@ -1900,6 +1912,16 @@ version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "61807f77802ff30975e01f4f071c8ba10c022052f98b3294119f3e615d13e5be" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-conv" version = "0.1.0" @@ -2095,6 +2117,12 @@ dependencies = [ "windows-sys 0.59.0", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "owo-colors" version = "3.5.0" @@ -2426,8 +2454,17 @@ checksum = "4219d74c6b67a3654a9fbebc4b419e22126d13d2f3c4a07ee0cb61ff79a79619" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.7", + "regex-syntax 0.8.4", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -2438,9 +2475,15 @@ checksum = "38caf58cc5ef2fed281f89292ef23f6365465ed9a41b7a7754eb4e26496c92df" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.4", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.4" @@ -2941,6 +2984,28 @@ dependencies = [ "windows-sys 0.59.0", ] +[[package]] +name = "test-log" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3dffced63c2b5c7be278154d76b479f9f9920ed34e7574201407f0b14e2bbb93" +dependencies = [ + "env_logger", + "test-log-macros", + "tracing-subscriber", +] + +[[package]] +name = "test-log-macros" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5999e24eaa32083191ba4e425deb75cdf25efefabe5aaccb7446dd0d4122a3f5" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.76", +] + [[package]] name = "thiserror" version = "1.0.63" @@ -3056,10 +3121,23 @@ version = "0.1.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ + "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.27" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.76", +] + [[package]] name = "tracing-core" version = "0.1.32" @@ -3080,15 +3158,33 @@ dependencies = [ "tracing-subscriber", ] +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", "sharded-slab", + "smallvec", "thread_local", + "tracing", "tracing-core", + "tracing-log", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 5a414160..7da0d0d8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -58,6 +58,9 @@ thiserror = "1.0.24" time = "0.3.7" trycmd = "0.15" url = "2.2.2" +tracing = "0.1" +tracing-subscriber = "0.3" +test-log = "0.2" [package] name = "magic-wormhole" @@ -101,6 +104,8 @@ futures = { workspace = true } url = { workspace = true, features = ["serde"] } percent-encoding = { workspace = true } +tracing = { workspace = true, features = ["log", "log-always"]} + # Transit dependencies @@ -138,7 +143,7 @@ getrandom = { version = "0.2.5", features = ["js"] } # for some tests [dev-dependencies] -env_logger = { workspace = true } +test-log = { workspace = true} eyre = { workspace = true } [features] diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 9835b8a3..de23ec8d 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -40,6 +40,8 @@ number_prefix = { workspace = true } ctrlc = { workspace = true } qr2term = { workspace = true } arboard = { workspace = true, features = ["wayland-data-control"] } # Wayland by default, fallback to X11. +tracing = { workspace = true, features = ["log", "log-always"] } +tracing-subscriber = { workspace=true, features = ["env-filter"] } [dev-dependencies] trycmd = { workspace = true } diff --git a/cli/src/main.rs b/cli/src/main.rs index a0e02883..c2f12834 100644 --- a/cli/src/main.rs +++ b/cli/src/main.rs @@ -10,13 +10,13 @@ use color_eyre::{eyre, eyre::Context}; use console::{style, Term}; use futures::{future::Either, Future, FutureExt}; use indicatif::{MultiProgress, ProgressBar}; -use std::{io::Write, path::PathBuf}; - use magic_wormhole::{ forwarding, transfer, transit::{self, TransitInfo}, MailboxConnection, Wormhole, }; +use std::{io::Write, path::PathBuf}; +use tracing_subscriber::EnvFilter; fn install_ctrlc_handler( ) -> eyre::Result futures::future::BoxFuture<'static, ()> + Clone> { @@ -31,11 +31,11 @@ fn install_ctrlc_handler( let mut has_notified = notifier2.0.lock().await; if *has_notified { /* Second signal. Exit */ - log::debug!("Exit."); + tracing::debug!("Exit."); std::process::exit(130); } /* First signal. */ - log::info!("Got Ctrl-C event. Press again to exit immediately"); + tracing::info!("Got Ctrl-C event. Press again to exit immediately"); *has_notified = true; notifier2.1.notify_all(); }) @@ -263,25 +263,25 @@ async fn main() -> eyre::Result<()> { let mut term = Term::stdout(); if app.log { - env_logger::builder() - .filter_level(log::LevelFilter::Debug) - .filter_module("magic_wormhole::core", log::LevelFilter::Trace) - .filter_module("mio", log::LevelFilter::Debug) - .filter_module("ws", log::LevelFilter::Error) - .try_init()?; - log::debug!("Logging enabled."); + tracing_subscriber::fmt() + .with_max_level(tracing::Level::TRACE) + .with_env_filter(EnvFilter::new( + "magic_wormhole::core=trace,mio=debug,ws=error", + )) + .with_target(false) + .init(); + tracing::trace!("Logging enabled."); } else { - env_logger::builder() - .filter_level(log::LevelFilter::Info) - .filter_module("ws", log::LevelFilter::Error) - .format_timestamp(None) - .format_target(false) - .try_init()?; - } + tracing_subscriber::fmt() + .with_max_level(tracing::Level::INFO) + .with_env_filter(EnvFilter::new("mio=debug")) + .with_target(false) + .init(); + }; let mut clipboard = Clipboard::new() .map_err(|err| { - log::warn!("Failed to initialize clipboard support: {}", err); + tracing::warn!("Failed to initialize clipboard support: {}", err); }) .ok(); @@ -407,7 +407,7 @@ async fn main() -> eyre::Result<()> { .. }) => { // TODO make fancy - log::warn!("This is an unstable feature. Make sure that your peer is running the exact same version of the program as you. Also, please report all bugs and crashes."); + tracing::warn!("This is an unstable feature. Make sure that your peer is running the exact same version of the program as you. Also, please report all bugs and crashes."); /* Map the CLI argument to Strings. Use the occasion to inspect them and fail early on malformed input. */ let targets = targets .into_iter() @@ -481,7 +481,7 @@ async fn main() -> eyre::Result<()> { .. }) => { // TODO make fancy - log::warn!("This is an unstable feature. Make sure that your peer is running the exact same version of the program as you. Also, please report all bugs and crashes."); + tracing::warn!("This is an unstable feature. Make sure that your peer is running the exact same version of the program as you. Also, please report all bugs and crashes."); let mut app_config = forwarding::APP_CONFIG; app_config.app_version.transit_abilities = parse_transit_args(&common); let (wormhole, _code, relay_hints) = parse_and_connect( @@ -504,10 +504,10 @@ async fn main() -> eyre::Result<()> { &ports, ) .await?; - log::info!("Mapping the following open ports to targets:"); - log::info!(" local port -> remote target (no address = localhost on remote)"); + tracing::info!("Mapping the following open ports to targets:"); + tracing::info!(" local port -> remote target (no address = localhost on remote)"); for (port, target) in &offer.mapping { - log::info!(" {} -> {}", port, target); + tracing::info!(" {} -> {}", port, target); } if noconfirm || util::ask_user("Accept forwarded ports?", true).await { offer.accept(ctrl_c()).await?; @@ -625,8 +625,8 @@ async fn parse_and_connect( if is_send { if let Some(clipboard) = clipboard { match clipboard.set_text(mailbox_connection.code().to_string()) { - Ok(()) => log::info!("Code copied to clipboard"), - Err(err) => log::warn!("Failed to copy code to clipboard: {}", err), + Ok(()) => tracing::info!("Code copied to clipboard"), + Err(err) => tracing::warn!("Failed to copy code to clipboard: {}", err), } } @@ -656,7 +656,7 @@ async fn make_send_offer( file.display() ); } - log::trace!("Making send offer in {files:?}, with name {file_name:?}"); + tracing::trace!("Making send offer in {files:?}, with name {file_name:?}"); match (files.len(), file_name) { (0, _) => unreachable!("Already checked by CLI parser"), @@ -826,7 +826,7 @@ async fn send_many( transit_abilities: transit::Abilities, ctrl_c: impl Fn() -> futures::future::BoxFuture<'static, ()>, ) -> eyre::Result<()> { - log::warn!("Reminder that you are sending the file to multiple people, and this may reduce the overall security. See the help page for more information."); + tracing::warn!("Reminder that you are sending the file to multiple people, and this may reduce the overall security. See the help page for more information."); /* Progress bar is commented out for now. See the issues about threading/async in * the Indicatif repository for more information. Multiple progress bars are not usable @@ -849,14 +849,14 @@ async fn send_many( for tries in 0.. { if time.elapsed() >= timeout { - log::info!( + tracing::info!( "{:?} have elapsed, we won't accept any new connections now.", timeout ); break; } if tries > max_tries { - log::info!("Max number of tries reached, we won't accept any new connections now."); + tracing::info!("Max number of tries reached, we won't accept any new connections now."); break; } @@ -907,11 +907,11 @@ async fn send_many( match result.await { Ok(_) => { pb.finish(); - log::info!("Successfully sent file to someone"); + tracing::info!("Successfully sent file to someone"); }, Err(e) => { pb.abandon(); - log::error!("Send failed, {}", e); + tracing::error!("Send failed, {}", e); }, }; }); @@ -1144,7 +1144,7 @@ async fn receive_inner_v2( } fn transit_handler(info: TransitInfo) { - log::info!("{info}"); + tracing::info!("{info}"); } #[cfg(test)] diff --git a/src/core.rs b/src/core.rs index 252cce9f..8844ba49 100644 --- a/src/core.rs +++ b/src/core.rs @@ -11,7 +11,6 @@ use serde_derive::{Deserialize, Serialize}; use std::borrow::Cow; use self::{rendezvous::*, server_messages::EncryptedMessage}; -use log::*; use crypto_secretbox as secretbox; @@ -384,7 +383,7 @@ impl Wormhole { server.release_nameplate().await?; } - log::info!("Found peer on the rendezvous server."); + tracing::info!("Found peer on the rendezvous server."); /* We are now fully initialized! Up and running! :tada: */ #[allow(deprecated)] @@ -463,7 +462,7 @@ impl Wormhole { { self.receive().await.map(|data: Vec| { serde_json::from_slice(&data).map_err(|e| { - log::error!( + tracing::error!( "Received invalid data from peer: '{}'", String::from_utf8_lossy(&data) ); @@ -474,7 +473,7 @@ impl Wormhole { /// Close the wormhole pub async fn close(self) -> Result<(), WormholeError> { - log::debug!("Closing Wormhole…"); + tracing::debug!("Closing Wormhole…"); self.server.shutdown(Mood::Happy).await.map_err(Into::into) } diff --git a/src/core/key.rs b/src/core/key.rs index 6c627ea1..f389e631 100644 --- a/src/core/key.rs +++ b/src/core/key.rs @@ -62,9 +62,8 @@ impl Key { )] pub fn derive_transit_key(&self, appid: &AppID) -> Key { let transit_purpose = format!("{}/transit-key", appid); - let derived_key = self.derive_subkey_from_purpose(&transit_purpose); - trace!( + tracing::trace!( "Input key: {}, Transit key: {}, Transit purpose: '{}'", self.to_hex(), derived_key.to_hex(), diff --git a/src/core/rendezvous.rs b/src/core/rendezvous.rs index fdd30660..d8ecbc47 100644 --- a/src/core/rendezvous.rs +++ b/src/core/rendezvous.rs @@ -100,7 +100,7 @@ impl WsConnection { message: &OutboundMessage, queue: Option<&mut MessageQueue>, ) -> Result<(), RendezvousError> { - log::debug!("Sending {}", message); + tracing::debug!("Sending {}", message); self.connection .send(ws2::Message::Text(serde_json::to_string(message).unwrap())) .await?; @@ -114,7 +114,7 @@ impl WsConnection { message: &OutboundMessage, queue: Option<&mut MessageQueue>, ) -> Result<(), RendezvousError> { - log::debug!("Sending {:?}", message); + tracing::debug!("Sending {:?}", message); self.connection .send(ws_stream_wasm::WsMessage::Text( serde_json::to_string(message).unwrap(), @@ -214,10 +214,10 @@ impl WsConnection { match message { ws2::Message::Text(message_plain) => { let message = serde_json::from_str(&message_plain)?; - log::debug!("Received {}", message); + tracing::debug!("Received {}", message); match message { InboundMessage::Unknown => { - log::warn!("Got unknown message, ignoring: '{}'", message_plain); + tracing::warn!("Got unknown message, ignoring: '{}'", message_plain); Ok(None) }, InboundMessage::Error { error, orig: _ } => Err(RendezvousError::server(error)), @@ -231,11 +231,11 @@ impl WsConnection { ws2::Message::Ping(_) => Ok(None), ws2::Message::Pong(_) => Ok(None), ws2::Message::Close(_) => { - log::debug!("Received connection close"); + tracing::debug!("Received connection close"); Err(ws2::Error::ConnectionClosed.into()) }, ws2::Message::Frame(_) => { - log::warn!("Received a WebSocket 'Frame' message and don't know what to do with it, please open a bug report"); + tracing::warn!("Received a WebSocket 'Frame' message and don't know what to do with it, please open a bug report"); Ok(None) }, } @@ -251,10 +251,10 @@ impl WsConnection { match message { ws_stream_wasm::WsMessage::Text(message_plain) => { let message = serde_json::from_str(&message_plain)?; - log::debug!("Received {:?}", message); + tracing::debug!("Received {:?}", message); match message { InboundMessage::Unknown => { - log::warn!("Got unknown message, ignoring: '{}'", message_plain); + tracing::warn!("Got unknown message, ignoring: '{}'", message_plain); Ok(None) }, InboundMessage::Error { error, orig: _ } => Err(RendezvousError::server(error)), @@ -409,7 +409,7 @@ impl RendezvousServer { .send_message(&OutboundMessage::bind(appid.clone(), side.clone()), None) .await?; - log::info!("Connected to rendezvous server."); + tracing::info!("Connected to rendezvous server."); Ok(( Self { diff --git a/src/core/test.rs b/src/core/test.rs index d8bd708d..ba1dd2f3 100644 --- a/src/core/test.rs +++ b/src/core/test.rs @@ -1,9 +1,6 @@ #![allow(irrefutable_let_patterns)] use super::{Mood, Phase}; -use rand::Rng; -use std::{borrow::Cow, time::Duration}; - #[cfg(feature = "transfer")] use crate::transfer; use crate::{ @@ -11,6 +8,9 @@ use crate::{ core::{MailboxConnection, Nameplate}, transit, AppConfig, AppID, Code, Wormhole, WormholeError, }; +use rand::Rng; +use std::{borrow::Cow, time::Duration}; +use test_log::test; pub const TEST_APPID: AppID = AppID(std::borrow::Cow::Borrowed( "piegames.de/wormhole/rusty-wormhole-test", @@ -24,17 +24,6 @@ pub const APP_CONFIG: AppConfig<()> = AppConfig::<()> { const TIMEOUT: Duration = Duration::from_secs(60); -fn init_logger() { - /* Ignore errors from succeedent initialization tries */ - let _ = env_logger::builder() - .filter_level(log::LevelFilter::Debug) - .filter_module("magic_wormhole", log::LevelFilter::Trace) - .filter_module("magic_wormhole::transfer", log::LevelFilter::Trace) - .filter_module("magic_wormhole::transit", log::LevelFilter::Trace) - .filter_module("mio", log::LevelFilter::Debug) - .try_init(); -} - /// Utility method that logs information of the transit result /// /// Example usage: @@ -55,7 +44,7 @@ fn init_logger() { /// ``` #[cfg(not(target_family = "wasm"))] pub(crate) fn log_transit_connection(info: crate::transit::TransitInfo) { - log::info!("{info}") + tracing::info!("{info}") } fn default_relay_hints() -> Vec { @@ -65,11 +54,9 @@ fn default_relay_hints() -> Vec { ] } -#[async_std::test] +#[test(async_std::test)] pub async fn test_connect_with_unknown_code_and_allocate_passes() -> eyre::Result<(), WormholeError> { - init_logger(); - let code = generate_random_code(); let mailbox_connection = @@ -80,10 +67,9 @@ pub async fn test_connect_with_unknown_code_and_allocate_passes() -> eyre::Resul mailbox_connection.unwrap().shutdown(Mood::Happy).await } -#[async_std::test] +#[test(async_std::test)] pub async fn test_connect_with_unknown_code_and_no_allocate_fails() { - init_logger(); - + tracing::info!("hola!"); let code = generate_random_code(); let mailbox_connection = MailboxConnection::connect( @@ -199,11 +185,9 @@ async fn file_offers( /** Send a file using the Rust implementation (using deprecated API). This does not guarantee compatibility with Python! ;) */ #[cfg(feature = "transfer")] -#[async_std::test] +#[test(async_std::test)] #[allow(deprecated)] pub async fn test_file_rust2rust_deprecated() -> eyre::Result<()> { - init_logger(); - for (offer, answer) in file_offers().await? { let (code_tx, code_rx) = futures::channel::oneshot::channel(); @@ -214,9 +198,9 @@ pub async fn test_file_rust2rust_deprecated() -> eyre::Result<()> { Wormhole::connect_without_code(transfer::APP_CONFIG.id(TEST_APPID).clone(), 2) .await?; if let Some(welcome) = &welcome.welcome { - log::info!("Got welcome: {}", welcome); + tracing::info!("Got welcome: {}", welcome); } - log::info!("This wormhole's code is: {}", &welcome.code); + tracing::info!("This wormhole's code is: {}", &welcome.code); code_tx.send(welcome.code.clone()).unwrap(); let wormhole = wormhole_future.await?; eyre::Result::<_>::Ok( @@ -237,10 +221,10 @@ pub async fn test_file_rust2rust_deprecated() -> eyre::Result<()> { .spawn(async { let code = code_rx.await?; let config = transfer::APP_CONFIG.id(TEST_APPID); - log::info!("Got code over local: {}", &code); + tracing::info!("Got code over local: {}", &code); let (welcome, wormhole) = Wormhole::connect_with_code(config.clone(), code).await?; if let Some(welcome) = &welcome.welcome { - log::info!("Got welcome: {}", welcome); + tracing::info!("Got welcome: {}", welcome); } // Hacky v1-compat conversion for now @@ -284,10 +268,8 @@ pub async fn test_file_rust2rust_deprecated() -> eyre::Result<()> { /** Send a file using the Rust implementation. This does not guarantee compatibility with Python! ;) */ #[cfg(feature = "transfer")] -#[async_std::test] +#[test(async_std::test)] pub async fn test_file_rust2rust() -> eyre::Result<()> { - init_logger(); - for (offer, answer) in file_offers().await? { let (code_tx, code_rx) = futures::channel::oneshot::channel(); @@ -298,9 +280,9 @@ pub async fn test_file_rust2rust() -> eyre::Result<()> { MailboxConnection::create(transfer::APP_CONFIG.id(TEST_APPID).clone(), 2) .await?; if let Some(welcome) = &mailbox_connection.welcome { - log::info!("Got welcome: {}", welcome); + tracing::info!("Got welcome: {}", welcome); } - log::info!("This wormhole's code is: {}", &mailbox_connection.code); + tracing::info!("This wormhole's code is: {}", &mailbox_connection.code); code_tx.send(mailbox_connection.code.clone()).unwrap(); let wormhole = Wormhole::connect(mailbox_connection).await?; eyre::Result::<_>::Ok( @@ -324,7 +306,7 @@ pub async fn test_file_rust2rust() -> eyre::Result<()> { let config = transfer::APP_CONFIG.id(TEST_APPID); let mailbox = MailboxConnection::connect(config, code.clone(), false).await?; if let Some(welcome) = mailbox.welcome.clone() { - log::info!("Got welcome: {}", welcome); + tracing::info!("Got welcome: {}", welcome); } let wormhole = Wormhole::connect(mailbox).await?; @@ -371,13 +353,11 @@ pub async fn test_file_rust2rust() -> eyre::Result<()> { /** Test the functionality used by the `send-many` subcommand. */ #[cfg(feature = "transfer")] -#[async_std::test] +#[test(async_std::test)] pub async fn test_send_many() -> eyre::Result<()> { - init_logger(); - let mailbox = MailboxConnection::create(transfer::APP_CONFIG.id(TEST_APPID), 2).await?; let code = mailbox.code.clone(); - log::info!("The code is {:?}", code); + tracing::info!("The code is {:?}", code); async fn gen_offer() -> eyre::Result { file_offers().await.map(|mut vec| vec.remove(0).0) @@ -395,7 +375,7 @@ pub async fn test_send_many() -> eyre::Result<()> { /* The first time, we reuse the current session for sending */ { - log::info!("Sending file #{}", 0); + tracing::info!("Sending file #{}", 0); let wormhole = Wormhole::connect(mailbox).await?; senders.push(async_std::task::spawn(async move { eyre::Result::Ok( @@ -415,7 +395,7 @@ pub async fn test_send_many() -> eyre::Result<()> { } for i in 1..5usize { - log::info!("Sending file #{}", i); + tracing::info!("Sending file #{}", i); let wormhole = Wormhole::connect( MailboxConnection::connect( transfer::APP_CONFIG.id(TEST_APPID), @@ -449,13 +429,13 @@ pub async fn test_send_many() -> eyre::Result<()> { /* Receive many */ for i in 0..5usize { - log::info!("Receiving file #{}", i); + tracing::info!("Receiving file #{}", i); let wormhole = Wormhole::connect( MailboxConnection::connect(transfer::APP_CONFIG.id(TEST_APPID), code.clone(), true) .await?, ) .await?; - log::info!("Got key: {}", &wormhole.key); + tracing::info!("Got key: {}", &wormhole.key); /*let transfer::ReceiveRequest::V1(req) = crate::transfer::request( wormhole, default_relay_hints(), @@ -503,10 +483,8 @@ pub async fn test_send_many() -> eyre::Result<()> { } /// Try to send a file, but use a bad code, and see how it's handled -#[async_std::test] +#[test(async_std::test)] pub async fn test_wrong_code() -> eyre::Result<()> { - init_logger(); - let (code_tx, code_rx) = futures::channel::oneshot::channel(); let sender_task = async_std::task::Builder::new() @@ -514,10 +492,10 @@ pub async fn test_wrong_code() -> eyre::Result<()> { .spawn(async { let mailbox = MailboxConnection::create(APP_CONFIG, 2).await?; if let Some(welcome) = &mailbox.welcome { - log::info!("Got welcome: {}", welcome); + tracing::info!("Got welcome: {}", welcome); } let code = mailbox.code.clone(); - log::info!("This wormhole's code is: {}", &code); + tracing::info!("This wormhole's code is: {}", &code); code_tx.send(code.nameplate()).unwrap(); let result = Wormhole::connect(mailbox).await; @@ -529,7 +507,7 @@ pub async fn test_wrong_code() -> eyre::Result<()> { .name("receiver".to_owned()) .spawn(async { let nameplate = code_rx.await?; - log::info!("Got nameplate over local: {}", &nameplate); + tracing::info!("Got nameplate over local: {}", &nameplate); let result = Wormhole::connect( MailboxConnection::connect( APP_CONFIG, @@ -553,12 +531,10 @@ pub async fn test_wrong_code() -> eyre::Result<()> { } /** Connect three people to the party and watch it explode … gracefully */ -#[async_std::test] +#[test(async_std::test)] pub async fn test_crowded() -> eyre::Result<()> { - init_logger(); - let initial_mailbox_connection = MailboxConnection::create(APP_CONFIG, 2).await?; - log::info!("This test's code is: {}", &initial_mailbox_connection.code); + tracing::info!("This test's code is: {}", &initial_mailbox_connection.code); let code = initial_mailbox_connection.code.clone(); let mailbox_connection_1 = MailboxConnection::connect(APP_CONFIG.clone(), code.clone(), false); diff --git a/src/forwarding.rs b/src/forwarding.rs index 56b25406..05d750bd 100644 --- a/src/forwarding.rs +++ b/src/forwarding.rs @@ -180,7 +180,7 @@ pub async fn serve( .map(|(host, port)| match host { Some(host) => { if port == 80 || port == 443 || port == 8000 || port == 8080 { - log::warn!("It seems like you are trying to forward a remote HTTP target ('{}'). Due to HTTP being host-aware this will very likely fail!", host); + tracing::warn!("It seems like you are trying to forward a remote HTTP target ('{}'). Due to HTTP being host-aware this will very likely fail!", host); } (format!("{}:{}", host, port), (Some(host), port)) }, @@ -191,7 +191,7 @@ pub async fn serve( /* Receive their transit hints */ let their_hints: transit::Hints = match wormhole.receive_json().await?? { PeerMessage::Transit { hints } => { - log::debug!("Received transit message: {:?}", hints); + tracing::debug!("Received transit message: {:?}", hints); hints }, PeerMessage::Error(err) => { @@ -303,12 +303,12 @@ impl ForwardingServe { connection_id: u64, payload: &[u8], ) -> Result<(), ForwardingError> { - log::debug!("Forwarding {} bytes from #{}", payload.len(), connection_id); + tracing::debug!("Forwarding {} bytes from #{}", payload.len(), connection_id); match self.connections.get_mut(&connection_id) { Some((_worker, connection)) => { /* On an error, log for the user and then terminate that connection */ if let Err(e) = connection.write_all(payload).await { - log::warn!("Forwarding to #{} failed: {}", connection_id, e); + tracing::warn!("Forwarding to #{} failed: {}", connection_id, e); self.remove_connection(transit_tx, connection_id, true) .await?; } @@ -330,7 +330,7 @@ impl ForwardingServe { connection_id: u64, tell_peer: bool, ) -> Result<(), ForwardingError> { - log::debug!("Removing connection: #{}", connection_id); + tracing::debug!("Removing connection: #{}", connection_id); if tell_peer { transit_tx .send( @@ -361,7 +361,7 @@ impl ForwardingServe { mut target: String, connection_id: u64, ) -> Result<(), ForwardingError> { - log::debug!("Creating new connection: #{} -> {}", connection_id, target); + tracing::debug!("Creating new connection: #{} -> {}", connection_id, target); use std::collections::hash_map::Entry; let entry = match self.connections.entry(connection_id) { @@ -381,7 +381,7 @@ impl ForwardingServe { let stream = match TcpStream::connect(&target).await { Ok(stream) => stream, Err(err) => { - log::warn!( + tracing::warn!( "Cannot open connection to {}: {}. The forwarded service might be down.", target, err @@ -431,7 +431,7 @@ impl ForwardingServe { } async fn shutdown(self) { - log::debug!("Shutting down everything"); + tracing::debug!("Shutting down everything"); for (worker, _connection) in self.connections.into_values() { worker.cancel().await; } @@ -445,7 +445,7 @@ impl ForwardingServe { cancel: &mut (impl futures::future::FusedFuture + Unpin), ) -> Result<(), ForwardingError> { /* Event processing loop */ - log::debug!("Entered processing loop"); + tracing::debug!("Entered processing loop"); let ret = loop { futures::select! { message = transit_rx.next() => { @@ -467,7 +467,7 @@ impl ForwardingServe { self.remove_connection(transit_tx, connection_id, false).await?; }, PeerMessage::Close => { - log::info!("Peer gracefully closed connection"); + tracing::info!("Peer gracefully closed connection"); self.shutdown().await; break Ok(()); }, @@ -501,7 +501,7 @@ impl ForwardingServe { }, /* We are done */ () = &mut *cancel => { - log::info!("Closing connection"); + tracing::info!("Closing connection"); transit_tx.send( PeerMessage::Close.ser_msgpack() .into_boxed_slice() @@ -513,7 +513,7 @@ impl ForwardingServe { }, } }; - log::debug!("Exited processing loop"); + tracing::debug!("Exited processing loop"); ret } } @@ -562,7 +562,7 @@ pub async fn connect( /* Receive their transit hints */ let their_hints: transit::Hints = match wormhole.receive_json().await?? { PeerMessage::Transit { hints } => { - log::debug!("Received transit message: {:?}", hints); + tracing::debug!("Received transit message: {:?}", hints); hints }, PeerMessage::Error(err) => { @@ -770,12 +770,12 @@ impl ForwardConnect { connection_id: u64, payload: &[u8], ) -> Result<(), ForwardingError> { - log::debug!("Forwarding {} bytes from #{}", payload.len(), connection_id); + tracing::debug!("Forwarding {} bytes from #{}", payload.len(), connection_id); match self.connections.get_mut(&connection_id) { Some((_worker, connection)) => { /* On an error, log for the user and then terminate that connection */ if let Err(e) = connection.write_all(payload).await { - log::warn!("Forwarding to #{} failed: {}", connection_id, e); + tracing::warn!("Forwarding to #{} failed: {}", connection_id, e); self.remove_connection(transit_tx, connection_id, true) .await?; } @@ -797,7 +797,7 @@ impl ForwardConnect { connection_id: u64, tell_peer: bool, ) -> Result<(), ForwardingError> { - log::debug!("Removing connection: #{}", connection_id); + tracing::debug!("Removing connection: #{}", connection_id); if tell_peer { transit_tx .send( @@ -832,7 +832,7 @@ impl ForwardConnect { self.connection_counter += 1; let (mut connection_rd, connection_wr) = connection.split(); let mut backchannel_tx = self.backchannel_tx.clone(); - log::debug!("Creating new connection: #{} -> {}", connection_id, target); + tracing::debug!("Creating new connection: #{} -> {}", connection_id, target); transit_tx .send( @@ -880,7 +880,7 @@ impl ForwardConnect { } async fn shutdown(self) { - log::debug!("Shutting down everything"); + tracing::debug!("Shutting down everything"); for (worker, _connection) in self.connections.into_values() { worker.cancel().await; } @@ -894,7 +894,7 @@ impl ForwardConnect { cancel: &mut (impl futures::future::FusedFuture + Unpin), ) -> Result<(), ForwardingError> { /* Event processing loop */ - log::debug!("Entered processing loop"); + tracing::debug!("Entered processing loop"); let ret = loop { futures::select! { message = transit_rx.next() => { @@ -906,7 +906,7 @@ impl ForwardConnect { self.remove_connection(transit_tx, connection_id, false).await?; }, PeerMessage::Close => { - log::info!("Peer gracefully closed connection"); + tracing::info!("Peer gracefully closed connection"); self.shutdown().await; break Ok(()) }, @@ -946,7 +946,7 @@ impl ForwardConnect { }, /* We are done */ () = &mut *cancel => { - log::info!("Closing connection"); + tracing::info!("Closing connection"); transit_tx.send( PeerMessage::Close.ser_msgpack() .into_boxed_slice() @@ -958,7 +958,7 @@ impl ForwardConnect { }, } }; - log::debug!("Exited processing loop"); + tracing::debug!("Exited processing loop"); ret } } diff --git a/src/transfer.rs b/src/transfer.rs index dcb70b7a..bfecd76b 100644 --- a/src/transfer.rs +++ b/src/transfer.rs @@ -18,7 +18,6 @@ use std::sync::Arc; use super::{core::WormholeError, transit, AppID, Wormhole}; use futures::Future; -use log::*; use std::{borrow::Cow, collections::BTreeMap}; #[cfg(not(target_family = "wasm"))] diff --git a/src/transfer/cancel.rs b/src/transfer/cancel.rs index 01e40297..6883e061 100644 --- a/src/transfer/cancel.rs +++ b/src/transfer/cancel.rs @@ -87,15 +87,15 @@ async fn wrap_timeout(run: impl Future, cancel: impl Future {}, - Ok(Err(_timeout)) => log::debug!("Post-transfer timed out"), - Err(_cancelled) => log::debug!("Post-transfer got cancelled by user"), + Ok(Err(_timeout)) => tracing::debug!("Post-transfer timed out"), + Err(_cancelled) => tracing::debug!("Post-transfer got cancelled by user"), }; } /// Ignore an error but at least debug print it fn debug_err(result: Result<(), impl std::fmt::Display>, operation: &str) { if let Err(error) = result { - log::debug!("Failed to {} after transfer: {}", operation, error); + tracing::debug!("Failed to {} after transfer: {}", operation, error); } } @@ -107,7 +107,7 @@ pub async fn handle_run_result( match handle_run_result_noclose(wormhole, result).await { Ok(Some(((), wormhole, cancel))) => { /* Happy case: everything went okay. Now close the wormholhe */ - log::debug!("Transfer done, doing cleanup logic"); + tracing::debug!("Transfer done, doing cleanup logic"); wrap_timeout( async { debug_err(wormhole.close().await, "close Wormhole"); @@ -132,7 +132,7 @@ pub async fn handle_run_result_noclose>( Ok((Ok(val), cancel)) => Ok(Some((val, wormhole, cancel))), /* Got peer error: stop everything immediately */ Ok((Err(error @ TransferError::PeerError(_)), cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -147,7 +147,7 @@ pub async fn handle_run_result_noclose>( }, /* Got transit error: try to receive peer error for better error message */ Ok((Err(mut error @ TransferError::Transit(_)), cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -160,7 +160,7 @@ pub async fn handle_run_result_noclose>( if let Ok(Ok(Ok(PeerMessage::Error(e)))) = util::timeout(SHUTDOWN_TIME / 3, wormhole.receive_json()).await { error = TransferError::PeerError(e); } else { - log::debug!("Failed to retrieve more specific error message from peer. Maybe it crashed?"); + tracing::debug!("Failed to retrieve more specific error message from peer. Maybe it crashed?"); } debug_err(wormhole.close().await, "close Wormhole"); }, cancel).await; @@ -168,7 +168,7 @@ pub async fn handle_run_result_noclose>( }, /* Other error: try to notify peer */ Ok((Err(error), cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -189,7 +189,7 @@ pub async fn handle_run_result_noclose>( }, /* Cancelled: try to notify peer */ Err(cancelled) => { - log::debug!("Transfer got cancelled, doing cleanup logic"); + tracing::debug!("Transfer got cancelled, doing cleanup logic"); /* Replace cancel with ever-pending future, as we have already been cancelled */ wrap_timeout( async { @@ -224,7 +224,7 @@ pub async fn handle_run_result_transit( Ok((Ok(val), _cancel)) => Ok(Some((val, transit))), /* Got peer error: stop everything immediately */ Ok((Err(error @ TransferError::PeerError(_)), _cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -232,7 +232,7 @@ pub async fn handle_run_result_transit( }, /* Got transit error: try to receive peer error for better error message */ Ok((Err(mut error @ TransferError::Transit(_)), cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -263,7 +263,7 @@ pub async fn handle_run_result_transit( }, /* Other error: try to notify peer */ Ok((Err(error), cancel)) => { - log::debug!( + tracing::debug!( "Transfer encountered an error ({}), doing cleanup logic", error ); @@ -281,7 +281,7 @@ pub async fn handle_run_result_transit( }, /* Cancelled: try to notify peer */ Err(cancelled) => { - log::debug!("Transfer got cancelled, doing cleanup logic"); + tracing::debug!("Transfer got cancelled, doing cleanup logic"); /* Replace cancel with ever-pending future, as we have already been cancelled */ wrap_timeout( async { diff --git a/src/transfer/offer.rs b/src/transfer/offer.rs index 1cb3f84d..d17057e8 100644 --- a/src/transfer/offer.rs +++ b/src/transfer/offer.rs @@ -21,7 +21,7 @@ impl OfferSend { path: impl AsRef, ) -> std::io::Result { let path = path.as_ref(); - log::trace!( + tracing::trace!( "OfferSend::new_file_or_folder: {offer_name}, {}", path.display() ); @@ -275,7 +275,7 @@ impl OfferSendEntry { // .unwrap_or_default() // .as_secs(); if metadata.is_file() { - log::trace!("OfferSendEntry::new {path:?} is file"); + tracing::trace!("OfferSendEntry::new {path:?} is file"); let path = path.to_owned(); Ok(Self::RegularFile { size: metadata.len(), @@ -285,7 +285,7 @@ impl OfferSendEntry { }), }) // } else if metadata.is_symlink() { - // log::trace!("OfferSendEntry::new {path:?} is symlink"); + // tracing::trace!("OfferSendEntry::new {path:?} is symlink"); // let target = async_std::fs::read_link(path).await?; // Ok(Self::Symlink { // target: target @@ -300,7 +300,7 @@ impl OfferSendEntry { // }) } else if metadata.is_dir() { use futures::TryStreamExt; - log::trace!("OfferSendEntry::new {path:?} is directory"); + tracing::trace!("OfferSendEntry::new {path:?} is directory"); let content: BTreeMap = async_std::fs::read_dir(path) .await? diff --git a/src/transfer/v1.rs b/src/transfer/v1.rs index adb01ced..3f1fdaed 100644 --- a/src/transfer/v1.rs +++ b/src/transfer/v1.rs @@ -151,7 +151,7 @@ where let connector = transit::init(transit_abilities, None, relay_hints).await?; // We want to do some transit - debug!("Sending transit message '{:?}", connector.our_hints()); + tracing::debug!("Sending transit message '{:?}", connector.our_hints()); wormhole .send_json(&PeerMessage::transit_v1( *connector.our_abilities(), @@ -160,7 +160,7 @@ where .await?; // Send file offer message. - debug!("Sending file offer"); + tracing::debug!("Sending file offer"); wormhole .send_json(&PeerMessage::offer_file_v1(file_name, file_size)) .await?; @@ -169,7 +169,7 @@ where let (their_abilities, their_hints): (transit::Abilities, transit::Hints) = match wormhole.receive_json::().await??.check_err()? { PeerMessage::Transit(transit) => { - debug!("Received transit message: {:?}", transit); + tracing::debug!("Received transit message: {:?}", transit); (transit.abilities_v1, transit.hints_v1) }, other => { @@ -180,7 +180,7 @@ where { // Wait for file_ack let fileack_msg = wormhole.receive_json::().await??; - debug!("Received file ack message: {:?}", fileack_msg); + tracing::debug!("Received file ack message: {:?}", fileack_msg); match fileack_msg.check_err()? { PeerMessage::Answer(AnswerMessage::FileAck(msg)) => { @@ -204,7 +204,7 @@ where .await?; transit_handler(info); - debug!("Beginning file transfer"); + tracing::debug!("Beginning file transfer"); // 11. send the file as encrypted records. let file = futures::stream::once(futures::future::ready(std::io::Result::Ok( @@ -213,14 +213,14 @@ where let checksum = v1::send_records(&mut transit, file, file_size, progress_handler).await?; // 13. wait for the transit ack with sha256 sum from the peer. - debug!("sent file. Waiting for ack"); + tracing::debug!("sent file. Waiting for ack"); let transit_ack = transit.receive_record().await?; let transit_ack_msg = serde_json::from_slice::(&transit_ack)?; ensure!( transit_ack_msg.sha256 == hex::encode(checksum), TransferError::Checksum ); - debug!("Transfer complete!"); + tracing::debug!("Transfer complete!"); Ok(()) }); @@ -244,7 +244,7 @@ pub(crate) async fn send_folder( let connector = transit::init(transit_abilities, None, relay_hints).await?; // We want to do some transit - debug!("Sending transit message '{:?}", connector.our_hints()); + tracing::debug!("Sending transit message '{:?}", connector.our_hints()); wormhole .send_json(&PeerMessage::transit_v1( *connector.our_abilities(), @@ -256,7 +256,7 @@ pub(crate) async fn send_folder( * all the headers of our file now but without the contents. We know that a file is * header + contents + padding */ - log::debug!("Estimating the file size"); + tracing::debug!("Estimating the file size"); // TODO try again but without pinning use futures::{ @@ -283,7 +283,7 @@ pub(crate) async fn send_folder( ) -> IoResult> { match offer { OfferSendEntry::Directory { content } => { - log::debug!("Adding directory {path:?}"); + tracing::debug!("Adding directory {path:?}"); let header = tar_helper::create_header_directory(path)?; *total_size += header.len() as u64; total_content.push(wrap(header)); @@ -295,7 +295,7 @@ pub(crate) async fn send_folder( } }, OfferSendEntry::RegularFile { size, content } => { - log::debug!("Adding file {path:?}; {size} bytes"); + tracing::debug!("Adding file {path:?}; {size} bytes"); let header = tar_helper::create_header_file(path, size)?; let padding = tar_helper::padding(size); *total_size += header.len() as u64; @@ -332,7 +332,7 @@ pub(crate) async fn send_folder( /* Convert to stream */ // Send file offer message. - log::debug!("Sending file offer ({total_size} bytes)"); + tracing::debug!("Sending file offer ({total_size} bytes)"); folder_name.push_str(".tar"); wormhole .send_json(&PeerMessage::offer_file_v1(folder_name, total_size)) @@ -342,7 +342,7 @@ pub(crate) async fn send_folder( let (their_abilities, their_hints): (transit::Abilities, transit::Hints) = match wormhole.receive_json::().await??.check_err()? { PeerMessage::Transit(transit) => { - debug!("received transit message: {:?}", transit); + tracing::debug!("received transit message: {:?}", transit); (transit.abilities_v1, transit.hints_v1) }, other => { @@ -369,21 +369,21 @@ pub(crate) async fn send_folder( .await?; transit_handler(info); - debug!("Beginning file transfer"); + tracing::debug!("Beginning file transfer"); // 11. send the file as encrypted records. let checksum = v1::send_records(&mut transit, content, total_size, progress_handler).await?; // 13. wait for the transit ack with sha256 sum from the peer. - debug!("sent file. Waiting for ack"); + tracing::debug!("sent file. Waiting for ack"); let transit_ack = transit.receive_record().await?; let transit_ack_msg = serde_json::from_slice::(&transit_ack)?; ensure!( transit_ack_msg.sha256 == hex::encode(checksum), TransferError::Checksum ); - debug!("Transfer complete!"); + tracing::debug!("Transfer complete!"); Ok(()) }); @@ -412,7 +412,7 @@ pub async fn request( let connector = transit::init(transit_abilities, None, relay_hints).await?; // send the transit message - debug!("Sending transit message '{:?}", connector.our_hints()); + tracing::debug!("Sending transit message '{:?}", connector.our_hints()); wormhole .send_json(&PeerMessage::transit_v1( *connector.our_abilities(), @@ -424,7 +424,7 @@ pub async fn request( let (their_abilities, their_hints): (transit::Abilities, transit::Hints) = match wormhole.receive_json::().await??.check_err()? { PeerMessage::Transit(transit) => { - debug!("received transit message: {:?}", transit); + tracing::debug!("received transit message: {:?}", transit); (transit.abilities_v1, transit.hints_v1) }, other => { @@ -558,7 +558,7 @@ impl ReceiveRequest { { let run = Box::pin(async { // send file ack. - debug!("Sending ack"); + tracing::debug!("Sending ack"); self.wormhole .send_json(&PeerMessage::file_ack_v1("ok")) .await?; @@ -575,7 +575,7 @@ impl ReceiveRequest { .await?; transit_handler(info); - debug!("Beginning file transfer"); + tracing::debug!("Beginning file transfer"); tcp_file_receive( &mut transit, self.filesize, @@ -721,7 +721,7 @@ where } content_handler.close().await?; - debug!("done"); + tracing::debug!("done"); // TODO: 5. write the buffer into a file. Ok(hasher.finalize_fixed().to_vec()) } @@ -742,7 +742,7 @@ where let checksum = receive_records(filesize, transit, progress_handler, content_handler).await?; let sha256sum = hex::encode(checksum.as_slice()); - debug!("sha256 sum: {:?}", sha256sum); + tracing::debug!("sha256 sum: {:?}", sha256sum); // 6. verify sha256 sum by sending an ack message to peer along with checksum. transit @@ -751,7 +751,7 @@ where // 7. close socket. // well, no need, it gets dropped when it goes out of scope. - debug!("Transfer complete"); + tracing::debug!("Transfer complete"); Ok(()) } diff --git a/src/transfer/v2.rs b/src/transfer/v2.rs index 2ea5383c..7c3b6b01 100644 --- a/src/transfer/v2.rs +++ b/src/transfer/v2.rs @@ -115,7 +115,7 @@ async fn make_transit( let their_hints: transit::Hints = match wormhole.receive_json::().await??.check_err()? { PeerMessage::TransitV2(transit) => { - debug!("received transit message: {:?}", transit); + tracing::debug!("received transit message: {:?}", transit); transit.hints_v2 }, other => { diff --git a/src/transit.rs b/src/transit.rs index b410f2ea..ccbb08e7 100644 --- a/src/transit.rs +++ b/src/transit.rs @@ -26,7 +26,6 @@ use futures::{ io::{AsyncRead, AsyncReadExt, AsyncWrite, AsyncWriteExt}, Sink, SinkExt, Stream, StreamExt, TryStreamExt, }; -use log::*; use std::{ collections::HashSet, net::{IpAddr, SocketAddr}, @@ -764,7 +763,7 @@ pub fn log_transit_connection( peer_addr, }; - log::info!("{info}"); + tracing::info!("{info}"); } /** @@ -806,12 +805,12 @@ pub async fn init( .map_err(|_| StunError::Timeout) { Ok(Ok((external_ip, stream))) => { - log::debug!("Our external IP address is {}", external_ip); + tracing::debug!("Our external IP address is {}", external_ip); our_hints.direct_tcp.insert(DirectHint { hostname: external_ip.ip().to_string(), port: external_ip.port(), }); - log::debug!( + tracing::debug!( "Our socket for connecting is bound to {} and connected to {}", stream.local_addr()?, stream.peer_addr()?, @@ -821,13 +820,13 @@ pub async fn init( // TODO replace with .flatten() once stable // https://github.com/rust-lang/rust/issues/70142 Err(err) | Ok(Err(err)) => { - log::warn!("Failed to get external address via STUN, {}", err); + tracing::warn!("Failed to get external address via STUN, {}", err); let socket = socket2::Socket::new(socket2::Domain::IPV6, socket2::Type::STREAM, None)?; transport::set_socket_opts(&socket)?; socket.bind(&"[::]:0".parse::().unwrap().into())?; - log::debug!( + tracing::debug!( "Our socket for connecting is bound to {}", socket.local_addr()?.as_socket().unwrap(), ); @@ -865,7 +864,7 @@ pub async fn init( .into_iter() }), ); - log::debug!("Our socket for listening is {}", listener.local_addr()?); + tracing::debug!("Our socket for listening is {}", listener.local_addr()?); Ok::<_, std::io::Error>((socket, listener)) }; @@ -874,7 +873,7 @@ pub async fn init( .await // TODO replace with inspect_err once stable .map_err(|err| { - log::error!("Failed to create direct hints for our side: {}", err); + tracing::error!("Failed to create direct hints for our side: {}", err); err }) .ok(); @@ -1002,7 +1001,7 @@ impl TransitConnector { match result { Ok(val) => Some(val), Err(err) => { - log::debug!("Some leader handshake failed: {:?}", err); + tracing::debug!("Some leader handshake failed: {:?}", err); None }, } @@ -1013,13 +1012,13 @@ impl TransitConnector { util::timeout(std::time::Duration::from_secs(60), connection_stream.next()) .await .map_err(|_| { - log::debug!("`leader_connect` timed out"); + tracing::debug!("`leader_connect` timed out"); TransitConnectError::Handshake })? .ok_or(TransitConnectError::Handshake)?; if conn_info.conn_type != ConnectionType::Direct && our_abilities.can_direct() { - log::debug!( + tracing::debug!( "Established transit connection over relay. Trying to find a direct connection …" ); /* Measure the time it took us to get a response. Based on this, wait some more for more responses @@ -1041,15 +1040,15 @@ impl TransitConnector { transit = new_transit; finalizer = new_finalizer; conn_info = new_conn_info; - log::debug!("Found direct connection; using that instead."); + tracing::debug!("Found direct connection; using that instead."); break; } } }) .await; - log::debug!("Did not manage to establish a better connection in time."); + tracing::debug!("Did not manage to establish a better connection in time."); } else { - log::debug!("Established direct transit connection"); + tracing::debug!("Established direct transit connection"); } /* Cancel all remaining non-finished handshakes. We could send "nevermind" to explicitly tell @@ -1061,7 +1060,7 @@ impl TransitConnector { .handshake_finalize(&mut transit) .await .map_err(|e| { - log::debug!("`handshake_finalize` failed: {e}"); + tracing::debug!("`handshake_finalize` failed: {e}"); TransitConnectError::Handshake })?; @@ -1107,7 +1106,7 @@ impl TransitConnector { match result { Ok(val) => Some(val), Err(err) => { - log::debug!("Some follower handshake failed: {:?}", err); + tracing::debug!("Some follower handshake failed: {:?}", err); None }, } @@ -1125,14 +1124,14 @@ impl TransitConnector { .handshake_finalize(&mut socket) .await .map_err(|e| { - log::debug!("`handshake_finalize` failed: {e}"); + tracing::debug!("`handshake_finalize` failed: {e}"); TransitConnectError::Handshake })?; Ok((Transit { socket, tx, rx }, conn_info)) }, Ok(None) | Err(_) => { - log::debug!("`follower_connect` timed out"); + tracing::debug!("`follower_connect` timed out"); Err(TransitConnectError::Handshake) }, }; @@ -1168,12 +1167,12 @@ impl TransitConnector { assert!(sockets.is_none() || our_abilities.can_direct()); let cryptor = if our_abilities.can_noise_crypto() && their_abilities.can_noise_crypto() { - log::debug!("Using noise protocol for encryption"); + tracing::debug!("Using noise protocol for encryption"); Arc::new(crypto::NoiseInit { key: transit_key.clone(), }) as Arc } else { - log::debug!("Using secretbox for encryption"); + tracing::debug!("Using secretbox for encryption"); Arc::new(crypto::SecretboxInit { key: transit_key.clone(), }) as Arc @@ -1361,7 +1360,7 @@ impl TransitConnector { let (socket, peer) = listener.accept().await?; let (socket, info) = transport::wrap_tcp_connection(socket, ConnectionType::Direct)?; - log::debug!("Got connection from {}!", peer); + tracing::debug!("Got connection from {}!", peer); let (transit, finalizer) = handshake_exchange( is_leader, tside.clone(), @@ -1377,7 +1376,7 @@ impl TransitConnector { match connect().await { Ok(success) => break Ok(success), Err(err) => { - log::debug!( + tracing::debug!( "Some handshake failed on the listening port: {:?}", err ); @@ -1424,7 +1423,7 @@ impl Transit { /// Flush the socket pub async fn flush(&mut self) -> Result<(), TransitError> { - log::debug!("Flush"); + tracing::debug!("Flush"); self.socket.flush().await.map_err(Into::into) } @@ -1486,7 +1485,7 @@ async fn handshake_exchange( TransitHandshakeError, > { if host_type != &ConnectionType::Direct { - log::trace!("initiating relay handshake"); + tracing::trace!("initiating relay handshake"); let sub_key = key.derive_subkey_from_purpose::("transit_relay_token"); socket diff --git a/src/transit/transport.rs b/src/transit/transport.rs index c3309507..a67640d4 100644 --- a/src/transit/transport.rs +++ b/src/transit/transport.rs @@ -196,7 +196,7 @@ async fn tcp_connect_custom( local_addr: &socket2::SockAddr, dest_addr: &socket2::SockAddr, ) -> std::io::Result { - log::debug!("Binding to {}", local_addr.as_socket().unwrap()); + tracing::debug!("Binding to {}", local_addr.as_socket().unwrap()); let socket = socket2::Socket::new(socket2::Domain::IPV6, socket2::Type::STREAM, None)?; /* Set our custum options */ set_socket_opts(&socket)?; @@ -231,15 +231,15 @@ pub(super) async fn connect_tcp_direct( hint: DirectHint, ) -> Result { let dest_addr = SocketAddr::try_from(&hint)?; - log::debug!("Connecting directly to {}", dest_addr); + tracing::debug!("Connecting directly to {}", dest_addr); let socket; if let Some(local_addr) = local_addr { socket = tcp_connect_custom(&local_addr, &dest_addr.into()).await?; - log::debug!("Connected to {}!", dest_addr); + tracing::debug!("Connected to {}!", dest_addr); } else { socket = async_std::net::TcpStream::connect(&dest_addr).await?; - log::debug!("Connected to {}!", dest_addr); + tracing::debug!("Connected to {}!", dest_addr); } wrap_tcp_connection(socket, ConnectionType::Direct) @@ -251,11 +251,11 @@ pub(super) async fn connect_tcp_relay( host: DirectHint, name: Option, ) -> Result { - log::debug!("Connecting to relay {}", host); + tracing::debug!("Connecting to relay {}", host); let socket = TcpStream::connect((host.hostname.as_str(), host.port)) .err_into::() .await?; - log::debug!("Connected to {}!", host); + tracing::debug!("Connected to {}!", host); wrap_tcp_connection(socket, ConnectionType::Relay { name }) } @@ -265,11 +265,11 @@ pub(super) async fn connect_ws_relay( url: url::Url, name: Option, ) -> Result { - log::debug!("Connecting to relay {}", url); + tracing::debug!("Connecting to relay {}", url); let (_meta, transit) = ws_stream_wasm::WsMeta::connect(&url, None) .err_into::() .await?; - log::debug!("Connected to {}!", url); + tracing::debug!("Connected to {}!", url); let transit = Box::new(transit.into_io()) as Box; diff --git a/src/util.rs b/src/util.rs index 96173fa5..2bc44890 100644 --- a/src/util.rs +++ b/src/util.rs @@ -104,7 +104,7 @@ pub fn hashcash(resource: String, bits: u32) -> String { use sha1::{Digest, Sha1}; if bits > 32 { - log::warn!( + tracing::warn!( "Minting a hashcash token with {} bits. If the application is frozen, you'll know why", bits );