daemon debugging

src/attach.rs

@@ -62,6 +62,12 @@ use crate::transport::{TransportError, read_message, write_message};
 /// will get a dedicated CLI flag.
 pub const PMACS_TEST_SSH_BIN: &str = "PMACS_TEST_SSH_BIN";
 
+/// Enable stderr breadcrumbs for SSH attach and the far-side
+/// `--daemon-attach` bridge. The local side propagates this to the
+/// remote command via `env PMACS_ATTACH_DEBUG=1 ...`, so users only
+/// need to set it on the initiating shell.
+const PMACS_ATTACH_DEBUG: &str = "PMACS_ATTACH_DEBUG";
+
 /// Maximum bytes of remote stderr retained for diagnostic surfacing
 /// in [`AttachError::SshChildExited`]. Sized to catch typical SSH
 /// failure messages (one or two short lines plus optional banner)
@@ -1004,6 +1010,16 @@ fn ssh_binary() -> PathBuf {
     std::env::var_os(PMACS_TEST_SSH_BIN).map_or_else(|| PathBuf::from("ssh"), PathBuf::from)
 }
 
+fn attach_debug_enabled() -> bool {
+    std::env::var_os(PMACS_ATTACH_DEBUG).is_some_and(|v| !v.is_empty() && v != "0")
+}
+
+fn attach_debug(msg: impl AsRef<str>) {
+    if attach_debug_enabled() {
+        eprintln!("pmacs attach debug: {}", msg.as_ref());
+    }
+}
+
 /// Construct the [`Command`] for SSH attach without spawning.
 ///
 /// Pure (modulo the env-var lookup for test substitution): used
@@ -1033,6 +1049,9 @@ pub(crate) fn build_ssh_command(target: &AttachTarget) -> Option<Command> {
         cmd.arg("-l").arg(u);
     }
     cmd.arg(host);
