diff --git a/Cargo.lock b/Cargo.lock index c512066..117473d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2250,6 +2250,8 @@ dependencies = [ "base64 0.22.1", "encrypted-spaces-ffproof", "encrypted-spaces-sdk", + "env_logger", + "log", "serde", "serde_json", "sha2 0.10.9", @@ -2267,6 +2269,7 @@ dependencies = [ "ffproof-tracer-shared", "hex", "instant", + "log", "merk", "postcard", "rand 0.9.4", diff --git a/README.md b/README.md index 2aa07a2..f17d5b0 100644 --- a/README.md +++ b/README.md @@ -120,6 +120,8 @@ export ENCRYPTED_SPACES_SCHEMA_PATH=/path/to/app-schema.kdl export ENCRYPTED_SPACES_BACKEND_URL=ws://127.0.0.1:8080/ws # Optional, 1..3600000; defaults to 30000. export ENCRYPTED_SPACES_REQUEST_TIMEOUT_MS=30000 +# Optional diagnostics go to stderr; the default filter is `warn`. +export RUST_LOG=encrypted_spaces_sdk=info,encrypted_spaces_changelog_core=debug encrypted-spaces-bridge ``` @@ -127,6 +129,9 @@ Requests cannot override the schema, data commitment, or fast-forward guest image ID. `hello` reports those process-derived trust values and the diagnostic client label. The label is not an identity or authorization claim; Space credentials and membership proofs establish authorization. The +bridge reserves stdout for JSONL responses. Configurable host SDK and verifier +diagnostics use stderr through the standard `RUST_LOG` filter; verifier code +inside a RISC Zero guest uses the zkVM debug console instead. The bridge supports Space create/join/snapshot/restore/sync, table insert/select, scoped list and collaborative text operations, encrypted file put/get, member invite/join/remove, cancellation, close, and shutdown. Request and diff --git a/bridge/Cargo.toml b/bridge/Cargo.toml index 606b8f3..38a8091 100644 --- a/bridge/Cargo.toml +++ b/bridge/Cargo.toml @@ -18,6 +18,8 @@ path = "src/main.rs" base64.workspace = true encrypted-spaces-ffproof = { workspace = true, features = ["prove"] } encrypted-spaces-sdk = { workspace = true, features = ["local-transport"] } +env_logger.workspace = true +log.workspace = true serde.workspace = true serde_json.workspace = true sha2.workspace = true diff --git a/bridge/src/main.rs b/bridge/src/main.rs index d509d92..fc082e1 100644 --- a/bridge/src/main.rs +++ b/bridge/src/main.rs @@ -1,13 +1,25 @@ +#![deny(clippy::print_stdout)] + mod protocol; mod runtime; mod schema; fn main() -> std::io::Result<()> { + env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("warn")) + .target(env_logger::Target::Stderr) + .init(); + log::debug!("bridge diagnostics initialized"); + let mut args = std::env::args_os(); let _program = args.next(); if args.next().is_some_and(|arg| arg == "--version") && args.next().is_none() { - println!("encrypted-spaces-bridge {}", env!("CARGO_PKG_VERSION")); + print_version(); return Ok(()); } protocol::run(std::io::stdin(), std::io::stdout()) } + +#[allow(clippy::print_stdout)] +fn print_version() { + println!("encrypted-spaces-bridge {}", env!("CARGO_PKG_VERSION")); +} diff --git a/bridge/tests/stdio.rs b/bridge/tests/stdio.rs index f443391..c6a8ac5 100644 --- a/bridge/tests/stdio.rs +++ b/bridge/tests/stdio.rs @@ -28,17 +28,25 @@ struct Bridge { impl Bridge { fn spawn(client_label: &str) -> Self { - let mut child = Command::new(env!("CARGO_BIN_EXE_encrypted-spaces-bridge")) + Self::spawn_with_log_filter(client_label, None) + } + + fn spawn_with_log_filter(client_label: &str, log_filter: Option<&str>) -> Self { + let mut command = Command::new(env!("CARGO_BIN_EXE_encrypted-spaces-bridge")); + command .env("ENCRYPTED_SPACES_CLIENT_LABEL", client_label) .env( "ENCRYPTED_SPACES_SCHEMA_PATH", concat!(env!("CARGO_MANIFEST_DIR"), "/../demos/tauri/app_schema.kdl"), ) + .env_remove("RUST_LOG") .stdin(Stdio::piped()) .stdout(Stdio::piped()) - .stderr(Stdio::piped()) - .spawn() - .expect("spawn bridge"); + .stderr(Stdio::piped()); + if let Some(filter) = log_filter { + command.env("RUST_LOG", filter); + } + let mut child = command.spawn().expect("spawn bridge"); let stdin = child.stdin.take().expect("bridge stdin"); let stdout = child.stdout.take().expect("bridge stdout"); let stderr = child.stderr.take().expect("bridge stderr"); @@ -177,6 +185,26 @@ impl Drop for Bridge { } } +#[test] +fn protocol_bridge_diagnostics_use_stderr_without_corrupting_jsonl() { + let mut bridge = + Bridge::spawn_with_log_filter(DEFAULT_CLIENT_LABEL, Some("encrypted_spaces_bridge=debug")); + bridge.send_request("diagnostic-hello", "hello", json!({})); + + let response = bridge.receive(); + assert_eq!(response["request_id"], "diagnostic-hello"); + assert_eq!(response["ok"], true); + + bridge.close_stdin(); + bridge.expect_stdout_eof(); + let (status, stderr) = bridge.finish(); + assert!(status.success(), "bridge exited with {status}"); + assert!( + stderr.contains("bridge diagnostics initialized"), + "configured diagnostics were not emitted to stderr: {stderr}" + ); +} + fn request(request_id: &str, operation: &str, payload: Value) -> String { serde_json::to_string(&json!({ "version": 1, diff --git a/ffproof/changelog_core/Cargo.toml b/ffproof/changelog_core/Cargo.toml index 13bf5cc..5ab3ebb 100644 --- a/ffproof/changelog_core/Cargo.toml +++ b/ffproof/changelog_core/Cargo.toml @@ -10,6 +10,7 @@ postcard = { workspace = true } encrypted-spaces-acl-types = { workspace = true } hex.workspace = true instant.workspace = true +log.workspace = true risc0-zkvm = { workspace = true, features = ["std"] } thiserror = { workspace = true } rand = { workspace = true, features = ["os_rng"] } diff --git a/ffproof/changelog_core/src/changelog.rs b/ffproof/changelog_core/src/changelog.rs index ab080c8..cf326a6 100644 --- a/ffproof/changelog_core/src/changelog.rs +++ b/ffproof/changelog_core/src/changelog.rs @@ -14,6 +14,15 @@ pub type HashedValues = BTreeMap<[u8; 32], Vec>; use serde::{Deserialize, Serialize}; use std::collections::BTreeMap; +macro_rules! verification_diagnostic { + ($($arg:tt)*) => {{ + #[cfg(target_os = "zkvm")] + risc0_zkvm::guest::env::log(&format!($($arg)*)); + #[cfg(not(target_os = "zkvm"))] + log::debug!($($arg)*); + }}; +} + ///// Changelog Structures #[cfg(test)] @@ -1289,7 +1298,7 @@ pub fn validate_parent_clc( match recent_roots.iter().find(|(cid, _)| *cid == parent_change) { Some((_, root)) => { if root != parent_clc { - println!( + verification_diagnostic!( "parent_clc mismatch: parent_change={parent_change}, claimed={}, expected={}", hex::encode(parent_clc), hex::encode(root) @@ -1300,7 +1309,7 @@ pub fn validate_parent_clc( } } None => { - println!( + verification_diagnostic!( "parent_clc lookup failed: no root in window for parent_change={parent_change} \ (window has {} entries)", recent_roots.len() @@ -1334,7 +1343,7 @@ pub fn validate_sigref( match sigref_map.get(&uid) { Some(&(prev_change_id, _)) => { if sig_ref != prev_change_id { - println!( + verification_diagnostic!( "Sigref chain broken at change {current_change_id}: \ uid={uid}, expected sig_ref={prev_change_id}, got sig_ref={sig_ref}" ); @@ -1343,7 +1352,7 @@ pub fn validate_sigref( } None => { if sig_ref != 0 { - println!( + verification_diagnostic!( "Sigref chain broken at change {current_change_id}: \ uid={uid} has no prior change, expected sig_ref=0, got sig_ref={sig_ref}" ); @@ -1829,7 +1838,7 @@ fn decode_postcard_pruned_tree(pruned_tree_bytes: &[u8]) -> Option { let pruned_tree: crate::PrunedMerkleTree = match postcard::from_bytes(pruned_tree_bytes) { Ok(p) => p, Err(e) => { - println!("Failed to deserialize pruned tree: {:?}", e); + verification_diagnostic!("Failed to deserialize pruned tree: {:?}", e); return None; } }; @@ -1837,7 +1846,7 @@ fn decode_postcard_pruned_tree(pruned_tree_bytes: &[u8]) -> Option { match crate::pruned_to_merk(pruned_tree) { Some(t) => Some(t), None => { - println!("Failed to verify: pruned tree is empty"); + verification_diagnostic!("Failed to verify: pruned tree is empty"); None } } @@ -1867,14 +1876,16 @@ fn verify_op_sequence_with_tree( let end_dc_bytes: [u8; 32] = end_dc.as_bytes().try_into().unwrap(); if !range.start_clc_state.verify_for_change_id(start_change_id) { - println!( + verification_diagnostic!( "FastForwardRange.start_clc_state is inconsistent with start_change_id={}", start_change_id ); return false; } if start_change_id == 0 && range.start_clc_state != initial_clc_state(&start_dc_bytes) { - println!("FastForwardRange.start_clc_state does not match MmrTree::initialize(start_dc)"); + verification_diagnostic!( + "FastForwardRange.start_clc_state does not match MmrTree::initialize(start_dc)" + ); return false; } @@ -1886,7 +1897,7 @@ fn verify_op_sequence_with_tree( match recent_roots.last().copied() { Some((last_cid, last_root)) => { if last_cid != start_change_id || last_root != start_root { - println!( + verification_diagnostic!( "recent_roots last entry ({last_cid}) does not match start_change_id \ ({start_change_id}) or start_clc_state.root" ); @@ -1895,7 +1906,7 @@ fn verify_op_sequence_with_tree( } None => { if start_change_id != 0 { - println!( + verification_diagnostic!( "recent_roots must be non-empty for extension chunks \ (start_change_id={start_change_id})" ); @@ -1919,7 +1930,7 @@ fn verify_op_sequence_with_tree( .end_clc_state .verify_for_tree_size(expected_end_tree_size) { - println!( + verification_diagnostic!( "FastForwardRange.end_clc_state is inconsistent: tree_size {} != start ({}) + chunk_len ({}), or peaks/root malformed", range.end_clc_state.tree_size, range.start_clc_state.tree_size, chunk_len ); @@ -1928,7 +1939,7 @@ fn verify_op_sequence_with_tree( tree.commit(); if tree.hash() != start_dc_bytes { - println!("Failed to verify: computed start root does not match"); + verification_diagnostic!("Failed to verify: computed start root does not match"); return false; } @@ -1948,13 +1959,15 @@ fn verify_op_sequence_with_tree( let entry_i = match ChangelogEntry::from_bytes_for_verification(e_i) { Ok(m) => m, Err(e) => { - println!("Failed to verify changes; Changelog entry didn't parse {e:?}"); + verification_diagnostic!( + "Failed to verify changes; Changelog entry didn't parse {e:?}" + ); return false; } }; if !validate_timestamp_hwm(entry_i.timestamp, timestamp_hwm) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} timestamp {} is older than HWM {} by more than {TIMESTAMP_HWM_TOLERANCE_SECONDS}s", entry_i.timestamp, *timestamp_hwm ); @@ -1974,7 +1987,7 @@ fn verify_op_sequence_with_tree( } if !validate_parent_change(entry_i.parent_change, current_change_id) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} has invalid \ parent_change={} (current_change_id={current_change_id}, \ MAX_PARENT_DISTANCE={MAX_PARENT_DISTANCE})", @@ -1988,7 +2001,7 @@ fn verify_op_sequence_with_tree( // server could splice signed entries from a divergent fork into // the proven chain if !validate_parent_clc(entry_i.parent_change, &entry_i.parent_clc, recent_roots) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} has invalid \ parent_clc for parent_change={}", entry_i.parent_change @@ -2002,7 +2015,7 @@ fn verify_op_sequence_with_tree( { Ok(r) => r, Err(e) => { - println!("Op validation failed at entry {current_change_id}: {e}"); + verification_diagnostic!("Op validation failed at entry {current_change_id}: {e}"); return false; } }; @@ -2010,7 +2023,9 @@ fn verify_op_sequence_with_tree( let writes = match flatten_write_steps(op_result) { Ok(w) => w, Err(e) => { - println!("Op at entry {current_change_id} produced invalid writes: {e}"); + verification_diagnostic!( + "Op at entry {current_change_id} produced invalid writes: {e}" + ); return false; } }; @@ -2018,7 +2033,7 @@ fn verify_op_sequence_with_tree( tree = match maybe_tree { Some(t) => t, None => { - println!("Tree became empty after entry {current_change_id}"); + verification_diagnostic!("Tree became empty after entry {current_change_id}"); return false; } }; @@ -2042,7 +2057,7 @@ fn verify_op_sequence_with_tree( tree.commit(); if tree.hash() != end_dc_bytes { - println!("Failed to verify changes; ending data root does not match"); + verification_diagnostic!("Failed to verify changes; ending data root does not match"); return false; } @@ -2050,7 +2065,9 @@ fn verify_op_sequence_with_tree( .tree_head() .expect("working tree must be non-empty after replay"); if computed_end != range.end_clc_state { - println!("Failed to verify changes; ending tree head does not match replay"); + verification_diagnostic!( + "Failed to verify changes; ending tree head does not match replay" + ); return false; } @@ -2086,11 +2103,11 @@ fn decode_compact_pruned_tree(pruned_tree_bytes: &[u8]) -> Option { match crate::decode_pruned_compact_to_merk(pruned_tree_bytes) { Ok(Some(t)) => Some(t), Ok(None) => { - println!("Failed to verify: pruned tree is empty"); + verification_diagnostic!("Failed to verify: pruned tree is empty"); None } Err(e) => { - println!("Failed to decode compact pruned tree into Merk: {:?}", e); + verification_diagnostic!("Failed to decode compact pruned tree into Merk: {:?}", e); None } } @@ -2143,14 +2160,16 @@ fn verify_op_sequence_timed_inner( let end_dc_bytes: [u8; 32] = end_dc.as_bytes().try_into().unwrap(); if !range.start_clc_state.verify_for_change_id(start_change_id) { - println!( + verification_diagnostic!( "FastForwardRange.start_clc_state is inconsistent with start_change_id={}", start_change_id ); return (false, timings); } if start_change_id == 0 && range.start_clc_state != initial_clc_state(&start_dc_bytes) { - println!("FastForwardRange.start_clc_state does not match MmrTree::initialize(start_dc)"); + verification_diagnostic!( + "FastForwardRange.start_clc_state does not match MmrTree::initialize(start_dc)" + ); return (false, timings); } @@ -2162,7 +2181,7 @@ fn verify_op_sequence_timed_inner( match recent_roots.last().copied() { Some((last_cid, last_root)) => { if last_cid != start_change_id || last_root != start_root { - println!( + verification_diagnostic!( "recent_roots last entry ({last_cid}) does not match start_change_id \ ({start_change_id}) or start_clc_state.root" ); @@ -2171,7 +2190,7 @@ fn verify_op_sequence_timed_inner( } None => { if start_change_id != 0 { - println!( + verification_diagnostic!( "recent_roots must be non-empty for extension chunks \ (start_change_id={start_change_id})" ); @@ -2195,7 +2214,7 @@ fn verify_op_sequence_timed_inner( .end_clc_state .verify_for_tree_size(expected_end_tree_size) { - println!( + verification_diagnostic!( "FastForwardRange.end_clc_state is inconsistent: tree_size {} != start ({}) + chunk_len ({}), or peaks/root malformed", range.end_clc_state.tree_size, range.start_clc_state.tree_size, chunk_len ); @@ -2208,11 +2227,11 @@ fn verify_op_sequence_timed_inner( let mut tree = match crate::decode_pruned_compact_to_merk(pruned_tree_bytes) { Ok(Some(t)) => t, Ok(None) => { - println!("Failed to verify: pruned tree is empty"); + verification_diagnostic!("Failed to verify: pruned tree is empty"); return (false, timings); } Err(e) => { - println!("Failed to decode compact pruned tree into Merk: {:?}", e); + verification_diagnostic!("Failed to decode compact pruned tree into Merk: {:?}", e); return (false, timings); } }; @@ -2227,7 +2246,7 @@ fn verify_op_sequence_timed_inner( timings.pruned_tree_root_check_cycles = cycle_count() - t0; timings.pruned_tree_cycles = cycle_count() - pruned_tree_t0; if !start_root_matches { - println!("Failed to verify: computed start root does not match"); + verification_diagnostic!("Failed to verify: computed start root does not match"); return (false, timings); } @@ -2248,14 +2267,16 @@ fn verify_op_sequence_timed_inner( let entry_i = match ChangelogEntry::from_bytes_for_verification(e_i) { Ok(m) => m, Err(e) => { - println!("Failed to verify changes; Changelog entry didn't parse {e:?}"); + verification_diagnostic!( + "Failed to verify changes; Changelog entry didn't parse {e:?}" + ); return (false, timings); } }; timings.entry_decode_cycles += cycle_count() - t0; if !validate_timestamp_hwm(entry_i.timestamp, timestamp_hwm) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} timestamp {} is older than HWM {} by more than {TIMESTAMP_HWM_TOLERANCE_SECONDS}s", entry_i.timestamp, *timestamp_hwm ); @@ -2276,7 +2297,7 @@ fn verify_op_sequence_timed_inner( } if !validate_parent_change(entry_i.parent_change, current_change_id) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} has invalid \ parent_change={} (current_change_id={current_change_id})", entry_i.parent_change @@ -2289,7 +2310,7 @@ fn verify_op_sequence_timed_inner( // server could splice signed entries from a divergent fork into // the proven chain. if !validate_parent_clc(entry_i.parent_change, &entry_i.parent_clc, recent_roots) { - println!( + verification_diagnostic!( "Failed to verify changes; entry {current_change_id} has invalid \ parent_clc for parent_change={}", entry_i.parent_change @@ -2306,7 +2327,7 @@ fn verify_op_sequence_timed_inner( { Ok(r) => r, Err(e) => { - println!("Op validation failed at entry {current_change_id}: {e}"); + verification_diagnostic!("Op validation failed at entry {current_change_id}: {e}"); return (false, timings); } }; @@ -2317,7 +2338,9 @@ fn verify_op_sequence_timed_inner( let writes = match flatten_write_steps(op_result) { Ok(w) => w, Err(e) => { - println!("Op at entry {current_change_id} produced invalid writes: {e}"); + verification_diagnostic!( + "Op at entry {current_change_id} produced invalid writes: {e}" + ); return (false, timings); } }; @@ -2328,7 +2351,7 @@ fn verify_op_sequence_timed_inner( tree = match maybe_tree { Some(t) => t, None => { - println!("Tree became empty after entry {current_change_id}"); + verification_diagnostic!("Tree became empty after entry {current_change_id}"); return (false, timings); } }; @@ -2354,7 +2377,7 @@ fn verify_op_sequence_timed_inner( let t0 = cycle_count(); tree.commit(); if tree.hash() != end_dc_bytes { - println!("Failed to verify changes; ending data root does not match"); + verification_diagnostic!("Failed to verify changes; ending data root does not match"); return (false, timings); } @@ -2362,7 +2385,9 @@ fn verify_op_sequence_timed_inner( .tree_head() .expect("working tree must be non-empty after replay"); if computed_end != range.end_clc_state { - println!("Failed to verify changes; ending tree head does not match replay"); + verification_diagnostic!( + "Failed to verify changes; ending tree head does not match replay" + ); return (false, timings); } timings.final_replay_cycles = cycle_count() - t0; diff --git a/ffproof/changelog_core/src/lib.rs b/ffproof/changelog_core/src/lib.rs index f5490a0..46b5536 100644 --- a/ffproof/changelog_core/src/lib.rs +++ b/ffproof/changelog_core/src/lib.rs @@ -1,3 +1,5 @@ +#![cfg_attr(not(test), deny(clippy::print_stdout))] + // Core modules (merk-only) pub mod changelog; pub mod mmr_tree; diff --git a/sdk/src/changelog.rs b/sdk/src/changelog.rs index 9abf6a2..e8f0b90 100644 --- a/sdk/src/changelog.rs +++ b/sdk/src/changelog.rs @@ -1999,7 +1999,7 @@ impl Space { let mut deferred_sigref: Option<(SigrefMap, SigrefEntries)> = None; if let Some(ref proof) = ff_data.proof { - println!( + log::info!( "Received FF proof covering changes up to {}, proof size: {} bytes", proof.end_change_id, proof.proof.len() @@ -2019,7 +2019,7 @@ impl Space { let end_clc: [u8; 32] = range.end_clc_state.root.into(); let proof_timestamp_hwm = range.timestamp_hwm; - println!( + log::info!( "FF proof verified: start_dc={}, end_dc={}", hex::encode(start_dc), hex::encode(end_dc) @@ -2059,7 +2059,7 @@ impl Space { range.end_change_id ))); } - println!("FF proof start_dc matches initial_dc"); + log::info!("FF proof start_dc matches initial_dc"); // Branch-continuity check. Bind the client's prior // changelog position to the FF proof's `end_clc_state` by @@ -2101,7 +2101,7 @@ impl Space { change_id={prior_change_id}" ))); } - println!("FF branch continuity verified at change_id={prior_change_id}"); + log::info!("FF branch continuity verified at change_id={prior_change_id}"); } else if proof.from_inclusion_proof.is_some() { // Defensive: a from_change_id==0 request should not // come back with a from_inclusion_proof; reject rather @@ -2154,7 +2154,7 @@ impl Space { None }; - println!( + log::info!( "FF proof CLCs: start={}, end={}", hex::encode(start_clc), hex::encode(end_clc) @@ -2254,7 +2254,7 @@ impl Space { self.with_state_mut(|state| { state.current_data_commitment = end_dc; }); - println!( + log::info!( "Set data commitment from FF proof end_dc: {}", hex::encode(end_dc) ); @@ -2266,13 +2266,13 @@ impl Space { self.with_state_mut(|state| { state.current_data_commitment = first_old_root; }); - println!( + log::info!( "Set data commitment from first ragged change's old_root: {}", hex::encode(first_old_root) ); } - println!( + log::info!( "Client state updated to change_id {} via verified FF proof", proof.end_change_id ); @@ -2518,7 +2518,7 @@ impl Space { )) })?; } - println!( + log::info!( "Sigref chain verified: {} user signature(s) checked", sigref_map.len() ); diff --git a/sdk/src/lib.rs b/sdk/src/lib.rs index a51ac33..f40d4b5 100644 --- a/sdk/src/lib.rs +++ b/sdk/src/lib.rs @@ -1,3 +1,5 @@ +#![cfg_attr(not(test), deny(clippy::print_stdout))] + pub mod action; pub mod authentication; mod broadcast;