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<Mutex<>>`.
  - 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.
This commit is contained in:
TomZz
2026-06-14 13:57:50 +08:00
parent 78f8626217
commit 33a3d624b7
11 changed files with 202 additions and 42 deletions
Generated
+72
View File
@@ -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"
+1
View File
@@ -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
+4 -18
View File
@@ -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(
+44
View File
@@ -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 {
+1
View File
@@ -115,6 +115,7 @@ pub fn spawn_local_terminal(
});
}
BackendCommand::Close => break,
BackendCommand::SampleMetrics => {}
}
}
let _ = child.kill();
+46 -7
View File
@@ -49,10 +49,12 @@ pub fn spawn_ssh_terminal(
BackendTx::Ssh(cmd_tx)
}
pub async fn sample_remote_system(session: Session) -> Result<SystemSnapshot> {
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<tokio::sync::Mutex<russh::client::Handle<ClientHandler>>>,
) -> Result<SystemSnapshot> {
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<SystemSnapshot> {
}
}
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]
+1 -6
View File
@@ -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()
+7 -4
View File
@@ -57,6 +57,7 @@ impl Ashell {
}
pub(crate) fn connect_ssh(&mut self, window: &mut Window, cx: &mut Context<Self>) {
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<Self>) {
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<Self>) {
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<Self>) {
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,
+3
View File
@@ -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(),
+13 -3
View File
@@ -40,6 +40,7 @@ impl Ashell {
pub(crate) fn navigate_sftp(&mut self, path: String, cx: &mut Context<Self>) {
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(),
+10 -4
View File
@@ -27,6 +27,7 @@ pub enum TabKind {
pub enum BackendCommand {
Input(Vec<u8>),
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<CursorState> {