Fix tun-helper IPC encryption mismatch and unify log format

tun-helper: the GUI encrypts all IPC commands with ChaCha20Poly1305 and
sends them as hex, but the helper was reading plain JSON — every command
was silently dropped and the tunnel core was never started. Fix by:
- Moving IpcCrypto + derive_key into ostp-client/src/ipc_crypto.rs as a
  shared module so GUI and helper always use identical crypto logic.
- Rewriting tun-helper/src/main.rs to hex-decode and decrypt every
  incoming line before JSON-parsing, and to encrypt + hex-encode every
  outgoing HelperMsg before sending.
- Replacing the custom log_to_file() helper with tracing::info/warn/error
  so all helper output goes through the standard tracing pipeline.
- Adding tracing and hex to ostp-tun-helper Cargo.toml; dropping chrono
  (no longer needed after removing log_to_file).

logging: unify output format across all OSTP binaries to match the
standard tracing-subscriber style:
  2026-06-21T19:11:18.643226Z  INFO ostp_server: message
- Enable the `time` feature in tracing-subscriber and set UTC RFC-3339
  timer on both file and stderr layers in init_tracing.
- Remove with_line_number(true) — line numbers are not part of the
  desired format and bloat the target field.
- Replace println! in runner.rs with tracing::info!.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

ostp-client/Cargo.toml

@@ -9,7 +9,7 @@ anyhow.workspace = true
 bytes.workspace = true
 tokio.workspace = true
 tracing.workspace = true
-tracing-subscriber = { version = "0.3", features = ["env-filter"] }
+tracing-subscriber = { version = "0.3", features = ["env-filter", "time"] }
 tracing-appender = "0.2"
 ostp-core = { path = "../ostp-core" }
 ostp-tun = { path = "../ostp-tun" }

ostp-client/src/ipc_crypto.rs

@@ -0,0 +1,41 @@
+use anyhow::{anyhow, Result};
+use chacha20poly1305::{ChaCha20Poly1305, Nonce};
+use chacha20poly1305::aead::{Aead, KeyInit};
+use sha2::{Sha256, Digest};
+
+/// Symmetric IPC channel encryption for the tun-helper ↔ GUI pipe.
+///
+/// Both sides derive the same key from the per-launch random token, so no
+/// secret is ever passed on the command line. The zero nonce is safe here
+/// because each session uses a fresh random token, making key reuse impossible.
+#[derive(Clone)]
+pub struct IpcCrypto {
+    cipher: ChaCha20Poly1305,
+}
+
+impl IpcCrypto {
+    pub fn new(key: &[u8; 32]) -> Self {
+        let cipher = ChaCha20Poly1305::new_from_slice(key)
+            .expect("32-byte key is always valid for ChaCha20Poly1305");
+        Self { cipher }
+    }
+
+    pub fn encrypt(&self, plaintext: &[u8]) -> Result<Vec<u8>> {
+        let nonce = Nonce::from_slice(&[0u8; 12]);
+        self.cipher.encrypt(nonce, plaintext)
+            .map_err(|e| anyhow!("IPC encrypt: {}", e))
+    }
+
+    pub fn decrypt(&self, ciphertext: &[u8]) -> Result<Vec<u8>> {
+        let nonce = Nonce::from_slice(&[0u8; 12]);
+        self.cipher.decrypt(nonce, ciphertext)
+            .map_err(|e| anyhow!("IPC decrypt: {}", e))
+    }
+}
+
+/// Derive a 32-byte key from the per-session random token.
+pub fn derive_key(token: &str) -> [u8; 32] {
+    let mut key = [0u8; 32];
+    key.copy_from_slice(&Sha256::digest(token.as_bytes()));
+    key
+}

ostp-client/src/lib.rs

@@ -9,3 +9,4 @@ pub mod tunnel;
 
 pub mod runner;
 pub mod logging;
+pub mod ipc_crypto;

ostp-client/src/logging.rs

