Add reducer name to database log records

Author: gefjon

crates/cli/src/subcommands/logs.rs

@@ -61,6 +61,7 @@ pub enum LogLevel {
     Panic,
 }
 
+/// Keep this in sync with `spacetimedb_core::database_logger::Record`.
 #[serde_with::serde_as]
 #[derive(serde::Deserialize)]
 struct Record<'a> {
@@ -74,6 +75,8 @@ struct Record<'a> {
     filename: Option<Cow<'a, str>>,
     line_number: Option<u32>,
     #[serde(borrow)]
+    function: Option<Cow<'a, str>>,
+    #[serde(borrow)]
     message: Cow<'a, str>,
     trace: Option<Vec<BacktraceFrame<'a>>>,
 }
@@ -195,9 +198,19 @@ pub async fn exec(mut config: Config, args: &ArgMatches) -> Result<(), anyhow::E
         out.set_color(&color)?;
         write!(out, "{level:>5}: ")?;
         out.reset()?;
+        let mut need_space = false;
         let dimmed = ColorSpec::new().set_dimmed(true).clone();
+        if let Some(function) = record.function {
+            out.set_color(&dimmed)?;
+            write!(out, "{function}")?;
+            out.reset()?;
+            need_space = true;
+        }
         if let Some(filename) = record.filename {
             out.set_color(&dimmed)?;
+            if need_space {
+                write!(out, " ")?;
+            }
             write!(out, "{filename}")?;
             if let Some(line) = record.line_number {
                 write!(out, ":{line}")?;

crates/core/src/database_logger.rs

@@ -49,12 +49,52 @@ impl From<u8> for LogLevel {
 pub struct Record<'a> {
     #[serde_as(as = "serde_with::TimestampMicroSeconds")]
     pub ts: chrono::DateTime<Utc>,
+    /// Target of the log call (usually source namespace or `mod`).
+    ///
+    /// Provided by the WASM guest as an argument to the `console_log` host function.
+    ///
+    /// The special sentinel value [`Record::SENTINEL_INJECTED_TARGET`]` denotes logs injected by the [`SystemLogger`].
     pub target: Option<&'a str>,
+    /// Filename of the source location of the log call.
+    ///
+    /// Provided by the WASM guest as an argument to the `console_log` host function.
+    ///
+    /// The special sentinel value [`Record::SENTINEL_INJECTED_FILENAME`]` denotes logs injected by the [`SystemLogger`].
     pub filename: Option<&'a str>,
     pub line_number: Option<u32>,
+    /// Which exported function (i.e. reducer) was being called when this message was produced.
+    ///
+    /// Unlike `target`, `filename` and `line_number`, this is not provided by the WASM guest.
+    /// Instead, the `WasmInstanceEnv` remembers what function call is in progress and adds it to the record.
+    ///
+    /// The special sentinel value [`Record::SENTINEL_INJECTED_FUNCTION`] denotes logs injected by the [`SystemLogger`].
+    pub function: Option<&'a str>,
     pub message: &'a str,
 }
 
+impl<'a> Record<'a> {
+    pub const SENTINEL_INJECTED_FUNCTION: Option<&'static str> = Some("__spacetimedb__");
+    pub const SENTINEL_INJECTED_TARGET: Option<&'static str> = Some("__spacetimedb__");
+    pub const SENTINEL_INJECTED_FILENAME: Option<&'static str> = Some("__spacetimedb__");
+
+    /// Create a log `Record` for a system message, not attributed to any reducer or user filename.
+    ///
+    /// The resulting `Record` will draw from [`chrono::Utc::now`] for its timestamp,
+    /// have `line_number: None`,
+    /// and will use [`Self::SENTINEL_INJECTED_FILENAME`], [`Self::SENTINEL_INJECTED_FUNCTION`]
+    /// and [`Self::SENTINEL_INJECTED_TARGET`].
+    pub fn injected(message: &'a str) -> Self {
+        Record {
+            ts: chrono::Utc::now(),
+            target: Self::SENTINEL_INJECTED_TARGET,
+            filename: Self::SENTINEL_INJECTED_FILENAME,
+            line_number: None,
+            function: Self::SENTINEL_INJECTED_FUNCTION,
+            message,
+        }
+    }
+}
+
 pub trait BacktraceProvider {
     fn capture(&self) -> Box<dyn ModuleBacktrace>;
 }
@@ -277,12 +317,6 @@ impl SystemLogger {
     }
 
     fn record(message: &str) -> Record {
-        Record {
-            ts: Utc::now(),
-            target: None,
-            filename: Some("spacetimedb"),
-            line_number: None,
-            message,
-        }
+        Record::injected(message)
     }
 }

crates/core/src/host/module_host.rs

@@ -1111,17 +1111,9 @@ impl ModuleHost {
     }
 
     pub fn inject_logs(&self, log_level: LogLevel, message: &str) {
-        self.replica_ctx().logger.write(
-            log_level,
-            &Record {
-                ts: chrono::Utc::now(),
-                target: None,
-                filename: Some("external"),
-                line_number: None,
-                message,
-            },
-            &(),
-        )
+        self.replica_ctx()
+            .logger
+            .write(log_level, &Record::injected(message), &())
     }
 
     /// Execute a one-off query and send the results to the given client.

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

@@ -584,12 +584,12 @@ fn maybe_log_long_running_reducer(reducer_name: &str, total_duration: Duration)
 
 /// Logs an error `message` for `reducer` at `timestamp` into `replica_ctx`.
 fn log_reducer_error(replica_ctx: &ReplicaContext, timestamp: Timestamp, reducer: &str, message: &str) {
-    let record = database_logger::Record {
+    use database_logger::Record;
+
+    let record = Record {
         ts: chrono::DateTime::from_timestamp_micros(timestamp.to_micros_since_unix_epoch()).unwrap(),
-        target: Some(reducer),
-        filename: None,
-        line_number: None,
-        message,
+        function: Some(reducer),
+        ..Record::injected(message)
     };
     replica_ctx.logger.write(database_logger::LogLevel::Error, &record, &());
 }

crates/core/src/host/wasmtime/wasm_instance_env.rs

@@ -164,6 +164,13 @@ impl WasmInstanceEnv {
         &self.reducer_name
     }
 
+    /// Returns the name of the most recent reducer to be run in this environment,
+    /// or `None` if no reducer is actively being invoked.
+    fn log_record_function(&self) -> Option<&str> {
+        let function = self.reducer_name();
+        (!function.is_empty()).then_some(function)
+    }
+
     /// Returns the name of the most recent reducer to be run in this environment.
     pub fn reducer_start(&self) -> Instant {
         self.reducer_start
@@ -1145,12 +1152,15 @@ impl WasmInstanceEnv {
             // The line number cannot be `u32::MAX` as this represents `Option::None`.
             let line_number = (line_number != u32::MAX).then_some(line_number);
 
+            let function = env.log_record_function();
+
             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,
+                function,
                 message: &message,
             };
 
@@ -1191,12 +1201,14 @@ impl WasmInstanceEnv {
 
             let elapsed = span.start.elapsed();
             let message = format!("Timing span {:?}: {:?}", &span.name, elapsed);
+            let function = caller.data().log_record_function();
 
             let record = Record {
                 ts: chrono::Utc::now(),
                 target: None,
                 filename: None,
                 line_number: None,
+                function,
                 message: &message,
             };
             caller.data().instance_env.console_log(

modules/quickstart-chat/src/lib.rs

@@ -27,6 +27,7 @@ fn validate_name(name: String) -> Result<String, String> {
 pub fn set_name(ctx: &ReducerContext, name: String) -> Result<(), String> {
     let name = validate_name(name)?;
     if let Some(user) = ctx.db.user().identity().find(ctx.sender) {
+        log::info!("User {} sets name to {name}", ctx.sender);
         ctx.db.user().identity().update(User {
             name: Some(name),
             ..user
@@ -51,6 +52,7 @@ pub fn send_message(ctx: &ReducerContext, text: String) -> Result<(), String> {
     // - Rate-limit messages per-user.
     // - Reject messages from unnamed user.
     let text = validate_message(text)?;
+    log::info!("User {}: {text}", ctx.sender);
     ctx.db.message().insert(Message {
         sender: ctx.sender,
         text,