diff --git a/common/bin-common/Cargo.toml b/common/bin-common/Cargo.toml index 29fd632897..a3682644ea 100644 --- a/common/bin-common/Cargo.toml +++ b/common/bin-common/Cargo.toml @@ -18,9 +18,23 @@ semver = "0.11" serde = { workspace = true, features = ["derive"], optional = true } serde_json = { workspace = true, optional = true } +## tracing +tracing-appender = { version = "0.2.2", optional = true } +tracing-subscriber = { version = "0.3.16", features = [ + "env-filter", +], optional = true } +tracing-tree = { version = "0.2.2", optional = true } + + [build-dependencies] -vergen = { version = "=7.4.3", default-features = false, features = ["build", "git", "rustc", "cargo"] } +vergen = { version = "=7.4.3", default-features = false, features = [ + "build", + "git", + "rustc", + "cargo", +] } [features] default = [] output_format = ["serde", "serde_json"] +tracing = ["tracing-appender", "tracing-subscriber", "tracing-tree"] diff --git a/common/bin-common/src/logging/mod.rs b/common/bin-common/src/logging/mod.rs index 1562c91e8b..3698f1210f 100644 --- a/common/bin-common/src/logging/mod.rs +++ b/common/bin-common/src/logging/mod.rs @@ -1,5 +1,16 @@ // Copyright 2022 - Nym Technologies SA // SPDX-License-Identifier: Apache-2.0 +// use tracing_subscriber::{ +// fmt::Layer, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Registry, +// }; +// use tracing_tree::HierarchicalLayer; + +#[cfg(feature = "tracing")] +pub use tracing_appender; +#[cfg(feature = "tracing")] +pub use tracing_subscriber; +#[cfg(feature = "tracing")] +pub use tracing_tree; // I'd argue we should start transitioning from `log` to `tracing` pub fn setup_logging() { @@ -24,6 +35,34 @@ pub fn setup_logging() { .init(); } +// TODO: This has to be a macro, running it as a function does not work for the file_appender for some reason +#[cfg(feature = "tracing")] +#[macro_export] +macro_rules! setup_tracing { + ($file_name: expr) => { + use nym_bin_common::logging::tracing_subscriber::layer::SubscriberExt; + use nym_bin_common::logging::tracing_subscriber::util::SubscriberInitExt; + + let file_appender = + nym_bin_common::logging::tracing_appender::rolling::hourly($file_name, "log"); + let (non_blocking, _guard) = + nym_bin_common::logging::tracing_appender::non_blocking(file_appender); + let appender_layer = nym_bin_common::logging::tracing_subscriber::fmt::Layer::new() + .with_ansi(false) + .with_writer(non_blocking); + + nym_bin_common::logging::tracing_subscriber::Registry::default() + .with(nym_bin_common::logging::tracing_subscriber::EnvFilter::from_default_env()) + .with(appender_layer) + .with( + nym_bin_common::logging::tracing_tree::HierarchicalLayer::new(4) + .with_targets(true) + .with_bracketed_fields(true), + ) + .init(); + }; +} + pub fn banner(crate_name: &str, crate_version: &str) -> String { format!( r#" diff --git a/common/mixnode-common/Cargo.toml b/common/mixnode-common/Cargo.toml index 0b0e444731..002b3f73df 100644 --- a/common/mixnode-common/Cargo.toml +++ b/common/mixnode-common/Cargo.toml @@ -13,12 +13,21 @@ humantime-serde = "1.0" log = { workspace = true } rand = "0.8" serde = { version = "1.0", features = ["derive"] } -tokio = { version = "1.24.1", features = ["time", "macros", "rt", "net", "io-util"] } +tokio = { version = "1.24.1", features = [ + "time", + "macros", + "rt", + "net", + "io-util", +] } tokio-util = { version = "0.7.4", features = ["codec"] } url = "2.2" thiserror = "1.0.37" -nym-crypto = { path = "../crypto" } +## tracing +tracing = { version = "0.1.37", optional = true } + +nym-crypto = { path = "../crypto" } nym-network-defaults = { path = "../network-defaults" } nym-sphinx-acknowledgements = { path = "../nymsphinx/acknowledgements" } nym-sphinx-addressing = { path = "../nymsphinx/addressing" } @@ -27,5 +36,13 @@ nym-sphinx-framing = { path = "../nymsphinx/framing" } nym-sphinx-params = { path = "../nymsphinx/params" } nym-sphinx-types = { path = "../nymsphinx/types" } nym-task = { path = "../task" } -validator-client = { path = "../client-libs/validator-client", features = ["nyxd-client"]} +validator-client = { path = "../client-libs/validator-client", features = [ + "nyxd-client", +] } nym-bin-common = { path = "../bin-common" } + +cfg-if = "1.0.0" +cpu-cycles = { path = "../../cpu-cycles", optional = true } + +[features] +cpucycles = ["cpu-cycles", "tracing"] diff --git a/common/mixnode-common/src/lib.rs b/common/mixnode-common/src/lib.rs index 34d43fc458..d4488ba44a 100644 --- a/common/mixnode-common/src/lib.rs +++ b/common/mixnode-common/src/lib.rs @@ -1,5 +1,41 @@ // Copyright 2021 - Nym Technologies SA // SPDX-License-Identifier: Apache-2.0 - pub mod packet_processor; pub mod verloc; + +pub fn cpu_cycles() -> Result> { + cfg_if::cfg_if! { + if #[cfg(feature = "cpucycles")] { + Ok(cpu_cycles::cpucycles()?) + } else { + Err("`cpucycles` feature is not turned on!".into()) + } + } +} + +#[macro_export] +macro_rules! measure { + ( $x:expr ) => {{ + cfg_if::cfg_if! { + if #[cfg(feature = "cpucycles")] { + let start_cycles = $crate::cpu_cycles(); + // if the block needs to return something, we can return it + let r = $x; + let end_cycles = $crate::cpu_cycles(); + let name = if let Some(meta) = tracing::Span::current().metadata() { + meta.name() + } else { + "measure" + }; + match (start_cycles, end_cycles) { + (Ok(start), Ok(end)) => info!("{} cpucycles: {}", name, end - start), + (Err(e), _) => error!("{e}"), + (_, Err(e)) => error!("{e}"), + } + r + } else { + $x + } + } + }}; +} diff --git a/common/mixnode-common/src/packet_processor/processor.rs b/common/mixnode-common/src/packet_processor/processor.rs index 7d041fce3b..98847d8983 100644 --- a/common/mixnode-common/src/packet_processor/processor.rs +++ b/common/mixnode-common/src/packet_processor/processor.rs @@ -1,6 +1,7 @@ // Copyright 2021 - Nym Technologies SA // SPDX-License-Identifier: Apache-2.0 +use crate::measure; use crate::packet_processor::error::MixProcessingError; use log::*; use nym_sphinx_acknowledgements::surb_ack::SurbAck; @@ -14,6 +15,8 @@ use nym_sphinx_types::{ }; use std::convert::TryFrom; use std::sync::Arc; +#[cfg(feature = "cpucycles")] +use tracing::instrument; type ForwardAck = MixPacket; @@ -46,29 +49,41 @@ impl SphinxPacketProcessor { } /// Performs a fresh sphinx unwrapping using no cache. + #[cfg_attr( + feature = "cpucycles", + instrument(skip(self, packet), fields(cpucycles)) + )] fn perform_initial_sphinx_packet_processing( &self, packet: SphinxPacket, ) -> Result { - packet.process(&self.sphinx_key).map_err(|err| { - debug!("Failed to unwrap Sphinx packet: {err}"); - MixProcessingError::SphinxProcessingError(err) + measure!({ + packet.process(&self.sphinx_key).map_err(|err| { + debug!("Failed to unwrap Sphinx packet: {err}"); + MixProcessingError::SphinxProcessingError(err) + }) }) } /// Takes the received framed packet and tries to unwrap it from the sphinx encryption. + #[cfg_attr( + feature = "cpucycles", + instrument(skip(self, received), fields(cpucycles)) + )] fn perform_initial_unwrapping( &self, received: FramedSphinxPacket, ) -> Result { - let packet_mode = received.packet_mode(); - let sphinx_packet = received.into_inner(); + measure!({ + let packet_mode = received.packet_mode(); + let sphinx_packet = received.into_inner(); - if packet_mode.is_old_vpn() { - return Err(MixProcessingError::ReceivedOldTypeVpnPacket); - } + if packet_mode.is_old_vpn() { + return Err(MixProcessingError::ReceivedOldTypeVpnPacket); + } - self.perform_initial_sphinx_packet_processing(sphinx_packet) + self.perform_initial_sphinx_packet_processing(sphinx_packet) + }) } /// Processed received forward hop packet - tries to extract next hop address, sets delay @@ -171,20 +186,26 @@ impl SphinxPacketProcessor { } } + #[cfg_attr( + feature = "cpucycles", + instrument(skip(self, received), fields(cpucycles)) + )] pub fn process_received( &self, received: FramedSphinxPacket, ) -> Result { // explicit packet size will help to correctly parse final hop - let packet_size = received.packet_size(); - let packet_mode = received.packet_mode(); + measure!({ + let packet_size = received.packet_size(); + let packet_mode = received.packet_mode(); - // unwrap the sphinx packet and if possible and appropriate, cache keys - let processed_packet = self.perform_initial_unwrapping(received)?; + // unwrap the sphinx packet and if possible and appropriate, cache keys + let processed_packet = self.perform_initial_unwrapping(received)?; - // for forward packets, extract next hop and set delay (but do NOT delay here) - // for final packets, extract SURBAck - self.perform_final_processing(processed_packet, packet_size, packet_mode) + // for forward packets, extract next hop and set delay (but do NOT delay here) + // for final packets, extract SURBAck + self.perform_final_processing(processed_packet, packet_size, packet_mode) + }) } } diff --git a/mixnode/Cargo.toml b/mixnode/Cargo.toml index 014f862b87..0f9b49d1aa 100644 --- a/mixnode/Cargo.toml +++ b/mixnode/Cargo.toml @@ -36,6 +36,12 @@ tokio = { version = "1.21.2", features = ["rt-multi-thread", "net", "signal"] } tokio-util = { version = "0.7.3", features = ["codec"] } toml = "0.5.8" url = { version = "2.2", features = ["serde"] } +cfg-if = "1.0.0" + +## tracing +tracing = { version = "0.1.37", optional = true } +opentelemetry = { version = "0.19.0", optional = true } + ## internal nym-config = { path = "../common/config" } @@ -63,3 +69,11 @@ tokio = { version = "1.21.2", features = [ nym-sphinx-types = { path = "../common/nymsphinx/types" } nym-sphinx-params = { path = "../common/nymsphinx/params" } + +[features] +cpucycles = [ + "mixnode-common/cpucycles", + "tracing", + "opentelemetry", + "nym-bin-common/tracing", +] diff --git a/mixnode/src/commands/sign.rs b/mixnode/src/commands/sign.rs index 706defb8df..e39d97571d 100644 --- a/mixnode/src/commands/sign.rs +++ b/mixnode/src/commands/sign.rs @@ -8,11 +8,12 @@ use crate::config::{persistence::pathfinder::MixNodePathfinder, Config}; use crate::node::MixNode; use anyhow::{bail, Result}; use clap::{ArgGroup, Args}; -use log::error; use nym_bin_common::output_format::OutputFormat; use nym_config::NymConfig; use nym_crypto::asymmetric::identity; use nym_types::helpers::ConsoleSigningOutput; +#[cfg(feature = "cpucycles")] +use tracing::error; use validator_client::nyxd; use super::version_check; diff --git a/mixnode/src/main.rs b/mixnode/src/main.rs index e9f9f9f59c..ca1780a0cf 100644 --- a/mixnode/src/main.rs +++ b/mixnode/src/main.rs @@ -7,9 +7,15 @@ extern crate rocket; use ::nym_config::defaults::setup_env; use clap::{crate_name, crate_version, Parser}; use lazy_static::lazy_static; +#[cfg(feature = "cpucycles")] +use mixnode_common::measure; use nym_bin_common::build_information::BinaryBuildInformation; +#[allow(unused_imports)] use nym_bin_common::logging::{maybe_print_banner, setup_logging}; - +#[cfg(feature = "cpucycles")] +use nym_bin_common::setup_tracing; +#[cfg(feature = "cpucycles")] +use tracing::instrument; mod commands; mod config; mod node; @@ -35,19 +41,32 @@ struct Cli { command: commands::Commands, } -#[cfg(feature = "cpu-cycles")] -pub fn cpu_cycles() { - info!("{}", cpu_cycles::cpucycles()) +#[cfg(feature = "cpucycles")] +#[instrument(fields(cpucycles))] +fn test_function() { + measure!({}) } #[tokio::main] async fn main() { - setup_logging(); + cfg_if::cfg_if! { + if #[cfg(feature = "cpucycles")] { + setup_tracing!("/tmp/tracing.log"); + } else { + setup_logging(); + } + } + maybe_print_banner(crate_name!(), crate_version!()); let args = Cli::parse(); setup_env(args.config_env_file.as_ref()); commands::execute(args).await; + + cfg_if::cfg_if! { + if #[cfg(feature = "cpucycles")] { + opentelemetry::global::shutdown_tracer_provider(); + }} } #[cfg(test)] diff --git a/mixnode/src/node/listener/connection_handler/mod.rs b/mixnode/src/node/listener/connection_handler/mod.rs index 684793b013..1e12075c13 100644 --- a/mixnode/src/node/listener/connection_handler/mod.rs +++ b/mixnode/src/node/listener/connection_handler/mod.rs @@ -7,7 +7,7 @@ use crate::node::listener::connection_handler::packet_processing::{ use crate::node::packet_delayforwarder::PacketDelayForwardSender; use crate::node::TaskClient; use futures::StreamExt; -use log::{error, info}; +use mixnode_common::measure; use nym_sphinx::forwarding::packet::MixPacket; use nym_sphinx::framing::codec::SphinxCodec; use nym_sphinx::framing::packet::FramedSphinxPacket; @@ -16,6 +16,8 @@ use std::net::SocketAddr; use tokio::net::TcpStream; use tokio::time::Instant; use tokio_util::codec::Framed; +#[cfg(feature = "cpucycles")] +use tracing::{error, info, instrument}; pub(crate) mod packet_processing; @@ -48,6 +50,10 @@ impl ConnectionHandler { .expect("the delay-forwarder has died!"); } + #[cfg_attr( + feature = "cpucycles", + instrument(skip(self, framed_sphinx_packet), fields(cpucycles)) + )] fn handle_received_packet(&self, framed_sphinx_packet: FramedSphinxPacket) { // // TODO: here be replay attack detection - it will require similar key cache to the one in @@ -57,17 +63,19 @@ impl ConnectionHandler { // all processing such, key caching, etc. was done. // however, if it was a forward hop, we still need to delay it - match self.packet_processor.process_received(framed_sphinx_packet) { - Err(err) => debug!("We failed to process received sphinx packet - {err}"), - Ok(res) => match res { - MixProcessingResult::ForwardHop(forward_packet, delay) => { - self.delay_and_forward_packet(forward_packet, delay) - } - MixProcessingResult::FinalHop(..) => { - warn!("Somehow processed a loop cover message that we haven't implemented yet!") - } - }, - } + measure!({ + match self.packet_processor.process_received(framed_sphinx_packet) { + Err(err) => debug!("We failed to process received sphinx packet - {err}"), + Ok(res) => match res { + MixProcessingResult::ForwardHop(forward_packet, delay) => { + self.delay_and_forward_packet(forward_packet, delay) + } + MixProcessingResult::FinalHop(..) => { + warn!("Somehow processed a loop cover message that we haven't implemented yet!") + } + }, + } + }) } pub(crate) async fn handle_connection( diff --git a/mixnode/src/node/listener/mod.rs b/mixnode/src/node/listener/mod.rs index 43732a772f..f8fad07b23 100644 --- a/mixnode/src/node/listener/mod.rs +++ b/mixnode/src/node/listener/mod.rs @@ -2,11 +2,12 @@ // SPDX-License-Identifier: Apache-2.0 use crate::node::listener::connection_handler::ConnectionHandler; -use log::error; use std::net::SocketAddr; use std::process; use tokio::net::TcpListener; use tokio::task::JoinHandle; +#[cfg(feature = "cpucycles")] +use tracing::error; use super::TaskClient; diff --git a/mixnode/src/node/mod.rs b/mixnode/src/node/mod.rs index 28716f120c..d0a28c82af 100644 --- a/mixnode/src/node/mod.rs +++ b/mixnode/src/node/mod.rs @@ -16,7 +16,6 @@ use crate::node::listener::Listener; use crate::node::node_description::NodeDescription; use crate::node::node_statistics::SharedNodeStats; use crate::node::packet_delayforwarder::{DelayForwarder, PacketDelayForwardSender}; -use log::{error, info, warn}; use mixnode_common::verloc::{self, AtomicVerlocResult, VerlocMeasurer}; use nym_bin_common::output_format::OutputFormat; use nym_bin_common::version_checker::parse_version; @@ -28,6 +27,8 @@ use rand::thread_rng; use std::net::SocketAddr; use std::process; use std::sync::Arc; +#[cfg(feature = "cpucycles")] +use tracing::{error, info, warn}; mod http; mod listener; diff --git a/nym-connect/desktop/Cargo.lock b/nym-connect/desktop/Cargo.lock index 0421b9637c..86d829bc7d 100644 --- a/nym-connect/desktop/Cargo.lock +++ b/nym-connect/desktop/Cargo.lock @@ -3276,6 +3276,7 @@ dependencies = [ name = "nym-bin-common" version = "0.3.0" dependencies = [ + "atty", "clap", "clap_complete", "clap_complete_fig",