@@ -74,16 +74,20 @@ pub fn init_tracing(level: &str, app_name: &str, version: &str) -> Option<tracin
     if let Ok(file) = OpenOptions::new().create(true).append(true).open(&path) {
         let (file_writer, guard) = tracing_appender::non_blocking(file);
 
+        let timer = tracing_subscriber::fmt::time::UtcTime::rfc_3339();
+
         let fmt_layer = tracing_subscriber::fmt::layer()
             .with_target(true)
-            .with_line_number(true)
+            .with_line_number(false)
             .with_thread_ids(false)
             .with_thread_names(false)
             .with_ansi(false)
+            .with_timer(timer.clone())
             .with_writer(file_writer);
 
         let stderr_layer = tracing_subscriber::fmt::layer()
             .with_target(true)
+            .with_timer(timer)
             .with_writer(std::io::stderr);
 
         let _ = tracing_subscriber::registry()
@@ -107,6 +111,7 @@ pub fn init_tracing(level: &str, app_name: &str, version: &str) -> Option<tracin
         // Fallback: stderr only
         let stderr_layer = tracing_subscriber::fmt::layer()
             .with_target(true)
+            .with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339())
             .with_writer(std::io::stderr);
         let _ = tracing_subscriber::registry()
             .with(EnvFilter::new(level))

ostp-client/src/runner.rs

@@ -13,7 +13,7 @@ pub async fn run_client_core(
     mut shutdown_rx_ext: watch::Receiver<bool>,
     _config_rx: Option<watch::Receiver<ClientConfig>>,
 ) -> Result<()> {
-    println!("[ostp] Starting run_client_core with multi-server architecture");
+    tracing::info!("starting client core");
 
     let router = Arc::new(Router::new(config.routing.clone()));
     let balancer = Arc::new(Balancer::new(&config));

ostp-gui/src-tauri/src/ipc_crypto.rs

@@ -1,41 +1,3 @@
-use anyhow::{anyhow, Result};
-use chacha20poly1305::{ChaCha20Poly1305, Nonce};
-use chacha20poly1305::aead::{Aead, KeyInit};
-use sha2::{Sha256, Digest};
-
-pub struct IpcCrypto {
-    cipher: ChaCha20Poly1305,
-    nonce: [u8; 12],
-}
-
-impl IpcCrypto {
-    pub fn new(key: &[u8; 32]) -> Self {
-        let cipher = ChaCha20Poly1305::new_from_slice(key)
-            .expect("valid key size");
-        let nonce = [0u8; 12];
-        Self { cipher, nonce }
-    }
-
-    pub fn encrypt(&self, plaintext: &[u8]) -> Result<Vec<u8>> {
-        let nonce = Nonce::from_slice(&self.nonce);
-        let ciphertext = self.cipher.encrypt(nonce, plaintext)
-            .map_err(|e| anyhow!("Encryption failed: {}", e))?;
-        Ok(ciphertext)
-    }
-
-    pub fn decrypt(&self, ciphertext: &[u8]) -> Result<Vec<u8>> {
-        let nonce = Nonce::from_slice(&self.nonce);
-        let plaintext = self.cipher.decrypt(nonce, ciphertext)
-            .map_err(|e| anyhow!("Decryption failed: {}", e))?;
-        Ok(plaintext)
-    }
-}
-
-pub fn derive_key(token: &str) -> [u8; 32] {
-    let mut hasher = Sha256::new();
-    hasher.update(token.as_bytes());
-    let result = hasher.finalize();
-    let mut key = [0u8; 32];
-    key.copy_from_slice(&result);
-    key
-}
+// Re-export the shared IPC crypto from ostp-client so that GUI and tun-helper
+// always use identical encrypt/decrypt logic.
+pub use ostp_client::ipc_crypto::{derive_key, IpcCrypto};

ostp-tun-helper/Cargo.toml

@@ -11,10 +11,11 @@ path = "src/main.rs"
 ostp-client = { path = "../ostp-client" }
 tokio = { workspace = true }
 anyhow = { workspace = true }
+tracing = { workspace = true }
 serde = { version = "1", features = ["derive"] }
 serde_json = "1"
 portable-atomic = { workspace = true }
-chrono = "0.4"
+hex = "0.4"
 
 [build-dependencies]
 # no extra build deps needed; manifest is embedded via build.rs

ostp-tun-helper/src/main.rs

@@ -2,30 +2,16 @@
 #![cfg_attr(not(debug_assertions), windows_subsystem = "windows")]
 
 use anyhow::Result;
+use hex;
+use ostp_client::ipc_crypto::{derive_key, IpcCrypto};
 use serde::{Deserialize, Serialize};
 use std::sync::Arc;
 use std::time::Duration;
-use std::io::Write as _;
 use tokio::io::{AsyncBufReadExt, AsyncWriteExt, BufReader};
-use tokio::sync::{watch, Mutex};
 use tokio::net::TcpListener;
+use tokio::sync::{watch, Mutex};
 use portable_atomic::Ordering;
 
-fn log_to_file(msg: &str) {
-    let msg = msg.to_string();
-    tokio::task::spawn_blocking(move || {
-        let path = std::env::current_exe()
-            .ok()
-            .and_then(|p| p.parent().map(|d| d.join("ostp-helper.log")))
-            .unwrap_or_else(|| std::path::PathBuf::from("ostp-helper.log"));
-        if let Ok(mut file) = std::fs::OpenOptions::new().create(true).append(true).open(path) {
-            let _ = writeln!(file, "[{}] {}", chrono::Local::now().format("%Y-%m-%d %H:%M:%S"), msg);
-        }
-    });
-}
-
-
-
 #[derive(Deserialize)]
 #[serde(tag = "cmd", rename_all = "lowercase")]
 enum GuiCmd {
@@ -72,22 +58,22 @@ async fn main() -> Result<()> {
             let path = &args[i + 1];
             if let Ok(content) = std::fs::read_to_string(path) {
                 expected_token = content.trim().to_string();
-                let _ = std::fs::remove_file(path); // securely delete after reading
+                let _ = std::fs::remove_file(path);
             }
         }
     }
 
-    log_to_file("Helper started (TCP mode)");
+    tracing::info!("helper started (TCP mode)");
 
     if expected_token.is_empty() {
-        log_to_file("FATAL: Auth token is required for security (--token-file or OSTP_TUN_TOKEN).");
-        return Err(anyhow::anyhow!("Auth token is required"));
+        tracing::error!("auth token is required (--token-file or OSTP_TUN_TOKEN)");
+        return Err(anyhow::anyhow!("auth token is required"));
     }
 
     if let Err(e) = run_server(expected_token, port).await {
-        log_to_file(&format!("Fatal error: {}", e));
+        tracing::error!("fatal: {}", e);
     }
-    log_to_file("Helper exiting");
+    tracing::info!("helper exiting");
     Ok(())
 }
 