+    if attach_debug_enabled() {
+        cmd.arg("env").arg(format!("{PMACS_ATTACH_DEBUG}=1"));
+    }
     cmd.arg("pmacs").arg("--daemon-attach");
     if let Some(name) = instance_name {
         cmd.arg("--socket").arg(name);
@@ -1421,10 +1440,12 @@ fn run_one_session(
         .stderr(Stdio::piped());
 
     let bin_for_error = ssh_binary();
+    attach_debug(format!("spawning ssh command: {:?}", cmd));
     let mut child = cmd.spawn().map_err(|source| AttachError::SshSpawnFailed {
         command: bin_for_error,
         source,
     })?;
+    attach_debug(format!("ssh child spawned with pid {}", child.id()));
 
     let mut child_stdout = child
         .stdout
@@ -1453,9 +1474,11 @@ fn run_one_session(
     // On reconnect (`Some`) the Frontend is up and the M5.8c
     // overlay communicates state; handshake errors here are bubbled
     // up so the M5.8d loop can decide whether to retry.
+    attach_debug("waiting for Hello from remote daemon bridge");
     let hello: Hello = match read_message(&mut child_stdout) {
         Ok(h) => h,
         Err(e) => {
+            attach_debug(format!("failed reading Hello: {e}"));
             return Err(handshake_error_with_child(
                 child,
                 stderr_handle,
@@ -1464,6 +1487,10 @@ fn run_one_session(
             ));
         }
     };
+    attach_debug(format!(
+        "received Hello: protocol_version={}, assigned_frontend_id={}",
+        hello.protocol_version, hello.assigned_frontend_id.0
+    ));
     // T M10.5: relaxed to range membership per
     // `§sec:m10-backward-compat`. Symmetric with the local-socket
     // attach path above.
@@ -1506,6 +1533,7 @@ fn run_one_session(
         initial_size,
     };
     if let Err(e) = write_message(&mut child_stdin, &req) {
+        attach_debug(format!("failed writing AttachRequest: {e}"));
         return Err(handshake_error_with_child(
             child,
             stderr_handle,
@@ -1513,6 +1541,7 @@ fn run_one_session(
             e.into(),
         ));
     }
+    attach_debug("sent AttachRequest");
 
     // First-attempt-only side effects. On reconnect the user already
     // saw the info banner and the Frontend is already up; we skip
@@ -1544,6 +1573,10 @@ fn run_one_session(
     };
 
     let pump_result = run_attach_pair(io, frontend, hello.assigned_frontend_id);
+    attach_debug(format!(
+        "attach pump exited: {:?}",
+        pump_result.as_ref().err()
+    ));
 
     // Reap the child and drain the stderr tee with the Frontend
     // still alive. None of these steps emit terminal output, so raw

src/daemon_attach.rs

@@ -158,6 +158,21 @@ const AUTO_START_TIMEOUT: Duration = Duration::from_secs(5);
 /// socket to become connectable.
 const AUTO_START_POLL_INTERVAL: Duration = Duration::from_millis(50);
 
+/// Shared with `attach.rs`: when set to a non-empty, non-"0" value,
+/// emit stderr breadcrumbs. The remote bridge's stderr is the SSH
+/// child's stderr, so this stays off the protocol stdout stream.
+const PMACS_ATTACH_DEBUG: &str = "PMACS_ATTACH_DEBUG";
+
+fn bridge_debug_enabled() -> bool {
+    std::env::var_os(PMACS_ATTACH_DEBUG).is_some_and(|v| !v.is_empty() && v != "0")
+}
+
+fn bridge_debug(msg: impl AsRef<str>) {
+    if bridge_debug_enabled() {
+        eprintln!("pmacs daemon-attach debug: {}", msg.as_ref());
+    }
+}
+
 /// Run `pmacs --daemon-attach`: ensure a daemon is listening at
 /// `socket_path` (auto-starting one if not), then bridge our
 /// stdin/stdout to it.
@@ -170,7 +185,12 @@ const AUTO_START_POLL_INTERVAL: Duration = Duration::from_millis(50);
 // (`run_attach`, `run_daemon`); pedantic clippy is wrong here.
 #[allow(clippy::needless_pass_by_value)]
 pub fn run_daemon_attach(socket_path: PathBuf) -> Result<(), BridgeError> {
+    bridge_debug(format!(
+        "starting bridge for socket {}",
+        socket_path.display()
+    ));
     let socket = ensure_daemon_running(&socket_path)?;
+    bridge_debug("daemon socket ready; entering byte bridge");
     // Use the owned `Stdin` / `Stdout` (not `.lock()`) so the halves
     // can move into threads with `'static` lifetimes. Both are
     // `Send` and behave as expected for line-oriented or byte
@@ -218,19 +238,40 @@ where
     // use it as the bridge socket. The daemon speaks first, so a
     // disposable connect probe is not transparent: dropping it before
     // reading the daemon's Hello can make the daemon log BrokenPipe.
-    if let Ok(stream) = UnixStream::connect(socket_path) {
-        return Ok(stream);
+    match UnixStream::connect(socket_path) {
+        Ok(stream) => {
+            bridge_debug(format!(
+                "connected to existing daemon at {}",
+                socket_path.display()
+            ));
+            return Ok(stream);
+        }
+        Err(e) => {
+            bridge_debug(format!(
+                "initial connect to {} failed: {e}; attempting auto-start",
+                socket_path.display()
+            ));
+        }
     }
 
     // Slow path: ask the spawner to arrange a daemon, then poll.
     spawner(socket_path)?;
+    bridge_debug("auto-start command spawned; polling socket");
 
     let deadline = Instant::now() + timeout;
     loop {
         if let Ok(stream) = UnixStream::connect(socket_path) {
+            bridge_debug(format!(
+                "connected to auto-started daemon at {}",
+                socket_path.display()
+            ));
             return Ok(stream);
         }
         if Instant::now() >= deadline {
+            bridge_debug(format!(
+                "auto-start timed out after {:.1}s",
+                timeout.as_secs_f32()
+            ));
             return Err(BridgeError::AutoStartTimeout {
                 socket: socket_path.to_path_buf(),
                 after: timeout,
@@ -254,6 +295,11 @@ fn spawn_daemon_subprocess(socket_path: &Path) -> Result<(), BridgeError> {
         exe: PathBuf::from("<current_exe unavailable>"),
         source,
     })?;
+    bridge_debug(format!(
+        "spawning daemon subprocess: {} --daemon --socket {}",
+        exe.display(),
+        socket_path.display()
+    ));
     Command::new(&exe)
         .arg("--daemon")
         .arg("--socket")
@@ -265,6 +311,9 @@ fn spawn_daemon_subprocess(socket_path: &Path) -> Result<(), BridgeError> {
         .map_err(|source| BridgeError::SpawnFailed {
             exe: exe.clone(),
             source,
+        })
+        .map(|child| {
+            bridge_debug(format!("spawned daemon subprocess pid {}", child.id()));
         })?;
     Ok(())
 }
@@ -391,11 +440,13 @@ where
     let socket_for_writer = socket.try_clone().map_err(BridgeError::Io)?;
     let kick_handle = socket.try_clone().map_err(BridgeError::Io)?;
     let mut socket_reader = socket;
+    bridge_debug("bridge connected; starting copy loops");
 
     let (done_tx, done_rx) = mpsc::channel::<()>();
     let stdin_thread = thread::spawn(move || {
         let mut local_input = local_input;
         let mut socket_writer = socket_for_writer;
+        bridge_debug("stdin->daemon copy loop started");
         // Diagnostic: mirror exactly the bytes we forward toward the
         // daemon (the client's AttachRequest et seq).
         let result = match capture_sink("to_daemon.bin") {
@@ -408,6 +459,10 @@ where
             }
             None => copy_with_flush(&mut local_input, &mut socket_writer),
         };
+        match &result {
+            Ok(n) => bridge_debug(format!("stdin->daemon copy loop ended after {n} bytes")),
+            Err(e) => bridge_debug(format!("stdin->daemon copy loop failed: {e}")),
+        }
         // After stdin EOF, signal write-side close so the daemon's
         // blocking read returns 0. Without this, the daemon never
         // sees EOF (we hold other socket FDs on the main thread)
@@ -425,7 +480,8 @@ where
     // shape of the disconnect.
     // Diagnostic: mirror exactly the bytes the daemon sent us (its
     // Hello et seq), as the client receives them.
-    let _ = match capture_sink("from_daemon.bin") {
+    bridge_debug("daemon->stdout copy loop started");
+    let daemon_to_stdout = match capture_sink("from_daemon.bin") {
         Some(sink) => {
             let mut tee = TeeReader {
                 inner: socket_reader,
@@ -435,6 +491,11 @@ where
         }
         None => copy_with_flush(&mut socket_reader, &mut local_output),
     };
+    match &daemon_to_stdout {
+        Ok(n) => bridge_debug(format!("daemon->stdout copy loop ended after {n} bytes")),
+        Err(e) => bridge_debug(format!("daemon->stdout copy loop failed: {e}")),
+    }
+    let _ = daemon_to_stdout;
 
     // Wake the stdin thread's pending socket write. If the thread is
     // currently blocked in a *read* of local_input, this doesn't
@@ -461,6 +522,7 @@ where
     let _ = done_rx.recv_timeout(Duration::from_millis(500));
     drop(stdin_thread);
 
+    bridge_debug("bridge exiting cleanly");
     Ok(())
 }