From 9bf28dd451145b57398ac0a171b48411ceb502ae Mon Sep 17 00:00:00 2001 From: l0ng-ai <24760907+l0ng-ai@users.noreply.github.com> Date: Thu, 5 Nov 2026 15:23:00 +0800 Subject: [PATCH] chore(terminal): log each session's start, first output and first input (#1493) A terminal that starts but never shows a prompt left nothing in the log: the spawn was logged at debug level only. The spawn (shell, pid, size), the first output (after how long, and whether it is ConPTY's cursor position query) and the first input (and whether it is the cursor position report) are now logged at info level, once per session, so a user's log tells whether the shell never wrote, or its query was never answered. Refs #1224 --- crates/ide-terminal/src/lib.rs | 27 +++++++++++++++++++++++++-- 1 file changed, 25 insertions(+), 2 deletions(-) diff --git a/crates/ide-terminal/src/lib.rs b/crates/ide-terminal/src/lib.rs index f08b3a069..56c6aaf28 100644 --- a/crates/ide-terminal/src/lib.rs +++ b/crates/ide-terminal/src/lib.rs @@ -60,6 +60,9 @@ struct Session { writer: Mutex>, killer: Mutex>, exited: Arc, + started: Instant, + /// The first input was logged (startup diagnostics, see `spawn`). + input_logged: AtomicBool, } type Sessions = Arc>>>; @@ -136,25 +139,34 @@ impl TerminalManager { writer: Mutex::new(writer), killer: Mutex::new(child.clone_killer()), exited: exited.clone(), + started: Instant::now(), + input_logged: AtomicBool::new(false), }); self.sessions.lock().insert(id, session); let (tx, rx) = mpsc::channel::(); let spawned = spawn_reader(id, reader, tx.clone()) .and_then(|_| spawn_waiter(id, child, tx)) - .and_then(|_| spawn_pump(id, rx, on_output, exited, self.sessions.clone(), sink)); + .and_then(|_| spawn_pump(id, rx, on_output, exited, self.sessions.clone(), sink, Instant::now())); if let Err(e) = spawned { if let Some(s) = self.sessions.lock().remove(&id) { let _ = s.killer.lock().kill(); } return Err(IdeError::internal(format!("failed to start terminal threads: {e}"))); } - tracing::debug!(%id, shell, pid = ?info.pid, "terminal spawned"); + // Info level, with the first output and input below: a session that starts but never shows a + // prompt can then be told apart in a user's log (no output, or no reply to the shell's query). + tracing::info!(%id, shell, pid = ?info.pid, cols = size.cols, rows = size.rows, "terminal spawned"); Ok(info) } pub fn write(&self, id: TerminalId, data: &str) -> IdeResult<()> { let session = self.session(id)?; + if !session.input_logged.swap(true, Ordering::Relaxed) { + let cursor_report = data.starts_with("\x1b[") && data.ends_with('R'); + let ms = session.started.elapsed().as_millis(); + tracing::info!(%id, ms, bytes = data.len(), cursor_report, "terminal first input"); + } let mut w = session.writer.lock(); w.write_all(data.as_bytes())?; w.flush()?; @@ -387,8 +399,19 @@ fn spawn_pump( exited: Arc, sessions: Sessions, sink: SharedSink, + started: Instant, ) -> std::io::Result<()> { std::thread::Builder::new().name(format!("openidea-term-pump-{}", id.0)).spawn(move || { + let first_output = std::cell::Cell::new(true); + let on_output = move |text: String| { + if first_output.replace(false) { + // ConPTY asks for the cursor position (`ESC[6n`) and waits for the answer. + let cursor_query = text.contains("\x1b[6n"); + let ms = started.elapsed().as_millis(); + tracing::info!(%id, ms, bytes = text.len(), cursor_query, "terminal first output"); + } + on_output(text) + }; let mut decoder = Utf8Decoder::new(); let mut pending = String::new(); let mut batch_started: Option = None;