From 83d9f2299ebfb4355ced1b3111b3e1f4bff62e43 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Thu, 4 Nov 2021 11:04:59 -0400 Subject: [PATCH] Replace all println/eprintln calls outside of arti CLI with trace. --- Cargo.lock | 1 + crates/tor-circmgr/src/build.rs | 7 +++-- crates/tor-circmgr/src/mgr.rs | 3 +- crates/tor-proto/src/channel/reactor.rs | 2 +- crates/tor-proto/src/circuit.rs | 6 ++-- crates/tor-rtmock/Cargo.toml | 1 + crates/tor-rtmock/src/sleep_runtime.rs | 11 +++---- crates/tor-rtmock/src/time.rs | 39 ++++++++++++++----------- 8 files changed, 40 insertions(+), 30 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5873bd18c..5b1d78971 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2883,6 +2883,7 @@ dependencies = [ "rand 0.8.4", "thiserror", "tor-rtcompat", + "tracing", ] [[package]] diff --git a/crates/tor-circmgr/src/build.rs b/crates/tor-circmgr/src/build.rs index 78ed00135..e9bafc25a 100644 --- a/crates/tor-circmgr/src/build.rs +++ b/crates/tor-circmgr/src/build.rs @@ -431,6 +431,7 @@ mod test { use std::sync::Mutex; use tor_llcrypto::pk::ed25519::Ed25519Identity; use tor_rtcompat::{test_with_all_runtimes, SleepProvider}; + use tracing::trace; /// Make a new nonfunctional `Arc` fn gs() -> Arc { @@ -457,7 +458,7 @@ mod test { assert!(x.is_ok()); assert_eq!(x.unwrap(), 3_u32); - eprintln!("acquiesce after test1"); + trace!("acquiesce after test1"); #[allow(clippy::clone_on_copy)] let rt = tor_rtmock::MockSleepRuntime::new(rto.clone()); @@ -481,7 +482,7 @@ mod test { assert!(x.is_ok()); assert_eq!(x.unwrap(), 4_u32); - eprintln!("acquiesce after test2"); + trace!("acquiesce after test2"); #[allow(clippy::clone_on_copy)] let rt = tor_rtmock::MockSleepRuntime::new(rto.clone()); @@ -511,7 +512,7 @@ mod test { let waited = rt.wait_for(rcv).await; assert_eq!(waited, Ok(())); - eprintln!("acquiesce after test3"); + trace!("acquiesce after test3"); #[allow(clippy::clone_on_copy)] let rt = tor_rtmock::MockSleepRuntime::new(rto.clone()); diff --git a/crates/tor-circmgr/src/mgr.rs b/crates/tor-circmgr/src/mgr.rs index c9d3429d3..f22251246 100644 --- a/crates/tor-circmgr/src/mgr.rs +++ b/crates/tor-circmgr/src/mgr.rs @@ -1135,6 +1135,7 @@ mod test { use std::sync::atomic::{self, AtomicUsize}; use tor_rtcompat::SleepProvider; use tor_rtmock::MockSleepRuntime; + use tracing::trace; #[derive(Debug, Clone, Eq, PartialEq, Hash, Copy)] struct FakeId { @@ -1291,7 +1292,7 @@ mod test { } FakeOp::Timeout => unreachable!(), // should be converted to the below FakeOp::TimeoutReleaseAdvance(reason) => { - eprintln!("releasing advance to fake a timeout"); + trace!("releasing advance to fake a timeout"); self.runtime.release_advance(reason); let () = futures::future::pending().await; unreachable!() diff --git a/crates/tor-proto/src/channel/reactor.rs b/crates/tor-proto/src/channel/reactor.rs index 8578134be..74a338d6b 100644 --- a/crates/tor-proto/src/channel/reactor.rs +++ b/crates/tor-proto/src/channel/reactor.rs @@ -415,7 +415,7 @@ pub(crate) mod test { let ed_id = [6; 32].into(); let rsa_id = [10; 20].into(); let send1 = send1.sink_map_err(|e| { - eprintln!("got sink error: {}", e); + trace!("got sink error: {}", e); tor_cell::Error::ChanProto("dummy message".into()) }); let (chan, reactor) = crate::channel::Channel::new( diff --git a/crates/tor-proto/src/circuit.rs b/crates/tor-proto/src/circuit.rs index e6f7a43cf..b8e35c95e 100644 --- a/crates/tor-proto/src/circuit.rs +++ b/crates/tor-proto/src/circuit.rs @@ -1284,15 +1284,15 @@ mod test { let target = example_target(); let params = CircParameters::default(); let ret = if fast { - eprintln!("doing fast create"); + trace!("doing fast create"); pending.create_firsthop_fast(&mut rng, ¶ms).await } else { - eprintln!("doing ntor create"); + trace!("doing ntor create"); pending .create_firsthop_ntor(&mut rng, &target, ¶ms) .await }; - eprintln!("create done: result {:?}", ret); + trace!("create done: result {:?}", ret); ret }; // Future to run the reactor. diff --git a/crates/tor-rtmock/Cargo.toml b/crates/tor-rtmock/Cargo.toml index 449475965..bfe066dae 100644 --- a/crates/tor-rtmock/Cargo.toml +++ b/crates/tor-rtmock/Cargo.toml @@ -15,6 +15,7 @@ async-trait = "0.1.48" futures = "0.3.13" pin-project = "1.0.5" thiserror = "1.0.24" +tracing = "0.1.26" tor-rtcompat = { version = "0.0.1", path = "../tor-rtcompat" } diff --git a/crates/tor-rtmock/src/sleep_runtime.rs b/crates/tor-rtmock/src/sleep_runtime.rs index b59631e8c..5c3593c70 100644 --- a/crates/tor-rtmock/src/sleep_runtime.rs +++ b/crates/tor-rtmock/src/sleep_runtime.rs @@ -10,6 +10,7 @@ use pin_project::pin_project; use std::io::Result as IoResult; use std::net::SocketAddr; use std::time::{Duration, Instant, SystemTime}; +use tracing::trace; /// A wrapper Runtime that overrides the SleepProvider trait for the /// underlying runtime. @@ -152,20 +153,20 @@ impl Future for WaitFor { type Output = F::Output; fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { - eprintln!("waitfor poll"); + trace!("waitfor poll"); let mut this = self.project(); this.sleep.register_waitfor_waker(cx.waker().clone()); if let Poll::Ready(r) = this.fut.poll(cx) { - eprintln!("waitfor done!"); + trace!("waitfor done!"); this.sleep.clear_waitfor_waker(); return Poll::Ready(r); } - eprintln!("waitfor poll complete"); + trace!("waitfor poll complete"); if this.sleep.should_advance() { if let Some(duration) = this.sleep.time_until_next_timeout() { - eprintln!("Advancing by {:?}", duration); + trace!("Advancing by {:?}", duration); this.sleep.advance_noyield(duration); } else { // If we get here, something's probably wedged and the test isn't going to complete @@ -175,7 +176,7 @@ impl Future for WaitFor { panic!("WaitFor told to advance, but didn't have any duration to advance by"); } } else { - eprintln!("waiting for sleepers to advance"); + trace!("waiting for sleepers to advance"); } Poll::Pending } diff --git a/crates/tor-rtmock/src/time.rs b/crates/tor-rtmock/src/time.rs index d67bfd10c..0509e4343 100644 --- a/crates/tor-rtmock/src/time.rs +++ b/crates/tor-rtmock/src/time.rs @@ -16,6 +16,7 @@ use std::{ }; use futures::Future; +use tracing::trace; use std::collections::HashSet; use tor_rtcompat::SleepProvider; @@ -164,7 +165,7 @@ impl MockSleepProvider { if !state.blocked_advance.is_empty() && state.allowed_advance == Duration::from_nanos(0) { // We've had advances blocked, and don't have any quota for doing allowances while // blocked left. - eprintln!( + trace!( "should_advance = false: blocked by {:?}", state.blocked_advance ); @@ -172,7 +173,7 @@ impl MockSleepProvider { } if !state.should_advance { // The advance flag wasn't set. - eprintln!("should_advance = false; bit not previously set"); + trace!("should_advance = false; bit not previously set"); return false; } // Clear the advance flag; we'll either return true and cause an advance to happen, @@ -182,7 +183,7 @@ impl MockSleepProvider { if state.sleepers_polled < state.sleepers_made { // Something did set the advance flag before, but it's not valid any more now because // more unpolled sleepers were created. - eprintln!("should_advance = false; advancing no longer valid"); + trace!("should_advance = false; advancing no longer valid"); return false; } if !state.blocked_advance.is_empty() && state.allowed_advance > Duration::from_nanos(0) { @@ -200,7 +201,7 @@ impl MockSleepProvider { Some(x) => x, None => { // There's no timeout set, so we really shouldn't be here anyway. - eprintln!("should_advance = false; allow_one set but no timeout yet"); + trace!("should_advance = false; allow_one set but no timeout yet"); return false; } }; @@ -208,15 +209,16 @@ impl MockSleepProvider { // We can advance up to the next timeout, since it's in our quota. // Subtract the amount we're going to advance by from said quota. state.allowed_advance -= next_timeout; - eprintln!( + trace!( "WARNING: allowing advance due to allow_one; new allowed is {:?}", state.allowed_advance ); } else { // The next timeout is too far in the future. - eprintln!( + trace!( "should_advance = false; allow_one set but only up to {:?}, next is {:?}", - state.allowed_advance, next_timeout + state.allowed_advance, + next_timeout ); return false; } @@ -273,11 +275,11 @@ impl SleepSchedule { fn maybe_advance(&mut self) { if self.sleepers_polled >= self.sleepers_made { if let Some(ref waker) = self.waitfor_waker { - eprintln!("setting advance flag"); + trace!("setting advance flag"); self.should_advance = true; waker.wake_by_ref(); } else { - eprintln!("would advance, but no waker"); + trace!("would advance, but no waker"); } } } @@ -285,9 +287,10 @@ impl SleepSchedule { /// Register a sleeper as having been polled, and advance if necessary. fn increment_poll_count(&mut self) { self.sleepers_polled += 1; - eprintln!( + trace!( "sleeper polled, {}/{}", - self.sleepers_polled, self.sleepers_made + self.sleepers_polled, + self.sleepers_made ); self.maybe_advance(); } @@ -300,9 +303,11 @@ impl SleepProvider for MockSleepProvider { let when = provider.instant + duration; // We're making a new sleeper, so register this in the state. provider.sleepers_made += 1; - eprintln!( + trace!( "sleeper made for {:?}, {}/{}", - duration, provider.sleepers_polled, provider.sleepers_made + duration, + provider.sleepers_polled, + provider.sleepers_made ); Sleeping { @@ -315,14 +320,14 @@ impl SleepProvider for MockSleepProvider { fn block_advance>(&self, reason: T) { let mut provider = self.state.lock().expect("Poisoned lock for state"); let reason = reason.into(); - eprintln!("advancing blocked: {}", reason); + trace!("advancing blocked: {}", reason); provider.blocked_advance.insert(reason); } fn release_advance>(&self, reason: T) { let mut provider = self.state.lock().expect("Poisoned lock for state"); let reason = reason.into(); - eprintln!("advancing released: {}", reason); + trace!("advancing released: {}", reason); provider.blocked_advance.remove(&reason); if provider.blocked_advance.is_empty() { provider.maybe_advance(); @@ -332,7 +337,7 @@ impl SleepProvider for MockSleepProvider { fn allow_one_advance(&self, dur: Duration) { let mut provider = self.state.lock().expect("Poisoned lock for state"); provider.allowed_advance = Duration::max(provider.allowed_advance, dur); - println!( + trace!( "** allow_one_advance fired; may advance up to {:?} **", provider.allowed_advance ); @@ -375,7 +380,7 @@ impl Drop for Sleeping { if !self.inserted { // A sleeper being dropped will never be polled, so there's no point waiting; // act as if it's been polled in order to avoid waiting forever. - eprintln!("sleeper dropped, incrementing count"); + trace!("sleeper dropped, incrementing count"); provider.increment_poll_count(); self.inserted = true; }