diff --git a/crates/openshell-sandbox/src/identity.rs b/crates/openshell-sandbox/src/identity.rs index d27976ba..0cc561ad 100644 --- a/crates/openshell-sandbox/src/identity.rs +++ b/crates/openshell-sandbox/src/identity.rs @@ -16,6 +16,7 @@ use std::fs::Metadata; use std::os::unix::fs::MetadataExt; use std::path::{Path, PathBuf}; use std::sync::Mutex; +use tracing::debug; #[derive(Clone)] struct FileFingerprint { @@ -100,6 +101,7 @@ impl BinaryIdentityCache { where F: FnMut(&Path) -> Result, { + let start = std::time::Instant::now(); let metadata = std::fs::metadata(path) .map_err(|error| miette::miette!("Failed to stat {}: {error}", path.display()))?; let fingerprint = FileFingerprint::from_metadata(&metadata); @@ -114,10 +116,24 @@ impl BinaryIdentityCache { if let Some(cached_binary) = &cached && cached_binary.fingerprint == fingerprint { + debug!( + " verify_or_cache: {}ms CACHE HIT path={}", + start.elapsed().as_millis(), path.display() + ); return Ok(cached_binary.hash.clone()); } + debug!( + " verify_or_cache: CACHE MISS size={} path={}", + metadata.len(), path.display() + ); + + let hash_start = std::time::Instant::now(); let current_hash = hash_file(path)?; + debug!( + " verify_or_cache SHA256: {}ms path={}", + hash_start.elapsed().as_millis(), path.display() + ); let mut hashes = self .hashes @@ -143,6 +159,11 @@ impl BinaryIdentityCache { }, ); + debug!( + " verify_or_cache TOTAL (cold): {}ms path={}", + start.elapsed().as_millis(), path.display() + ); + Ok(current_hash) } } diff --git a/crates/openshell-sandbox/src/procfs.rs b/crates/openshell-sandbox/src/procfs.rs index ece16c82..15360a11 100644 --- a/crates/openshell-sandbox/src/procfs.rs +++ b/crates/openshell-sandbox/src/procfs.rs @@ -10,6 +10,7 @@ use miette::{IntoDiagnostic, Result}; use std::path::Path; #[cfg(target_os = "linux")] use std::path::PathBuf; +use tracing::debug; /// Read the binary path of a process via `/proc/{pid}/exe` symlink. /// @@ -48,9 +49,33 @@ pub fn resolve_tcp_peer_binary(entrypoint_pid: u32, peer_port: u16) -> Result/status` PPid chain. #[cfg(target_os = "linux")] pub fn resolve_tcp_peer_identity(entrypoint_pid: u32, peer_port: u16) -> Result<(PathBuf, u32)> { + let start = std::time::Instant::now(); + + let phase = std::time::Instant::now(); let inode = parse_proc_net_tcp(entrypoint_pid, peer_port)?; + debug!( + " parse_proc_net_tcp: {}ms inode={}", + phase.elapsed().as_millis(), inode + ); + + let phase = std::time::Instant::now(); let pid = find_pid_by_socket_inode(inode, entrypoint_pid)?; + debug!( + " find_pid_by_socket_inode: {}ms pid={}", + phase.elapsed().as_millis(), pid + ); + + let phase = std::time::Instant::now(); let path = binary_path(pid.cast_signed())?; + debug!( + " binary_path: {}ms path={}", + phase.elapsed().as_millis(), path.display() + ); + + debug!( + " resolve_tcp_peer_identity TOTAL: {}ms", + start.elapsed().as_millis() + ); Ok((path, pid)) } @@ -227,18 +252,32 @@ fn parse_proc_net_tcp(pid: u32, peer_port: u16) -> Result { /// `/proc//fd/` for processes running as a different user. #[cfg(target_os = "linux")] fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result { + let start = std::time::Instant::now(); let target = format!("socket:[{inode}]"); - // First: scan descendants of the entrypoint process (targeted, most likely to succeed) + let phase = std::time::Instant::now(); let descendants = collect_descendant_pids(entrypoint_pid); + debug!( + " collect_descendant_pids: {}ms count={}", + phase.elapsed().as_millis(), descendants.len() + ); + + let phase = std::time::Instant::now(); for &pid in &descendants { if let Some(found) = check_pid_fds(pid, &target) { + debug!( + " find_pid_by_socket_inode: {}ms found_pid={} scan=descendants", + start.elapsed().as_millis(), found + ); return Ok(found); } } + debug!( + " descendant_fd_scan (not found): {}ms", + phase.elapsed().as_millis() + ); - // Fallback: scan all of /proc in case the process isn't in the tree - // (e.g., if /proc//task//children wasn't available) + let phase = std::time::Instant::now(); if let Ok(proc_dir) = std::fs::read_dir("/proc") { for entry in proc_dir.flatten() { let name = entry.file_name(); @@ -246,15 +285,22 @@ fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result { Ok(p) => p, Err(_) => continue, }; - // Skip PIDs we already checked if descendants.contains(&pid) { continue; } if let Some(found) = check_pid_fds(pid, &target) { + debug!( + " find_pid_by_socket_inode: {}ms found_pid={} scan=full_proc", + start.elapsed().as_millis(), found + ); return Ok(found); } } } + debug!( + " full_proc_scan (not found): {}ms", + phase.elapsed().as_millis() + ); Err(miette::miette!( "No process found owning socket inode {} \ @@ -318,9 +364,28 @@ fn collect_descendant_pids(root_pid: u32) -> Vec { /// same hash, or the request is denied. pub fn file_sha256(path: &Path) -> Result { use sha2::{Digest, Sha256}; + use std::io::Read; + + let start = std::time::Instant::now(); + let mut file = std::fs::File::open(path) + .map_err(|e| miette::miette!("Failed to open {}: {e}", path.display()))?; + let mut hasher = Sha256::new(); + let mut buf = [0u8; 65536]; + let mut total_read = 0u64; + loop { + let n = file.read(&mut buf).into_diagnostic()?; + if n == 0 { + break; + } + total_read += n as u64; + hasher.update(&buf[..n]); + } - let bytes = std::fs::read(path).into_diagnostic()?; - let hash = Sha256::digest(&bytes); + let hash = hasher.finalize(); + debug!( + " file_sha256: {}ms size={} path={}", + start.elapsed().as_millis(), total_read, path.display() + ); Ok(hex::encode(hash)) } diff --git a/crates/openshell-sandbox/src/proxy.rs b/crates/openshell-sandbox/src/proxy.rs index d662399b..d31e70c4 100644 --- a/crates/openshell-sandbox/src/proxy.rs +++ b/crates/openshell-sandbox/src/proxy.rs @@ -336,14 +336,31 @@ async fn handle_tcp_connection( let peer_addr = client.peer_addr().into_diagnostic()?; let local_addr = client.local_addr().into_diagnostic()?; - // Evaluate OPA policy with process-identity binding - let decision = evaluate_opa_tcp( - peer_addr, - &opa_engine, - &identity_cache, - &entrypoint_pid, - &host_lc, - port, + let connect_start = std::time::Instant::now(); + debug!("handle_tcp_connection START host={host_lc} port={port}"); + + // Evaluate OPA policy with process-identity binding. + // Wrapped in spawn_blocking because identity resolution does heavy sync I/O: + // /proc scanning + SHA256 hashing of binaries (e.g. node at 124MB). + let opa_clone = opa_engine.clone(); + let cache_clone = identity_cache.clone(); + let pid_clone = entrypoint_pid.clone(); + let host_clone = host_lc.clone(); + let decision = tokio::task::spawn_blocking(move || { + evaluate_opa_tcp( + peer_addr, + &opa_clone, + &cache_clone, + &pid_clone, + &host_clone, + port, + ) + }) + .await + .map_err(|e| miette::miette!("identity resolution task panicked: {e}"))?; + debug!( + "handle_tcp_connection evaluate_opa_tcp: {}ms", + connect_start.elapsed().as_millis() ); // Extract action string and matched policy for logging @@ -421,6 +438,7 @@ async fn handle_tcp_connection( let raw_allowed_ips = query_allowed_ips(&opa_engine, &decision, &host_lc, port); // Defense-in-depth: resolve DNS and reject connections to internal IPs. + let dns_connect_start = std::time::Instant::now(); let mut upstream = if !raw_allowed_ips.is_empty() { // allowed_ips mode: validate resolved IPs against CIDR allowlist. // Loopback and link-local are still always blocked. @@ -497,6 +515,11 @@ async fn handle_tcp_connection( } }; + debug!( + "handle_tcp_connection dns_resolve_and_tcp_connect: {}ms host={host_lc}", + dns_connect_start.elapsed().as_millis() + ); + respond(&mut client, b"HTTP/1.1 200 Connection Established\r\n\r\n").await?; // Check if endpoint has L7 config for protocol-aware inspection @@ -701,7 +724,11 @@ fn evaluate_opa_tcp( ); } + let total_start = std::time::Instant::now(); let peer_port = peer_addr.port(); + debug!("evaluate_opa_tcp START host={host} port={port}"); + + let phase_start = std::time::Instant::now(); let (bin_path, binary_pid) = match crate::procfs::resolve_tcp_peer_identity(pid, peer_port) { Ok(r) => r, Err(e) => { @@ -714,8 +741,14 @@ fn evaluate_opa_tcp( ); } }; + debug!( + " resolve_tcp_peer_identity: {}ms binary={} pid={}", + phase_start.elapsed().as_millis(), + bin_path.display(), + binary_pid + ); - // TOFU verify the immediate binary + let phase_start = std::time::Instant::now(); let bin_hash = match identity_cache.verify_or_cache(&bin_path) { Ok(h) => h, Err(e) => { @@ -728,12 +761,23 @@ fn evaluate_opa_tcp( ); } }; + debug!( + " tofu_verify_binary: {}ms binary={}", + phase_start.elapsed().as_millis(), + bin_path.display() + ); - // Walk the process tree upward to collect ancestor binaries + let phase_start = std::time::Instant::now(); let ancestors = crate::procfs::collect_ancestor_binaries(binary_pid, pid); + debug!( + " collect_ancestor_binaries: {}ms count={}", + phase_start.elapsed().as_millis(), + ancestors.len() + ); - // TOFU verify each ancestor binary + let phase_start = std::time::Instant::now(); for ancestor in &ancestors { + let ancestor_start = std::time::Instant::now(); if let Err(e) = identity_cache.verify_or_cache(ancestor) { return deny( format!( @@ -746,14 +790,27 @@ fn evaluate_opa_tcp( vec![], ); } + debug!( + " tofu_verify_ancestor: {}ms ancestor={}", + ancestor_start.elapsed().as_millis(), + ancestor.display() + ); } + debug!( + " tofu_verify_all_ancestors: {}ms", + phase_start.elapsed().as_millis() + ); - // Collect cmdline paths for script-based binary detection. - // Excludes exe paths already captured in bin_path/ancestors to avoid duplicates. + let phase_start = std::time::Instant::now(); let mut exclude = ancestors.clone(); exclude.push(bin_path.clone()); let cmdline_paths = crate::procfs::collect_cmdline_paths(binary_pid, pid, &exclude); + debug!( + " collect_cmdline_paths: {}ms", + phase_start.elapsed().as_millis() + ); + let phase_start = std::time::Instant::now(); let input = NetworkInput { host: host.to_string(), port, @@ -763,7 +820,7 @@ fn evaluate_opa_tcp( cmdline_paths: cmdline_paths.clone(), }; - match engine.evaluate_network_action(&input) { + let result = match engine.evaluate_network_action(&input) { Ok(action) => ConnectDecision { action, binary: Some(bin_path), @@ -778,7 +835,16 @@ fn evaluate_opa_tcp( ancestors, cmdline_paths, ), - } + }; + debug!( + " opa_evaluate_network_action: {}ms", + phase_start.elapsed().as_millis() + ); + debug!( + "evaluate_opa_tcp TOTAL: {}ms host={host} port={port}", + total_start.elapsed().as_millis() + ); + result } /// Non-Linux stub: OPA identity binding requires /proc. @@ -1600,14 +1666,22 @@ async fn handle_forward_proxy( let peer_addr = client.peer_addr().into_diagnostic()?; let local_addr = client.local_addr().into_diagnostic()?; - let decision = evaluate_opa_tcp( - peer_addr, - &opa_engine, - &identity_cache, - &entrypoint_pid, - &host_lc, - port, - ); + let opa_clone = opa_engine.clone(); + let cache_clone = identity_cache.clone(); + let pid_clone = entrypoint_pid.clone(); + let host_clone = host_lc.clone(); + let decision = tokio::task::spawn_blocking(move || { + evaluate_opa_tcp( + peer_addr, + &opa_clone, + &cache_clone, + &pid_clone, + &host_clone, + port, + ) + }) + .await + .map_err(|e| miette::miette!("identity resolution task panicked: {e}"))?; // Build log context let binary_str = decision