From 33a3d624b76e353c566a36885f5d76b4ffbb9aaa Mon Sep 17 00:00:00 2001 From: TomZz Date: Sun, 14 Jun 2026 13:57:50 +0800 Subject: [PATCH] Refactor: integrate comprehensive tracing logs and SSH multiplexing This commit introduces a robust logging system and optimizes remote metric collection over SSH: - Logging Infrastructure: - Replaced ad-hoc `eprintln!` and `println!` with the `tracing` crate. - Implemented a rolling file appender in `~/.config/ashell/log/` keeping the last 6 minutes of logs. - Restricted stdout logging to debug builds only, keeping release builds clean. - SSH Multiplexing & Performance: - Shared `russh::client::Handle` across tasks using `Arc>`. - Replaced the 5-second polling of new SSH connections with `SampleMetrics` over the existing channel. - Eliminated authentication log spam and vastly improved polling latency. - Optimized terminal `resize` events to only trigger when dimensions actually change, further reducing UI layout spam and backend load. - Application & Network Auditing: - Log window lifecycles (open, close). - Log UI actions such as session connects and tab closures. - Detailed connection logs distinguishing between graceful EOFs, network drops, and abrupt closures. - Granular SFTP tracking including directory navigation, creation, batch uploads/downloads, and online file editing. --- Cargo.lock | 72 ++++++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 1 + src/app/mod.rs | 22 +++----------- src/app/startup.rs | 44 +++++++++++++++++++++++++++ src/backend/local.rs | 1 + src/backend/ssh.rs | 53 +++++++++++++++++++++++++++----- src/main.rs | 7 +---- src/session/mod.rs | 11 ++++--- src/sftp/mod.rs | 3 ++ src/sftp/ops.rs | 16 ++++++++-- src/terminal/mod.rs | 14 ++++++--- 11 files changed, 202 insertions(+), 42 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 29049d4..16f017a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -335,6 +335,7 @@ dependencies = [ "thiserror 1.0.69", "tokio", "tracing", + "tracing-appender", "tracing-subscriber", "uuid", "walkdir", @@ -1650,6 +1651,15 @@ dependencies = [ "zeroize", ] +[[package]] +name = "deranged" +version = "0.5.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7cd812cc2bc1d69d4764bd80df88b4317eaef9e773c75226407d9bc0876b211c" +dependencies = [ + "powerfmt", +] + [[package]] name = "derive_arbitrary" version = "1.4.2" @@ -4540,6 +4550,12 @@ dependencies = [ "num-traits", ] +[[package]] +name = "num-conv" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "51d515d32fb182ee37cda2ccdcb92950d6a3c2893aa280e540671c2cd0f3b1d9" + [[package]] name = "num-derive" version = "0.4.2" @@ -5371,6 +5387,12 @@ dependencies = [ "zerovec", ] +[[package]] +name = "powerfmt" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391" + [[package]] name = "ppv-lite86" version = "0.2.21" @@ -7298,6 +7320,12 @@ dependencies = [ "zeno", ] +[[package]] +name = "symlink" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7973cce6668464ea31f176d85b13c7ab3bba2cb3b77a2ed26abd7801688010a" + [[package]] name = "syn" version = "2.0.117" @@ -7533,6 +7561,37 @@ dependencies = [ "zune-jpeg 0.5.15", ] +[[package]] +name = "time" +version = "0.3.45" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f9e442fc33d7fdb45aa9bfeb312c095964abdf596f7567261062b2a7107aaabd" +dependencies = [ + "deranged", + "itoa", + "num-conv", + "powerfmt", + "serde_core", + "time-core", + "time-macros", +] + +[[package]] +name = "time-core" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b36ee98fd31ec7426d599183e8fe26932a8dc1fb76ddb6214d05493377d34ca" + +[[package]] +name = "time-macros" +version = "0.2.25" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "71e552d1249bf61ac2a52db88179fd0673def1e1ad8243a00d9ec9ed71fee3dd" +dependencies = [ + "num-conv", + "time-core", +] + [[package]] name = "tiny-keccak" version = "2.0.2" @@ -7807,6 +7866,19 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "050686193eb999b4bb3bc2acfa891a13da00f79734704c4b8b4ef1a10b368a3c" +dependencies = [ + "crossbeam-channel", + "symlink", + "thiserror 2.0.18", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.31" diff --git a/Cargo.toml b/Cargo.toml index 51a55df..11f7d94 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -42,6 +42,7 @@ image = { version = "0.25.9", default-features = false, features = ["png"] } futures = "0.3.32" notify = "6.1.1" open = "5.1" +tracing-appender = "0.2.5" [profile.release] opt-level = 3 diff --git a/src/app/mod.rs b/src/app/mod.rs index 5898b92..f848d73 100644 --- a/src/app/mod.rs +++ b/src/app/mod.rs @@ -31,7 +31,7 @@ use crate::{ session::config::{AuthMethod, ConfigStore}, system::{SystemSampler, SystemSnapshot}, terminal::{self, BackendEvent, TabKind, TerminalTab}, - backend::ssh, + }; #[derive(Clone, Debug)] @@ -778,30 +778,16 @@ impl Ashell { pub(crate) fn request_active_system_snapshot(&mut self) { let Some(ref tab_id) = self.system_tab_id.clone() else { return }; - let Some(session) = (|| { + let Some(backend) = (|| { let tab = self.tabs.iter().find(|t| t.id == *tab_id)?; if !tab.connected { return None; } - tab.session.clone() + Some(tab.backend.clone()) })() else { return }; if self.remote_sample_in_flight { return; } self.remote_sample_in_flight = true; - let events = self.events_tx.clone(); - let tab_id = tab_id.clone(); - self.runtime.spawn(async move { - match ssh::sample_remote_system(session).await { - Ok(snapshot) => { - let _ = events.send(BackendEvent::RemoteSystem { tab_id, snapshot }); - } - Err(err) => { - let _ = events.send(BackendEvent::RemoteSystemUnavailable { - tab_id, - reason: format!("remote metrics unavailable: {err:#}"), - }); - } - } - }); + backend.send(crate::terminal::BackendCommand::SampleMetrics); } pub(crate) fn terminal_ime_bounds_for_range( diff --git a/src/app/startup.rs b/src/app/startup.rs index 9c5bd03..72d3235 100644 --- a/src/app/startup.rs +++ b/src/app/startup.rs @@ -4,6 +4,47 @@ use gpui_component::Root; use crate::session::config::ConfigStore; use crate::Ashell; +pub(crate) fn init_logging() { + use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; + + let log_dir = directories::BaseDirs::new() + .map(|dirs| dirs.home_dir().join(".config").join("ashell").join("log")) + .unwrap_or_else(|| std::path::PathBuf::from(".")); + + std::fs::create_dir_all(&log_dir).ok(); + + let file_appender = tracing_appender::rolling::Builder::new() + .rotation(tracing_appender::rolling::Rotation::MINUTELY) + .max_log_files(6) + .filename_prefix("ashell.log") + .build(log_dir) + .expect("failed to initialize rolling file appender"); + + let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender); + // Leak the guard so it lives for the entire duration of the app since GPUI's run might not return + std::mem::forget(_guard); + + let env_filter = tracing_subscriber::EnvFilter::try_from_default_env() + .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")); + + let stdout_layer = if cfg!(debug_assertions) { + Some(tracing_subscriber::fmt::layer().with_target(true)) + } else { + None + }; + + let file_layer = tracing_subscriber::fmt::layer() + .with_writer(non_blocking) + .with_ansi(false) + .with_target(true); + + tracing_subscriber::registry() + .with(env_filter) + .with(stdout_layer) + .with(file_layer) + .init(); +} + #[cfg(target_os = "macos")] pub(crate) fn sync_macos_launch_environment() { let shell = std::env::var("SHELL").unwrap_or_else(|_| "/bin/zsh".to_string()); @@ -117,9 +158,12 @@ pub(crate) fn open_main_window(cx: &mut App) { gpui_component::Theme::sync_system_appearance(Some(window), cx); let view = cx.new(|cx| Ashell::new(window, cx)); + tracing::info!("[ui] main application window opened"); + let workspace_panels_clone = view.read(cx).workspace_panels.clone(); let body_panels_clone = view.read(cx).body_panels.clone(); window.on_window_should_close(cx, move |window: &mut gpui::Window, cx: &mut gpui::App| { + tracing::info!("[ui] main application window closed, saving layout state..."); let mut config = ConfigStore::load().unwrap_or_else(|_| ConfigStore::in_memory()); let current_bounds = window.window_bounds(); let saved_bounds = match current_bounds { diff --git a/src/backend/local.rs b/src/backend/local.rs index 587fbde..eeb2c83 100644 --- a/src/backend/local.rs +++ b/src/backend/local.rs @@ -115,6 +115,7 @@ pub fn spawn_local_terminal( }); } BackendCommand::Close => break, + BackendCommand::SampleMetrics => {} } } let _ = child.kill(); diff --git a/src/backend/ssh.rs b/src/backend/ssh.rs index 6714b99..dc0bfa5 100644 --- a/src/backend/ssh.rs +++ b/src/backend/ssh.rs @@ -49,10 +49,12 @@ pub fn spawn_ssh_terminal( BackendTx::Ssh(cmd_tx) } -pub async fn sample_remote_system(session: Session) -> Result { - let (events_tx, _events_rx) = std::sync::mpsc::channel(); - let handle = connect_and_authenticate("remote-metrics", &session, &events_tx).await?; +async fn sample_remote_system_with_handle( + handle: Arc>>, +) -> Result { let mut channel = handle + .lock() + .await .channel_open_session() .await .context("open metrics session")?; @@ -72,9 +74,6 @@ pub async fn sample_remote_system(session: Session) -> Result { } } - let _ = handle - .disconnect(Disconnect::ByApplication, "metrics done", "") - .await; let output = String::from_utf8_lossy(&stdout); remote_snapshot_from_kv(&output) } @@ -95,9 +94,11 @@ async fn run_ssh( ), }); - let handle = connect_and_authenticate(&tab_id, &session, &events).await?; + let handle = Arc::new(tokio::sync::Mutex::new(connect_and_authenticate(&tab_id, &session, &events).await?)); let mut channel = handle + .lock() + .await .channel_open_session() .await .context("open session")?; @@ -124,6 +125,7 @@ async fn run_ssh( match command { Some(BackendCommand::Input(bytes)) => { if let Err(err) = channel.data(bytes.as_slice()).await { + tracing::error!("[ssh] write error on tab {}: {}", tab_id, err); exit_reason = format!("ssh write error: {err}"); break; } @@ -131,7 +133,29 @@ async fn run_ssh( Some(BackendCommand::Resize { cols, rows }) => { let _ = channel.window_change(cols.into(), rows.into(), 0, 0).await; } + Some(BackendCommand::SampleMetrics) => { + let handle_clone = handle.clone(); + let tab_id_clone = tab_id.clone(); + let events_clone = events.clone(); + tokio::spawn(async move { + match sample_remote_system_with_handle(handle_clone).await { + Ok(snapshot) => { + let _ = events_clone.send(BackendEvent::RemoteSystem { + tab_id: tab_id_clone, + snapshot, + }); + } + Err(err) => { + let _ = events_clone.send(BackendEvent::RemoteSystemUnavailable { + tab_id: tab_id_clone, + reason: format!("remote metrics unavailable: {err:#}"), + }); + } + } + }); + } Some(BackendCommand::Close) | None => { + tracing::info!("[ssh] local client closed the session for tab {}", tab_id); let _ = channel.eof().await; exit_reason = "ssh session closed".to_string(); break; @@ -151,16 +175,20 @@ async fn run_ssh( } Some(ChannelMsg::Close) => { if is_graceful_close { + tracing::info!("[ssh] session gracefully closed by server for tab {}", tab_id); exit_reason = "ssh session closed".to_string(); } else { + tracing::warn!("[ssh] connection abruptly closed by server for tab {}", tab_id); exit_reason = "ssh connection lost (abrupt close)".to_string(); } break; } None => { if is_graceful_close { + tracing::info!("[ssh] network stream ended gracefully for tab {}", tab_id); exit_reason = "ssh session closed".to_string(); } else { + tracing::warn!("[ssh] network drop detected for tab {}", tab_id); exit_reason = "ssh connection lost (network drop)".to_string(); } break; @@ -172,6 +200,8 @@ async fn run_ssh( } let _ = handle + .lock() + .await .disconnect(Disconnect::ByApplication, "bye", "") .await; let _ = events.send(BackendEvent::Closed { @@ -193,6 +223,7 @@ async fn connect_and_authenticate( ..Default::default() }); let addr = format!("{}:{}", session.host, session.port); + tracing::info!("[ssh] initiating tcp connection to {} (user: {})", addr, session.user); let _ = events.send(BackendEvent::Status { tab_id: tab_id.to_string(), text: format!("opening tcp connection to {addr}"), @@ -200,9 +231,12 @@ async fn connect_and_authenticate( let mut handle = client::connect(config, addr.as_str(), ClientHandler) .await .with_context(|| format!("connect {addr} failed"))?; + + tracing::debug!("[ssh] tcp connected to {}", addr); let authed = match session.auth { AuthMethod::Password => { + tracing::info!("[ssh] sending password authentication for {}@{}", session.user, addr); let _ = events.send(BackendEvent::Status { tab_id: tab_id.to_string(), text: format!( @@ -217,6 +251,7 @@ async fn connect_and_authenticate( } AuthMethod::Key => { let source = key_source_label(session); + tracing::info!("[ssh] sending key authentication for {}@{} (key source: {})", session.user, addr, source); let _ = events.send(BackendEvent::Status { tab_id: tab_id.to_string(), text: format!("connected to {addr}, loading private key from {source}"), @@ -241,6 +276,7 @@ async fn connect_and_authenticate( }; if !authed { + tracing::warn!("[ssh] authentication failed for {}@{}", session.user, addr); let _ = handle .disconnect(Disconnect::ByApplication, "auth failed", "") .await; @@ -262,6 +298,8 @@ async fn connect_and_authenticate( )); } + tracing::info!("[ssh] authentication successful for {}@{}", session.user, addr); + let _ = events.send(BackendEvent::Status { tab_id: tab_id.to_string(), text: format!( @@ -438,6 +476,7 @@ echo "NET_RX=0" echo "NET_TX=0" '"#; +#[derive(Clone)] struct ClientHandler; #[async_trait] diff --git a/src/main.rs b/src/main.rs index 05efc2e..a4543fd 100644 --- a/src/main.rs +++ b/src/main.rs @@ -20,12 +20,7 @@ pub(crate) use app::{ fn main() { app::startup::sync_macos_launch_environment(); - tracing_subscriber::fmt() - .with_env_filter( - tracing_subscriber::EnvFilter::try_from_default_env() - .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")), - ) - .init(); + app::startup::init_logging(); #[cfg(target_os = "macos")] let app = gpui_platform::application() diff --git a/src/session/mod.rs b/src/session/mod.rs index 1078e21..06d33d7 100644 --- a/src/session/mod.rs +++ b/src/session/mod.rs @@ -57,6 +57,7 @@ impl Ashell { } pub(crate) fn connect_ssh(&mut self, window: &mut Window, cx: &mut Context) { + tracing::info!("[ui] user initiating new ssh connection from form"); let session_name = self.session_name_input.read(cx).value().trim().to_string(); let host = self.host_input.read(cx).value().trim().to_string(); let port = self @@ -297,6 +298,7 @@ impl Ashell { } pub(crate) fn connect_saved_session(&mut self, session_id: String, cx: &mut Context) { + tracing::info!("[ui] user clicked to connect saved session '{}'", session_id); let Some(session) = self.config.get(&session_id).cloned() else { self.status = "saved session not found".into(); cx.notify(); @@ -390,6 +392,7 @@ impl Ashell { } pub(crate) fn open_ssh_session(&mut self, session: Session, cx: &mut Context) { + tracing::info!("[session] opening ssh tab for session '{}' ({}@{})", session.name, session.user, session.host); let id = Uuid::new_v4().to_string(); let backend = ssh::spawn_ssh_terminal( self.runtime.handle(), @@ -600,7 +603,7 @@ impl Ashell { let group_ix = self.tab_groups.iter().position(|g| g.pane_root.contains(&id)); let Some(ref group) = group_ix.map(|i| self.tab_groups[i].clone()) else { // Fallback: find and close individual tab - eprintln!("[handle_tab_close] no group found for tab '{}', closing individually", id); + tracing::info!("[handle_tab_close] no group found for tab '{}', closing individually", id); if let Some(ix) = self.tabs.iter().position(|tab| tab.id == id) { self.tabs[ix].backend.send(BackendCommand::Close); self.tabs.remove(ix); @@ -611,7 +614,7 @@ impl Ashell { let pane_ids = group.pane_root.tab_ids(); let pane_ids_str: Vec<&str> = pane_ids.iter().map(|s| *s).collect(); let is_group_close = pane_ids.len() <= 1; - eprintln!( + tracing::info!( "[handle_tab_close] id='{}' group_panes={:?} is_group_close={}", id, pane_ids_str, is_group_close ); @@ -842,7 +845,7 @@ impl Ashell { } pub(crate) fn split_current_pane(&mut self, direction: &str, cx: &mut Context) { - eprintln!( + tracing::info!( "[split] direction={} pane_root={:?} focused_path={:?} active_tab={:?} tabs={}", direction, self.pane_root, @@ -949,7 +952,7 @@ impl Ashell { self.focused_pane_path = new_full_path; self.active_tab = Some(new_id); self.status = "pane split".into(); - eprintln!( + tracing::info!( "[split] DONE: pane_root={:?} focused_path={:?} active_tab={:?} tabs={}", self.pane_root, self.focused_pane_path, diff --git a/src/sftp/mod.rs b/src/sftp/mod.rs index 925a6dd..4904922 100644 --- a/src/sftp/mod.rs +++ b/src/sftp/mod.rs @@ -642,6 +642,8 @@ async fn run_sftp( } else { path.clone() }; + + tracing::info!("[sftp] creating directory: '{}'", actual_path); match sftp.create_dir(&actual_path).await { Ok(_) => { @@ -666,6 +668,7 @@ async fn run_sftp( } } SftpCommand::DeletePaths(paths) => { + tracing::info!("[sftp] batch deleting {} paths", paths.len()); let _ = events.send(BackendEvent::SftpStatus { tab_id: tab_id.clone(), text: t!("deleting_paths", count = paths.len()).to_string(), diff --git a/src/sftp/ops.rs b/src/sftp/ops.rs index 298f132..36e67e4 100644 --- a/src/sftp/ops.rs +++ b/src/sftp/ops.rs @@ -40,6 +40,7 @@ impl Ashell { pub(crate) fn navigate_sftp(&mut self, path: String, cx: &mut Context) { if let Some(handle) = self.active_sftp_handle() { + tracing::info!("[sftp] navigating to directory: '{}'", path); handle.list_dir(path.clone()); if let Some(sftp) = self.active_sftp_mut() { sftp.current_path = path; @@ -134,6 +135,7 @@ impl Ashell { return; }; if let Some(handle) = self.active_sftp_handle() { + tracing::info!("[sftp] triggering edit for file: '{}'", menu.remote_path); handle.edit_file(menu.remote_path); } cx.notify(); @@ -158,7 +160,9 @@ impl Ashell { match path_prompt.await { Ok(Ok(Some(mut paths))) => { if let Some(folder) = paths.pop() { - handle.download(remote_path, folder.to_string_lossy().to_string()); + let local_path = folder.to_string_lossy().to_string(); + tracing::info!("[sftp] initiating download of '{}' to '{}'", remote_path, local_path); + handle.download(remote_path, local_path); } } Ok(Err(err)) => { @@ -192,7 +196,9 @@ impl Ashell { match path_prompt.await { Ok(Ok(Some(mut paths))) => { if let Some(file) = paths.pop() { - handle.upload_paths(vec![file.to_string_lossy().to_string()], remote_dir); + let local_path = file.to_string_lossy().to_string(); + tracing::info!("[sftp] initiating upload of file '{}' to '{}'", local_path, remote_dir); + handle.upload_paths(vec![local_path], remote_dir); } } Ok(Err(err)) => { @@ -226,7 +232,9 @@ impl Ashell { match path_prompt.await { Ok(Ok(Some(mut paths))) => { if let Some(folder) = paths.pop() { - handle.upload_paths(vec![folder.to_string_lossy().to_string()], remote_dir); + let local_path = folder.to_string_lossy().to_string(); + tracing::info!("[sftp] initiating upload of folder '{}' to '{}'", local_path, remote_dir); + handle.upload_paths(vec![local_path], remote_dir); } } Ok(Err(err)) => { @@ -291,6 +299,7 @@ impl Ashell { if let Ok(Ok(Some(mut paths))) = path_prompt.await { if let Some(folder) = paths.pop() { let local_dir = folder.to_string_lossy().to_string(); + tracing::info!("[sftp] initiating batch download of {} entries to '{}'", selected.len(), local_dir); for remote in selected { let _ = handle.commands.send(crate::sftp::SftpCommand::Download { remote, @@ -317,6 +326,7 @@ impl Ashell { } if let Some(sftp) = self.active_sftp() { if let Some(handle) = self.active_sftp_handle() { + tracing::info!("[sftp] initiating batch upload of {} files to '{}'", paths.len(), sftp.current_path); let _ = handle.commands.send(crate::sftp::SftpCommand::UploadPaths { locals: paths, remote_dir: sftp.current_path.clone(), diff --git a/src/terminal/mod.rs b/src/terminal/mod.rs index ab5ee1b..8f8e0d4 100644 --- a/src/terminal/mod.rs +++ b/src/terminal/mod.rs @@ -27,6 +27,7 @@ pub enum TabKind { pub enum BackendCommand { Input(Vec), Resize { cols: u16, rows: u16 }, + SampleMetrics, Close, } @@ -235,10 +236,15 @@ impl TerminalTab { } pub fn resize(&mut self, cols: u16, rows: u16) { - self.cols = cols.max(1); - self.rows = rows.max(1); - self.term.resize(TerminalSize::new(self.cols, self.rows)); - self.backend.send(BackendCommand::Resize { cols, rows }); + let new_cols = cols.max(1); + let new_rows = rows.max(1); + if self.cols != new_cols || self.rows != new_rows { + self.cols = new_cols; + self.rows = new_rows; + tracing::info!("[ui] terminal resized to {}x{} (cols x rows)", self.cols, self.rows); + self.term.resize(TerminalSize::new(self.cols, self.rows)); + self.backend.send(BackendCommand::Resize { cols, rows }); + } } pub fn cursor_state(&self) -> Option {