Add non-blocking file logging and stderr error logging

CLAUDE.md

@@ -34,6 +34,7 @@ The binary requires these environment variables:
 - `SPICEIO_SMB_DOMAIN` — SMB domain (default empty)
 - `SPICEIO_BUCKET` — virtual S3 bucket name (defaults to `SPICEIO_SMB_SHARE`)
 - `SPICEIO_REGION` — AWS region to advertise (default `us-east-1`)
+- `SPICEIO_LOG_FILE` — append logs to this file in addition to stderr (optional; non-blocking, never stalls the proxy)
 
 ## Architecture
 

src/lib.rs

@@ -1,4 +1,24 @@
-//! spiceio — S3-compatible API proxy to SMB 3.1.1 file shares (macOS 26).
+//! spiceio — S3-compatible API proxy to SMB 3.1.x file shares.
+//!
+//! Library crate exposing modules for benchmarking and testing.
+
+pub mod log;
+
+/// Log to stdout and optionally to a file (non-blocking).
+#[macro_export]
+macro_rules! slog {
+    ($($arg:tt)*) => {
+        $crate::log::emit(format_args!($($arg)*))
+    };
+}
+
+/// Log to stderr and optionally to a file (non-blocking).
+#[macro_export]
+macro_rules! serr {
+    ($($arg:tt)*) => {
+        $crate::log::emit_err(format_args!($($arg)*))
+    };
+}
 
 pub mod crypto;
 pub mod s3;

src/log.rs

