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

* perf(sandbox): streaming SHA256, spawn_blocking for identity resolution

Key changes:
- Replace full file read + SHA256 with streaming 64KB-buffered hash
  (saves 124MB allocation for node binary)
- Wrap evaluate_opa_tcp in spawn_blocking to prevent blocking tokio
  runtime during heavy /proc I/O and SHA256 computation
- Add file-based perf logging for profiling proxy latency phases

Profiling data (node binary, 124MB):
- Cold TOFU: ~890ms (read+hash), warm: 0ms (cache hit)
- evaluate_opa_tcp: cold=1002ms, warm=11ms
- OPA evaluation: 1ms
- DNS+TCP connect: 166-437ms

Made-with: Cursor
Signed-off-by: Rafael Koike <koike.rafael@gmail.com>

* refactor(sandbox): replace perf_log with tracing::debug

Replace the custom file-based perf_log() helper with standard
tracing::debug!() macros as requested in PR review. This removes
the custom log file writes to /var/log/openshell-perf.log and
routes all performance timing through the tracing framework at
DEBUG level, consistent with the rest of the codebase.

Made-with: Cursor

* refactor(sandbox): reduce tracing to 6 key diagnostic logs

Address PR review feedback:

1. Remove ~20 inner-phase timing logs, keeping only the 6 that tell
   the full diagnostic story:
   - evaluate_opa_tcp TOTAL (proxy.rs)
   - dns_resolve_and_tcp_connect (proxy.rs)
   - file_sha256 (procfs.rs)
   - verify_or_cache CACHE HIT / CACHE MISS / TOTAL cold (identity.rs)

2. Restore intent-describing comments that were replaced by timing logs:
   - "TOFU verify the immediate binary" (proxy.rs)
   - "Walk the process tree upward to collect ancestor binaries" (proxy.rs)
   - "Collect cmdline paths for script-based binary detection." (proxy.rs)
   - "First: scan descendants of the entrypoint process" (procfs.rs)
   - "Fallback: scan all of /proc in case the process isn't in the tree" (procfs.rs)
   - "Skip PIDs we already checked" (procfs.rs)

3. Preserve file path in file_sha256 read errors instead of losing
   context via into_diagnostic().

4. Tests: 293 passed, 1 pre-existing failure (drop_privileges), 1 ignored.

Made-with: Cursor

* style(sandbox): apply rustfmt formatting to debug macros

---------

Signed-off-by: Rafael Koike <koike.rafael@gmail.com>
Co-authored-by: John Myers <johntmyers@users.noreply.github.com>

Author: koiker

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,9 +116,20 @@ 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 current_hash = hash_file(path)?;
 
         let mut hashes = self
@@ -143,6 +156,12 @@ 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

@@ -6,10 +6,11 @@
 //! Provides functions to resolve binary paths and compute file hashes
 //! for process-identity binding in the OPA proxy policy engine.
 
-use miette::{IntoDiagnostic, Result};
+use miette::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.
 ///
@@ -229,16 +230,16 @@ fn parse_proc_net_tcp(pid: u32, peer_port: u16) -> Result<u64> {
 fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result<u32> {
     let target = format!("socket:[{inode}]");
 
-    // First: scan descendants of the entrypoint process (targeted, most likely to succeed)
+    // First: scan descendants of the entrypoint process
     let descendants = collect_descendant_pids(entrypoint_pid);
+
     for &pid in &descendants {
         if let Some(found) = check_pid_fds(pid, &target) {
             return Ok(found);
         }
     }
 
     // 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)
     if let Ok(proc_dir) = std::fs::read_dir("/proc") {
         for entry in proc_dir.flatten() {
             let name = entry.file_name();
@@ -318,9 +319,32 @@ 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)
+            .map_err(|e| miette::miette!("Failed to read {}: {e}", path.display()))?;
+        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,15 +336,25 @@ 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,
-    );
+    // 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}"))?;
 
     // Extract action string and matched policy for logging
     let (matched_policy, deny_reason) = match &decision.action {
@@ -426,6 +436,7 @@ async fn handle_tcp_connection(
     }
 
     // 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.
@@ -502,6 +513,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
@@ -736,7 +752,9 @@ fn evaluate_opa_tcp(
         );
     }
 
+    let total_start = std::time::Instant::now();
     let peer_port = peer_addr.port();
+
     let (bin_path, binary_pid) = match crate::procfs::resolve_tcp_peer_identity(pid, peer_port) {
         Ok(r) => r,
         Err(e) => {
@@ -767,7 +785,6 @@ fn evaluate_opa_tcp(
     // Walk the process tree upward to collect ancestor binaries
     let ancestors = crate::procfs::collect_ancestor_binaries(binary_pid, pid);
 
-    // TOFU verify each ancestor binary
     for ancestor in &ancestors {
         if let Err(e) = identity_cache.verify_or_cache(ancestor) {
             return deny(
@@ -784,7 +801,6 @@ fn evaluate_opa_tcp(
     }
 
     // Collect cmdline paths for script-based binary detection.
-    // Excludes exe paths already captured in bin_path/ancestors to avoid duplicates.
     let mut exclude = ancestors.clone();
     exclude.push(bin_path.clone());
     let cmdline_paths = crate::procfs::collect_cmdline_paths(binary_pid, pid, &exclude);
@@ -798,7 +814,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),
@@ -813,7 +829,12 @@ fn evaluate_opa_tcp(
             ancestors,
             cmdline_paths,
         ),
-    }
+    };
+    debug!(
+        "evaluate_opa_tcp TOTAL: {}ms host={host} port={port}",
+        total_start.elapsed().as_millis()
+    );
+    result
 }
 
 /// Non-Linux stub: OPA identity binding requires /proc.
@@ -1728,14 +1749,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