Skip to content

Commit f32135d

Browse files
authored
Add non-blocking file logging and stderr error logging (#7)
Add a lightweight logging system with two macros — slog! (stdout) and serr! (stderr) — that also tee to a log file via SPICEIO_LOG_FILE. The file writer runs on a dedicated OS thread fed by a bounded mpsc channel; try_send ensures logging never blocks the proxy. When no file is configured there is zero overhead (no thread, no channel, no allocation). All log lines are timestamped (ISO-8601 UTC with milliseconds) using gettimeofday — no allocations in the timestamp path. Also adds logging for: - Connection lifecycle (stdout): client TCP accept, SMB TCP connect, negotiate, auth, tree connect - All failure paths (stderr): every SMB wire error, S3 streaming errors, body read errors, access denied, client disconnects
1 parent 67dcbee commit f32135d

6 files changed

Lines changed: 282 additions & 27 deletions

File tree

CLAUDE.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@ The binary requires these environment variables:
3434
- `SPICEIO_SMB_DOMAIN` — SMB domain (default empty)
3535
- `SPICEIO_BUCKET` — virtual S3 bucket name (defaults to `SPICEIO_SMB_SHARE`)
3636
- `SPICEIO_REGION` — AWS region to advertise (default `us-east-1`)
37+
- `SPICEIO_LOG_FILE` — append logs to this file in addition to stderr (optional; non-blocking, never stalls the proxy)
3738

3839
## Architecture
3940

src/lib.rs

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,24 @@
1-
//! spiceio — S3-compatible API proxy to SMB 3.1.1 file shares (macOS 26).
1+
//! spiceio — S3-compatible API proxy to SMB 3.1.x file shares.
2+
//!
3+
//! Library crate exposing modules for benchmarking and testing.
4+
5+
pub mod log;
6+
7+
/// Log to stdout and optionally to a file (non-blocking).
8+
#[macro_export]
9+
macro_rules! slog {
10+
($($arg:tt)*) => {
11+
$crate::log::emit(format_args!($($arg)*))
12+
};
13+
}
14+
15+
/// Log to stderr and optionally to a file (non-blocking).
16+
#[macro_export]
17+
macro_rules! serr {
18+
($($arg:tt)*) => {
19+
$crate::log::emit_err(format_args!($($arg)*))
20+
};
21+
}
222

323
pub mod crypto;
424
pub mod s3;

src/log.rs

Lines changed: 154 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,154 @@
1+
//! Non-blocking file logger backed by a dedicated OS thread.
2+
//!
3+
//! Design: a bounded `mpsc::sync_channel` feeds a background thread that owns
4+
//! the file descriptor and writes through a 64 KB `BufWriter`. The hot path
5+
//! (`emit` / `emit_err`) does a single `try_send` — if the channel is full
6+
//! the message is silently dropped, so logging never blocks the proxy.
7+
//!
8+
//! Two entry points: `emit` (stdout) and `emit_err` (stderr). Both prepend
9+
//! an ISO-8601 timestamp and write to the log file when configured. When no
10+
//! log file is configured only the console stream is written (zero overhead
11+
//! from the file path — no channel, no allocation, no thread).
12+
13+
use std::fmt;
14+
use std::fs::OpenOptions;
15+
use std::io::{BufWriter, Write};
16+
use std::sync::OnceLock;
17+
use std::sync::mpsc;
18+
19+
/// Channel capacity — number of formatted log lines buffered before drops.
20+
const CHANNEL_CAP: usize = 4096;
21+
22+
/// BufWriter capacity — bytes buffered before a syscall write.
23+
const BUF_CAP: usize = 64 * 1024;
24+
25+
static FILE_TX: OnceLock<mpsc::SyncSender<String>> = OnceLock::new();
26+
27+
/// Initialise file logging. Call once at startup.
28+
/// If `path` is `None`, only console logging is active (the default).
29+
pub fn init(path: Option<&str>) {
30+
let Some(p) = path else { return };
31+
32+
let file = OpenOptions::new()
33+
.create(true)
34+
.append(true)
35+
.open(p)
36+
.unwrap_or_else(|e| panic!("[spiceio] failed to open log file {p}: {e}"));
37+
38+
let (tx, rx) = mpsc::sync_channel::<String>(CHANNEL_CAP);
39+
40+
std::thread::Builder::new()
41+
.name("spiceio-log".into())
42+
.spawn(move || writer_loop(rx, file))
43+
.expect("[spiceio] failed to spawn log thread");
44+
45+
FILE_TX.set(tx).ok();
46+
}
47+
48+
/// Background writer — drains the channel and flushes in batches.
49+
fn writer_loop(rx: mpsc::Receiver<String>, file: std::fs::File) {
50+
let mut w = BufWriter::with_capacity(BUF_CAP, file);
51+
while let Ok(line) = rx.recv() {
52+
let _ = w.write_all(line.as_bytes());
53+
let _ = w.write_all(b"\n");
54+
// Drain any queued messages before issuing the syscall flush.
55+
while let Ok(line) = rx.try_recv() {
56+
let _ = w.write_all(line.as_bytes());
57+
let _ = w.write_all(b"\n");
58+
}
59+
let _ = w.flush();
60+
}
61+
}
62+
63+
/// Format a timestamp from `gettimeofday` into a fixed 24-byte ISO-8601 UTC
64+
/// string: `2026-04-02T16:09:34.123Z`. Uses a stack buffer — no allocation.
65+
fn timestamp(buf: &mut [u8; 24]) {
66+
#[repr(C)]
67+
struct Timeval {
68+
tv_sec: i64,
69+
tv_usec: i32,
70+
}
71+
72+
unsafe extern "C" {
73+
fn gettimeofday(tp: *mut Timeval, tzp: *const std::ffi::c_void) -> i32;
74+
}
75+
76+
let mut tv = Timeval {
77+
tv_sec: 0,
78+
tv_usec: 0,
79+
};
80+
unsafe {
81+
gettimeofday(&mut tv, std::ptr::null());
82+
}
83+
84+
let secs = tv.tv_sec as u64;
85+
let millis = (tv.tv_usec / 1000) as u64;
86+
87+
// Civil time from Unix epoch (Howard Hinnant algorithm)
88+
let days = secs / 86400;
89+
let rem = secs % 86400;
90+
let z = days + 719468;
91+
let era = z / 146097;
92+
let doe = z - era * 146097;
93+
let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365;
94+
let y = yoe + era * 400;
95+
let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
96+
let mp = (5 * doy + 2) / 153;
97+
let d = doy - (153 * mp + 2) / 5 + 1;
98+
let m = if mp < 10 { mp + 3 } else { mp - 9 };
99+
let y = if m <= 2 { y + 1 } else { y };
100+
101+
let h = rem / 3600;
102+
let min = (rem % 3600) / 60;
103+
let s = rem % 60;
104+
105+
// Write directly: "YYYY-MM-DDThh:mm:ss.mmmZ"
106+
buf[0] = b'0' + ((y / 1000) % 10) as u8;
107+
buf[1] = b'0' + ((y / 100) % 10) as u8;
108+
buf[2] = b'0' + ((y / 10) % 10) as u8;
109+
buf[3] = b'0' + (y % 10) as u8;
110+
buf[4] = b'-';
111+
buf[5] = b'0' + ((m / 10) % 10) as u8;
112+
buf[6] = b'0' + (m % 10) as u8;
113+
buf[7] = b'-';
114+
buf[8] = b'0' + ((d / 10) % 10) as u8;
115+
buf[9] = b'0' + (d % 10) as u8;
116+
buf[10] = b'T';
117+
buf[11] = b'0' + ((h / 10) % 10) as u8;
118+
buf[12] = b'0' + (h % 10) as u8;
119+
buf[13] = b':';
120+
buf[14] = b'0' + ((min / 10) % 10) as u8;
121+
buf[15] = b'0' + (min % 10) as u8;
122+
buf[16] = b':';
123+
buf[17] = b'0' + ((s / 10) % 10) as u8;
124+
buf[18] = b'0' + (s % 10) as u8;
125+
buf[19] = b'.';
126+
buf[20] = b'0' + ((millis / 100) % 10) as u8;
127+
buf[21] = b'0' + ((millis / 10) % 10) as u8;
128+
buf[22] = b'0' + (millis % 10) as u8;
129+
buf[23] = b'Z';
130+
}
131+
132+
/// Write a formatted message to **stdout** and (if configured) to the log file.
133+
#[inline]
134+
pub fn emit(args: fmt::Arguments<'_>) {
135+
let mut ts = [0u8; 24];
136+
timestamp(&mut ts);
137+
let ts = unsafe { std::str::from_utf8_unchecked(&ts) };
138+
println!("{ts} {args}");
139+
if let Some(tx) = FILE_TX.get() {
140+
let _ = tx.try_send(format!("{ts} {args}"));
141+
}
142+
}
143+
144+
/// Write a formatted message to **stderr** and (if configured) to the log file.
145+
#[inline]
146+
pub fn emit_err(args: fmt::Arguments<'_>) {
147+
let mut ts = [0u8; 24];
148+
timestamp(&mut ts);
149+
let ts = unsafe { std::str::from_utf8_unchecked(&ts) };
150+
eprintln!("{ts} {args}");
151+
if let Some(tx) = FILE_TX.get() {
152+
let _ = tx.try_send(format!("{ts} {args}"));
153+
}
154+
}

src/main.rs

Lines changed: 35 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
//! spiceio — S3-compatible API proxy to SMB 3.1.1 file shares (macOS 26).
22
33
mod crypto;
4+
mod log;
45
mod s3;
56
mod smb;
67

@@ -20,6 +21,22 @@ use s3::router::AppState;
2021
use smb::client::SmbConfig;
2122
use smb::ops::ShareSession;
2223

24+
/// Log to stdout and optionally to a file (non-blocking).
25+
#[macro_export]
26+
macro_rules! slog {
27+
($($arg:tt)*) => {
28+
$crate::log::emit(format_args!($($arg)*))
29+
};
30+
}
31+
32+
/// Log to stderr and optionally to a file (non-blocking).
33+
#[macro_export]
34+
macro_rules! serr {
35+
($($arg:tt)*) => {
36+
$crate::log::emit_err(format_args!($($arg)*))
37+
};
38+
}
39+
2340
/// Runtime configuration parsed from environment variables.
2441
struct Config {
2542
/// Address to bind the HTTP server to
@@ -73,11 +90,16 @@ async fn main() {
7390
return;
7491
}
7592

93+
log::init(env::var("SPICEIO_LOG_FILE").ok().as_deref());
94+
7695
let config = Config::from_env();
7796

78-
eprintln!(
97+
slog!(
7998
"[spiceio] connecting to smb://{}@{}:{}/{}",
80-
config.smb_username, config.smb_server, config.smb_port, config.smb_share
99+
config.smb_username,
100+
config.smb_server,
101+
config.smb_port,
102+
config.smb_share
81103
);
82104

83105
// Connect to SMB server
@@ -114,20 +136,24 @@ async fn main() {
114136
.await
115137
.expect("failed to bind TCP listener");
116138

117-
eprintln!("[spiceio] listening on http://{bind_addr}");
118-
eprintln!(
139+
slog!("[spiceio] listening on http://{bind_addr}");
140+
slog!(
119141
"[spiceio] bucket: {} region: {}",
120-
config.bucket_name, config.region
142+
config.bucket_name,
143+
config.region
121144
);
122145

123146
// Accept loop
124147
loop {
125148
tokio::select! {
126149
accepted = listener.accept() => {
127150
let (stream, peer_addr) = match accepted {
128-
Ok(v) => v,
151+
Ok(v) => {
152+
slog!("[spiceio] client connected: {}", v.1);
153+
v
154+
}
129155
Err(e) => {
130-
eprintln!("[spiceio] accept error: {e}");
156+
serr!("[spiceio] accept error: {e}");
131157
continue;
132158
}
133159
};
@@ -148,12 +174,12 @@ async fn main() {
148174
.serve_connection(io, service)
149175
.await
150176
&& !e.to_string().contains("connection reset") {
151-
eprintln!("[spiceio] connection error from {peer_addr}: {e}");
177+
serr!("[spiceio] connection error from {peer_addr}: {e}");
152178
}
153179
});
154180
}
155181
_ = signal::ctrl_c() => {
156-
eprintln!("\n[spiceio] shutting down");
182+
slog!("\n[spiceio] shutting down");
157183
break;
158184
}
159185
}

src/s3/router.rs

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -597,10 +597,14 @@ async fn handle_get_object(
597597
Ok(chunk) => {
598598
offset += chunk.len() as u64;
599599
if tx.send(chunk).await.is_err() {
600-
break; // Client disconnected
600+
crate::serr!("[spiceio] getobject client disconnected");
601+
break;
601602
}
602603
}
603-
Err(_) => break,
604+
Err(e) => {
605+
crate::serr!("[spiceio] getobject read error: {e}");
606+
break;
607+
}
604608
}
605609
}
606610
let _ = handle.close().await;
@@ -722,6 +726,7 @@ async fn handle_put_object(
722726
}
723727
}
724728
Err(e) => {
729+
crate::serr!("[spiceio] putobject body read error: {e}");
725730
let _ = handle.close().await;
726731
return io_to_s3_error(&io::Error::other(format!("body read error: {e}")));
727732
}
@@ -1422,10 +1427,11 @@ fn io_to_s3_error(e: &io::Error) -> Response<SpiceioBody> {
14221427
"The specified key does not exist.",
14231428
),
14241429
io::ErrorKind::PermissionDenied => {
1430+
crate::serr!("[spiceio] access denied: {e}");
14251431
error_response(StatusCode::FORBIDDEN, "AccessDenied", "Access Denied")
14261432
}
14271433
_ => {
1428-
eprintln!("[spiceio] error: {e}");
1434+
crate::serr!("[spiceio] error: {e}");
14291435
error_response(
14301436
StatusCode::INTERNAL_SERVER_ERROR,
14311437
"InternalError",
@@ -1477,7 +1483,7 @@ async fn collect_body(req: Request<Incoming>) -> Bytes {
14771483
match req.into_body().collect().await {
14781484
Ok(collected) => collected.to_bytes(),
14791485
Err(e) => {
1480-
eprintln!("[spiceio] body collect error: {e}");
1486+
crate::serr!("[spiceio] body collect error: {e}");
14811487
Bytes::new()
14821488
}
14831489
}

0 commit comments

Comments
 (0)