Add timestamp to module logs (#641)

* Add timestamp to module logs

* Update tests

crates/cli/Cargo.toml

@@ -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/src/subcommands/logs.rs

@@ -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,10 @@ 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 {
+            out.set_color(ColorSpec::new().set_dimmed(true))?;
+            write!(out, "{ts:?} ")?;
+        }
         let mut color = ColorSpec::new();
         let level = match record.level {
             LogLevel::Error => {

crates/core/Cargo.toml

@@ -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/src/database_logger.rs

@@ -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/host/wasm_common/module_host_actor.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/wasmtime/wasm_instance_env.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,

test/tests/connect-disconnect-from-cli.sh

@@ -36,6 +36,6 @@ IDENT="$(grep "reated new database" "$TEST_OUT" | awk 'NF>1{print $NF}')"
 
 run_test cargo run call "$IDENT" say_hello
 run_test cargo run logs "$IDENT"
-[ ' _connect called' == "$(grep '_connect called' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' disconnect called' == "$(grep 'disconnect called' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, World!' == "$(grep 'Hello, World!' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' _connect called' == "$(grep '_connect called' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' disconnect called' == "$(grep 'disconnect called' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, World!' == "$(grep 'Hello, World!' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]

test/tests/filtering.sh

@@ -170,33 +170,33 @@ run_test cargo run call "$IDENT" insert_person 64 Bob b2
 # Find a person who is there.
 run_test cargo run call "$IDENT" find_person 23
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE FOUND: id 23: Alice' == "$(grep 'UNIQUE FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE FOUND: id 23: Alice' == "$(grep 'UNIQUE FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Find persons with the same name.
 run_test cargo run call "$IDENT" find_person_by_name Bob
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE FOUND: id 42: Bob aka bo' == "$(grep 'UNIQUE FOUND: id 42' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' UNIQUE FOUND: id 64: Bob aka b2' == "$(grep 'UNIQUE FOUND: id 64' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE FOUND: id 42: Bob aka bo' == "$(grep 'UNIQUE FOUND: id 42' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' UNIQUE FOUND: id 64: Bob aka b2' == "$(grep 'UNIQUE FOUND: id 64' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Fail to find a person who is not there.
 run_test cargo run call "$IDENT" find_person 43
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE NOT FOUND: id 43' == "$(grep 'UNIQUE NOT FOUND: id 43' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE NOT FOUND: id 43' == "$(grep 'UNIQUE NOT FOUND: id 43' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Find a person by nickname.
 run_test cargo run call "$IDENT" find_person_by_nick al
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE FOUND: id 23: al' == "$(grep 'UNIQUE FOUND: id 23: al' "$TEST_OUT" | tail -n4 | cut -d: -f4-)" ]
+[ ' UNIQUE FOUND: id 23: al' == "$(grep 'UNIQUE FOUND: id 23: al' "$TEST_OUT" | tail -n4 | cut -d: -f6-)" ]
 
 # Remove a person, and then fail to find them.
 run_test cargo run call "$IDENT" delete_person 23
 run_test cargo run call "$IDENT" find_person 23
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE NOT FOUND: id 23' == "$(grep 'UNIQUE NOT FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE NOT FOUND: id 23' == "$(grep 'UNIQUE NOT FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 # Also fail by nickname
 run_test cargo run call "$IDENT" find_person_by_nick al
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE NOT FOUND: nick al' == "$(grep 'UNIQUE NOT FOUND: nick al' "$TEST_OUT" | tail -n4 | cut -d: -f4-)" ]
+[ ' UNIQUE NOT FOUND: nick al' == "$(grep 'UNIQUE NOT FOUND: nick al' "$TEST_OUT" | tail -n4 | cut -d: -f6-)" ]
 
 # Add some nonunique people.
 run_test cargo run call "$IDENT" insert_nonunique_person 23 Alice true
@@ -205,29 +205,29 @@ run_test cargo run call "$IDENT" insert_nonunique_person 42 Bob true
 # Find a nonunique person who is there.
 run_test cargo run call "$IDENT" find_nonunique_person 23
 run_test cargo run logs "$IDENT" 100
-[ ' NONUNIQUE FOUND: id 23: Alice' == "$(grep 'NONUNIQUE FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' NONUNIQUE FOUND: id 23: Alice' == "$(grep 'NONUNIQUE FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Fail to find a nonunique person who is not there.
 run_test cargo run call "$IDENT" find_nonunique_person 43
 run_test cargo run logs "$IDENT" 100
-[ '' == "$(grep 'NONUNIQUE NOT FOUND: id 43' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ '' == "$(grep 'NONUNIQUE NOT FOUND: id 43' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Insert a non-human, then find humans, then find non-humans
 run_test cargo run call "$IDENT" insert_nonunique_person 64 Jibbitty false
 run_test cargo run call "$IDENT" find_nonunique_humans
 run_test cargo run logs "$IDENT" 100
-[ ' HUMAN FOUND: id 23: Alice' == "$(grep 'HUMAN FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' HUMAN FOUND: id 42: Bob' == "$(grep 'HUMAN FOUND: id 42' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' HUMAN FOUND: id 23: Alice' == "$(grep 'HUMAN FOUND: id 23' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' HUMAN FOUND: id 42: Bob' == "$(grep 'HUMAN FOUND: id 42' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 run_test cargo run call "$IDENT" find_nonunique_non_humans
 run_test cargo run logs "$IDENT" 100
-[ ' NON-HUMAN FOUND: id 64: Jibbitty' == "$(grep 'NON-HUMAN FOUND: id 64' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' NON-HUMAN FOUND: id 64: Jibbitty' == "$(grep 'NON-HUMAN FOUND: id 64' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Add another person with the same id, and find them both.
 run_test cargo run call "$IDENT" insert_nonunique_person 23 Claire true
 run_test cargo run call "$IDENT" find_nonunique_person 23
 run_test cargo run logs "$IDENT" 2
-[ ' NONUNIQUE FOUND: id 23: Alice' == "$(grep 'NONUNIQUE FOUND: id 23: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' NONUNIQUE FOUND: id 23: Claire' == "$(grep 'NONUNIQUE FOUND: id 23: Claire' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' NONUNIQUE FOUND: id 23: Alice' == "$(grep 'NONUNIQUE FOUND: id 23: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' NONUNIQUE FOUND: id 23: Claire' == "$(grep 'NONUNIQUE FOUND: id 23: Claire' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Check for issues with things present in index but not DB
 run_test cargo run call "$IDENT" insert_person 101 Fee fee
@@ -237,7 +237,7 @@ run_test cargo run call "$IDENT" insert_person 104 Fum fum
 run_test cargo run call "$IDENT" delete_person 103
 run_test cargo run call "$IDENT" find_person 104
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE FOUND: id 104: Fum' == "$(grep 'UNIQUE FOUND: id 104: Fum' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE FOUND: id 104: Fum' == "$(grep 'UNIQUE FOUND: id 104: Fum' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # As above, but for non-unique indices: check for consistency between index and DB
 run_test cargo run call "$IDENT" insert_indexed_person 7 James Bond
@@ -259,15 +259,15 @@ run_test cargo run logs "$IDENT" 100
 # run_test cargo run call "$IDENT" insert_nonunique_person 104 Fum
 # run_test cargo run call "$IDENT" find_nonunique_person 104
 # run_test cargo run logs "$IDENT" 100
-# [ ' NONUNIQUE FOUND: id 104: Fum' == "$(grep 'NONUNIQUE FOUND: id 104: Fum' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+# [ ' NONUNIQUE FOUND: id 104: Fum' == "$(grep 'NONUNIQUE FOUND: id 104: Fum' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Filter by Identity
 run_test cargo run call "$IDENT" insert_identified_person 23 Alice
 run_test cargo run call "$IDENT" find_identified_person 23
 run_test cargo run logs "$IDENT" 100
-[ ' IDENTIFIED FOUND: Alice' == "$(grep 'IDENTIFIED FOUND: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' IDENTIFIED FOUND: Alice' == "$(grep 'IDENTIFIED FOUND: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Insert row with unique columns twice should fail
 run_test cargo run call "$IDENT" insert_person_twice 23 Alice al
 run_test cargo run logs "$IDENT" 100
-[ ' UNIQUE CONSTRAINT VIOLATION ERROR: id 23: Alice' == "$(grep 'UNIQUE CONSTRAINT VIOLATION ERROR: id 23: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' UNIQUE CONSTRAINT VIOLATION ERROR: id 23: Alice' == "$(grep 'UNIQUE CONSTRAINT VIOLATION ERROR: id 23: Alice' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]

test/tests/module-nested-op.sh

@@ -61,4 +61,4 @@ run_test cargo run call "$IDENT" create_account 2 Wilson
 run_test cargo run call "$IDENT" add_friend 1 2
 run_test cargo run call "$IDENT" say_friends
 run_test cargo run logs "$IDENT" 100
-[ ' House is friends with Wilson' == "$(grep 'House' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' House is friends with Wilson' == "$(grep 'House' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]

test/tests/panic.sh

@@ -40,4 +40,4 @@ set -e
 run_test cargo run call "$IDENT" second
 
 run_test cargo run logs "$IDENT"
-[ ' Test Passed' == "$(grep 'Test Passed' "$TEST_OUT" | cut -d: -f4-)" ]
+[ ' Test Passed' == "$(grep 'Test Passed' "$TEST_OUT" | cut -d: -f6-)" ]

test/tests/update-module.sh

@@ -43,10 +43,10 @@ run_test cargo run call "$IDENT" add Julie
 run_test cargo run call "$IDENT" add Samantha
 run_test cargo run call "$IDENT" say_hello
 run_test cargo run logs "$IDENT" 100
-[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
 
 # Unchanged module is ok
 run_test cargo run publish --skip_clippy --project-path "$PROJECT_PATH" "$IDENT"
@@ -91,7 +91,7 @@ EOF
 run_test cargo run publish --skip_clippy --project-path "$PROJECT_PATH" "$IDENT"
 [ "1" == "$(grep -c "Updated database" "$TEST_OUT")" ]
 run_test cargo run logs "$IDENT" 2
-[ ' INDEX ADDED' == "$(grep 'INDEX ADDED' "$TEST_OUT" | tail -n 1 | cut -d: -f4-)" ]
+[ ' INDEX ADDED' == "$(grep 'INDEX ADDED' "$TEST_OUT" | tail -n 1 | cut -d: -f6-)" ]
 
 # Adding a table is ok, and invokes update
 cat > "${PROJECT_PATH}/src/lib.rs" <<EOF
@@ -119,4 +119,4 @@ EOF
 run_test cargo run publish --skip_clippy --project-path "$PROJECT_PATH" "$IDENT"
 [ "1" == "$(grep -c "Updated database" "$TEST_OUT")" ]
 run_test cargo run logs "$IDENT" 2
-[ ' MODULE UPDATED' == "$(grep 'MODULE UPDATED' "$TEST_OUT" | tail -n 1 | cut -d: -f4-)" ]
+[ ' MODULE UPDATED' == "$(grep 'MODULE UPDATED' "$TEST_OUT" | tail -n 1 | cut -d: -f6-)" ]

test/tests/upload-module-1.sh

@@ -40,7 +40,7 @@ run_test cargo run call "$IDENT" add Julie
 run_test cargo run call "$IDENT" add Samantha
 run_test cargo run call "$IDENT" say_hello
 run_test cargo run logs "$IDENT" 100
-[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]

test/tests/zz_docker-restart-module.sh

@@ -48,7 +48,7 @@ run_test cargo run call "$IDENT" add Samantha
 run_test cargo run call "$IDENT" say_hello
 run_test cargo run logs "$IDENT" 100
 
-[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
-[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f4-)" ]
+[ ' Hello, Samantha!' == "$(grep 'Samantha' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Julie!' == "$(grep 'Julie' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, Robert!' == "$(grep 'Robert' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]
+[ ' Hello, World!' == "$(grep 'World' "$TEST_OUT" | tail -n 4 | cut -d: -f6-)" ]

test/tests/zz_docker-restart-sql.sh

@@ -47,10 +47,10 @@ run_test cargo run call "$IDENT" add Samantha
 run_test cargo run call "$IDENT" say_hello
 run_test cargo run logs "$IDENT" 100
 
-[ ' Hello, Samantha!' == "$(tail -n 4 "$TEST_OUT" | grep 'Samantha' | cut -d: -f4-)" ]
-[ ' Hello, Julie!'    == "$(tail -n 4 "$TEST_OUT" | grep 'Julie'    | cut -d: -f4-)" ]
-[ ' Hello, Robert!'   == "$(tail -n 4 "$TEST_OUT" | grep 'Robert'   | cut -d: -f4-)" ]
-[ ' Hello, World!'    == "$(tail -n 4 "$TEST_OUT" | grep 'World'    | cut -d: -f4-)" ]
+[ ' Hello, Samantha!' == "$(tail -n 4 "$TEST_OUT" | grep 'Samantha' | cut -d: -f6-)" ]
+[ ' Hello, Julie!'    == "$(tail -n 4 "$TEST_OUT" | grep 'Julie'    | cut -d: -f6-)" ]
+[ ' Hello, Robert!'   == "$(tail -n 4 "$TEST_OUT" | grep 'Robert'   | cut -d: -f6-)" ]
+[ ' Hello, World!'    == "$(tail -n 4 "$TEST_OUT" | grep 'World'    | cut -d: -f6-)" ]
 
 restart_docker
 run_test cargo run sql "${IDENT}" "SELECT name FROM Person WHERE id = 3"