From 820c41b54f657b2c0940bd6aa7eb1ea2ac56d6f7 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:05:51 +0200 Subject: [PATCH 01/18] Instead of allowing dead code, make `shutdown_server` only available to tests --- src/components/small_network.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/components/small_network.rs b/src/components/small_network.rs index c218f94d2e..6ee92fd3ce 100644 --- a/src/components/small_network.rs +++ b/src/components/small_network.rs @@ -208,7 +208,7 @@ where /// waits for it to complete the shutdown. This explicitly allows the background task to finish /// and drop everything it owns, ensuring that resources such as allocated ports are free to be /// reused once this completes. - #[allow(dead_code)] + #[cfg(test)] async fn shutdown_server(&mut self) { // Close the shutdown socket, causing the server to exit. drop(self.shutdown.take()); From 3944f79c65c4c38946b3443202afd53a6dccdfef Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:06:40 +0200 Subject: [PATCH 02/18] Store nodes of the network in a hashmap instead of a vec to allow retrieval by node ID --- src/components/small_network/test.rs | 36 +++++++++++++++------------- 1 file changed, 19 insertions(+), 17 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index b8bd7f0825..d42db472c7 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -4,7 +4,7 @@ //! instances of `small_net` arranged in a network. use std::{ - collections::HashSet, + collections::{HashMap, HashSet}, fmt::{self, Debug, Display, Formatter}, io, time::Duration, @@ -113,13 +113,15 @@ impl Display for Message { /// cranking until a condition has been reached. #[derive(Debug)] struct Network { - nodes: Vec>, + nodes: HashMap>, } impl Network { /// Creates a new network. fn new() -> Self { - Network { nodes: Vec::new() } + Network { + nodes: HashMap::new(), + } } /// Creates a new networking node on the network using the default root node port. @@ -133,18 +135,18 @@ impl Network { &mut self, cfg: small_network::Config, ) -> anyhow::Result<&mut reactor::Runner> { - let runner = reactor::Runner::new(cfg).await?; - self.nodes.push(runner); + let runner: reactor::Runner = reactor::Runner::new(cfg).await?; + let node_id = runner.reactor().net.node_id(); + self.nodes.insert(node_id, runner); - Ok(self - .nodes - .last_mut() - .expect("vector cannot be empty after insertion")) + self.nodes + .get_mut(&node_id) + .ok_or_else(|| anyhow::anyhow!("node mysteriously disappeared, this should not happen")) } /// Crank all runners once, returning the number of events processed. async fn crank_all(&mut self) -> usize { - join_all(self.nodes.iter_mut().map(|runner| runner.try_crank())) + join_all(self.nodes.iter_mut().map(|(_, runner)| runner.try_crank())) .await .into_iter() .filter(|opt| opt.is_some()) @@ -175,7 +177,7 @@ impl Network { /// Runs the main loop of every reactor until a condition is true. async fn settle_on(&mut self, f: F) where - F: Fn(&[reactor::Runner]) -> bool, + F: Fn(&HashMap>) -> bool, { loop { // Check condition. @@ -191,8 +193,8 @@ impl Network { } } - // Returns the internal list of nodes. - fn nodes(&self) -> &[reactor::Runner] { + // Returns the internal map of nodes. + fn nodes(&self) -> &HashMap> { &self.nodes } @@ -205,7 +207,7 @@ impl Network { /// gets the job done. async fn shutdown(self) { // Shutdown the sender of every reactor node to ensure the port is open again. - for node in self.nodes.into_iter() { + for (_, node) in self.nodes.into_iter() { node.into_inner().net.shutdown_server().await; } @@ -227,7 +229,7 @@ fn init_logging() -> DefaultGuard { } /// Checks whether or not a given network is completely connected. -fn network_is_complete(nodes: &[reactor::Runner]) -> bool { +fn network_is_complete(nodes: &HashMap>) -> bool { // We need at least one node. if nodes.is_empty() { return false; @@ -235,12 +237,12 @@ fn network_is_complete(nodes: &[reactor::Runner]) -> bool { let expected: HashSet<_> = nodes .iter() - .map(|runner| runner.reactor().net.node_id()) + .map(|(_, runner)| runner.reactor().net.node_id()) .collect(); nodes .iter() - .map(|runner| { + .map(|(_, runner)| { let net = &runner.reactor().net; let mut actual = net.connected_nodes(); From e0617b40823a29b294b937b789891bcb9bd63a5e Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:09:20 +0200 Subject: [PATCH 03/18] Make node creation functions return node id as well as a reference for convenience --- src/components/small_network/test.rs | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index d42db472c7..9a0db3cb98 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -125,7 +125,7 @@ impl Network { } /// Creates a new networking node on the network using the default root node port. - async fn add_node(&mut self) -> anyhow::Result<&mut reactor::Runner> { + async fn add_node(&mut self) -> anyhow::Result<(NodeId, &mut reactor::Runner)> { self.add_node_with_config(small_network::Config::default_on_port(TEST_ROOT_NODE_PORT)) .await } @@ -134,14 +134,16 @@ impl Network { async fn add_node_with_config( &mut self, cfg: small_network::Config, - ) -> anyhow::Result<&mut reactor::Runner> { + ) -> anyhow::Result<(NodeId, &mut reactor::Runner)> { let runner: reactor::Runner = reactor::Runner::new(cfg).await?; let node_id = runner.reactor().net.node_id(); self.nodes.insert(node_id, runner); - self.nodes - .get_mut(&node_id) - .ok_or_else(|| anyhow::anyhow!("node mysteriously disappeared, this should not happen")) + let node_ref = self.nodes.get_mut(&node_id).ok_or_else(|| { + anyhow::anyhow!("node mysteriously disappeared, this should not happen") + })?; + + Ok((node_id, node_ref)) } /// Crank all runners once, returning the number of events processed. From 6193f58c83bad17d211378be0cd7278764d53973 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:24:20 +0200 Subject: [PATCH 04/18] Make `init_logging` actually initialize logging again --- src/components/small_network/test.rs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 9a0db3cb98..01e1fd2d82 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -24,7 +24,7 @@ use crate::{ }; use pnet::datalink; use tokio::time::{timeout, Timeout}; -use tracing::{debug, dispatcher::DefaultGuard, info}; +use tracing::{debug, info}; /// Time interval for which to poll an observed testing network when no events have occurred. const POLL_INTERVAL: Duration = Duration::from_millis(10); @@ -220,14 +220,16 @@ impl Network { /// Sets up logging for testing. /// /// Returns a guard that when dropped out of scope, clears the logger again. -fn init_logging() -> DefaultGuard { +fn init_logging() { // TODO: Write logs to file by default for each test. - tracing::subscriber::set_default( + tracing::subscriber::set_global_default( tracing_subscriber::fmt() .with_writer(io::stderr) .with_env_filter(EnvFilter::from_default_env()) .finish(), ) + // Ignore the return value, setting the global subscriber will fail if `init_logging` has been called before, which we don't care about. + .ok(); } /// Checks whether or not a given network is completely connected. From 02fb456c6f338823c9e741dbf29655d6451be4b3 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:24:34 +0200 Subject: [PATCH 05/18] Initialize logging `bind_to_real_network_interface` test --- src/components/small_network/test.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 01e1fd2d82..fa7b968106 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -322,6 +322,8 @@ async fn run_two_node_network_five_times() { /// Very unlikely to ever fail on a real machine. #[tokio::test] async fn bind_to_real_network_interface() { + init_logging(); + let iface = datalink::interfaces() .into_iter() .find(|net| !net.ips.is_empty() && !net.ips.iter().any(|ip| ip.ip().is_loopback())) From 022009d381ebc7ce7c6ce1324e5b0df55869f42d Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 20:42:23 +0200 Subject: [PATCH 06/18] Make logging a library module instead of being app only to facilitate reuse in tests --- src/apps/node/cli.rs | 4 ++-- src/apps/node/main.rs | 1 - src/lib.rs | 1 + src/{apps/node => }/logging.rs | 5 ++--- 4 files changed, 5 insertions(+), 6 deletions(-) rename src/{apps/node => }/logging.rs (93%) diff --git a/src/apps/node/cli.rs b/src/apps/node/cli.rs index 1cc822fa37..e49fc577f8 100644 --- a/src/apps/node/cli.rs +++ b/src/apps/node/cli.rs @@ -7,8 +7,8 @@ use std::{io, io::Write, path::PathBuf}; use anyhow::bail; use structopt::StructOpt; -use crate::{config, logging}; -use casperlabs_node::{reactor, tls}; +use crate::config; +use casperlabs_node::{logging, reactor, tls}; // Note: The docstring on `Cli` is the help shown when calling the binary with `--help`. #[derive(Debug, StructOpt)] diff --git a/src/apps/node/main.rs b/src/apps/node/main.rs index 44c54a8895..955348b7b0 100644 --- a/src/apps/node/main.rs +++ b/src/apps/node/main.rs @@ -5,7 +5,6 @@ mod cli; pub mod config; -pub mod logging; use structopt::StructOpt; diff --git a/src/lib.rs b/src/lib.rs index 53fbfcc3bb..337a084ed2 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -25,6 +25,7 @@ mod components; pub mod crypto; pub mod effect; +pub mod logging; pub mod reactor; pub mod tls; pub mod types; diff --git a/src/apps/node/logging.rs b/src/logging.rs similarity index 93% rename from src/apps/node/logging.rs rename to src/logging.rs index 26a35777c1..df19122808 100644 --- a/src/apps/node/logging.rs +++ b/src/logging.rs @@ -104,10 +104,9 @@ where } } -/// Initializes logging system based on settings in configuration. +/// Initializes the logging system. /// -/// Will setup logging as described in this configuration for the whole application. This -/// function should only be called once during the lifetime of the application. +/// This function should only be called once during the lifetime of the application. pub fn init() -> anyhow::Result<()> { let formatter = format::debug_fn(|writer, field, value| { if field.name() == "message" { From a21ef4a628c132998cda8078d4f751c06d1cda54 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 21:56:27 +0200 Subject: [PATCH 07/18] Track a runner/reactor id in the reactor runner --- src/apps/node/cli.rs | 3 ++- src/components/small_network/test.rs | 8 +++++++- src/reactor.rs | 30 +++++++++++++++++++++------- 3 files changed, 32 insertions(+), 9 deletions(-) diff --git a/src/apps/node/cli.rs b/src/apps/node/cli.rs index e49fc577f8..f313b7718d 100644 --- a/src/apps/node/cli.rs +++ b/src/apps/node/cli.rs @@ -66,7 +66,8 @@ impl Cli { .transpose()? .unwrap_or_default(); - let mut runner = reactor::Runner::::new(cfg).await?; + let mut runner = + reactor::Runner::::new(0, cfg).await?; runner.run().await; } } diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index fa7b968106..6fce9882c5 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -113,6 +113,7 @@ impl Display for Message { /// cranking until a condition has been reached. #[derive(Debug)] struct Network { + node_count: usize, nodes: HashMap>, } @@ -120,6 +121,7 @@ impl Network { /// Creates a new network. fn new() -> Self { Network { + node_count: 0, nodes: HashMap::new(), } } @@ -135,7 +137,11 @@ impl Network { &mut self, cfg: small_network::Config, ) -> anyhow::Result<(NodeId, &mut reactor::Runner)> { - let runner: reactor::Runner = reactor::Runner::new(cfg).await?; + let id = self.node_count; + + let runner: reactor::Runner = reactor::Runner::new(id, cfg).await?; + self.node_count += 1; + let node_id = runner.reactor().net.node_id(); self.nodes.insert(node_id, runner); diff --git a/src/reactor.rs b/src/reactor.rs index 289411e8e4..9bc2ab4809 100644 --- a/src/reactor.rs +++ b/src/reactor.rs @@ -35,7 +35,7 @@ use std::{ }; use futures::FutureExt; -use tracing::{debug, info, trace, warn}; +use tracing::{debug, info, trace, warn, Span}; use crate::{ effect::{Effect, EffectBuilder, Multiple}, @@ -147,6 +147,9 @@ where /// The reactor instance itself. reactor: R, + + /// The logging span indicating which reactor we are in. + span: Span, } impl Runner @@ -154,18 +157,24 @@ where R: Reactor, { /// Creates a new runner from a given configuration. + /// + /// The `id` is used to identify the runner during logging when debugging and can be chosen + /// arbitrarily. #[inline] - pub async fn new(cfg: R::Config) -> Result { + pub async fn new(id: usize, cfg: R::Config) -> Result { + // We create a new logging span, ensuring that we can always associate log messages to this + // specific reactor. This is usually only relevant when running multiple reactors, e.g. + // during testing, so we set the log level to `debug` here. + let span = tracing::debug_span!("node", id = id); + let entered = span.enter(); + let event_size = mem::size_of::(); // Check if the event is of a reasonable size. This only emits a runtime warning at startup // right now, since storage size of events is not an issue per se, but copying might be // expensive if events get too large. if event_size > 16 * mem::size_of::() { - warn!( - "event size is {} bytes, consider reducing it or boxing", - event_size - ); + warn!(%event_size, "large event size, consider reducing it or boxing"); } // Create a new event queue for this reactor run. @@ -179,12 +188,19 @@ where info!("reactor main loop is ready"); - Ok(Runner { scheduler, reactor }) + drop(entered); + Ok(Runner { + scheduler, + reactor, + span, + }) } /// Processes a single event on the event queue. #[inline] pub async fn crank(&mut self) { + let _enter = self.span.enter(); + let event_queue = EventQueueHandle::new(self.scheduler); let effect_builder = EffectBuilder::new(event_queue); From ae3498cf89ff6653ddcc90dafdee0e611800bc8d Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 22:27:16 +0200 Subject: [PATCH 08/18] Instead of storing an ID, store node identification on logging span of reactor --- src/apps/node/cli.rs | 3 +-- src/components/small_network.rs | 1 - src/components/small_network/test.rs | 8 ++++++-- src/reactor.rs | 21 ++++++++++++++++++--- src/reactor/validator.rs | 4 ++++ 5 files changed, 29 insertions(+), 8 deletions(-) diff --git a/src/apps/node/cli.rs b/src/apps/node/cli.rs index f313b7718d..e49fc577f8 100644 --- a/src/apps/node/cli.rs +++ b/src/apps/node/cli.rs @@ -66,8 +66,7 @@ impl Cli { .transpose()? .unwrap_or_default(); - let mut runner = - reactor::Runner::::new(0, cfg).await?; + let mut runner = reactor::Runner::::new(cfg).await?; runner.run().await; } } diff --git a/src/components/small_network.rs b/src/components/small_network.rs index 6ee92fd3ce..8f58b133f2 100644 --- a/src/components/small_network.rs +++ b/src/components/small_network.rs @@ -471,7 +471,6 @@ where } /// Returns the node id of this network node. - #[cfg(test)] pub(crate) fn node_id(&self) -> NodeId { self.cert.public_key_fingerprint() } diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 6fce9882c5..0ce535ff59 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -24,7 +24,7 @@ use crate::{ }; use pnet::datalink; use tokio::time::{timeout, Timeout}; -use tracing::{debug, info}; +use tracing::{debug, info, Span}; /// Time interval for which to poll an observed testing network when no events have occurred. const POLL_INTERVAL: Duration = Duration::from_millis(10); @@ -82,9 +82,13 @@ impl Reactor for TestReactor { fn new( cfg: Self::Config, event_queue: EventQueueHandle, + span: &Span, ) -> reactor::Result<(Self, Multiple>)> { let (net, effects) = SmallNetwork::new(event_queue, cfg)?; + let node_id = net.node_id(); + span.record("id", &tracing::field::display(node_id)); + Ok(( TestReactor { net }, reactor::wrap_effects(Event::SmallNet, effects), @@ -139,7 +143,7 @@ impl Network { ) -> anyhow::Result<(NodeId, &mut reactor::Runner)> { let id = self.node_count; - let runner: reactor::Runner = reactor::Runner::new(id, cfg).await?; + let runner: reactor::Runner = reactor::Runner::new(cfg).await?; self.node_count += 1; let node_id = runner.reactor().net.node_id(); diff --git a/src/reactor.rs b/src/reactor.rs index 9bc2ab4809..15047ef602 100644 --- a/src/reactor.rs +++ b/src/reactor.rs @@ -115,10 +115,14 @@ pub trait Reactor: Sized { /// This method creates the full state, which consists of all components, and returns a reactor /// instances along with the effects the components generated upon instantiation. /// + /// The function is also given an instance to the tracing span used, this enables it to set up + /// tracing fields like `id` to set an ID for the reactor if desired. + /// /// If any instantiation fails, an error is returned. fn new( cfg: Self::Config, event_queue: EventQueueHandle, + span: &Span, ) -> Result<(Self, Multiple>)>; } @@ -150,6 +154,9 @@ where /// The logging span indicating which reactor we are in. span: Span, + + /// Counter for events, to aid tracing. + event_count: usize, } impl Runner @@ -161,11 +168,11 @@ where /// The `id` is used to identify the runner during logging when debugging and can be chosen /// arbitrarily. #[inline] - pub async fn new(id: usize, cfg: R::Config) -> Result { + pub async fn new(cfg: R::Config) -> Result { // We create a new logging span, ensuring that we can always associate log messages to this // specific reactor. This is usually only relevant when running multiple reactors, e.g. // during testing, so we set the log level to `debug` here. - let span = tracing::debug_span!("node", id = id); + let mut span = tracing::debug_span!("node", id = tracing::field::Empty); let entered = span.enter(); let event_size = mem::size_of::(); @@ -181,7 +188,8 @@ where let scheduler = utils::leak(Scheduler::new(QueueKind::weights())); let event_queue = EventQueueHandle::new(scheduler); - let (reactor, initial_effects) = R::new(cfg, event_queue)?; + + let (reactor, initial_effects) = R::new(cfg, event_queue, &span)?; // Run all effects from component instantiation. process_effects(scheduler, initial_effects).await; @@ -193,6 +201,7 @@ where scheduler, reactor, span, + event_count: 0, }) } @@ -201,6 +210,12 @@ where pub async fn crank(&mut self) { let _enter = self.span.enter(); + // Create another span for tracing the processing of one event. + let crank_span = tracing::debug_span!("crank", ev = self.event_count); + let _inner_enter = crank_span.enter(); + + self.event_count += 1; + let event_queue = EventQueueHandle::new(self.scheduler); let effect_builder = EffectBuilder::new(event_queue); diff --git a/src/reactor/validator.rs b/src/reactor/validator.rs index e0b7aebabe..7e10389757 100644 --- a/src/reactor/validator.rs +++ b/src/reactor/validator.rs @@ -10,6 +10,7 @@ use derive_more::From; use rand::SeedableRng; use rand_chacha::ChaCha20Rng; use serde::{Deserialize, Serialize}; +use tracing::Span; use crate::{ components::{ @@ -138,9 +139,12 @@ impl reactor::Reactor for Reactor { fn new( cfg: Self::Config, event_queue: EventQueueHandle, + span: &Span, ) -> Result<(Self, Multiple>)> { let effect_builder = EffectBuilder::new(event_queue); let (net, net_effects) = SmallNetwork::new(event_queue, cfg.validator_net)?; + span.record("id", &tracing::field::display(net.node_id())); + let (pinger, pinger_effects) = Pinger::new(effect_builder); let storage = Storage::new(cfg.storage)?; let (api_server, api_server_effects) = ApiServer::new(cfg.http_server, effect_builder); From 9f66654ea67129f29b40136c9bfd2a11252b7d44 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 22:28:20 +0200 Subject: [PATCH 09/18] Use actual node app logging in tests --- src/components/small_network/test.rs | 13 ++++--------- 1 file changed, 4 insertions(+), 9 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 0ce535ff59..6e138ea7c6 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -14,11 +14,11 @@ use derive_more::From; use futures::{future::join_all, Future}; use serde::{Deserialize, Serialize}; use small_network::NodeId; -use tracing_subscriber::{self, EnvFilter}; use crate::{ components::Component, effect::{announcements::NetworkAnnouncement, Effect, EffectBuilder, Multiple}, + logging, reactor::{self, EventQueueHandle, Reactor}, small_network::{self, SmallNetwork}, }; @@ -232,14 +232,9 @@ impl Network { /// Returns a guard that when dropped out of scope, clears the logger again. fn init_logging() { // TODO: Write logs to file by default for each test. - tracing::subscriber::set_global_default( - tracing_subscriber::fmt() - .with_writer(io::stderr) - .with_env_filter(EnvFilter::from_default_env()) - .finish(), - ) - // Ignore the return value, setting the global subscriber will fail if `init_logging` has been called before, which we don't care about. - .ok(); + logging::init() + // Ignore the return value, setting the global subscriber will fail if `init_logging` has been called before, which we don't care about. + .ok(); } /// Checks whether or not a given network is completely connected. From d98772e6d91abaa33de7e546cc2e807c2a447f01 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 22:29:12 +0200 Subject: [PATCH 10/18] Remove unnecessary `mut` qualifier --- src/reactor.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/reactor.rs b/src/reactor.rs index 15047ef602..776f03cdbf 100644 --- a/src/reactor.rs +++ b/src/reactor.rs @@ -172,7 +172,7 @@ where // We create a new logging span, ensuring that we can always associate log messages to this // specific reactor. This is usually only relevant when running multiple reactors, e.g. // during testing, so we set the log level to `debug` here. - let mut span = tracing::debug_span!("node", id = tracing::field::Empty); + let span = tracing::debug_span!("node", id = tracing::field::Empty); let entered = span.enter(); let event_size = mem::size_of::(); From ae0e32b9c6889c397a8b18b94243b37aafcc7812 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Sat, 20 Jun 2020 22:40:39 +0200 Subject: [PATCH 11/18] Store a `server_span` for the server background task --- src/components/small_network.rs | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/components/small_network.rs b/src/components/small_network.rs index 8f58b133f2..ee8a9cdbd1 100644 --- a/src/components/small_network.rs +++ b/src/components/small_network.rs @@ -80,7 +80,7 @@ use tokio::{ use tokio_openssl::SslStream; use tokio_serde::{formats::SymmetricalMessagePack, SymmetricallyFramed}; use tokio_util::codec::{Framed, LengthDelimitedCodec}; -use tracing::{debug, error, info, warn}; +use tracing::{debug, error, info, warn, Span}; pub(crate) use self::{endpoint::Endpoint, event::Event, message::Message}; use self::{endpoint::EndpointUpdate, error::Result}; @@ -139,6 +139,11 @@ where event_queue: EventQueueHandle, cfg: Config, ) -> Result<(SmallNetwork, Multiple>>)> { + let span = tracing::debug_span!("net"); + let _enter = span.enter(); + + let server_span = tracing::info_span!("server"); + // First, we load or generate the TLS keys. let (cert, private_key) = match (&cfg.cert, &cfg.private_key) { // We're given a cert_file and a private_key file. Just load them, additional checking @@ -177,6 +182,7 @@ where event_queue, tokio::net::TcpListener::from_std(listener).map_err(Error::ListenerConversion)?, server_shutdown_receiver, + server_span, )); let model = SmallNetwork { @@ -670,9 +676,12 @@ async fn server_task( event_queue: EventQueueHandle, mut listener: tokio::net::TcpListener, shutdown: oneshot::Receiver<()>, + span: Span, ) where REv: From>, { + let _enter = span.enter(); + // The server task is a bit tricky, since it has to wait on incoming connections while at the // same time shut down if the networking component is dropped, otherwise the TCP socket will // stay open, preventing reuse. From f40fbef26a0169158c5c1629a3a6399e9e77e813 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Tue, 30 Jun 2020 10:29:32 +0200 Subject: [PATCH 12/18] Remove unused code and imports in `small_net` tests --- src/components/small_network/test.rs | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 6e138ea7c6..5cc845c5d7 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -6,7 +6,6 @@ use std::{ collections::{HashMap, HashSet}, fmt::{self, Debug, Display, Formatter}, - io, time::Duration, }; @@ -141,8 +140,6 @@ impl Network { &mut self, cfg: small_network::Config, ) -> anyhow::Result<(NodeId, &mut reactor::Runner)> { - let id = self.node_count; - let runner: reactor::Runner = reactor::Runner::new(cfg).await?; self.node_count += 1; From 81e47e267a847adfc345672ac4d034fbf5757581 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann <63730123+marc-casperlabs@users.noreply.github.com> Date: Tue, 30 Jun 2020 13:21:35 +0200 Subject: [PATCH 13/18] Cleanup imports as suggested Co-authored-by: Fraser Hutchison <190532+Fraser999@users.noreply.github.com> --- src/components/small_network/test.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 5cc845c5d7..6ec326be89 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -23,7 +23,7 @@ use crate::{ }; use pnet::datalink; use tokio::time::{timeout, Timeout}; -use tracing::{debug, info, Span}; +use tracing::{debug, field, info, Span}; /// Time interval for which to poll an observed testing network when no events have occurred. const POLL_INTERVAL: Duration = Duration::from_millis(10); @@ -86,7 +86,7 @@ impl Reactor for TestReactor { let (net, effects) = SmallNetwork::new(event_queue, cfg)?; let node_id = net.node_id(); - span.record("id", &tracing::field::display(node_id)); + span.record("id", &field::display(node_id)); Ok(( TestReactor { net }, From 32f15400ced34f445aa4b99a316d6562699fc4f6 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann <63730123+marc-casperlabs@users.noreply.github.com> Date: Tue, 30 Jun 2020 13:22:12 +0200 Subject: [PATCH 14/18] Fix formatting in docstring Co-authored-by: Fraser Hutchison <190532+Fraser999@users.noreply.github.com> --- src/components/small_network/test.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 6ec326be89..b65daec432 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -230,7 +230,8 @@ impl Network { fn init_logging() { // TODO: Write logs to file by default for each test. logging::init() - // Ignore the return value, setting the global subscriber will fail if `init_logging` has been called before, which we don't care about. + // Ignore the return value, setting the global subscriber will fail if `init_logging` has + // been called before, which we don't care about. .ok(); } From 525e5632c10ccb10e4594c27d08c016c4d31045c Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Tue, 30 Jun 2020 13:25:29 +0200 Subject: [PATCH 15/18] Be more elaborate in documentation on logging init --- src/logging.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/logging.rs b/src/logging.rs index df19122808..2c7ed2e00f 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -106,7 +106,10 @@ where /// Initializes the logging system. /// -/// This function should only be called once during the lifetime of the application. +/// This function should only be called once during the lifetime of the application. Do not call +/// this outside of the application or testing code, the installed logger is global. +/// +/// See the `README.md` for hints on how to configure logging at runtime. pub fn init() -> anyhow::Result<()> { let formatter = format::debug_fn(|writer, field, value| { if field.name() == "message" { From dfed5d51457653947d70fadffeb391642ae7437e Mon Sep 17 00:00:00 2001 From: Marc Brinkmann <63730123+marc-casperlabs@users.noreply.github.com> Date: Tue, 30 Jun 2020 13:27:08 +0200 Subject: [PATCH 16/18] Simplify iterator and subsequent map in `small_network::test` Co-authored-by: Andreas Fackler --- src/components/small_network/test.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index b65daec432..4b4f90ef1e 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -155,7 +155,7 @@ impl Network { /// Crank all runners once, returning the number of events processed. async fn crank_all(&mut self) -> usize { - join_all(self.nodes.iter_mut().map(|(_, runner)| runner.try_crank())) + join_all(self.nodes.values_mut().map(Runner::try_crank)) .await .into_iter() .filter(|opt| opt.is_some()) From 081c8a88238e3e78183e86b259aa0e85b2e9db58 Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Tue, 30 Jun 2020 13:34:59 +0200 Subject: [PATCH 17/18] Fix typo in `try_crank` call --- src/components/small_network/test.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 4b4f90ef1e..881529b148 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -155,7 +155,7 @@ impl Network { /// Crank all runners once, returning the number of events processed. async fn crank_all(&mut self) -> usize { - join_all(self.nodes.values_mut().map(Runner::try_crank)) + join_all(self.nodes.values_mut().map(reactor::Runner::try_crank)) .await .into_iter() .filter(|opt| opt.is_some()) From 546651fc651c0282f42c317c40a5776970708a1e Mon Sep 17 00:00:00 2001 From: Marc Brinkmann Date: Tue, 30 Jun 2020 13:36:19 +0200 Subject: [PATCH 18/18] Cleanup node insertion logic in `small_net` test network --- src/components/small_network/test.rs | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/src/components/small_network/test.rs b/src/components/small_network/test.rs index 881529b148..92e4bc8736 100644 --- a/src/components/small_network/test.rs +++ b/src/components/small_network/test.rs @@ -4,7 +4,7 @@ //! instances of `small_net` arranged in a network. use std::{ - collections::{HashMap, HashSet}, + collections::{hash_map::Entry, HashMap, HashSet}, fmt::{self, Debug, Display, Formatter}, time::Duration, }; @@ -144,11 +144,15 @@ impl Network { self.node_count += 1; let node_id = runner.reactor().net.node_id(); - self.nodes.insert(node_id, runner); - let node_ref = self.nodes.get_mut(&node_id).ok_or_else(|| { - anyhow::anyhow!("node mysteriously disappeared, this should not happen") - })?; + let node_ref = match self.nodes.entry(node_id) { + Entry::Occupied(_) => { + // This happens in the event of the extremely unlikely hash collision, or if the + // node ID was set manually. + anyhow::bail!("trying to insert a duplicate node {}", node_id) + } + Entry::Vacant(entry) => entry.insert(runner), + }; Ok((node_id, node_ref)) }