diff options
| author | Ogulcan Celik <ogulcancelik@gmail.com> | 2026-04-23 00:48:22 +0300 |
|---|---|---|
| committer | Ogulcan Celik <ogulcancelik@gmail.com> | 2026-04-23 00:48:22 +0300 |
| commit | 40750418049c5125724b004c8f55ae66ca77edcf (patch) | |
| tree | d72ecadb0506c3643ffaa5fe7cf40f22c90d967a /src | |
| parent | 3d6f3e78624f1308a360cbf02eeca3fec2434436 (diff) | |
feat(logging): add robust rotating support logs
Diffstat (limited to 'src')
| -rw-r--r-- | src/api/mod.rs | 126 | ||||
| -rw-r--r-- | src/app/actions.rs | 27 | ||||
| -rw-r--r-- | src/app/api.rs | 82 | ||||
| -rw-r--r-- | src/app/config_io.rs | 2 | ||||
| -rw-r--r-- | src/app/creation.rs | 9 | ||||
| -rw-r--r-- | src/app/input/modal.rs | 22 | ||||
| -rw-r--r-- | src/app/mod.rs | 4 | ||||
| -rw-r--r-- | src/client/mod.rs | 5 | ||||
| -rw-r--r-- | src/logging.rs | 605 | ||||
| -rw-r--r-- | src/main.rs | 11 | ||||
| -rw-r--r-- | src/pane.rs | 16 | ||||
| -rw-r--r-- | src/persist/io.rs | 10 | ||||
| -rw-r--r-- | src/server/headless.rs | 3 | ||||
| -rw-r--r-- | src/update.rs | 8 | ||||
| -rw-r--r-- | src/workspace.rs | 2 |
15 files changed, 841 insertions, 91 deletions
diff --git a/src/api/mod.rs b/src/api/mod.rs index 437a616e..7da81d12 100644 --- a/src/api/mod.rs +++ b/src/api/mod.rs @@ -218,26 +218,70 @@ fn handle_connection( } }; + let request_id = request.id.clone(); + let method = api_method_name(&request.method); + crate::logging::api_request_started(&request_id, method, request_changes_ui(&request)); + match request.method { Method::EventsSubscribe(params) => { - stream_subscriptions(stream, request.id, params, api_tx, event_hub, running) + let result = stream_subscriptions( + stream, + request_id.clone(), + params, + api_tx, + event_hub, + running, + ); + match &result { + Ok(()) => { + crate::logging::api_request_completed(&request_id, method, "stream_closed") + } + Err(err) => { + crate::logging::api_request_failed(&request_id, method, &err.to_string()) + } + } + result } Method::PaneWaitForOutput(params) => { - let Some(response) = wait_for_output(request.id, params, &mut stream, api_tx, running)? + let Some(response) = + wait_for_output(request_id.clone(), params, &mut stream, api_tx, running)? else { + crate::logging::api_request_completed(&request_id, method, "client_disconnected"); return Ok(()); }; - write_text_line_allow_disconnect(&mut stream, &response) + let result = write_text_line_allow_disconnect(&mut stream, &response); + match &result { + Ok(()) => crate::logging::api_request_completed( + &request_id, + method, + api_response_outcome(&response), + ), + Err(err) => { + crate::logging::api_request_failed(&request_id, method, &err.to_string()) + } + } + result } - method => { + method_body => { let response = handle_request( Request { - id: request.id, - method, + id: request_id.clone(), + method: method_body, }, api_tx, ); - write_text_line_allow_disconnect(&mut stream, &response) + let result = write_text_line_allow_disconnect(&mut stream, &response); + match &result { + Ok(()) => crate::logging::api_request_completed( + &request_id, + method, + api_response_outcome(&response), + ), + Err(err) => { + crate::logging::api_request_failed(&request_id, method, &err.to_string()) + } + } + result } } } @@ -258,6 +302,57 @@ fn handle_request(request: Request, api_tx: &ApiRequestSender) -> String { } } +fn api_method_name(method: &Method) -> &'static str { + match method { + Method::Ping(_) => "ping", + Method::ServerStop(_) => "server.stop", + Method::WorkspaceCreate(_) => "workspace.create", + Method::WorkspaceList(_) => "workspace.list", + Method::WorkspaceGet(_) => "workspace.get", + Method::WorkspaceFocus(_) => "workspace.focus", + Method::WorkspaceRename(_) => "workspace.rename", + Method::WorkspaceClose(_) => "workspace.close", + Method::TabCreate(_) => "tab.create", + Method::TabList(_) => "tab.list", + Method::TabGet(_) => "tab.get", + Method::TabFocus(_) => "tab.focus", + Method::TabRename(_) => "tab.rename", + Method::TabClose(_) => "tab.close", + Method::PaneSplit(_) => "pane.split", + Method::PaneList(_) => "pane.list", + Method::PaneGet(_) => "pane.get", + Method::PaneSendText(_) => "pane.send_text", + Method::PaneSendKeys(_) => "pane.send_keys", + Method::PaneSendInput(_) => "pane.send_input", + Method::PaneRead(_) => "pane.read", + Method::PaneReportAgent(_) => "pane.report_agent", + Method::PaneClearAgentAuthority(_) => "pane.clear_agent_authority", + Method::PaneReleaseAgent(_) => "pane.release_agent", + Method::PaneClose(_) => "pane.close", + Method::EventsSubscribe(_) => "events.subscribe", + Method::EventsWait(_) => "events.wait", + Method::PaneWaitForOutput(_) => "pane.wait_for_output", + Method::IntegrationInstall(_) => "integration.install", + Method::IntegrationUninstall(_) => "integration.uninstall", + } +} + +fn api_response_outcome(response: &str) -> &'static str { + let Ok(value) = serde_json::from_str::<serde_json::Value>(response) else { + return "error"; + }; + + match value + .get("error") + .and_then(|error| error.get("code")) + .and_then(|code| code.as_str()) + { + Some("timeout") => "timeout", + Some(_) => "error", + None => "ok", + } +} + fn output_match_read_source( source: &crate::api::schema::ReadSource, ) -> crate::api::schema::ReadSource { @@ -274,6 +369,7 @@ fn wait_for_output( api_tx: &ApiRequestSender, running: &Arc<AtomicBool>, ) -> std::io::Result<Option<String>> { + crate::logging::api_wait_started(&request_id, ¶ms.pane_id, params.timeout_ms); let deadline = params .timeout_ms .map(|ms| std::time::Instant::now() + std::time::Duration::from_millis(ms)); @@ -299,6 +395,7 @@ fn wait_for_output( loop { if should_stop_connection(stream, running)? { + crate::logging::api_wait_completed(&request_id, ¶ms.pane_id, "client_disconnected"); return Ok(None); } @@ -340,6 +437,7 @@ fn wait_for_output( let matched_line = match_output(&read.text, ¶ms.r#match, regex.as_ref()); if matched_line.is_some() { let revision = read.revision; + crate::logging::api_wait_completed(&request_id, ¶ms.pane_id, "matched"); return Ok(Some( serde_json::to_string(&SuccessResponse { id: request_id, @@ -355,6 +453,7 @@ fn wait_for_output( } if deadline.is_some_and(|deadline| std::time::Instant::now() >= deadline) { + crate::logging::api_wait_timed_out(&request_id, ¶ms.pane_id); return Ok(Some( serde_json::to_string(&ErrorResponse { id: request_id, @@ -992,6 +1091,19 @@ mod tests { } #[test] + fn api_response_outcome_uses_top_level_error_shape() { + let ok_with_error_text = r#"{"id":"req","result":{"read":{"text":"user said \"error\": \"timeout\"","revision":1}}}"#; + assert_eq!(api_response_outcome(ok_with_error_text), "ok"); + + let timeout = r#"{"id":"req","error":{"code":"timeout","message":"timed out waiting for output match"}}"#; + assert_eq!(api_response_outcome(timeout), "timeout"); + + let generic_error = + r#"{"id":"req","error":{"code":"server_unavailable","message":"boom"}}"#; + assert_eq!(api_response_outcome(generic_error), "error"); + } + + #[test] fn ping_request_returns_pong() { let (tx, _rx) = mpsc::unbounded_channel(); let response = handle_request( diff --git a/src/app/actions.rs b/src/app/actions.rs index 33952b9f..b1bdfc63 100644 --- a/src/app/actions.rs +++ b/src/app/actions.rs @@ -105,6 +105,8 @@ impl AppState { if idx < self.workspaces.len() { self.active = Some(idx); self.selected = idx; + let workspace_id = self.workspaces[idx].id.clone(); + crate::logging::workspace_focused(&workspace_id); self.mark_session_dirty(); if matches!( self.agent_panel_scope, @@ -114,7 +116,10 @@ impl AppState { } self.ensure_workspace_visible(idx); if let Some(ws) = self.workspaces.get_mut(idx) { - ws.switch_tab(ws.active_tab); + let active_tab = ws.active_tab; + ws.switch_tab(active_tab); + let tab_id = format!("{}:{}", workspace_id, active_tab + 1); + crate::logging::tab_focused(&workspace_id, &tab_id); } self.tab_scroll_follow_active = true; self.refresh_tab_bar_view(); @@ -152,8 +157,14 @@ impl AppState { } pub fn switch_tab(&mut self, idx: usize) { - if let Some(ws) = self.active.and_then(|i| self.workspaces.get_mut(i)) { + if let Some(ws_idx) = self.active { + let Some(ws) = self.workspaces.get_mut(ws_idx) else { + return; + }; ws.switch_tab(idx); + let workspace_id = ws.id.clone(); + let tab_id = format!("{}:{}", workspace_id, idx + 1); + crate::logging::tab_focused(&workspace_id, &tab_id); self.mark_session_dirty(); self.tab_scroll_follow_active = true; self.refresh_tab_bar_view(); @@ -258,8 +269,8 @@ impl AppState { return; } self.mark_session_dirty(); - let name = self.workspaces[self.selected].display_name(); - info!(workspace = %name, "workspace closed"); + let workspace_id = self.workspaces[self.selected].id.clone(); + crate::logging::workspace_closed(&workspace_id); self.workspaces.remove(self.selected); if self.workspaces.is_empty() { self.active = None; @@ -394,8 +405,14 @@ impl AppState { self.close_selected_workspace(); return; } - if let Some(ws) = self.active.and_then(|i| self.workspaces.get_mut(i)) { + if let Some(ws_idx) = self.active { + let Some(ws) = self.workspaces.get_mut(ws_idx) else { + return; + }; + let workspace_id = ws.id.clone(); + let closing_tab_id = format!("{}:{}", workspace_id, ws.active_tab + 1); ws.close_active_tab(); + crate::logging::tab_closed(&workspace_id, &closing_tab_id); self.tab_scroll_follow_active = true; self.refresh_tab_bar_view(); } diff --git a/src/app/api.rs b/src/app/api.rs index b07c1267..364097dc 100644 --- a/src/app/api.rs +++ b/src/app/api.rs @@ -333,6 +333,7 @@ impl App { if let Some(label) = params.label { if let Some(workspace) = self.state.workspaces.get_mut(index) { workspace.set_custom_name(label); + crate::logging::workspace_renamed(&workspace.id); } } let workspace = self.workspace_info(index); @@ -428,6 +429,7 @@ impl App { .unwrap(); }; ws.set_custom_name(params.label.clone()); + crate::logging::workspace_renamed(&ws.id); self.schedule_session_save(); self.emit_event(crate::api::schema::EventEnvelope { event: crate::api::schema::EventKind::WorkspaceRenamed, @@ -604,6 +606,10 @@ impl App { match result { Ok(tab_idx) => { if let Some(label) = label { + let workspace_id = self.state.workspaces[ws_idx].id.clone(); + let tab_id = self + .public_tab_id(ws_idx, tab_idx) + .unwrap_or_else(|| format!("{}:{}", workspace_id, tab_idx + 1)); if let Some(tab) = self .state .workspaces @@ -611,6 +617,7 @@ impl App { .and_then(|ws| ws.tabs.get_mut(tab_idx)) { tab.set_custom_name(label); + crate::logging::tab_renamed(&workspace_id, &tab_id); } } if focus { @@ -682,6 +689,10 @@ impl App { }) .unwrap(); }; + let workspace_id = self.state.workspaces[ws_idx].id.clone(); + let tab_id = self + .public_tab_id(ws_idx, tab_idx) + .unwrap_or_else(|| format!("{}:{}", workspace_id, tab_idx + 1)); let Some(tab) = self .state .workspaces @@ -698,6 +709,7 @@ impl App { .unwrap(); }; tab.set_custom_name(params.label.clone()); + crate::logging::tab_renamed(&workspace_id, &tab_id); self.schedule_session_save(); self.emit_event(crate::api::schema::EventEnvelope { event: crate::api::schema::EventKind::TabRenamed, @@ -1237,6 +1249,7 @@ impl App { }); match path { Ok(path) => { + crate::logging::integration_action("install", "pi", "ok"); vec![format!("installed pi integration to {}", path.display())] } Err(response) => return response, @@ -1254,16 +1267,19 @@ impl App { .unwrap() }); match installed { - Ok(installed) => vec![ - format!( - "installed claude integration hook to {}", - installed.hook_path.display() - ), - format!( - "ensured claude settings at {}", - installed.settings_path.display() - ), - ], + Ok(installed) => { + crate::logging::integration_action("install", "claude", "ok"); + vec![ + format!( + "installed claude integration hook to {}", + installed.hook_path.display() + ), + format!( + "ensured claude settings at {}", + installed.settings_path.display() + ), + ] + } Err(response) => return response, } } @@ -1279,20 +1295,23 @@ impl App { .unwrap() }); match installed { - Ok(installed) => vec![ - format!( - "installed codex integration hook to {}", - installed.hook_path.display() - ), - format!( - "ensured codex hooks at {}", - installed.hooks_path.display() - ), - format!( - "ensured codex config at {}", - installed.config_path.display() - ), - ], + Ok(installed) => { + crate::logging::integration_action("install", "codex", "ok"); + vec![ + format!( + "installed codex integration hook to {}", + installed.hook_path.display() + ), + format!( + "ensured codex hooks at {}", + installed.hooks_path.display() + ), + format!( + "ensured codex config at {}", + installed.config_path.display() + ), + ] + } Err(response) => return response, } } @@ -1308,10 +1327,13 @@ impl App { .unwrap() }); match installed { - Ok(installed) => vec![format!( - "installed opencode integration plugin to {}", - installed.plugin_path.display() - )], + Ok(installed) => { + crate::logging::integration_action("install", "opencode", "ok"); + vec![format!( + "installed opencode integration plugin to {}", + installed.plugin_path.display() + )] + } Err(response) => return response, } } @@ -1341,6 +1363,7 @@ impl App { }); match result { Ok(result) => { + crate::logging::integration_action("uninstall", "pi", "ok"); if result.removed_extension { vec![format!( "removed pi integration extension at {}", @@ -1369,6 +1392,7 @@ impl App { }); match result { Ok(result) => { + crate::logging::integration_action("uninstall", "claude", "ok"); let mut messages = Vec::new(); if result.removed_hook_file { messages.push(format!( @@ -1410,6 +1434,7 @@ impl App { }); match result { Ok(result) => { + crate::logging::integration_action("uninstall", "codex", "ok"); let mut messages = Vec::new(); if result.removed_hook_file { messages.push(format!( @@ -1455,6 +1480,7 @@ impl App { }); match result { Ok(result) => { + crate::logging::integration_action("uninstall", "opencode", "ok"); if result.removed_plugin { vec![format!( "removed opencode integration plugin at {}", diff --git a/src/app/config_io.rs b/src/app/config_io.rs index 5d4b2b13..6770d61e 100644 --- a/src/app/config_io.rs +++ b/src/app/config_io.rs @@ -8,6 +8,7 @@ impl App { let path = crate::config::config_path(); if let Some(parent) = path.parent() { if let Err(err) = std::fs::create_dir_all(parent) { + crate::logging::config_write_failed(&path, error_context, &err.to_string()); self.state.config_diagnostic = Some(format!("failed to save {error_context}: {err}")); self.config_diagnostic_deadline = @@ -19,6 +20,7 @@ impl App { let content = std::fs::read_to_string(&path).unwrap_or_default(); let new_content = update(&content); if let Err(err) = std::fs::write(&path, new_content) { + crate::logging::config_write_failed(&path, error_context, &err.to_string()); self.state.config_diagnostic = Some(format!("failed to save {error_context}: {err}")); self.config_diagnostic_deadline = Some(std::time::Instant::now() + std::time::Duration::from_secs(5)); diff --git a/src/app/creation.rs b/src/app/creation.rs index dd2833e0..508bf023 100644 --- a/src/app/creation.rs +++ b/src/app/creation.rs @@ -89,6 +89,12 @@ impl App { ws.switch_tab(idx); self.state.mode = Mode::Terminal; } + let workspace_id = self.state.workspaces[ws_idx].id.clone(); + let tab_id = self + .public_tab_id(ws_idx, idx) + .unwrap_or_else(|| format!("{}:{}", workspace_id, idx + 1)); + let root_pane = self.state.workspaces[ws_idx].tabs[idx].root_pane.raw(); + crate::logging::tab_created(&workspace_id, &tab_id, root_pane); self.schedule_session_save(); Ok(idx) } @@ -112,6 +118,9 @@ impl App { ws.refresh_git_ahead_behind(); self.state.workspaces.push(ws); let idx = self.state.workspaces.len() - 1; + let workspace_id = self.state.workspaces[idx].id.clone(); + let root_pane = self.state.workspaces[idx].tabs[0].root_pane.raw(); + crate::logging::workspace_created(&workspace_id, root_pane); if focus || self.state.active.is_none() { self.state.switch_workspace(idx); self.state.mode = Mode::Terminal; diff --git a/src/app/input/modal.rs b/src/app/input/modal.rs index 5c3108f2..aa25ea1e 100644 --- a/src/app/input/modal.rs +++ b/src/app/input/modal.rs @@ -263,7 +263,9 @@ pub(super) fn apply_rename_action(state: &mut AppState, action: ModalAction) { match state.mode { Mode::RenameWorkspace if !state.workspaces.is_empty() => { if !new_name.is_empty() { + let workspace_id = state.workspaces[state.selected].id.clone(); state.workspaces[state.selected].set_custom_name(new_name); + crate::logging::workspace_renamed(&workspace_id); state.mark_session_dirty(); } } @@ -278,13 +280,19 @@ pub(super) fn apply_rename_action(state: &mut AppState, action: ModalAction) { }; } Mode::RenameTab => { - if let Some(ws) = state.active.and_then(|i| state.workspaces.get_mut(i)) { - if let Some(tab) = ws.active_tab_mut() { - let keep_auto_name = - tab.is_auto_named() && new_name == tab.number.to_string(); - if !new_name.is_empty() && !keep_auto_name { - tab.set_custom_name(new_name); - state.mark_session_dirty(); + if let Some(ws_idx) = state.active { + if let Some(ws) = state.workspaces.get_mut(ws_idx) { + let workspace_id = ws.id.clone(); + let active_tab = ws.active_tab; + if let Some(tab) = ws.active_tab_mut() { + let keep_auto_name = + tab.is_auto_named() && new_name == tab.number.to_string(); + if !new_name.is_empty() && !keep_auto_name { + tab.set_custom_name(new_name); + let tab_id = format!("{}:{}", workspace_id, active_tab + 1); + crate::logging::tab_renamed(&workspace_id, &tab_id); + state.mark_session_dirty(); + } } } } diff --git a/src/app/mod.rs b/src/app/mod.rs index 78681e06..14c50f7f 100644 --- a/src/app/mod.rs +++ b/src/app/mod.rs @@ -182,7 +182,7 @@ impl App { render_dirty.clone(), ); if ws.is_empty() { - info!("session file found but no workspaces restored"); + crate::logging::session_restored(0, "empty"); ( Vec::new(), None, @@ -192,7 +192,7 @@ impl App { snap.sidebar_section_split.unwrap_or(0.5), ) } else { - info!(count = ws.len(), "session restored"); + crate::logging::session_restored(ws.len(), "ok"); let active = snap.active.filter(|&i| i < ws.len()); let selected = snap.selected.min(ws.len().saturating_sub(1)); ( diff --git a/src/client/mod.rs b/src/client/mod.rs index 66e11ad2..0ca2fe0f 100644 --- a/src/client/mod.rs +++ b/src/client/mod.rs @@ -258,6 +258,7 @@ pub fn run_client() -> io::Result<()> { let toast_config = loaded_config.config.ui.toast; let socket_path = client_socket_path(); + crate::logging::startup("client"); info!(path = %socket_path.display(), "connecting to server"); // Try to connect to the server. @@ -320,7 +321,7 @@ pub fn run_client() -> io::Result<()> { if let Err(err) = result { eprintln!("herdr: {err}"); rt.shutdown_timeout(Duration::from_millis(100)); - info!("herdr client exiting"); + crate::logging::shutdown("client"); if matches!( err, @@ -335,7 +336,7 @@ pub fn run_client() -> io::Result<()> { } rt.shutdown_timeout(Duration::from_millis(100)); - info!("herdr client exiting"); + crate::logging::shutdown("client"); Ok(()) } diff --git a/src/logging.rs b/src/logging.rs index 899a9588..323910ca 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -1,20 +1,22 @@ -pub(crate) fn init_file_logging(file_name: &str) { - use std::fs::{self, OpenOptions}; - use tracing_subscriber::EnvFilter; +use std::fs::{self, File, OpenOptions}; +use std::io::{self, Write}; +use std::path::{Path, PathBuf}; +use std::sync::{Arc, Mutex}; - let log_dir = crate::config::config_dir(); - let _ = fs::create_dir_all(&log_dir); - let log_path = log_dir.join(file_name); +use tracing_subscriber::fmt::writer::MakeWriter; +use tracing_subscriber::EnvFilter; - if let Ok(meta) = fs::metadata(&log_path) { - if meta.len() > 5 * 1024 * 1024 { - let _ = fs::remove_file(&log_path); - } - } +const DEFAULT_MAX_LOG_BYTES: u64 = 5 * 1024 * 1024; +const DEFAULT_RETAINED_LOG_FILES: usize = 4; - let file = match OpenOptions::new().create(true).append(true).open(&log_path) { - Ok(file) => file, - Err(_) => return, +pub(crate) fn init_file_logging(file_name: &str) { + let Ok(make_writer) = RotatingFileMakeWriter::new( + crate::config::config_dir(), + file_name, + DEFAULT_MAX_LOG_BYTES, + DEFAULT_RETAINED_LOG_FILES, + ) else { + return; }; let filter = @@ -22,8 +24,579 @@ pub(crate) fn init_file_logging(file_name: &str) { let _ = tracing_subscriber::fmt() .with_env_filter(filter) - .with_writer(file) + .with_writer(make_writer) .with_ansi(false) - .with_target(false) + .with_target(true) .try_init(); } + +pub(crate) fn help_log_paths_summary() -> String { + let dir = crate::config::config_dir(); + format!( + "{} (plus herdr-client.log, herdr-server.log)", + dir.join("herdr.log").display() + ) +} + +pub(crate) fn startup(role: &'static str) { + tracing::info!( + event = "app.startup", + subsystem = role, + outcome = "started", + pid = std::process::id(), + "herdr starting" + ); +} + +pub(crate) fn shutdown(role: &'static str) { + tracing::info!( + event = "app.shutdown", + subsystem = role, + outcome = "completed", + pid = std::process::id(), + "herdr exiting" + ); +} + +pub(crate) fn api_request_started(request_id: &str, method: &'static str, changes_ui: bool) { + tracing::info!( + event = "api.request.start", + subsystem = "api", + outcome = "started", + request_id, + method, + changes_ui, + "api request received" + ); +} + +pub(crate) fn api_request_completed(request_id: &str, method: &'static str, outcome: &'static str) { + tracing::info!( + event = "api.request.complete", + subsystem = "api", + outcome, + request_id, + method, + "api request completed" + ); +} + +pub(crate) fn api_request_failed(request_id: &str, method: &'static str, err: &str) { + tracing::warn!( + event = "api.request.fail", + subsystem = "api", + outcome = "error", + request_id, + method, + err, + "api request failed" + ); +} + +pub(crate) fn api_wait_started(request_id: &str, pane_id: &str, timeout_ms: Option<u64>) { + tracing::info!( + event = "api.wait.start", + subsystem = "api", + outcome = "started", + request_id, + pane_id, + timeout_ms, + "api output wait started" + ); +} + +pub(crate) fn api_wait_completed(request_id: &str, pane_id: &str, outcome: &'static str) { + tracing::info!( + event = "api.wait.complete", + subsystem = "api", + outcome, + request_id, + pane_id, + "api output wait finished" + ); +} + +pub(crate) fn api_wait_timed_out(request_id: &str, pane_id: &str) { + tracing::warn!( + event = "api.wait.timeout", + subsystem = "api", + outcome = "timeout", + request_id, + pane_id, + "api output wait timed out" + ); +} + +pub(crate) fn pane_spawn_started( + pane_id: u32, + rows: u16, + cols: u16, + scrollback_limit_bytes: usize, +) { + tracing::info!( + event = "pane.spawn.start", + subsystem = "pane", + outcome = "started", + pane_id, + rows, + cols, + scrollback_limit_bytes, + "spawning pane terminal" + ); +} + +pub(crate) fn pane_spawned(pane_id: u32, pid: u32) { + tracing::info!( + event = "pane.spawned", + subsystem = "pane", + outcome = "ok", + pane_id, + pid, + "pane child spawned" + ); +} + +pub(crate) fn pane_exited(pane_id: u32, status: &str) { + tracing::info!( + event = "pane.exit", + subsystem = "pane", + outcome = "completed", + pane_id, + status, + "pane child exited" + ); +} + +pub(crate) fn pane_exit_failed(pane_id: u32, err: &str) { + tracing::error!( + event = "pane.exit", + subsystem = "pane", + outcome = "error", + pane_id, + err, + "pane child wait failed" + ); +} + +pub(crate) fn workspace_created(workspace_id: &str, root_pane_id: u32) { + tracing::info!( + event = "workspace.create", + subsystem = "workspace", + outcome = "ok", + workspace_id, + pane_id = root_pane_id, + "workspace created" + ); +} + +pub(crate) fn workspace_focused(workspace_id: &str) { + tracing::info!( + event = "workspace.focus", + subsystem = "workspace", + outcome = "ok", + workspace_id, + "workspace focused" + ); +} + +pub(crate) fn workspace_closed(workspace_id: &str) { + tracing::info!( + event = "workspace.close", + subsystem = "workspace", + outcome = "ok", + workspace_id, + "workspace closed" + ); +} + +pub(crate) fn workspace_renamed(workspace_id: &str) { + tracing::info!( + event = "workspace.rename", + subsystem = "workspace", + outcome = "ok", + workspace_id, + "workspace renamed" + ); +} + +pub(crate) fn tab_created(workspace_id: &str, tab_id: &str, root_pane_id: u32) { + tracing::info!( + event = "tab.create", + subsystem = "tab", + outcome = "ok", + workspace_id, + tab_id, + pane_id = root_pane_id, + "tab created" + ); +} + +pub(crate) fn tab_focused(workspace_id: &str, tab_id: &str) { + tracing::info!( + event = "tab.focus", + subsystem = "tab", + outcome = "ok", + workspace_id, + tab_id, + "tab focused" + ); +} + +pub(crate) fn tab_closed(workspace_id: &str, tab_id: &str) { + tracing::info!( + event = "tab.close", + subsystem = "tab", + outcome = "ok", + workspace_id, + tab_id, + "tab closed" + ); +} + +pub(crate) fn tab_renamed(workspace_id: &str, tab_id: &str) { + tracing::info!( + event = "tab.rename", + subsystem = "tab", + outcome = "ok", + workspace_id, + tab_id, + "tab renamed" + ); +} + +pub(crate) fn session_saved(path: &Path, workspaces: usize) { + tracing::info!( + event = "persist.save", + subsystem = "persist", + outcome = "ok", + path = %path.display(), + workspaces, + "session saved" + ); +} + +pub(crate) fn session_save_failed(path: &Path, err: &str) { + tracing::error!( + event = "persist.save", + subsystem = "persist", + outcome = "error", + path = %path.display(), + err, + "failed to save session" + ); +} + +pub(crate) fn session_cleared(path: &Path) { + tracing::info!( + event = "persist.clear", + subsystem = "persist", + outcome = "ok", + path = %path.display(), + "session cleared" + ); +} + +pub(crate) fn session_clear_failed(path: &Path, err: &str) { + tracing::error!( + event = "persist.clear", + subsystem = "persist", + outcome = "error", + path = %path.display(), + err, + "failed to clear session" + ); +} + +pub(crate) fn session_restored(workspaces: usize, outcome: &'static str) { + tracing::info!( + event = "persist.restore", + subsystem = "persist", + outcome, + workspaces, + "session restore evaluated" + ); +} + +pub(crate) fn update_check_started() { + tracing::info!( + event = "update.check.start", + subsystem = "update", + outcome = "started", + "checking for updates" + ); +} + +pub(crate) fn update_check_failed(err: &str) { + tracing::warn!( + event = "update.check.complete", + subsystem = "update", + outcome = "error", + err, + "update check failed" + ); +} + +pub(crate) fn update_available(version: &str) { + tracing::info!( + event = "update.available", + subsystem = "update", + outcome = "ok", + version, + "update available" + ); +} + +pub(crate) fn config_write_failed(path: &Path, context: &str, err: &str) { + tracing::warn!( + event = "config.write", + subsystem = "config", + outcome = "error", + path = %path.display(), + context, + err, + "failed to write config" + ); +} + +pub(crate) fn integration_action( + action: &'static str, + target: &'static str, + outcome: &'static str, +) { + tracing::info!( + event = "integration.action", + subsystem = "integration", + outcome, + action, + target, + "integration action finished" + ); +} + +struct RotatingFileMakeWriter { + state: Arc<Mutex<RotatingFileState>>, +} + +impl RotatingFileMakeWriter { + fn new( + dir: PathBuf, + file_name: &str, + max_bytes: u64, + retained_files: usize, + ) -> io::Result<Self> { + fs::create_dir_all(&dir)?; + let path = dir.join(file_name); + let mut state = RotatingFileState { + path, + max_bytes, + retained_files, + file: None, + current_size: 0, + disabled: false, + }; + state.open_current_file()?; + Ok(Self { + state: Arc::new(Mutex::new(state)), + }) + } +} + +impl<'a> MakeWriter<'a> for RotatingFileMakeWriter { + type Writer = RotatingFileGuard; + + fn make_writer(&'a self) -> Self::Writer { + RotatingFileGuard { + state: Arc::clone(&self.state), + } + } +} + +struct RotatingFileGuard { + state: Arc<Mutex<RotatingFileState>>, +} + +impl Write for RotatingFileGuard { + fn write(&mut self, buf: &[u8]) -> io::Result<usize> { + let Ok(mut state) = self.state.lock() else { + return Ok(buf.len()); + }; + if state.disabled { + return Ok(buf.len()); + } + if state.rotate_if_needed(buf.len() as u64).is_err() { + state.disabled = true; + return Ok(buf.len()); + } + if let Some(file) = state.file.as_mut() { + match file.write(buf) { + Ok(written) => { + state.current_size = state.current_size.saturating_add(written as u64); + Ok(written) + } + Err(_) => { + state.disabled = true; + Ok(buf.len()) + } + } + } else { + Ok(buf.len()) + } + } + + fn flush(&mut self) -> io::Result<()> { + let Ok(mut state) = self.state.lock() else { + return Ok(()); + }; + if state.disabled { + return Ok(()); + } + match state.file.as_mut() { + Some(file) => match file.flush() { + Ok(()) => Ok(()), + Err(_) => { + state.disabled = true; + Ok(()) + } + }, + None => Ok(()), + } + } +} + +struct RotatingFileState { + path: PathBuf, + max_bytes: u64, + retained_files: usize, + file: Option<File>, + current_size: u64, + disabled: bool, +} + +impl RotatingFileState { + fn rotate_if_needed(&mut self, incoming_len: u64) -> io::Result<()> { + if self.file.is_none() { + self.open_current_file()?; + } + if self.max_bytes == 0 || self.current_size.saturating_add(incoming_len) <= self.max_bytes { + return Ok(()); + } + self.rotate_files()?; + self.open_current_file() + } + + fn open_current_file(&mut self) -> io::Result<()> { + let file = OpenOptions::new() + .create(true) + .append(true) + .open(&self.path)?; + self.current_size = file.metadata().map(|meta| meta.len()).unwrap_or(0); + self.file = Some(file); + Ok(()) + } + + fn rotate_files(&mut self) -> io::Result<()> { + self.file.take(); + if self.retained_files == 0 { + match fs::remove_file(&self.path) { + Ok(()) => {} + Err(err) if err.kind() == io::ErrorKind::NotFound => {} + Err(err) => return Err(err), + } + self.current_size = 0; + return Ok(()); + } + + let oldest = rotated_log_path(&self.path, self.retained_files); + match fs::remove_file(&oldest) { + Ok(()) => {} + Err(err) if err.kind() == io::ErrorKind::NotFound => {} + Err(err) => return Err(err), + } + + for index in (1..=self.retained_files).rev() { + let source = if index == 1 { + self.path.clone() + } else { + rotated_log_path(&self.path, index - 1) + }; + let target = rotated_log_path(&self.path, index); + if !source.exists() { + continue; + } + fs::rename(source, target)?; + } + + self.current_size = 0; + Ok(()) + } +} + +fn rotated_log_path(path: &Path, index: usize) -> PathBuf { + let suffix = format!(".{}", index); + let file_name = path + .file_name() + .map(|name| { + let mut name = name.to_os_string(); + name.push(&suffix); + name + }) + .unwrap_or_else(|| suffix.clone().into()); + path.with_file_name(file_name) +} + +#[cfg(test)] +mod tests { + use super::*; + + fn temp_log_path(name: &str) -> PathBuf { + let unique = format!( + "herdr-logging-tests-{}-{}-{}", + name, + std::process::id(), + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_nanos() + ); + std::env::temp_dir().join(unique).join("herdr.log") + } + + #[test] + fn rotated_log_path_appends_numeric_suffix() { + let path = PathBuf::from("/tmp/herdr.log"); + assert_eq!( + rotated_log_path(&path, 2), + PathBuf::from("/tmp/herdr.log.2") + ); + } + + #[test] + fn rotate_files_shifts_existing_generations() { + let path = temp_log_path("rotate"); + fs::create_dir_all(path.parent().unwrap()).unwrap(); + fs::write(&path, "current").unwrap(); + fs::write(rotated_log_path(&path, 1), "older").unwrap(); + + let mut state = RotatingFileState { + path: path.clone(), + max_bytes: 128, + retained_files: 2, + file: None, + current_size: 0, + disabled: false, + }; + state.rotate_files().unwrap(); + + assert_eq!( + fs::read_to_string(rotated_log_path(&path, 1)).unwrap(), + "current" + ); + assert_eq!( + fs::read_to_string(rotated_log_path(&path, 2)).unwrap(), + "older" + ); + assert!(!path.exists()); + + let _ = fs::remove_dir_all(path.parent().unwrap()); + } +} diff --git a/src/main.rs b/src/main.rs index 4f929b22..982e787d 100644 --- a/src/main.rs +++ b/src/main.rs @@ -5,7 +5,6 @@ use crossterm::event::{ KeyboardEnhancementFlags, PopKeyboardEnhancementFlags, PushKeyboardEnhancementFlags, }; use crossterm::execute; -use tracing::info; pub(crate) const HERDR_ENV_VAR: &str = "HERDR_ENV"; pub(crate) const HERDR_ENV_VALUE: &str = "1"; @@ -218,10 +217,7 @@ fn main() -> io::Result<()> { println!(" --help, -h Show this help"); println!(); println!("Config: {}", config::config_path().display()); - println!( - "Logs: {}", - config::config_dir().join("herdr.log").display() - ); + println!("Logs: {}", logging::help_log_paths_summary()); println!("Env: HERDR_CONFIG_PATH overrides config file path"); println!("Home: https://herdr.dev"); return Ok(()); @@ -285,7 +281,6 @@ fn main() -> io::Result<()> { // Auto-detect launch: when --no-session is NOT set, use server/client mode. // Check if a server is running, spawn one if needed, then attach as client. if !no_session { - init_logging(); return server::autodetect::auto_detect_launch(); } @@ -338,7 +333,7 @@ fn main() -> io::Result<()> { loaded_config.diagnostics.len() - 1 )) }; - info!("herdr starting (monolithic), pid={}", std::process::id()); + logging::startup("app"); // Background update check (non-blocking, best-effort) // Only checks for newer versions and notifies the TUI. @@ -411,7 +406,7 @@ fn main() -> io::Result<()> { // Shut down runtime immediately — kills lingering PTY reader/writer tasks rt.shutdown_timeout(std::time::Duration::from_millis(100)); - info!("herdr exiting"); + logging::shutdown("app"); result } diff --git a/src/pane.rs b/src/pane.rs index 8de53f59..ae44bde1 100644 --- a/src/pane.rs +++ b/src/pane.rs @@ -335,10 +335,7 @@ impl PaneRuntime { // --- Writer channel --- let (input_tx, mut input_rx) = mpsc::channel::<Bytes>(32); - info!( - pane = pane_id.raw(), - rows, cols, scrollback_limit_bytes, "spawning pane terminal" - ); + crate::logging::pane_spawn_started(pane_id.raw(), rows, cols, scrollback_limit_bytes); let terminal = crate::ghostty::Terminal::new(cols, rows, scrollback_limit_bytes) .map_err(|e| std::io::Error::other(e.to_string()))?; @@ -368,11 +365,16 @@ impl PaneRuntime { Ok(mut child) => { if let Some(pid) = child.process_id() { child_pid.store(pid, Ordering::Release); - info!(pane = pane_id.raw(), pid, "child spawned"); + crate::logging::pane_spawned(pane_id.raw(), pid); } match child.wait() { - Ok(status) => info!(pane = pane_id.raw(), ?status, "child exited"), - Err(e) => error!(pane = pane_id.raw(), err = %e, "child wait failed"), + Ok(status) => { + let status_text = format!("{status:?}"); + crate::logging::pane_exited(pane_id.raw(), &status_text); + } + Err(e) => { + crate::logging::pane_exit_failed(pane_id.raw(), &e.to_string()) + } } } Err(e) => error!(pane = pane_id.raw(), err = %e, "{spawn_error_message}"), diff --git a/src/persist/io.rs b/src/persist/io.rs index 26e6fd4e..f4acd662 100644 --- a/src/persist/io.rs +++ b/src/persist/io.rs @@ -1,6 +1,6 @@ use std::path::{Path, PathBuf}; -use tracing::{error, info, warn}; +use tracing::warn; use super::snapshot::{parse_snapshot, snapshot_file_version, SessionSnapshot, SNAPSHOT_VERSION}; @@ -33,19 +33,19 @@ pub(super) fn clear_path(path: &Path) -> std::io::Result<()> { pub fn save(snapshot: &SessionSnapshot) { let path = session_path(); if let Err(err) = save_to_path(&path, snapshot) { - error!(err = %err, path = %path.display(), "failed to save session"); + crate::logging::session_save_failed(&path, &err.to_string()); return; } - info!(workspaces = snapshot.workspaces.len(), "session saved"); + crate::logging::session_saved(&path, snapshot.workspaces.len()); } pub fn clear() { let path = session_path(); if let Err(err) = clear_path(&path) { - error!(err = %err, path = %path.display(), "failed to clear session"); + crate::logging::session_clear_failed(&path, &err.to_string()); return; } - info!(path = %path.display(), "session cleared"); + crate::logging::session_cleared(&path); } pub fn load() -> Option<SessionSnapshot> { diff --git a/src/server/headless.rs b/src/server/headless.rs index 414b2fca..b567158c 100644 --- a/src/server/headless.rs +++ b/src/server/headless.rs @@ -393,7 +393,7 @@ impl HeadlessServer { /// - Handles scheduled tasks (resize poll, animation, session save, etc.) /// - Renders virtually and streams frames to clients pub async fn run(&mut self) -> io::Result<()> { - info!("headless server starting"); + crate::logging::startup("server"); // Register SIGINT handler for graceful shutdown. let should_quit = self.should_quit.clone(); @@ -2015,6 +2015,7 @@ pub fn run_server() -> io::Result<()> { }); rt.shutdown_timeout(Duration::from_millis(100)); + crate::logging::shutdown("server"); result } diff --git a/src/update.rs b/src/update.rs index 1183a7eb..6a0b586b 100644 --- a/src/update.rs +++ b/src/update.rs @@ -437,6 +437,7 @@ pub fn self_update() -> Result<Version, String> { /// Background update check: only surface availability and release notes. /// Runs in a background thread at startup. pub fn auto_update(events: tokio::sync::mpsc::Sender<crate::events::AppEvent>) { + crate::logging::update_check_started(); if let Ok(version) = env::var(FAKE_UPDATE_VERSION_ENV) { let version = version.trim(); if !version.is_empty() { @@ -459,9 +460,14 @@ pub fn auto_update(events: tokio::sync::mpsc::Sender<crate::events::AppEvent>) { let release = match check_latest() { Ok(Some(r)) => r, - _ => return, // up to date or failed — silently do nothing + Ok(None) => return, + Err(err) => { + crate::logging::update_check_failed(&err); + return; + } }; + crate::logging::update_available(&release.version.to_string()); tracing::info!( "new version v{} available at {}", release.version, diff --git a/src/workspace.rs b/src/workspace.rs index 6d0d2488..e429ec10 100644 --- a/src/workspace.rs +++ b/src/workspace.rs @@ -7,7 +7,6 @@ use std::time::{SystemTime, UNIX_EPOCH}; use ratatui::layout::Direction; use tokio::sync::{mpsc, Notify}; -use tracing::info; use crate::events::AppEvent; use crate::layout::PaneId; @@ -96,7 +95,6 @@ impl Workspace { )?; let mut public_pane_numbers = HashMap::new(); public_pane_numbers.insert(tab.root_pane, 1); - info!(root_pane = tab.root_pane.raw(), "workspace created"); Ok(Self { id: generate_workspace_id(), custom_name: None, |
