perf(sandbox): streaming SHA256 and spawn_blocking for identity resolution

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<String>,
     {
+        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)
     }
 }

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<Pa
 /// Needed for the ancestor walk: we must know the PID to walk `/proc/<pid>/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,34 +252,55 @@ fn parse_proc_net_tcp(pid: u32, peer_port: u16) -> Result<u64> {
 /// `/proc/<pid>/fd/` for processes running as a different user.
 #[cfg(target_os = "linux")]
 fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result<u32> {
+    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/<pid>/task/<tid>/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();
             let pid: u32 = match name.to_string_lossy().parse() {
                 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<u32> {
 /// same hash, or the request is denied.
 pub fn file_sha256(path: &Path) -> Result<String> {
     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))
 }
 

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