vincenzopalazzo
/
arti
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add a few tracing calls to tor-guardmgr.

This commit is contained in:
Nick Mathewson 2021-10-08 09:14:36 -04:00
parent 29112e0729
commit aed9572c03
3 changed files with 74 additions and 17 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

31
crates/tor-guardmgr/src/guard.rs
View File

@ -7,6 +7,7 @@ use tor_netdir::{NetDir, Relay, RelayWeight};
use serde::{Deserialize, Serialize};
use std::net::SocketAddr;
use std::time::{Duration, Instant, SystemTime};
use tracing::trace;
use crate::util::randomize_time;
use crate::{GuardId, GuardParams, GuardRestriction, GuardUsage};
@ -209,6 +210,14 @@ impl Guard {
self.reachable
}
/// Change the reachability status for this guard.
fn set_reachable(&mut self, r: Reachable) {
if self.reachable != r {
trace!(guard_id = ?self.id, old=?self.reachable, new=?r, "Guard status changed.");
self.reachable = r;
}
}
/// Return true if at least one exploratory circuit is pending to this
/// guard.
///
@ -247,7 +256,7 @@ impl Guard {
/// and mark it as Unknown.
pub(crate) fn mark_retriable(&mut self) {
if self.reachable != Reachable::Reachable {
self.reachable = Reachable::Unknown;
self.set_reachable(Reachable::Unknown);
self.retry_at = None;
}
}
@ -302,17 +311,28 @@ impl Guard {
if listed {
// Definitely listed, so clear unlisted_since.
self.unlisted_since = None;
self.mark_listed();
} else {
// Unlisted or not a guard; mark it unlisted.
self.mark_unlisted(netdir.lifetime().valid_after());
}
}
/// Mark this guard as currently listed in the directory.
fn mark_listed(&mut self) {
if self.unlisted_since.is_some() {
trace!(guard_id = ?self.id, "Guard is now listed again.");
self.unlisted_since = None;
}
}
/// Mark this guard as having been unlisted since `now`, if it is not
/// already so marked.
fn mark_unlisted(&mut self, now: SystemTime) {
self.unlisted_since.get_or_insert(now);
if self.unlisted_since.is_none() {
trace!(guard_id = ?self.id, "Guard is now unlisted.");
self.unlisted_since = Some(now);
}
}
/// Return true if we should remove this guard from the current guard
@ -354,7 +374,7 @@ impl Guard {
pub(crate) fn record_failure(&mut self, now: Instant, is_primary: bool) {
let failing_since = self.failing_since.get_or_insert(now);
let failing_time = now.saturating_duration_since(*failing_since);
self.reachable = Reachable::Unreachable;
self.set_reachable(Reachable::Unreachable);
self.exploratory_circ_pending = false;
let connect_attempt = self.last_tried_to_connect_at.unwrap_or(now);
@ -401,7 +421,7 @@ impl Guard {
) -> NewlyConfirmed {
self.failing_since = None;
self.retry_at = None;
self.reachable = Reachable::Reachable;
self.set_reachable(Reachable::Reachable);
self.exploratory_circ_pending = false;
if self.confirmed_at.is_none() {
@ -415,6 +435,7 @@ impl Guard {
);
// TODO-SPEC: The "max" above isn't specified by guard-spec,
// but I think it's wise.
trace!(guard_id = ?self.id, "Newly confirmed");
NewlyConfirmed::Yes
} else {
NewlyConfirmed::No

33
crates/tor-guardmgr/src/lib.rs
View File

@ -136,7 +136,7 @@ use std::collections::HashMap;
use std::convert::{TryFrom, TryInto};
use std::sync::Arc;
use std::time::{Duration, Instant, SystemTime};
use tracing::warn;
use tracing::{debug, info, trace, warn};
use tor_llcrypto::pk;
use tor_netdir::{params::NetParameters, NetDir, Relay};
@ -275,11 +275,18 @@ impl<R: Runtime> GuardMgr<R> {
/// Flush our current guard state to the state manager, if there
/// is any unsaved state.
pub async fn update_persistent_state(&self) -> Result<(), GuardMgrError> {
///
/// Return true if we were able to save, and false if we couldn't
/// get the lock.
pub async fn update_persistent_state(&self) -> Result<bool, GuardMgrError> {
let inner = self.inner.lock().await;
let _ignore = inner.default_storage.try_lock()?;
inner.default_storage.store(&inner.active_guards)?;
Ok(())
if inner.default_storage.try_lock()? {
trace!("Flushing guard state to disk.");
inner.default_storage.store(&inner.active_guards)?;
Ok(true)
} else {
Ok(false)
}
}
/// Update the state of this [`GuardMgr`] based on a new or modified
@ -291,6 +298,7 @@ impl<R: Runtime> GuardMgr<R> {
///
/// Call this method whenever the `NetDir` changes.
pub async fn update_network(&self, netdir: &NetDir) {
trace!("Updating guard state from network directory");
let now = self.runtime.wallclock();
let mut inner = self.inner.lock().await;
@ -343,6 +351,11 @@ impl<R: Runtime> GuardMgr<R> {
// TODO: Once we support nontrivial filters, we might have to
// swap out "active_guards" depending on which set it is.
// TODO: Warn if the filter is waaaay to small according to guard params.
info!(
?filter,
restrictive = restrictive_filter,
"Guard filter replaced."
);
inner.active_guards.set_filter(filter, restrictive_filter);
inner.update(now, Some(netdir));
@ -388,6 +401,8 @@ impl<R: Runtime> GuardMgr<R> {
let (origin, guard_id) = inner.select_guard_with_retries(&usage, netdir, wallclock)?;
trace!(?guard_id, ?usage, "Guard selected");
let (usable, usable_sender) = if origin.is_primary() {
(GuardUsable::new_primary(), None)
} else {
@ -479,6 +494,7 @@ impl GuardMgrInner {
if let Some(mut pending) = self.pending.remove(&request_id) {
// If there was a pending request matching this RequestId, great!
let guard_id = pending.guard_id();
trace!(?guard_id, ?status, "Received report of guard status");
match status {
GuardStatusMsg::Success => {
let now = runtime.now();
@ -493,6 +509,7 @@ impl GuardMgrInner {
// let timeout = self.params.internet_down_timeout;
let timeout = Duration::from_secs(7200); // (Fake timeout)
if dur >= timeout {
debug!("Retrying primary guards");
self.active_guards.mark_primary_guards_retriable();
}
}
@ -504,10 +521,12 @@ impl GuardMgrInner {
// Either tell the request whether the guard is
// usable, or schedule it as a "waiting" request.
if let Some(usable) = self.guard_usability_status(&pending, runtime.now()) {
trace!(?guard_id, usable, "Known usability status");
pending.reply(usable);
} else {
// This is the one case where we can't use the
// guard yet.
trace!(?guard_id, "Not able to answer right now");
pending.mark_waiting(runtime.now());
self.waiting.push(pending);
}
@ -572,6 +591,7 @@ impl GuardMgrInner {
.map(|d| d >= self.params.np_idle_timeout)
== Some(true);
if expired {
trace!(?pending, "Pending request expired");
pending.reply(false);
return false;
}
@ -588,6 +608,7 @@ impl GuardMgrInner {
// See comments in sample::GuardSet::circ_usability_status.
if let Some(answer) = self.guard_usability_status(pending, now) {
trace!(?pending, answer, "Pending request now ready");
pending.reply(answer);
return false;
}
@ -621,6 +642,7 @@ impl GuardMgrInner {
// That didn't work. If we have a netdir, expand the sample and try again.
if let Some(dir) = netdir {
trace!("No guards available, trying to extend the sample.");
self.update(now, Some(dir));
if self
.active_guards
@ -634,6 +656,7 @@ impl GuardMgrInner {
}
// That didn't work either. Mark everybody as potentially retriable.
info!("All guards seem down. Marking them retriable and trying again.");
self.active_guards.mark_all_guards_retriable();
self.active_guards.pick_guard(usage, &self.params)
}

27
crates/tor-guardmgr/src/sample.rs
View File

@ -12,6 +12,7 @@ use serde::{Deserialize, Serialize};
use std::borrow::Cow;
use std::collections::{HashMap, HashSet};
use std::time::{Instant, SystemTime};
use tracing::{debug, info};
/// A set of sampled guards, along with various orderings on subsets
/// of the sample.
@ -92,6 +93,7 @@ impl ListKind {
self == &ListKind::Primary
}
}
impl GuardSet {
/// Return a new empty guard set.
pub(crate) fn new() -> Self {
@ -196,12 +198,17 @@ impl GuardSet {
guard_set.fix_consistency();
let len_post = guard_set.inner_lengths();
if len_pre != len_post {
tracing::info!(
info!(
"Resolved a consistency issue in stored guard state. Diagnostic codes: {:?}, {:?}",
len_pre,
len_post
len_pre, len_post
);
}
info!(
n_guards = len_post.0,
n_confirmed = len_post.2,
"Guard set loaded."
);
guard_set
}
@ -342,6 +349,7 @@ impl GuardSet {
if self.guards.contains_key(&id) {
return;
}
debug!(guard_id=?id, "Adding guard to sample.");
let guard = Guard::from_relay(relay, now, params);
self.guards.insert(id.clone(), guard);
self.sample.push(id);
@ -370,6 +378,9 @@ impl GuardSet {
// then from any previous primary guards, and then from maybe-reachable
// guards in the sample.
// Only for logging.
let old_primary = self.primary.clone();
self.primary = self
// First, we look at the confirmed guards.
.confirmed
@ -394,6 +405,10 @@ impl GuardSet {
.take(params.n_primary)
.collect();
if self.primary != old_primary {
debug!(old=?old_primary, new=?self.primary, "Updated primary guards.");
}
// Clear exploratory_circ_pending for all primary guards.
for id in self.primary.iter() {
if let Some(guard) = self.guards.get_mut(id) {
@ -421,10 +436,8 @@ impl GuardSet {
self.assert_consistency();
if self.guards.len() < n_pre {
tracing::debug!(
"{} guards have been expired as too old.",
n_pre - self.guards.len()
);
let n_expired = n_pre - self.guards.len();
debug!(n_expired, "Expired guards as too old.");
self.primary_guards_invalidated = true;
}
}