From 33f7877d1bfe3bcf44974563fa1a51b868de72b1 Mon Sep 17 00:00:00 2001 From: Arthur Petukhovsky Date: Wed, 23 Aug 2023 10:10:11 +0000 Subject: [PATCH] Show simulation time in logs --- Cargo.lock | 3 ++ libs/walproposer/Cargo.toml | 3 ++ libs/walproposer/src/simtest/log.rs | 49 +++++++++++++++++++++++++++ libs/walproposer/src/simtest/mod.rs | 1 + libs/walproposer/src/simtest/wp_sk.rs | 32 +++++++++-------- libs/walproposer/test.c | 1 + 6 files changed, 74 insertions(+), 15 deletions(-) create mode 100644 libs/walproposer/src/simtest/log.rs diff --git a/Cargo.lock b/Cargo.lock index 6124c7fb1e..ab26a84e9d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4642,6 +4642,7 @@ name = "walproposer" version = "0.1.0" dependencies = [ "anyhow", + "atty", "bindgen", "byteorder", "bytes", @@ -4661,6 +4662,8 @@ dependencies = [ "safekeeper", "serde", "thiserror", + "tracing", + "tracing-subscriber", "utils", "workspace_hack", ] diff --git a/libs/walproposer/Cargo.toml b/libs/walproposer/Cargo.toml index cb7b84bc11..3ac7080260 100644 --- a/libs/walproposer/Cargo.toml +++ b/libs/walproposer/Cargo.toml @@ -5,6 +5,7 @@ edition.workspace = true license.workspace = true [dependencies] +atty.workspace = true rand.workspace = true regex.workspace = true bytes.workspace = true @@ -17,6 +18,8 @@ log.workspace = true libc.workspace = true memoffset.workspace = true thiserror.workspace = true +tracing.workspace = true +tracing-subscriber = { workspace = true, features = ["json"] } serde.workspace = true utils.workspace = true safekeeper.workspace = true diff --git a/libs/walproposer/src/simtest/log.rs b/libs/walproposer/src/simtest/log.rs new file mode 100644 index 0000000000..f04e56f968 --- /dev/null +++ b/libs/walproposer/src/simtest/log.rs @@ -0,0 +1,49 @@ +use std::{sync::Arc, fmt}; + +use safekeeper::simlib::{world::World, sync::Mutex}; +use tracing_subscriber::fmt::{time::FormatTime, format::Writer}; + + +#[derive(Clone)] +pub struct SimClock { + world_ptr: Arc>>>, +} + +impl Default for SimClock { + fn default() -> Self { + SimClock { + world_ptr: Arc::new(Mutex::new(None)), + } + } +} + +impl SimClock { + pub fn set_world(&self, world: Arc) { + *self.world_ptr.lock() = Some(world); + } +} + +impl FormatTime for SimClock { + fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result { + let world = self.world_ptr.lock().clone(); + + if let Some(world) = world { + let now = world.now(); + write!(w, "[{}]", now) + } else { + write!(w, "[?]") + } + } +} + +pub fn init_logger() -> SimClock { + let clock = SimClock::default(); + let base_logger = tracing_subscriber::fmt() + .with_target(false) + .with_timer(clock.clone()) + .with_ansi(true) + .with_writer(std::io::stdout); + base_logger.init(); + + clock +} diff --git a/libs/walproposer/src/simtest/mod.rs b/libs/walproposer/src/simtest/mod.rs index 0776a9cdfc..81b0f37ff1 100644 --- a/libs/walproposer/src/simtest/mod.rs +++ b/libs/walproposer/src/simtest/mod.rs @@ -7,3 +7,4 @@ pub mod wp_sk; pub mod disk; pub mod safekeeper; pub mod storage; +pub mod log; diff --git a/libs/walproposer/src/simtest/wp_sk.rs b/libs/walproposer/src/simtest/wp_sk.rs index b6583bf214..63a8ed8183 100644 --- a/libs/walproposer/src/simtest/wp_sk.rs +++ b/libs/walproposer/src/simtest/wp_sk.rs @@ -6,7 +6,7 @@ use safekeeper::simlib::{ world::World, world::{Node, NodeEvent}, }; -use utils::{id::TenantTimelineId, logging, lsn::Lsn}; +use utils::{id::TenantTimelineId, lsn::Lsn}; use crate::{ bindings::{ @@ -15,7 +15,7 @@ use crate::{ MyInsertRecord, WalProposerCleanup, WalProposerRust, }, c_context, - simtest::safekeeper::run_server, + simtest::{safekeeper::run_server, log::{SimClock, init_logger}}, }; use super::disk::Disk; @@ -57,10 +57,11 @@ impl SkNode { struct TestConfig { network: NetworkOptions, timeout: u64, + clock: Option, } impl TestConfig { - fn new() -> Self { + fn new(clock: Option) -> Self { Self { network: NetworkOptions { timeout: Some(2000), @@ -76,6 +77,7 @@ impl TestConfig { }, }, timeout: 1_000 * 10, + clock, } } @@ -87,6 +89,10 @@ impl TestConfig { )); world.register_world(); + if let Some(clock) = &self.clock { + clock.set_world(world.clone()); + } + let servers = [ SkNode::new(world.new_node()), SkNode::new(world.new_node()), @@ -304,9 +310,8 @@ impl WalProposer { #[test] fn sync_empty_safekeepers() { - logging::init(logging::LogFormat::Plain).unwrap(); - - let config = TestConfig::new(); + let clock = init_logger(); + let mut config = TestConfig::new(Some(clock)); let test = config.start(1337); let lsn = test.sync_safekeepers().unwrap(); @@ -320,9 +325,8 @@ fn sync_empty_safekeepers() { #[test] fn run_walproposer_generate_wal() { - logging::init(logging::LogFormat::Plain).unwrap(); - - let mut config = TestConfig::new(); + let clock = init_logger(); + let mut config = TestConfig::new(Some(clock)); // config.network.timeout = Some(250); let test = config.start(1337); @@ -343,9 +347,8 @@ fn run_walproposer_generate_wal() { #[test] fn crash_safekeeper() { - logging::init(logging::LogFormat::Plain).unwrap(); - - let mut config = TestConfig::new(); + let clock = init_logger(); + let mut config = TestConfig::new(Some(clock)); // config.network.timeout = Some(250); let test = config.start(1337); @@ -373,9 +376,8 @@ fn crash_safekeeper() { #[test] fn test_simple_restart() { - logging::init(logging::LogFormat::Plain).unwrap(); - - let mut config = TestConfig::new(); + let clock = init_logger(); + let mut config = TestConfig::new(Some(clock)); // config.network.timeout = Some(250); let test = config.start(1337); diff --git a/libs/walproposer/test.c b/libs/walproposer/test.c index ab8093b97f..a32ff2124a 100644 --- a/libs/walproposer/test.c +++ b/libs/walproposer/test.c @@ -81,6 +81,7 @@ void MyContextInit() { exit(1); log_min_messages = LOG; + Log_line_prefix = "[%p] "; InitializeMaxBackends(); ChangeToDataDir();