Logging API

api/examples/log.rs

@@ -0,0 +1,11 @@
+use std::error::Error;
+
+use shopify_function_wasm_api::log::log_utf8_str;
+
+fn main() -> Result<(), Box<dyn Error>> {
+    log_utf8_str("Hi!\n");
+    log_utf8_str("Hello\n");
+    log_utf8_str("Here's a third string\n");
+    log_utf8_str("✌️\n");
+    Ok(())
+}

api/examples/panic.rs

@@ -0,0 +1,8 @@
+use std::error::Error;
+
+use shopify_function_wasm_api::log::init_panic_handler;
+
+fn main() -> Result<(), Box<dyn Error>> {
+    init_panic_handler();
+    panic!("at the disco");
+}

api/src/lib.rs

@@ -29,6 +29,7 @@ use std::{
     sync::atomic::{AtomicPtr, AtomicUsize, Ordering},
 };
 
+pub mod log;
 pub mod read;
 pub mod write;
 
@@ -88,6 +89,9 @@ extern "C" {
     fn shopify_function_output_new_array(context: ContextPtr, len: usize) -> usize;
     fn shopify_function_output_finish_array(context: ContextPtr) -> usize;
 
+    // Log API.
+    fn shopify_function_log_new_utf8_str(ptr: *const u8, len: usize) -> usize;
+
     // Other.
     fn shopify_function_intern_utf8_str(context: ContextPtr, ptr: *const u8, len: usize) -> usize;
 }
@@ -211,6 +215,17 @@ mod provider_fallback {
         shopify_function_provider::write::shopify_function_output_finish_array(context) as usize
     }
 
+    // Logging.
+    pub(crate) unsafe fn shopify_function_log_new_utf8_str(ptr: *const u8, len: usize) -> usize {
+        let result = shopify_function_provider::log::shopify_function_log_new_utf8_str(len);
+        let write_result = (result >> usize::BITS) as usize;
+        let dst = result as usize;
+        if write_result == WriteResult::Ok as usize {
+            std::ptr::copy(ptr as _, dst as _, len);
+        }
+        write_result
+    }
+
     // Other.
     pub(crate) unsafe fn shopify_function_intern_utf8_str(
         context: ContextPtr,

api/src/log.rs

@@ -0,0 +1,15 @@
+//! The log API for the Shopify Function Wasm API.
+
+/// Configures panics to write to the logging API.
+pub fn init_panic_handler() {
+    #[cfg(target_family = "wasm")]
+    std::panic::set_hook(Box::new(|info| {
+        let message = format!("{info}");
+        log_utf8_str(&message);
+    }));
+}
+
+/// Log `message`.
+pub fn log_utf8_str(message: &str) {
+    unsafe { crate::shopify_function_log_new_utf8_str(message.as_ptr(), message.len()) };
+}

api/src/shopify_function.h

@@ -222,4 +222,14 @@ __attribute__((import_module(SHOPIFY_FUNCTION_IMPORT_MODULE)))
 __attribute__((import_name("shopify_function_intern_utf8_str")))
 extern InternedStringId shopify_function_intern_utf8_str(ContextPtr context, const uint8_t* ptr, size_t len);
 
+/**
+ * Logs a new UTF-8 string output value
+ * @param ptr The string data
+ * @param len The length of the string
+ * @return LogResult indicating success or failure
+ */
+__attribute__((import_module(SHOPIFY_FUNCTION_IMPORT_MODULE)))
+__attribute__((import_name("shopify_function_log_new_utf8_str")))
+extern WriteResult shopify_function_log_new_utf8_str(const uint8_t* ptr, size_t len);
+
 #endif // SHOPIFY_FUNCTION_H

api/src/shopify_function.wat

@@ -277,4 +277,16 @@
   (import "shopify_function_v1" "shopify_function_intern_utf8_str" 
     (func (param $context i32) (param $ptr i32) (param $len i32) (result i32))
   )
+
+  ;; Logs a new string output value.
+  ;; Used for text values in the logs.
+  ;; The string data is copied from WebAssembly memory.
+  ;; Parameters:
+  ;;   - ptr: i32 pointer to string data in WebAssembly memory.
+  ;;   - len: i32 length of string in bytes.
+  ;; Returns:
+  ;;   - i32 status code indicating success or failure
+  (import "shopify_function_v1" "shopify_function_log_new_utf8_str" 
+    (func (param $ptr i32) (param $len i32) (result i32))
+  )
 )

api/src/test_data/header_test.c

@@ -27,5 +27,6 @@ volatile void* imports[] = {
     (void*)shopify_function_output_finish_object,
     (void*)shopify_function_output_new_array,
     (void*)shopify_function_output_finish_array,
-    (void*)shopify_function_intern_utf8_str
+    (void*)shopify_function_intern_utf8_str,
+    (void*)shopify_function_log_new_utf8_str
 };

core/src/lib.rs

@@ -1,3 +1,4 @@
+pub mod log;
 pub mod read;
 pub mod write;
 

