GRIN/nym
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

otel: add tracing

Browse Source
This commit is contained in:
Tommy Verrall
2026-02-16 13:46:17 +01:00
parent d93d25ebae
commit 40a3cd28b7
12 changed files with 2191 additions and 1763 deletions
Download Patch File Download Diff File Expand all files Collapse all files
nym-node/src/node/mixnet/handler.rs
+219 -32
View File
@@ -20,7 +20,7 @@ use std::net::SocketAddr;
use tokio::net::TcpStream;
use tokio::time::Instant;
use tokio_util::codec::Framed;
use tracing::{debug, error, instrument, trace, warn};
use tracing::{debug, error, instrument, trace, warn, Span};
struct PendingReplayCheckPackets {
// map of rotation id used for packet creation to the packets
@@ -51,6 +51,10 @@ impl PendingReplayCheckPackets {
.push(packet.packet)
}
fn total_count(&self) -> usize {
self.packets.values().map(|v| v.len()).sum()
}
fn replay_tags(&self) -> HashMap<u32, Vec<&[u8; REPLAY_TAG_SIZE]>> {
let mut replay_tags = HashMap::with_capacity(self.packets.len());
'outer: for (rotation_id, packets) in &self.packets {
@@ -130,20 +134,54 @@ impl ConnectionHandler {
Some(now + delay)
}
#[instrument(
name = "mixnode.forward_packet",
skip(self, mix_packet, delay),
level = "debug",
fields(
remote_addr = %self.remote_address,
delay_ms,
)
)]
fn handle_forward_packet(&self, now: Instant, mix_packet: MixPacket, delay: Option<Delay>) {
if !self.shared.processing_config.forward_hop_processing_enabled {
trace!("this nym-node does not support forward hop packets");
warn!(
event = "packet.dropped.forward_disabled",
remote_addr = %self.remote_address,
"dropping packet: forward hop processing disabled"
);
self.shared.dropped_forward_packet(self.remote_address.ip());
return;
}
let forward_instant = self.create_delay_target(now, delay);
Span::current().record(
"delay_ms",
forward_instant
.map(|i| i.saturating_duration_since(now).as_millis() as u64)
.unwrap_or(0),
);
self.shared.forward_mix_packet(mix_packet, forward_instant);
}
#[instrument(
name = "mixnode.final_hop",
skip(self, final_hop_data),
level = "debug",
fields(
remote_addr = %self.remote_address,
client_online,
disk_fallback = false,
ack_forwarded = false,
)
)]
async fn handle_final_hop(&self, final_hop_data: ProcessedFinalHop) {
if !self.shared.processing_config.final_hop_processing_enabled {
trace!("this nym-node does not support final hop packets");
warn!(
event = "packet.dropped.final_hop_disabled",
remote_addr = %self.remote_address,
"dropping packet: final hop processing disabled"
);
self.shared
.dropped_final_hop_packet(self.remote_address.ip());
return;
@@ -151,11 +189,11 @@ impl ConnectionHandler {
let client = final_hop_data.destination;
let message = final_hop_data.message;
let has_ack = final_hop_data.forward_ack.is_some();
// if possible attempt to push message directly to the client
match self.shared.try_push_message_to_client(client, message) {
Err(unsent_plaintext) => {
// if that failed, store it on disk (to be 🔥 soon...)
Span::current().record("client_online", false);
match self
.shared
.store_processed_packet_payload(client, unsent_plaintext)
@@ -163,6 +201,7 @@ impl ConnectionHandler {
{
Err(err) => error!("Failed to store client data - {err}"),
Ok(_) => {
Span::current().record("disk_fallback", true);
self.shared
.metrics
.mixnet
@@ -172,13 +211,16 @@ impl ConnectionHandler {
}
}
}
Ok(_) => trace!("Pushed received packet to {client}"),
Ok(_) => {
Span::current().record("client_online", true);
trace!("Pushed received packet to {client}");
}
}
// if we managed to either push message directly to the [online] client or store it at
// its inbox, it means that it must exist at this gateway, hence we can send the
// received ack back into the network
self.shared.forward_ack_packet(final_hop_data.forward_ack);
if has_ack {
Span::current().record("ack_forwarded", true);
}
}
fn within_deferral_threshold(&self, now: Instant) -> bool {
@@ -206,32 +248,56 @@ impl ConnectionHandler {
if !time_threshold {
warn!(
"{}: time failure - {}",
event = "replay_detection.deferral_exceeded",
threshold_type = "time",
deferred_count = self.pending_packets.total_count(),
deferral_ms = now.saturating_duration_since(self.pending_packets.last_acquired_mutex).as_millis() as u64,
remote_addr = %self.remote_address,
"{}: time deferral threshold exceeded with {} pending packets",
self.remote_address,
self.pending_packets.packets.len()
self.pending_packets.total_count()
)
}
if !count_threshold {
warn!("{}, count failure", self.remote_address)
warn!(
event = "replay_detection.deferral_exceeded",
threshold_type = "count",
deferred_count = self.pending_packets.total_count(),
remote_addr = %self.remote_address,
"{}: count deferral threshold exceeded",
self.remote_address
)
}
time_threshold && count_threshold
}
#[instrument(
name = "mixnode.sphinx_partial_unwrap",
skip(self, packet),
level = "debug",
fields(
key_rotation,
unwrap_result,
)
)]
fn try_partially_unwrap_packet(
&self,
packet: FramedNymPacket,
) -> Result<PartialyUnwrappedPacketWithKeyRotation, PacketProcessingError> {
// based on the received sphinx key rotation information,
// attempt to choose appropriate key for processing the packet
match packet.header().key_rotation {
let rotation_label = match packet.header().key_rotation {
SphinxKeyRotation::Unknown => "unknown",
SphinxKeyRotation::OddRotation => "odd",
SphinxKeyRotation::EvenRotation => "even",
};
Span::current().record("key_rotation", rotation_label);
let result = match packet.header().key_rotation {
SphinxKeyRotation::Unknown => {
let primary = self.shared.sphinx_keys.primary();
let primary_rotation = primary.rotation_id();
// we have to try both keys, start with the primary as it has higher likelihood of being correct
// if let Ok(partially_unwrapped) = PartiallyUnwrappedPacket::new()
match PartiallyUnwrappedPacket::new(packet, primary.inner().as_ref()) {
Ok(unwrapped_packet) => {
Ok(unwrapped_packet.with_key_rotation(primary_rotation))
@@ -250,6 +316,12 @@ impl ConnectionHandler {
}
SphinxKeyRotation::OddRotation => {
let Some(odd_key) = self.shared.sphinx_keys.odd() else {
warn!(
event = "packet.dropped.expired_key",
key_rotation = "odd",
remote_addr = %self.remote_address,
"dropping packet: odd key rotation expired"
);
return Err(PacketProcessingError::ExpiredKey);
};
let odd_rotation = odd_key.rotation_id();
@@ -259,6 +331,12 @@ impl ConnectionHandler {
}
SphinxKeyRotation::EvenRotation => {
let Some(even_key) = self.shared.sphinx_keys.even() else {
warn!(
event = "packet.dropped.expired_key",
key_rotation = "even",
remote_addr = %self.remote_address,
"dropping packet: even key rotation expired"
);
return Err(PacketProcessingError::ExpiredKey);
};
let even_rotation = even_key.rotation_id();
@@ -266,7 +344,10 @@ impl ConnectionHandler {
.map_err(|(_, err)| err)
.map(|p| p.with_key_rotation(even_rotation))
}
}
};
Span::current().record("unwrap_result", if result.is_ok() { "ok" } else { "err" });
result
}
async fn handle_received_packet_with_replay_detection(
@@ -280,6 +361,12 @@ impl ConnectionHandler {
Ok(unwrapped) => unwrapped,
Err(err) => {
trace!("failed to process received mix packet: {err}");
warn!(
event = "packet.dropped.malformed",
error = %err,
remote_addr = %self.remote_address,
"dropping malformed packet"
);
self.shared
.metrics
.mixnet
@@ -316,7 +403,9 @@ impl ConnectionHandler {
// 3. forward the packet to the relevant sink (if enabled)
match unwrapped_packet {
Err(err) => trace!("failed to process received mix packet: {err}"),
Err(err) => {
trace!("failed to process received mix packet: {err}");
}
Ok(processed_packet) => match processed_packet.processing_data {
MixProcessingResultData::ForwardHop { packet, delay } => {
self.handle_forward_packet(now, packet, delay);
@@ -334,6 +423,7 @@ impl ConnectionHandler {
packets: HashMap<u32, Vec<PartiallyUnwrappedPacket>>,
replay_check_results: HashMap<u32, Vec<bool>>,
) {
let mut replays_detected: u64 = 0;
for (rotation_id, packets) in packets {
let Some(replay_checks) = replay_check_results.get(&rotation_id) else {
// this should never happen, but if we messed up, and it does, don't panic, just drop the packets
@@ -342,6 +432,13 @@ impl ConnectionHandler {
};
for (packet, &replayed) in packets.into_iter().zip(replay_checks) {
let unwrapped_packet = if replayed {
replays_detected += 1;
warn!(
event = "packet.dropped.replay",
remote_addr = %self.remote_address,
rotation_id,
"dropping replayed packet"
);
Err(PacketProcessingError::PacketReplay)
} else {
packet.finalise_unwrapping()
@@ -350,6 +447,13 @@ impl ConnectionHandler {
self.handle_unwrapped_packet(now, unwrapped_packet).await;
}
}
if replays_detected > 0 {
debug!(
replays_detected,
remote_addr = %self.remote_address,
"replay detection batch completed with replays"
);
}
}
async fn handle_pending_packets_batch_no_locking(&mut self, now: Instant) -> bool {
@@ -379,13 +483,26 @@ impl ConnectionHandler {
true
}
#[instrument(
name = "mixnode.replay_check_batch",
skip(self),
level = "debug",
fields(
batch_size,
mutex_wait_ms,
)
)]
async fn handle_pending_packets_batch(&mut self, now: Instant) {
let batch_size = self.pending_packets.total_count();
Span::current().record("batch_size", batch_size as u64);
let batch = self.pending_packets.reset(now);
let replay_tags = self.pending_packets.replay_tags();
if replay_tags.is_empty() {
return;
}
let mutex_start = Instant::now();
let Ok(replay_check_results) = self
.shared
.replay_protection_filter
@@ -396,32 +513,56 @@ impl ConnectionHandler {
self.shared.shutdown_token.cancel();
return;
};
Span::current().record(
"mutex_wait_ms",
mutex_start.elapsed().as_millis() as u64,
);
self.handle_post_replay_detection_packets(now, batch, replay_check_results)
.await;
}
#[instrument(
name = "mixnode.sphinx_full_unwrap",
skip(self, packet),
level = "debug",
fields(key_rotation)
)]
fn try_full_unwrap_packet(
&self,
packet: FramedNymPacket,
) -> Result<MixProcessingResult, PacketProcessingError> {
// based on the received sphinx key rotation information,
// attempt to choose appropriate key for processing the packet
// NOTE: due to the function signatures, outfox packets will **only** attempt primary key
// if no rotation information is available (but that's fine given outfox is not really in use,
// and by the time we need it, the rotation info should be present)
let rotation_label = match packet.header().key_rotation {
SphinxKeyRotation::Unknown => "unknown",
SphinxKeyRotation::OddRotation => "odd",
SphinxKeyRotation::EvenRotation => "even",
};
Span::current().record("key_rotation", rotation_label);
match packet.header().key_rotation {
SphinxKeyRotation::Unknown => {
process_framed_packet(packet, self.shared.sphinx_keys.primary().inner().as_ref())
}
SphinxKeyRotation::OddRotation => {
let Some(odd_key) = self.shared.sphinx_keys.odd() else {
warn!(
event = "packet.dropped.expired_key",
key_rotation = "odd",
remote_addr = %self.remote_address,
"dropping packet: odd key rotation expired"
);
return Err(PacketProcessingError::ExpiredKey);
};
process_framed_packet(packet, odd_key.inner().as_ref())
}
SphinxKeyRotation::EvenRotation => {
let Some(even_key) = self.shared.sphinx_keys.even() else {
warn!(
event = "packet.dropped.expired_key",
key_rotation = "even",
remote_addr = %self.remote_address,
"dropping packet: even key rotation expired"
);
return Err(PacketProcessingError::ExpiredKey);
};
process_framed_packet(packet, even_key.inner().as_ref())
@@ -456,23 +597,36 @@ impl ConnectionHandler {
}
#[instrument(
skip(self),
name = "mixnode.connection",
skip(self, socket),
level = "debug",
fields(
remote = %self.remote_address
remote = %self.remote_address,
noise_handshake_ms,
)
)]
pub(crate) async fn handle_connection(&mut self, socket: TcpStream) {
let handshake_start = Instant::now();
let noise_stream = match upgrade_noise_responder(socket, &self.shared.noise_config).await {
Ok(noise_stream) => noise_stream,
Err(err) => {
error!(
"Failed to perform Noise handshake with {:?} - {err}",
self.remote_address
Span::current().record(
"noise_handshake_ms",
handshake_start.elapsed().as_millis() as u64,
);
warn!(
event = "connection.failed.noise",
remote_addr = %self.remote_address,
error = %err,
"Noise responder handshake failed"
);
return;
}
};
Span::current().record(
"noise_handshake_ms",
handshake_start.elapsed().as_millis() as u64,
);
debug!(
"Noise responder handshake completed for {:?}",
self.remote_address
@@ -481,26 +635,58 @@ impl ConnectionHandler {
.await
}
#[instrument(
name = "mixnode.stream",
skip(self, mixnet_connection),
level = "debug",
fields(
remote = %self.remote_address,
packets_processed = 0u64,
exit_reason,
)
)]
pub(crate) async fn handle_stream(
&mut self,
mut mixnet_connection: Framed<Connection<TcpStream>, NymCodec>,
) {
let mut packets_processed: u64 = 0;
loop {
tokio::select! {
biased;
_ = self.shared.shutdown_token.cancelled() => {
trace!("connection handler: received shutdown");
Span::current().record("exit_reason", "shutdown");
break
}
maybe_framed_nym_packet = mixnet_connection.next() => {
match maybe_framed_nym_packet {
Some(Ok(packet)) => self.handle_received_nym_packet(packet).await,
Some(Ok(packet)) => {
self.handle_received_nym_packet(packet).await;
packets_processed += 1;
if packets_processed % 10000 == 0 {
Span::current().record("packets_processed", packets_processed);
}
}
Some(Err(err)) => {
debug!("connection got corrupted with: {err}");
warn!(
event = "connection.corrupted",
remote_addr = %self.remote_address,
error = %err,
packets_processed,
"connection stream corrupted"
);
Span::current().record("exit_reason", "corrupted");
Span::current().record("packets_processed", packets_processed);
return
}
None => {
debug!("connection got closed by the remote");
debug!(
remote_addr = %self.remote_address,
packets_processed,
"connection closed by remote"
);
Span::current().record("exit_reason", "closed_by_remote");
Span::current().record("packets_processed", packets_processed);
return
}
}
@@ -508,6 +694,7 @@ impl ConnectionHandler {
}
}
Span::current().record("packets_processed", packets_processed);
debug!("exiting and closing connection");
}
}
nym-node/src/node/mixnet/packet_forwarding/mod.rs
+36 -9
View File
@@ -55,12 +55,17 @@ impl<C, F> PacketForwarder<C, F> {
if let Err(err) = self.mixnet_client.send_without_response(packet) {
if err.kind() == io::ErrorKind::WouldBlock {
// we only know for sure if we dropped a packet if our sending queue was full
// in any other case the connection might still be re-established (or created for the first time)
// and the packet might get sent, but we won't know about it
warn!(
event = "packet.dropped.buffer_full",
next_hop = %next_hop,
"dropping packet: egress connection buffer full (WouldBlock)"
);
self.metrics.mixnet.egress_dropped_forward_packet(next_hop)
} else if err.kind() == io::ErrorKind::NotConnected {
// let's give the benefit of the doubt and assume we manage to establish connection
debug!(
next_hop = %next_hop,
"packet queued for not-yet-connected peer"
);
self.metrics.mixnet.egress_sent_forward_packet(next_hop)
}
} else {
@@ -86,7 +91,11 @@ impl<C, F> PacketForwarder<C, F> {
let next_hop = new_packet.packet.next_hop();
if !self.routing_filter.should_route(next_hop.as_ref().ip()) {
debug!("dropping packet as the egress address does not belong to any known node");
warn!(
event = "packet.dropped.routing_filter",
next_hop = %next_hop,
"dropping packet: egress address does not belong to any known node"
);
self.metrics
.mixnet
.egress_dropped_forward_packet(next_hop.into());
@@ -125,7 +134,7 @@ impl<C, F> PacketForwarder<C, F> {
C: SendWithoutResponse,
F: RoutingFilter,
{
let mut processed = 0;
let mut processed: u64 = 0;
trace!("starting PacketForwarder");
loop {
tokio::select! {
@@ -145,11 +154,29 @@ impl<C, F> PacketForwarder<C, F> {
#[allow(clippy::unwrap_used)]
self.handle_new_packet(new_packet.unwrap());
let channel_len = self.packet_sender.len();
let delay_queue_len = self.delay_queue.len();
if processed % 1000 == 0 {
match channel_len {
n if n > 1000 => error!("there are currently {n} mix packets waiting to get forwarded - the node seems to be significantly overloaded!"),
n if n > 500 => warn!("there are currently {n} mix packets waiting to get forwarded - is the node overloaded?"),
n => trace!("there are currently {n} mix packets waiting to get forwarded"),
n if n > 1000 => error!(
event = "forwarder.queue_overload",
channel_depth = n,
delay_queue_depth = delay_queue_len,
packets_processed = processed,
"there are currently {n} mix packets waiting to get forwarded - the node seems to be significantly overloaded!"
),
n if n > 500 => warn!(
event = "forwarder.queue_high",
channel_depth = n,
delay_queue_depth = delay_queue_len,
packets_processed = processed,
"there are currently {n} mix packets waiting to get forwarded - is the node overloaded?"
),
n => trace!(
channel_depth = n,
delay_queue_depth = delay_queue_len,
packets_processed = processed,
"forwarder queue status"
),
}
}
self.update_channel_size_metric(channel_len);
nym-node/src/node/mixnet/shared/final_hop.rs
+40 -4
View File
@@ -5,7 +5,8 @@ use nym_gateway::node::{
ActiveClientsStore, GatewayStorage, GatewayStorageError, InboxGatewayStorage,
};
use nym_sphinx_types::DestinationAddressBytes;
use tracing::debug;
use tokio::time::Instant;
use tracing::{debug, warn};
#[derive(Clone)]
pub(crate) struct SharedFinalHopData {
@@ -27,14 +28,34 @@ impl SharedFinalHopData {
message: Vec<u8>,
) -> Result<(), Vec<u8>> {
match self.active_clients.get_sender(client_address) {
None => Err(message),
None => {
debug!(
event = "gateway.push_to_client",
client_found = false,
send_result = "client_not_found",
"client {client_address} not found in active clients"
);
Err(message)
}
Some(sender_channel) => {
if let Err(unsent) = sender_channel.unbounded_send(vec![message]) {
warn!(
event = "gateway.push_to_client",
client_found = true,
send_result = "channel_closed",
"client {client_address} channel closed, message not delivered"
);
// the unwrap here is fine as the original message got returned;
// plus we're only ever sending 1 message at the time (for now)
#[allow(clippy::unwrap_used)]
Err(unsent.into_inner().pop().unwrap())
} else {
debug!(
event = "gateway.push_to_client",
client_found = true,
send_result = "ok",
"pushed message to client {client_address}"
);
Ok(())
}
}
@@ -46,8 +67,23 @@ impl SharedFinalHopData {
client_address: DestinationAddressBytes,
message: Vec<u8>,
) -> Result<(), GatewayStorageError> {
let start = Instant::now();
debug!("Storing received message for {client_address} on the disk...",);
self.storage.store_message(client_address, message).await
let result = self.storage.store_message(client_address, message).await;
let store_ms = start.elapsed().as_millis() as u64;
if result.is_ok() {
debug!(
event = "gateway.disk_store",
store_ms,
"stored message for {client_address} on disk in {store_ms}ms"
);
} else {
warn!(
event = "gateway.disk_store_failed",
store_ms,
"failed to store message for {client_address} on disk after {store_ms}ms"
);
}
result
}
}
nym-node/src/node/mixnet/shared/mod.rs
+9 -5
View File
@@ -185,16 +185,20 @@ impl SharedData {
}
pub(super) fn forward_mix_packet(&self, packet: MixPacket, delay_until: Option<Instant>) {
let has_delay = delay_until.is_some();
if self
.mixnet_forwarder
.forward_packet(PacketToForward::new(packet, delay_until))
.is_err()
&& !self.shutdown_token.is_cancelled()
{
error!(
"failed to forward sphinx packet on the channel while the process is not going through the shutdown!"
);
self.shutdown_token.cancel();
if !self.shutdown_token.is_cancelled() {
error!(
event = "forwarder.channel_send_failed",
has_delay,
"failed to forward sphinx packet on the channel while the process is not going through the shutdown!"
);
self.shutdown_token.cancel();
}
}
}