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

Author: koiker

crates/openshell-sandbox/src/identity.rs

@@ -16,24 +16,7 @@ use std::fs::Metadata;
 use std::os::unix::fs::MetadataExt;
 use std::path::{Path, PathBuf};
 use std::sync::Mutex;
-
-fn perf_log(msg: &str) {
-    use std::io::Write;
-    for path in &["/var/log/openshell-perf.log", "/tmp/openshell-perf.log"] {
-        if let Ok(mut f) = std::fs::OpenOptions::new()
-            .create(true)
-            .append(true)
-            .open(path)
-        {
-            let now = std::time::SystemTime::now()
-                .duration_since(std::time::UNIX_EPOCH)
-                .unwrap_or_default();
-            let _ = writeln!(f, "[{:.3}] {}", now.as_secs_f64(), msg);
-            return;
-        }
-    }
-    eprintln!("PERF_LOG_FALLBACK: {msg}");
-}
+use tracing::debug;
 
 #[derive(Clone)]
 struct FileFingerprint {
@@ -133,24 +116,24 @@ impl BinaryIdentityCache {
         if let Some(cached_binary) = &cached
             && cached_binary.fingerprint == fingerprint
         {
-            perf_log(&format!(
+            debug!(
                 "      verify_or_cache: {}ms CACHE HIT path={}",
                 start.elapsed().as_millis(), path.display()
-            ));
+            );
             return Ok(cached_binary.hash.clone());
         }
 
-        perf_log(&format!(
+        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)?;
-        perf_log(&format!(
+        debug!(
             "      verify_or_cache SHA256: {}ms path={}",
             hash_start.elapsed().as_millis(), path.display()
-        ));
+        );
 
         let mut hashes = self
             .hashes
@@ -176,10 +159,10 @@ impl BinaryIdentityCache {
             },
         );
 
-        perf_log(&format!(
+        debug!(
             "      verify_or_cache TOTAL (cold): {}ms path={}",
             start.elapsed().as_millis(), path.display()
-        ));
+        );
 
         Ok(current_hash)
     }

crates/openshell-sandbox/src/procfs.rs

@@ -10,24 +10,7 @@ use miette::{IntoDiagnostic, Result};
 use std::path::Path;
 #[cfg(target_os = "linux")]
 use std::path::PathBuf;
-
-fn perf_log(msg: &str) {
-    use std::io::Write;
-    for path in &["/var/log/openshell-perf.log", "/tmp/openshell-perf.log"] {
-        if let Ok(mut f) = std::fs::OpenOptions::new()
-            .create(true)
-            .append(true)
-            .open(path)
-        {
-            let now = std::time::SystemTime::now()
-                .duration_since(std::time::UNIX_EPOCH)
-                .unwrap_or_default();
-            let _ = writeln!(f, "[{:.3}] {}", now.as_secs_f64(), msg);
-            return;
-        }
-    }
-    eprintln!("PERF_LOG_FALLBACK: {msg}");
-}
+use tracing::debug;
 
 /// Read the binary path of a process via `/proc/{pid}/exe` symlink.
 ///
@@ -70,29 +53,29 @@ pub fn resolve_tcp_peer_identity(entrypoint_pid: u32, peer_port: u16) -> Result<
 
     let phase = std::time::Instant::now();
     let inode = parse_proc_net_tcp(entrypoint_pid, peer_port)?;
-    perf_log(&format!(
+    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)?;
-    perf_log(&format!(
+    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())?;
-    perf_log(&format!(
+    debug!(
         "    binary_path: {}ms path={}",
         phase.elapsed().as_millis(), path.display()
-    ));
+    );
 
-    perf_log(&format!(
+    debug!(
         "    resolve_tcp_peer_identity TOTAL: {}ms",
         start.elapsed().as_millis()
-    ));
+    );
     Ok((path, pid))
 }
 
@@ -274,25 +257,25 @@ fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result<u32> {
 
     let phase = std::time::Instant::now();
     let descendants = collect_descendant_pids(entrypoint_pid);
-    perf_log(&format!(
+    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) {
-            perf_log(&format!(
+            debug!(
                 "      find_pid_by_socket_inode: {}ms found_pid={} scan=descendants",
                 start.elapsed().as_millis(), found
-            ));
+            );
             return Ok(found);
         }
     }
-    perf_log(&format!(
+    debug!(
         "      descendant_fd_scan (not found): {}ms",
         phase.elapsed().as_millis()
-    ));
+    );
 
     let phase = std::time::Instant::now();
     if let Ok(proc_dir) = std::fs::read_dir("/proc") {
@@ -306,18 +289,18 @@ fn find_pid_by_socket_inode(inode: u64, entrypoint_pid: u32) -> Result<u32> {
                 continue;
             }
             if let Some(found) = check_pid_fds(pid, &target) {
-                perf_log(&format!(
+                debug!(
                     "      find_pid_by_socket_inode: {}ms found_pid={} scan=full_proc",
                     start.elapsed().as_millis(), found
-                ));
+                );
                 return Ok(found);
             }
         }
     }
-    perf_log(&format!(
+    debug!(
         "      full_proc_scan (not found): {}ms",
         phase.elapsed().as_millis()
-    ));
+    );
 
     Err(miette::miette!(
         "No process found owning socket inode {} \
@@ -399,10 +382,10 @@ pub fn file_sha256(path: &Path) -> Result<String> {
     }
 
     let hash = hasher.finalize();
-    perf_log(&format!(
+    debug!(
         "        file_sha256: {}ms size={} path={}",
         start.elapsed().as_millis(), total_read, path.display()
-    ));
+    );
     Ok(hex::encode(hash))
 }
 

crates/openshell-sandbox/src/proxy.rs

@@ -20,24 +20,6 @@ use tokio::sync::mpsc;
 use tokio::task::JoinHandle;
 use tracing::{debug, info, warn};
 
-fn perf_log(msg: &str) {
-    use std::io::Write;
-    for path in &["/var/log/openshell-perf.log", "/tmp/openshell-perf.log"] {
-        if let Ok(mut f) = std::fs::OpenOptions::new()
-            .create(true)
-            .append(true)
-            .open(path)
-        {
-            let now = std::time::SystemTime::now()
-                .duration_since(std::time::UNIX_EPOCH)
-                .unwrap_or_default();
-            let _ = writeln!(f, "[{:.3}] {}", now.as_secs_f64(), msg);
-            return;
-        }
-    }
-    eprintln!("PERF_LOG_FALLBACK: {msg}");
-}
-
 const MAX_HEADER_BYTES: usize = 8192;
 const INFERENCE_LOCAL_HOST: &str = "inference.local";
 
@@ -355,7 +337,7 @@ async fn handle_tcp_connection(
     let local_addr = client.local_addr().into_diagnostic()?;
 
     let connect_start = std::time::Instant::now();
-    perf_log(&format!("handle_tcp_connection START host={host_lc} port={port}"));
+    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:
@@ -376,10 +358,10 @@ async fn handle_tcp_connection(
     })
     .await
     .map_err(|e| miette::miette!("identity resolution task panicked: {e}"))?;
-    perf_log(&format!(
+    debug!(
         "handle_tcp_connection evaluate_opa_tcp: {}ms",
         connect_start.elapsed().as_millis()
-    ));
+    );
 
     // Extract action string and matched policy for logging
     let (matched_policy, deny_reason) = match &decision.action {
@@ -533,10 +515,10 @@ async fn handle_tcp_connection(
         }
     };
 
-    perf_log(&format!(
+    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?;
 
@@ -744,7 +726,7 @@ fn evaluate_opa_tcp(
 
     let total_start = std::time::Instant::now();
     let peer_port = peer_addr.port();
-    perf_log(&format!("evaluate_opa_tcp START host={host} port={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) {
@@ -759,12 +741,12 @@ fn evaluate_opa_tcp(
             );
         }
     };
-    perf_log(&format!(
+    debug!(
         "  resolve_tcp_peer_identity: {}ms binary={} pid={}",
         phase_start.elapsed().as_millis(),
         bin_path.display(),
         binary_pid
-    ));
+    );
 
     let phase_start = std::time::Instant::now();
     let bin_hash = match identity_cache.verify_or_cache(&bin_path) {
@@ -779,19 +761,19 @@ fn evaluate_opa_tcp(
             );
         }
     };
-    perf_log(&format!(
+    debug!(
         "  tofu_verify_binary: {}ms binary={}",
         phase_start.elapsed().as_millis(),
         bin_path.display()
-    ));
+    );
 
     let phase_start = std::time::Instant::now();
     let ancestors = crate::procfs::collect_ancestor_binaries(binary_pid, pid);
-    perf_log(&format!(
+    debug!(
         "  collect_ancestor_binaries: {}ms count={}",
         phase_start.elapsed().as_millis(),
         ancestors.len()
-    ));
+    );
 
     let phase_start = std::time::Instant::now();
     for ancestor in &ancestors {
@@ -808,25 +790,25 @@ fn evaluate_opa_tcp(
                 vec![],
             );
         }
-        perf_log(&format!(
+        debug!(
             "    tofu_verify_ancestor: {}ms ancestor={}",
             ancestor_start.elapsed().as_millis(),
             ancestor.display()
-        ));
+        );
     }
-    perf_log(&format!(
+    debug!(
         "  tofu_verify_all_ancestors: {}ms",
         phase_start.elapsed().as_millis()
-    ));
+    );
 
     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);
-    perf_log(&format!(
+    debug!(
         "  collect_cmdline_paths: {}ms",
         phase_start.elapsed().as_millis()
-    ));
+    );
 
     let phase_start = std::time::Instant::now();
     let input = NetworkInput {
@@ -854,14 +836,14 @@ fn evaluate_opa_tcp(
             cmdline_paths,
         ),
     };
-    perf_log(&format!(
+    debug!(
         "  opa_evaluate_network_action: {}ms",
         phase_start.elapsed().as_millis()
-    ));
-    perf_log(&format!(
+    );
+    debug!(
         "evaluate_opa_tcp TOTAL: {}ms host={host} port={port}",
         total_start.elapsed().as_millis()
-    ));
+    );
     result
 }