core/src/log.rs

@@ -0,0 +1,6 @@
+#[repr(usize)]
+#[derive(Debug, strum::FromRepr, PartialEq, Eq)]
+pub enum LogResult {
+    /// The log operation was successful.
+    Ok = 0,
+}

integration_tests/tests/integration_test.rs

@@ -1,6 +1,6 @@
-use anyhow::Result;
+use anyhow::{Error, Result};
 use integration_tests::prepare_example;
-use std::sync::LazyLock;
+use std::{fmt::Display, sync::LazyLock};
 use wasmtime::{Config, Engine, Linker, Module, Store};
 use wasmtime_wasi::{
     pipe::{MemoryInputPipe, MemoryOutputPipe},
@@ -43,7 +43,7 @@ fn assert_fuel_consumed_within_threshold(target_fuel: u64, fuel_consumed: u64) {
     }
 }
 
-fn run_example(example: &str, input_bytes: Vec<u8>) -> Result<(Vec<u8>, u64)> {
+fn run_example(example: &str, input_bytes: Vec<u8>) -> Result<(Vec<u8>, String, u64)> {
     let manifest_dir = env!("CARGO_MANIFEST_DIR");
     let workspace_root = std::path::PathBuf::from(manifest_dir).join("..");
     let engine = Engine::new(Config::new().consume_fuel(true))?;
@@ -97,19 +97,27 @@ fn run_example(example: &str, input_bytes: Vec<u8>) -> Result<(Vec<u8>, u64)> {
 
     let instructions = STARTING_FUEL.saturating_sub(store.get_fuel().unwrap_or_default());
 
+    let logs_func = provider_instance
+        .get_typed_func::<(), u64>(&mut store, "shopify_function_retrieve_logs")?;
+    let logs_result = logs_func.call(&mut store, ())?;
+    let ptr = (logs_result >> u32::BITS) as usize;
+    let len = logs_result as u32;
+    let provider_memory = provider_instance.get_memory(&mut store, "memory").unwrap();
+    let mut log_buffer = vec![0; len as usize];
+    provider_memory.read(&store, ptr, &mut log_buffer)?;
+    let logs = String::from_utf8_lossy(&log_buffer).to_string();
+
     drop(store);
 
     if let Err(e) = result {
-        let error = stderr.contents().to_vec();
-        return Err(anyhow::anyhow!(
-            "{}\n\nSTDERR:\n{}",
-            e,
-            String::from_utf8(error)?
-        ));
+        return Err(anyhow::anyhow!(CallFuncError {
+            trap_error: e,
+            logs,
+        }));
     }
 
     let output = stdout.contents().to_vec();
-    Ok((output, instructions))
+    Ok((output, logs, instructions))
 }
 
 fn decode_msgpack_output(output: Vec<u8>) -> Result<serde_json::Value> {
@@ -151,15 +159,29 @@ fn prepare_wasi_json_input(input: serde_json::Value) -> Result<Vec<u8>> {
 
 fn run_wasm_api_example(example: &str, input: serde_json::Value) -> Result<serde_json::Value> {
     let input_bytes = prepare_wasm_api_input(input)?;
-    let (output, _fuel) = run_example(example, input_bytes)?;
+    let (output, _fuel, _logs) = run_example(example, input_bytes)?;
     decode_msgpack_output(output)
 }
 
+#[derive(Debug)]
+struct CallFuncError {
+    trap_error: Error,
+    logs: String,
+}
+
+impl Display for CallFuncError {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{}\n\nLogs: {}", self.trap_error, self.logs)
+    }
+}
+
 static ECHO_EXAMPLE_RESULT: LazyLock<Result<()>> = LazyLock::new(|| prepare_example("echo"));
 static BENCHMARK_EXAMPLE_RESULT: LazyLock<Result<()>> =
     LazyLock::new(|| prepare_example("cart-checkout-validation-wasm-api"));
 static BENCHMARK_NON_WASM_API_EXAMPLE_RESULT: LazyLock<Result<()>> =
     LazyLock::new(|| prepare_example("cart-checkout-validation-wasi-json"));
+static LOG_EXAMPLE_RESULT: LazyLock<Result<()>> = LazyLock::new(|| prepare_example("log"));
+static PANIC_EXAMPLE_RESULT: LazyLock<Result<()>> = LazyLock::new(|| prepare_example("panic"));
 
 #[test]
 fn test_echo_with_bool_input() -> Result<()> {
@@ -341,7 +363,7 @@ fn test_fuel_consumption_within_threshold() -> Result<()> {
         .map_err(|e| anyhow::anyhow!("Failed to prepare example: {}", e))?;
     let input = generate_cart_with_size(2, true);
     let wasm_api_input = prepare_wasm_api_input(input.clone())?;
-    let (_, wasm_api_fuel) = run_example("cart-checkout-validation-wasm-api", wasm_api_input)?;
+    let (_, _, wasm_api_fuel) = run_example("cart-checkout-validation-wasm-api", wasm_api_input)?;
     eprintln!("WASM API fuel: {}", wasm_api_fuel);
     // Using a target fuel value as reference similar to the Javy example
     assert_fuel_consumed_within_threshold(15880, wasm_api_fuel);
@@ -360,12 +382,12 @@ fn test_benchmark_comparison_with_input() -> Result<()> {
     let input = generate_cart_with_size(2, true);
 
     let wasm_api_input = prepare_wasm_api_input(input.clone())?;
-    let (wasm_api_output, wasm_api_fuel) =
+    let (wasm_api_output, _, wasm_api_fuel) =
         run_example("cart-checkout-validation-wasm-api", wasm_api_input)?;
     let wasm_api_value = decode_msgpack_output(wasm_api_output)?;
 
     let wasi_json_input = prepare_wasi_json_input(input)?;
-    let (non_wasm_api_output, non_wasm_api_fuel) =
+    let (non_wasm_api_output, _, non_wasm_api_fuel) =
         run_example("cart-checkout-validation-wasi-json", wasi_json_input)?;
     let non_wasm_api_value = decode_json_output(non_wasm_api_output)?;
 
@@ -402,12 +424,12 @@ fn test_benchmark_comparison_with_input_early_exit() -> Result<()> {
     let input = generate_cart_with_size(100, false);
 
     let wasm_api_input = prepare_wasm_api_input(input.clone())?;
-    let (wasm_api_output, wasm_api_fuel) =
+    let (wasm_api_output, _, wasm_api_fuel) =
         run_example("cart-checkout-validation-wasm-api", wasm_api_input)?;
     let wasm_api_value = decode_msgpack_output(wasm_api_output)?;
 
     let wasi_json_input = prepare_wasi_json_input(input)?;
-    let (non_wasm_api_output, non_wasm_api_fuel) =
+    let (non_wasm_api_output, _, non_wasm_api_fuel) =
         run_example("cart-checkout-validation-wasi-json", wasi_json_input)?;
     let non_wasm_api_value = decode_json_output(non_wasm_api_output)?;
 
@@ -432,3 +454,30 @@ fn test_benchmark_comparison_with_input_early_exit() -> Result<()> {
 
     Ok(())
 }
+
+#[test]
+fn test_log() -> Result<()> {
+    LOG_EXAMPLE_RESULT
+        .as_ref()
+        .map_err(|e| anyhow::anyhow!("Failed to prepare example: {e}"))?;
+    let (_, logs, fuel) = run_example("log", vec![])?;
+    assert_eq!(logs, "Hi!\nHello\nHere's a third string\n✌️\n");
+    assert_fuel_consumed_within_threshold(2455, fuel);
+    Ok(())
+}
+
+#[test]
+fn test_panic() -> Result<()> {
+    PANIC_EXAMPLE_RESULT
+        .as_ref()
+        .map_err(|e| anyhow::anyhow!("Failed to prepare example: {e}"))?;
+    let error = run_example("panic", vec![])
+        .unwrap_err()
+        .downcast::<CallFuncError>()?;
+    assert_eq!(
+        error.logs,
+        "panicked at api/examples/panic.rs:7:5:
+at the disco"
+    );
+    Ok(())
+}

provider/src/lib.rs

@@ -1,4 +1,5 @@
 mod alloc;
+pub mod log;
 pub mod read;
 mod string_interner;
 pub mod write;

provider/src/log.rs

@@ -0,0 +1,39 @@
+use crate::{decorate_for_target, DoubleUsize};
+use shopify_function_wasm_api_core::log::LogResult;
+use std::cell::RefCell;
+
+thread_local! {
+    static LOGS: RefCell<Vec<u8>> = RefCell::new(Vec::with_capacity(1024));
+}
+
+fn allocate_log(len: usize) -> *const u8 {
+    LOGS.with_borrow_mut(|logs| {
+        let write_index = logs.len();
+        logs.append(&mut vec![0; len]);
+        unsafe { logs.as_ptr().add(write_index) }
+    })
+}
+
+decorate_for_target! {
+    /// The most significant 32 bits are the result, the least significant 32 bits are the pointer.
+    fn shopify_function_log_new_utf8_str(len: usize) -> DoubleUsize {
+        let ptr = allocate_log(len);
+        let result = LogResult::Ok;
+        ((result as DoubleUsize) << usize::BITS) | ptr as DoubleUsize
+    }
+}
+
+/// The most significant 32 bits are the pointer, the least significant 32 bits are the length.
+pub fn shopify_function_retrieve_logs() -> DoubleUsize {
+    LOGS.with_borrow(|logs| {
+        let ptr = logs.as_ptr();
+        let len = logs.len();
+        ((ptr as DoubleUsize) << usize::BITS) | len as DoubleUsize
+    })
+}
+
+#[cfg(target_family = "wasm")]
+#[export_name = "shopify_function_retrieve_logs"]
+extern "C" fn shopify_function_retrieve_logs2() -> DoubleUsize {
+    shopify_function_retrieve_logs()
+}