@@ -98,24 +84,26 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
         metrics: None,
     }));
 
+    let ipc_key = derive_key(&expected_token);
+    let crypto = IpcCrypto::new(&ipc_key);
+
     let bind_addr = format!("127.0.0.1:{}", port);
-    log_to_file(&format!("Attempting to bind to {}", bind_addr));
+    tracing::info!("binding to {}", bind_addr);
     let listener = TcpListener::bind(&bind_addr).await.map_err(|e| {
-        log_to_file(&format!("Bind failed: {}", e));
+        tracing::error!("bind failed: {}", e);
         e
     })?;
-    log_to_file("Listening successfully");
+    tracing::info!("listening, waiting for GUI connection");
 
-    // Wait for GUI to connect (60 second timeout)
     let (socket, _) = match tokio::time::timeout(Duration::from_secs(60), listener.accept()).await {
         Ok(Ok(s)) => s,
         _ => {
-            log_to_file("No connection from GUI within 60s, exiting");
+            tracing::warn!("no connection from GUI within 60s, exiting");
             return Ok(());
         }
     };
 
-    log_to_file("GUI connected via TCP");
+    tracing::info!("GUI connected");
 
     let (reader_half, writer_half) = tokio::io::split(socket);
     let writer = Arc::new(Mutex::new(writer_half));