@@ -0,0 +1,154 @@
+//! Non-blocking file logger backed by a dedicated OS thread.
+//!
+//! Design: a bounded `mpsc::sync_channel` feeds a background thread that owns
+//! the file descriptor and writes through a 64 KB `BufWriter`. The hot path
+//! (`emit` / `emit_err`) does a single `try_send` — if the channel is full
+//! the message is silently dropped, so logging never blocks the proxy.
+//!
+//! Two entry points: `emit` (stdout) and `emit_err` (stderr). Both prepend
+//! an ISO-8601 timestamp and write to the log file when configured. When no
+//! log file is configured only the console stream is written (zero overhead
+//! from the file path — no channel, no allocation, no thread).
+
+use std::fmt;
+use std::fs::OpenOptions;
+use std::io::{BufWriter, Write};
+use std::sync::OnceLock;
+use std::sync::mpsc;
+
+/// Channel capacity — number of formatted log lines buffered before drops.
+const CHANNEL_CAP: usize = 4096;
+
+/// BufWriter capacity — bytes buffered before a syscall write.
+const BUF_CAP: usize = 64 * 1024;
+
+static FILE_TX: OnceLock<mpsc::SyncSender<String>> = OnceLock::new();
+
+/// Initialise file logging.  Call once at startup.
+/// If `path` is `None`, only console logging is active (the default).
+pub fn init(path: Option<&str>) {
+    let Some(p) = path else { return };
+
+    let file = OpenOptions::new()
+        .create(true)
+        .append(true)
+        .open(p)
+        .unwrap_or_else(|e| panic!("[spiceio] failed to open log file {p}: {e}"));
+
+    let (tx, rx) = mpsc::sync_channel::<String>(CHANNEL_CAP);
+
+    std::thread::Builder::new()
+        .name("spiceio-log".into())
+        .spawn(move || writer_loop(rx, file))
+        .expect("[spiceio] failed to spawn log thread");
+
+    FILE_TX.set(tx).ok();
+}
+
+/// Background writer — drains the channel and flushes in batches.
+fn writer_loop(rx: mpsc::Receiver<String>, file: std::fs::File) {
+    let mut w = BufWriter::with_capacity(BUF_CAP, file);
+    while let Ok(line) = rx.recv() {
+        let _ = w.write_all(line.as_bytes());
+        let _ = w.write_all(b"\n");
+        // Drain any queued messages before issuing the syscall flush.
+        while let Ok(line) = rx.try_recv() {
+            let _ = w.write_all(line.as_bytes());
+            let _ = w.write_all(b"\n");
+        }
+        let _ = w.flush();
+    }
+}
+
+/// Format a timestamp from `gettimeofday` into a fixed 24-byte ISO-8601 UTC
+/// string: `2026-04-02T16:09:34.123Z`. Uses a stack buffer — no allocation.
+fn timestamp(buf: &mut [u8; 24]) {
+    #[repr(C)]
+    struct Timeval {
+        tv_sec: i64,
+        tv_usec: i32,
+    }
+
+    unsafe extern "C" {
+        fn gettimeofday(tp: *mut Timeval, tzp: *const std::ffi::c_void) -> i32;
+    }
+
+    let mut tv = Timeval {
+        tv_sec: 0,
+        tv_usec: 0,
+    };
+    unsafe {
+        gettimeofday(&mut tv, std::ptr::null());
+    }
+
+    let secs = tv.tv_sec as u64;
+    let millis = (tv.tv_usec / 1000) as u64;
+
+    // Civil time from Unix epoch (Howard Hinnant algorithm)
+    let days = secs / 86400;
+    let rem = secs % 86400;
+    let z = days + 719468;
+    let era = z / 146097;
+    let doe = z - era * 146097;
+    let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365;
+    let y = yoe + era * 400;
+    let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
+    let mp = (5 * doy + 2) / 153;
+    let d = doy - (153 * mp + 2) / 5 + 1;
+    let m = if mp < 10 { mp + 3 } else { mp - 9 };
+    let y = if m <= 2 { y + 1 } else { y };
+
+    let h = rem / 3600;
+    let min = (rem % 3600) / 60;
+    let s = rem % 60;
+
+    // Write directly: "YYYY-MM-DDThh:mm:ss.mmmZ"
+    buf[0] = b'0' + ((y / 1000) % 10) as u8;
+    buf[1] = b'0' + ((y / 100) % 10) as u8;
+    buf[2] = b'0' + ((y / 10) % 10) as u8;
+    buf[3] = b'0' + (y % 10) as u8;
+    buf[4] = b'-';
+    buf[5] = b'0' + ((m / 10) % 10) as u8;
+    buf[6] = b'0' + (m % 10) as u8;
+    buf[7] = b'-';
+    buf[8] = b'0' + ((d / 10) % 10) as u8;
+    buf[9] = b'0' + (d % 10) as u8;
+    buf[10] = b'T';
+    buf[11] = b'0' + ((h / 10) % 10) as u8;
+    buf[12] = b'0' + (h % 10) as u8;
+    buf[13] = b':';
+    buf[14] = b'0' + ((min / 10) % 10) as u8;
+    buf[15] = b'0' + (min % 10) as u8;
+    buf[16] = b':';
+    buf[17] = b'0' + ((s / 10) % 10) as u8;
+    buf[18] = b'0' + (s % 10) as u8;
+    buf[19] = b'.';
+    buf[20] = b'0' + ((millis / 100) % 10) as u8;
+    buf[21] = b'0' + ((millis / 10) % 10) as u8;
+    buf[22] = b'0' + (millis % 10) as u8;
+    buf[23] = b'Z';
+}
+
+/// Write a formatted message to **stdout** and (if configured) to the log file.
+#[inline]
+pub fn emit(args: fmt::Arguments<'_>) {
+    let mut ts = [0u8; 24];
+    timestamp(&mut ts);
+    let ts = unsafe { std::str::from_utf8_unchecked(&ts) };
+    println!("{ts} {args}");
+    if let Some(tx) = FILE_TX.get() {
+        let _ = tx.try_send(format!("{ts} {args}"));
+    }
+}
+
+/// Write a formatted message to **stderr** and (if configured) to the log file.
+#[inline]
+pub fn emit_err(args: fmt::Arguments<'_>) {
+    let mut ts = [0u8; 24];
+    timestamp(&mut ts);
+    let ts = unsafe { std::str::from_utf8_unchecked(&ts) };
+    eprintln!("{ts} {args}");
+    if let Some(tx) = FILE_TX.get() {
+        let _ = tx.try_send(format!("{ts} {args}"));
+    }
+}

src/main.rs

@@ -1,6 +1,7 @@
 //! spiceio — S3-compatible API proxy to SMB 3.1.1 file shares (macOS 26).
 
 mod crypto;
+mod log;
 mod s3;
 mod smb;
 
@@ -20,6 +21,22 @@ use s3::router::AppState;
 use smb::client::SmbConfig;
 use smb::ops::ShareSession;
 
