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

@@ -60,6 +60,9 @@ struct Session {
     writer: Mutex<Box<dyn Write + Send>>,
     killer: Mutex<Box<dyn ChildKiller + Send + Sync>>,
     exited: Arc<AtomicBool>,
+    started: Instant,
+    /// The first input was logged (startup diagnostics, see `spawn`).
+    input_logged: AtomicBool,
 }
 
 type Sessions = Arc<Mutex<HashMap<TerminalId, Arc<Session>>>>;
@@ -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::<Msg>();
         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<AtomicBool>,
     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<Instant> = None;