Add reducer name to database log records (#3274)

# Description of Changes

Extends log records with a new field, `function`, which stores the name
of the reducer being executed when the log was produced. I have chosen
to name this field `function` rather than `reducer` because we will soon
be adding procedures, which are not reducers but will also be valid
values for this field.

While making this change, I noticed inconsistent values for injected
logs. Previously, we injected logs in three places, with different
values for the record fields:

1. `SystemLogger` (used when publishing and updating) set `filename:
Some("spacetimedb")` and `target: None`.
2. `log_reducer_error` (used for reducer error returns) set `filename:
None` and `target: Some(reducer)`, with `reducer` being the name of the
reducer.
3. `ModuleHost::inject_logs` (used for calls to nonexistent reducers and
calls with ill-typed arguments) set `filename: Some("external")` and
`target: None`.

With this change, I have decided that injected logs universally have
`filename: Some("__spacetimedb__")` and `target:
Some("__spacetimedb__")`. I have chosen the double-underscore convention
for reserved names to avoid confusion should a user name a source file
or reducer `spacetimedb`. I am not terribly attached to using
`spacetimedb` here, and would be happy to change to some other string,
like `internal` or `system`.

I have further decided that `log_reducer_error` and `inject_logs` both
have access to a sensible non-`None` value for `function` and so should
set it to the name of the reducer. The `target` field is not used for
this. Note that in cases where a client attempts to call a non-existent
reducer, the `function` field of the log record will be set to that
client-supplied non-existent reducer name.

# API and ABI breaking changes

Changes our log record format. This is at least backwards-compatible (as
in, newer consumers can read older logs) because the new field is
optional. I am unsure if it is forwards-compatible (as in, older
consumers reading newer logs) because I don't know if `serde_json` will
ignore unknown fields or will error.

# Expected complexity level and risk

1

# Testing

- [x] Manually ran `quickstart-chat` (modified to log messages and name
changes) and saw sensible output.

Author: gefjon

crates/cli/src/subcommands/logs.rs

@@ -61,6 +61,12 @@ pub enum LogLevel {
     Panic,
 }
 
+/// Sentinel value used for injected system logs.
+///
+/// Keep this in sync with the constants in `spacetimedb_core::database_logger::Record`.
+const SENTINEL: &str = "__spacetimedb__";
+
+/// Keep this in sync with `spacetimedb_core::database_logger::Record`.
 #[serde_with::serde_as]
 #[derive(serde::Deserialize)]
 struct Record<'a> {
@@ -74,6 +80,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,16 +203,36 @@ 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_before_filename = false;
+        let mut need_colon_sep = false;
         let dimmed = ColorSpec::new().set_dimmed(true).clone();
+        if let Some(function) = record.function {
+            if function != SENTINEL {
+                out.set_color(&dimmed)?;
+                write!(out, "{function}")?;
+                out.reset()?;
+                need_space_before_filename = true;
+                need_colon_sep = true;
+            }
+        }
         if let Some(filename) = record.filename {
-            out.set_color(&dimmed)?;
-            write!(out, "{filename}")?;
-            if let Some(line) = record.line_number {
-                write!(out, ":{line}")?;
+            if filename != SENTINEL {
+                out.set_color(&dimmed)?;
+                if need_space_before_filename {
+                    write!(out, " ")?;
+                }
+                write!(out, "{filename}")?;
+                if let Some(line) = record.line_number {
+                    write!(out, ":{line}")?;
+                }
+                out.reset()?;
+                need_colon_sep = true;
             }
-            out.reset()?;
         }
-        writeln!(out, ": {}", record.message)?;
+        if need_colon_sep {
+            write!(out, ": ")?;
+        }
+        writeln!(out, "{}", record.message)?;
         if let Some(trace) = &record.trace {
             for frame in trace {
                 write!(out, "    in ")?;

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

@@ -1021,7 +1021,7 @@ impl ModuleHost {
             _ => None,
         };
         if let Some(log_message) = log_message {
-            self.inject_logs(LogLevel::Error, &log_message)
+            self.inject_logs(LogLevel::Error, reducer_name, &log_message)
         }
 
         res
@@ -1110,15 +1110,12 @@ impl ModuleHost {
         tokio::join!(self.module.scheduler().closed(), self.job_tx.closed());
     }
 
-    pub fn inject_logs(&self, log_level: LogLevel, message: &str) {
+    pub fn inject_logs(&self, log_level: LogLevel, reducer_name: &str, message: &str) {
         self.replica_ctx().logger.write(
             log_level,
             &Record {
-                ts: chrono::Utc::now(),
-                target: None,
-                filename: Some("external"),
-                line_number: None,
-                message,
+                function: Some(reducer_name),
+                ..Record::injected(message)
             },
             &(),
         )

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,