@@ -123,12 +111,20 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
 
     let send_msg = {
         let writer = writer.clone();
+        let crypto = crypto.clone();
         move |msg: HelperMsg| {
             let writer = writer.clone();
+            let crypto = crypto.clone();
             let json = serde_json::to_string(&msg).unwrap_or_default();
             tokio::spawn(async move {
+                match crypto.encrypt(json.as_bytes()) {
+                    Ok(enc) => {
+                        let line = format!("{}\n", hex::encode(&enc));
                         let mut w = writer.lock().await;
-                let _ = w.write_all(format!("{}\n", json).as_bytes()).await;
+                        let _ = w.write_all(line.as_bytes()).await;
+                    }
+                    Err(e) => tracing::error!("send_msg encrypt failed: {}", e),
+                }
             });
         }
     };
@@ -138,7 +134,7 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
         line.clear();
         let n = reader.read_line(&mut line).await.unwrap_or(0);
         if n == 0 {
-            log_to_file("GUI disconnected, stopping tunnel");
+            tracing::info!("GUI disconnected, stopping tunnel");
             let mut st = state.lock().await;
             if let Some(tx) = st.shutdown_tx.take() {
                 let _ = tx.send(true);
@@ -149,10 +145,23 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
         let trimmed = line.trim();
         if trimmed.is_empty() { continue; }
 
-        let cmd: GuiCmd = match serde_json::from_str(trimmed) {
+        // Decrypt the hex-encoded encrypted command from the GUI
+        let decrypted_json = match hex::decode(trimmed)
+            .ok()
+            .and_then(|enc| crypto.decrypt(&enc).ok())
+            .and_then(|dec| String::from_utf8(dec).ok())
+        {
+            Some(s) => s,
+            None => {
+                tracing::warn!("received undecodable command, ignoring");
+                continue;
+            }
+        };
+
+        let cmd: GuiCmd = match serde_json::from_str(&decrypted_json) {
             Ok(c) => c,
             Err(e) => {
-                send_msg(HelperMsg::Error { message: format!("Bad command: {}", e) });
+                send_msg(HelperMsg::Error { message: format!("bad command: {}", e) });
                 continue;
             }
         };
@@ -160,11 +169,11 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
         match cmd {
             GuiCmd::Start { config, token } => {
                 if token != expected_token {
-                    log_to_file("Received START command with invalid token");
-                    send_msg(HelperMsg::Error { message: "Invalid authorization token".to_string() });
+                    tracing::warn!("START command with invalid token");
+                    send_msg(HelperMsg::Error { message: "invalid authorization token".to_string() });
                     continue;
                 }
-                log_to_file("Received START command");
+                tracing::info!("received START command");
                 {
                     let mut st = state.lock().await;
                     if let Some(tx) = st.shutdown_tx.take() {
@@ -176,8 +185,8 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
                 let cfg: ostp_client::config::ClientConfig = match serde_json::from_str(&config) {
                     Ok(c) => c,
                     Err(e) => {
-                        log_to_file(&format!("Config parse error: {}", e));
-                        send_msg(HelperMsg::Error { message: format!("Config parse error: {}", e) });
+                        tracing::error!("config parse error: {}", e);
+                        send_msg(HelperMsg::Error { message: format!("config parse error: {}", e) });
                         continue;
                     }
                 };
@@ -201,21 +210,26 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
 
                 let metrics_for_runner = metrics.clone();
                 let writer_for_err = writer.clone();
+                let crypto_for_err = crypto.clone();
                 let shutdown_rx_for_core = shutdown_rx.clone();
                 tokio::spawn(async move {
-                    log_to_file("Starting tunnel core...");
+                    tracing::info!("starting tunnel core");
                     match ostp_client::runner::run_client_core(cfg, metrics_for_runner, shutdown_rx_for_core, Some(config_rx)).await {
-                        Ok(_) => { log_to_file("Tunnel core stopped normally"); }
+                        Ok(_) => tracing::info!("tunnel core stopped normally"),
                         Err(e) => {
-                            log_to_file(&format!("Tunnel core error: {}", e));
-                            let json = serde_json::to_string(&HelperMsg::Error { message: e.to_string() }).unwrap_or_default();
+                            tracing::error!("tunnel core error: {}", e);
+                            let json = serde_json::to_string(&HelperMsg::Error { message: e.to_string() })
+                                .unwrap_or_default();
+                            if let Ok(enc) = crypto_for_err.encrypt(json.as_bytes()) {
                                 let mut w = writer_for_err.lock().await;
-                            let _ = w.write_all(format!("{}\n", json).as_bytes()).await;
+                                let _ = w.write_all(format!("{}\n", hex::encode(&enc)).as_bytes()).await;
+                            }
                         }
                     }
                 });
 
                 let writer_tick = writer.clone();
+                let crypto_tick = crypto.clone();
                 let metrics_tick = metrics.clone();
                 let mut shutdown_rx_tick = shutdown_rx.clone();
                 tokio::spawn(async move {
@@ -231,17 +245,24 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
                         let cs = metrics_tick.connection_state.load(Ordering::Relaxed);
                         let sent = metrics_tick.bytes_sent.load(Ordering::Relaxed);
                         let recv = metrics_tick.bytes_recv.load(Ordering::Relaxed);
-
                         let rtt = metrics_tick.rtt_ms.load(Ordering::Relaxed);
 
-                        let mut w = writer_tick.lock().await;
+                        let mut msgs: Vec<HelperMsg> = Vec::new();
                         if cs != last_state {
                             last_state = cs;
-                            let json = serde_json::to_string(&HelperMsg::Status { value: cs }).unwrap_or_default();
-                            if w.write_all(format!("{}\n", json).as_bytes()).await.is_err() { break; }
+                            msgs.push(HelperMsg::Status { value: cs });
+                        }
+                        msgs.push(HelperMsg::Metrics { bytes_sent: sent, bytes_recv: recv, rtt_ms: rtt });
+
+                        let mut w = writer_tick.lock().await;
+                        for msg in msgs {
+                            let json = serde_json::to_string(&msg).unwrap_or_default();
+                            if let Ok(enc) = crypto_tick.encrypt(json.as_bytes()) {
+                                if w.write_all(format!("{}\n", hex::encode(&enc)).as_bytes()).await.is_err() {
+                                    return;
+                                }
+                            }
                         }
-                        let json = serde_json::to_string(&HelperMsg::Metrics { bytes_sent: sent, bytes_recv: recv, rtt_ms: rtt }).unwrap_or_default();
-                        if w.write_all(format!("{}\n", json).as_bytes()).await.is_err() { break; }
                         drop(w);
                     }
                 });
@@ -250,15 +271,15 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
             }
             GuiCmd::Reload { config, token } => {
                 if token != expected_token {
-                    send_msg(HelperMsg::Error { message: "Invalid authorization token".to_string() });
+                    send_msg(HelperMsg::Error { message: "invalid authorization token".to_string() });
                     continue;
                 }
-                log_to_file("Received RELOAD command");
+                tracing::info!("received RELOAD command");
 
                 let cfg: ostp_client::config::ClientConfig = match serde_json::from_str(&config) {
                     Ok(c) => c,
                     Err(e) => {
-                        send_msg(HelperMsg::Error { message: format!("Config parse error during reload: {}", e) });
+                        send_msg(HelperMsg::Error { message: format!("config parse error during reload: {}", e) });
                         continue;
                     }
                 };
@@ -267,7 +288,7 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
                     let st = state.lock().await;
                     if let Some(tx) = &st.config_tx {
                         let _ = tx.send(cfg);
-                        log_to_file("Config sent to running core for seamless hot-reload");
+                        tracing::info!("config sent to running core for hot-reload");
                     }
                 }
 
@@ -275,11 +296,11 @@ async fn run_server(expected_token: String, port: u16) -> Result<()> {
             }
             GuiCmd::Stop { token } => {
                 if token != expected_token {
-                    log_to_file("Received STOP command with invalid token");
-                    send_msg(HelperMsg::Error { message: "Invalid authorization token".to_string() });
+                    tracing::warn!("STOP command with invalid token");
+                    send_msg(HelperMsg::Error { message: "invalid authorization token".to_string() });
                     continue;
                 }
-                log_to_file("Received STOP command");
+                tracing::info!("received STOP command");
                 let mut st = state.lock().await;
                 if let Some(tx) = st.shutdown_tx.take() {
                     let _ = tx.send(true);