Add timestamp to module logs

Author: coolreader18

Cargo.lock

@@ -24,6 +24,7 @@ spacetimedb-standalone = { path = "../standalone", version = "0.8.0", optional =
 anyhow.workspace = true
 base64.workspace = true
 cargo_metadata.workspace = true
+chrono.workspace = true
 clap = {workspace = true, features = ["derive", "env", "string"]}
 colored.workspace = true
 convert_case.workspace = true
@@ -43,6 +44,7 @@ reqwest.workspace = true
 rustyline.workspace = true
 serde = { workspace = true, features = ["derive"] }
 serde_json = { workspace = true, features = ["raw_value", "preserve_order"] }
+serde_with = { workspace = true, features = ["chrono_0_4"] }
 slab.workspace = true
 syntect.workspace = true
 tabled.workspace = true

crates/cli/Cargo.toml

@@ -56,8 +56,11 @@ pub enum LogLevel {
     Panic,
 }
 
+#[serde_with::serde_as]
 #[derive(serde::Deserialize)]
 struct Record<'a> {
+    #[serde_as(as = "Option<serde_with::TimestampMicroSeconds>")]
+    ts: Option<chrono::DateTime<chrono::Utc>>, // TODO: remove Option once 0.9 has been out for a while
     level: LogLevel,
     #[serde(borrow)]
     #[allow(unused)] // TODO: format this somehow
@@ -124,6 +127,9 @@ pub async fn exec(mut config: Config, args: &ArgMatches) -> Result<(), anyhow::E
     while rdr.read_line(&mut line).await? != 0 {
         let record = serde_json::from_str::<Record<'_>>(&line)?;
 
+        if let Some(ts) = record.ts {
+            write!(out, "{ts} ")?;
+        }
         let mut color = ColorSpec::new();
         let level = match record.level {
             LogLevel::Error => {

crates/cli/src/subcommands/logs.rs

@@ -31,6 +31,7 @@ backtrace.workspace = true
 base64.workspace = true
 bytes.workspace = true
 bytestring.workspace = true
+chrono.workspace = true
 clap.workspace = true
 crossbeam-channel.workspace = true
 derive_more.workspace = true
@@ -67,7 +68,7 @@ sendgrid.workspace = true
 serde.workspace = true
 serde_json.workspace = true
 serde_path_to_error.workspace = true
-serde_with.workspace = true
+serde_with = { workspace = true, features = ["chrono_0_4"] }
 sha1.workspace = true
 slab.workspace = true
 sled.workspace = true

crates/core/Cargo.toml

@@ -37,8 +37,11 @@ impl From<u8> for LogLevel {
 }
 
 #[serde_with::skip_serializing_none]
+#[serde_with::serde_as]
 #[derive(serde::Serialize, Copy, Clone)]
 pub struct Record<'a> {
+    #[serde_as(as = "serde_with::TimestampMicroSeconds")]
+    pub ts: chrono::DateTime<chrono::Utc>,
     pub target: Option<&'a str>,
     pub filename: Option<&'a str>,
     pub line_number: Option<u32>,
@@ -227,6 +230,7 @@ impl SystemLogger {
 
     fn record(message: &str) -> Record {
         Record {
+            ts: chrono::Utc::now(),
             target: None,
             filename: Some("spacetimedb"),
             line_number: None,

crates/core/src/database_logger.rs

@@ -231,6 +231,7 @@ impl<T: WasmModule> Module for WasmModuleHostActor<T> {
         self.database_instance_context.logger.write(
             log_level,
             &Record {
+                ts: chrono::Utc::now(),
                 target: None,
                 filename: Some("external"),
                 line_number: None,

crates/core/src/host/wasm_common/module_host_actor.rs

@@ -344,6 +344,8 @@ impl WasmInstanceEnv {
             let line_number = (line_number != u32::MAX).then_some(line_number);
 
             let record = Record {
+                // TODO: figure out whether to use walltime now or logical reducer now (env.reducer_start)
+                ts: chrono::Utc::now(),
                 target: target.as_deref(),
                 filename: filename.as_deref(),
                 line_number,
@@ -754,6 +756,7 @@ impl WasmInstanceEnv {
         let message = format!("Timing span {:?}: {:?}", name, elapsed);
 
         let record = Record {
+            ts: chrono::Utc::now(),
             target: None,
             filename: None,
             line_number: None,