+/// Log to stdout and optionally to a file (non-blocking).
+#[macro_export]
+macro_rules! slog {
+    ($($arg:tt)*) => {
+        $crate::log::emit(format_args!($($arg)*))
+    };
+}
+
+/// Log to stderr and optionally to a file (non-blocking).
+#[macro_export]
+macro_rules! serr {
+    ($($arg:tt)*) => {
+        $crate::log::emit_err(format_args!($($arg)*))
+    };
+}
+
 /// Runtime configuration parsed from environment variables.
 struct Config {
     /// Address to bind the HTTP server to
@@ -73,11 +90,16 @@ async fn main() {
         return;
     }
 
+    log::init(env::var("SPICEIO_LOG_FILE").ok().as_deref());
+
     let config = Config::from_env();
 
-    eprintln!(
+    slog!(
         "[spiceio] connecting to smb://{}@{}:{}/{}",
-        config.smb_username, config.smb_server, config.smb_port, config.smb_share
+        config.smb_username,
+        config.smb_server,
+        config.smb_port,
+        config.smb_share
     );
 
     // Connect to SMB server
@@ -114,20 +136,24 @@ async fn main() {
         .await
         .expect("failed to bind TCP listener");
 
-    eprintln!("[spiceio] listening on http://{bind_addr}");
-    eprintln!(
+    slog!("[spiceio] listening on http://{bind_addr}");
+    slog!(
         "[spiceio] bucket: {} region: {}",
-        config.bucket_name, config.region
+        config.bucket_name,
+        config.region
     );
 
     // Accept loop
     loop {
         tokio::select! {
             accepted = listener.accept() => {
                 let (stream, peer_addr) = match accepted {
-                    Ok(v) => v,
+                    Ok(v) => {
+                        slog!("[spiceio] client connected: {}", v.1);
+                        v
+                    }
                     Err(e) => {
-                        eprintln!("[spiceio] accept error: {e}");
+                        serr!("[spiceio] accept error: {e}");
                         continue;
                     }
                 };
@@ -148,12 +174,12 @@ async fn main() {
                         .serve_connection(io, service)
                         .await
                         && !e.to_string().contains("connection reset") {
-                            eprintln!("[spiceio] connection error from {peer_addr}: {e}");
+                            serr!("[spiceio] connection error from {peer_addr}: {e}");
                         }
                 });
             }
             _ = signal::ctrl_c() => {
-                eprintln!("\n[spiceio] shutting down");
+                slog!("\n[spiceio] shutting down");
                 break;
             }
         }

src/s3/router.rs

@@ -597,10 +597,14 @@ async fn handle_get_object(
                 Ok(chunk) => {
                     offset += chunk.len() as u64;
                     if tx.send(chunk).await.is_err() {
-                        break; // Client disconnected
+                        crate::serr!("[spiceio] getobject client disconnected");
+                        break;
                     }
                 }
-                Err(_) => break,
+                Err(e) => {
+                    crate::serr!("[spiceio] getobject read error: {e}");
+                    break;
+                }
             }
         }
         let _ = handle.close().await;
@@ -722,6 +726,7 @@ async fn handle_put_object(
                 }
             }
             Err(e) => {
+                crate::serr!("[spiceio] putobject body read error: {e}");
                 let _ = handle.close().await;
                 return io_to_s3_error(&io::Error::other(format!("body read error: {e}")));
             }
@@ -1422,10 +1427,11 @@ fn io_to_s3_error(e: &io::Error) -> Response<SpiceioBody> {
             "The specified key does not exist.",
         ),
         io::ErrorKind::PermissionDenied => {
+            crate::serr!("[spiceio] access denied: {e}");
             error_response(StatusCode::FORBIDDEN, "AccessDenied", "Access Denied")
         }
         _ => {
-            eprintln!("[spiceio] error: {e}");
+            crate::serr!("[spiceio] error: {e}");
             error_response(
                 StatusCode::INTERNAL_SERVER_ERROR,
                 "InternalError",
@@ -1477,7 +1483,7 @@ async fn collect_body(req: Request<Incoming>) -> Bytes {
     match req.into_body().collect().await {
         Ok(collected) => collected.to_bytes(),
         Err(e) => {
-            eprintln!("[spiceio] body collect error: {e}");
+            crate::serr!("[spiceio] body collect error: {e}");
             Bytes::new()
         }
     }