Show simulation time in logs

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",
 ]

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

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<Mutex<Option<Arc<World>>>>,
+}
+
+impl Default for SimClock {
+    fn default() -> Self {
+        SimClock {
+            world_ptr: Arc::new(Mutex::new(None)),
+        }
+    }
+}
+
+impl SimClock {
+    pub fn set_world(&self, world: Arc<World>) {
+        *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
+}

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;

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<SimClock>,
 }
 
 impl TestConfig {
-    fn new() -> Self {
+    fn new(clock: Option<SimClock>) -> 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);
 

libs/walproposer/test.c

@@ -81,6 +81,7 @@ void MyContextInit() {
             exit(1);
 
         log_min_messages = LOG;
+        Log_line_prefix = "[%p] ";
 
         InitializeMaxBackends();
         ChangeToDataDir();