github-personal/firezone
1
0
Fork 0
mirror of https://github.com/outbackdingo/firezone.git synced 2026-01-27 18:18:55 +00:00
Code Issues Packages Projects Releases Wiki Activity

chore(snownet): improve logs in Allocation (#3986)

Browse Source 
This adds a few logs that I noticed could be helpful after looking at
some logs shared by a customer. Most importantly, we now log everything
in `handle_timeout` in the scope of the relay's IP, meaning we can
differentiate them from each other.
This commit is contained in:
Thomas Eizinger
2024-03-07 06:54:05 +11:00
committed by GitHub
parent 0ed2480ac0
commit 46d60da136
1 changed files with 11 additions and 7 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
rust/connlib/snownet/src/allocation.rs
View File

@@ -114,8 +114,6 @@ impl Allocation {
backoff: backoff::new(now, REQUEST_TIMEOUT),
};
tracing::debug!(%server, "Requesting new allocation");
allocation.authenticate_and_queue(make_allocate_request());
allocation
@@ -158,7 +156,7 @@ impl Allocation {
self.authenticate_and_queue(make_refresh_request());
}
#[tracing::instrument(level = "debug", skip_all, fields(relay = %self.server, id, method, class, rtt))]
#[tracing::instrument(level = "debug", skip_all, fields(id, method, class, rtt))]
pub fn handle_input(
&mut self,
from: SocketAddr,
@@ -391,6 +389,7 @@ impl Allocation {
Some((peer, payload, socket))
}
#[tracing::instrument(level = "debug", skip_all, fields(relay = %self.server))]
pub fn handle_timeout(&mut self, now: Instant) {
self.update_now(now);
@@ -398,14 +397,16 @@ impl Allocation {
.allocation_expires_at()
.is_some_and(|expires_at| now >= expires_at)
{
tracing::debug!("Allocation is expired");
self.invalidate_allocation();
}
while let Some(timed_out_request) =
while let Some((timed_out_request, backoff)) =
self.sent_requests
.iter()
.find_map(|(id, (_, sent_at, backoff))| {
(now.duration_since(*sent_at) >= *backoff).then_some(*id)
(now.duration_since(*sent_at) >= *backoff).then_some((*id, *backoff))
})
{
let (request, _, _) = self
@@ -413,7 +414,7 @@ impl Allocation {
.remove(&timed_out_request)
.expect("ID is from list");
tracing::debug!(id = ?request.transaction_id(), method = %request.method(), "Request timed out, re-sending");
tracing::debug!(id = ?request.transaction_id(), method = %request.method(), "Request timed out after {backoff:?}, re-sending");
self.authenticate_and_queue(request);
}
@@ -435,6 +436,9 @@ impl Allocation {
.channels_to_refresh(now, |number| {
self.channel_binding_in_flight_by_number(number)
})
.inspect(|(number, peer)| {
tracing::debug!(%number, %peer, "Channel is due for a refresh");
})
.map(|(number, peer)| make_channel_bind_request(peer, number))
.collect::<Vec<_>>(); // Need to allocate here to satisfy borrow-checker. Number of channel refresh messages should be small so this shouldn't be a big impact.
@@ -685,7 +689,7 @@ impl Allocation {
/// Returns: Whether we actually queued a message.
fn authenticate_and_queue(&mut self, message: Message<Attribute>) -> bool {
let Some(backoff) = self.backoff.next_backoff() else {
tracing::warn!(
tracing::debug!(
"Unable to queue {} because we've exceeded our backoffs",
message.method()
);