bug: shpool gets intermittantly wedged when a shell is `shpool kill`ed

[CyberShadow]

Hi,

Is shpool usable for TUI applications other than interactive shells like bash?

I'm struggling to make it work with Emacs. I see that it has some shell prompt integration, which I thought was optional - I've set prompt_prefix = "", but now see that doing so is documented in the troubleshooting page as unsupported before #66 is fixed.

[CyberShadow]

I'm struggling to make it work with Emacs

For what it's worth, the problem I'm seeing is that the shpool daemon gets into a busyloop and stops responding to requests. I'm guessing this is a bug, and I'm trying to use the software in a way outside the set of circumstances that it was tested with or designed to be used with.

[ethanpailes]

I use shpool with vim every day, so it is definitely supposed to be able to handle this.

doing so is documented in the troubleshooting page as unsupported before #66 is fixed.

That's wrong. I must have pointed to the wrong bug for some reason. I've removed it since prompt_prefix = "" has suppressed the prompt hook for a while now.

the shpool daemon gets into a busyloop and stops responding to requests

Can you post the logs requested by the bug template? (don't make a new bug, just post in this thread).

I'm curious what you mean by this because once a session is attached, the shpool protocol is a streaming protocol. It doesn't follow a request response pattern anymore. Is it that once you get in this state you can no longer talk to the daemon with the CLI (for example shpool list starts hanging)?

[CyberShadow]

I use shpool with vim every day, so it is definitely supposed to be able to handle this.

That's wrong. I must have pointed to the wrong bug for some reason. I've removed it since prompt_prefix = "" has suppressed the prompt hook for a while now.

Thanks, that's good to know!

Run journalctl --output cat --user-unit shpool to pull logs related to shpool, then attach the file to this issue. You may need to trim the output with tail.

This produces empty output for me. Looks like I'm using auto-daemon mode.

I see the process table mentions /run/user/1000/shpool/daemonized-shpool.log, which has some entries, so I'm attaching that one.

daemonized-shpool.log

I'm curious what you mean by this because once a session is attached, the shpool protocol is a streaming protocol. It doesn't follow a request response pattern anymore. Is it that once you get in this state you can no longer talk to the daemon with the CLI (for example shpool list starts hanging)?

Yes, that's exactly right. Right now I see three threads use 100% CPU each. Here's their stack trace:

Thread 1 (Thread 0x7f2e00dba6c0 (LWP 2438324) "shell->client(p"):
#0  0x00007f2e02114e4a in read () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
#1  0x0000558a5ec7ee5f in <shpool_pty::fork::pty::master::Master as std::io::Read>::read ()
#2  0x0000558a5ec477e5 in libshpool::daemon::shell::SessionInner::spawn_shell_to_client::{{closure}} ()
#3  0x0000558a5ec40987 in std::sys::backtrace::__rust_begin_short_backtrace ()
#4  0x0000558a5ec375a8 in core::ops::function::FnOnce::call_once{{vtable.shim}} ()
#5  0x0000558a5ed7fe4b in std::sys::pal::unix::thread::Thread::new::thread_start ()
#6  0x00007f2e0209af08 in start_thread () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
#7  0x00007f2e021230ac in __clone3 () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
Detaching from program: /nix/store/gqzrkyaz1b058v8s4sb56dhs25ggj6mq-shpool-0.8.0/bin/shpool, process 2438324

Let we try with 0.9.3.

[CyberShadow]

Still happening with a source build. Spinning here:

Thread 1 (Thread 0x7f234aff76c0 (LWP 2784022) "shell->client(p"):
#0  0x00007f23ab314e4a in read () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
#1  0x000055850b8c6a72 in shpool_pty::fork::pty::master::{impl#2}::read (self=0x7f234aff5f40, buf=...) at src/fork/pty/master/mod.rs:104
#2  0x000055850b64df91 in libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure#0} () at libshpool/src/daemon/shell.rs:474
#3  0x000055850b650cff in libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure#1} () at libshpool/src/daemon/shell.rs:539
#4  0x000055850b82a049 in std::sys::backtrace::__rust_begin_short_backtrace<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>> (f=<error reading variable: Cannot access memory at address 0x112>) at /build/rustc-1.87.0-src/library/std/src/sys/backtrace.rs:152
#5  0x000055850b758ce1 in std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure#0}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>> () at /build/rustc-1.87.0-src/library/std/src/thread/mod.rs:559
#6  0x000055850b6f8a24 in core::panic::unwind_safe::{impl#23}::call_once<core::result::Result<(), anyhow::Error>, std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>>> (self=...) at /build/rustc-1.87.0-src/library/core/src/panic/unwind_safe.rs:272
#7  0x000055850b6b5b61 in std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>>>, core::result::Result<(), anyhow::Error>> (data=0x7f234aff69b0) at /build/rustc-1.87.0-src/library/std/src/panicking.rs:589
#8  0x000055850b75a03b in __rust_try ()
#9  0x000055850b755f9a in std::panicking::try<core::result::Result<(), anyhow::Error>, core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>>>> (f=...) at /build/rustc-1.87.0-src/library/std/src/panicking.rs:552
#10 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>>>, core::result::Result<(), anyhow::Error>> (f=...) at /build/rustc-1.87.0-src/library/std/src/panic.rs:359
#11 std::thread::{impl#0}::spawn_unchecked_::{closure#1}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>> () at /build/rustc-1.87.0-src/library/std/src/thread/mod.rs:557
#12 0x000055850b5415bf in core::ops::function::FnOnce::call_once<std::thread::{impl#0}::spawn_unchecked_::{closure_env#1}<libshpool::daemon::shell::{impl#1}::spawn_shell_to_client::{closure_env#1}, core::result::Result<(), anyhow::Error>>, ()> () at /build/rustc-1.87.0-src/library/core/src/ops/function.rs:250
#13 0x000055850bbfc6ab in std::sys::pal::unix::thread::Thread::new::thread_start ()
#14 0x00007f23ab29af08 in start_thread () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
#15 0x00007f23ab3230ac in __clone3 () from /nix/store/q4wq65gl3r8fy746v9bbwgx4gzn0r2kl-glibc-2.40-66/lib/libc.so.6
Detaching from program: /home/vladimir/work/extern/shpool/target/debug/shpool, process 2784022

[ethanpailes]

This might be a dup of #243. The CPU pegging seems simillar. How are you invoking shpool attach?

Looking at your logs, I see lots of successful connections but by the bottom it seems like new connections are deadlocking when they try to grab a lock on the global shells table. I still haven't found where that first starts happening.

[CyberShadow]

How are you invoking shpool attach?

Like this:

exec ~/work/extern/shpool/target/debug/shpool attach -f -c "/bin/sh -c $(printf '%q' "$command")" "persistent-ssh-$id"

Looking at your logs, I see lots of successful connections but by the bottom it seems like new connections are deadlocking when they try to grab a lock on the global shells table.

Yes, it does seem to work for a bit before it reaches that state.

[ethanpailes]

Can you try just doing shpool attach basic to see if an unadorned attach command has the same issue?

2026-02-05T18:05:59.909228Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach:2_lock(shells): new

looks like the first line that is deadlocking, but it's not super obvious from the logs who is holding the lock at that time:

$ rg shells daemonized-shpool.log | rg -C 3 cid=73 | tail -n 10
2026-02-05T18:05:04.629679Z  INFO ThreadId(174) handle_conn{cid=74}:handle_session_message{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}:lock(shells):lock(pager_ctl): new
2026-02-05T18:05:04.629683Z  INFO ThreadId(174) handle_conn{cid=74}:handle_session_message{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}:lock(shells):lock(pager_ctl):resize_lock(shell_to_client_ctl): new
--
2026-02-05T18:05:33.188694Z  INFO ThreadId(183) handle_conn{cid=78}:handle_session_message{s="persistent-ssh-dDU4MC0yNjk0ODU3LTE3NzAwNDk1OTIK"}:lock(shells): close time.busy=501ms time.idle=2.94µs
2026-02-05T18:05:59.883190Z  INFO ThreadId(177) handle_conn{cid=77}:handle_attach:2_lock(shells): new
2026-02-05T18:05:59.883196Z  INFO ThreadId(177) handle_conn{cid=77}:handle_attach:2_lock(shells): close time.busy=3.14µs time.idle=3.09µs
2026-02-05T18:05:59.909228Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach:2_lock(shells): new  <--- first thread queing up against the stuck lock.
2026-02-05T18:05:59.952665Z  INFO ThreadId(185) handle_conn{cid=80}:handle_session_message{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}:lock(shells): new
2026-02-05T18:06:10.303486Z  INFO ThreadId(187) handle_conn{cid=82}:handle_attach:1_lock(shells): new
2026-02-05T18:06:10.366753Z  INFO ThreadId(188) handle_conn{cid=83}:handle_session_message{s="persistent-ssh-dDU4MC0yNjk0ODU3LTE3NzAwNDk1OTIK"}:lock(shells): new

The previous mention of the shells lock is a span close line, indicating an unlock, not a lock. it might be that a previous thread was waiting for the lock and grabbed it as soon as

2026-02-05T18:05:59.883196Z  INFO ThreadId(177) handle_conn{cid=77}:handle_attach:2_lock(shells): close time.busy=3.14µs time.idle=3.09µs

releases the lock, but that won't jump out from the log since we print before grabbing the lock. I probably need to cook up a script to track lock state at the time of the problematic line.

[CyberShadow]

This is a little speculative, but I think I found the problem:

• My integration uses shpool kill, which runs on the remote host when I close my local terminal. This recreates the expected behavior that remote processes are killed when the terminal is closed (but not when there is a temporary connection error). I wouldn't expect this to be a common setup.

• shpool kill seems to interact with the read loop there to make it spin. This patch seems to fix it for me:

  diff --git a/libshpool/src/daemon/shell.rs b/libshpool/src/daemon/shell.rs
  index b5f81f1f..57ac5738 100644
  --- a/libshpool/src/daemon/shell.rs
  +++ b/libshpool/src/daemon/shell.rs
  @@ -471,6 +471,13 @@ impl SessionInner {
                   if nready != 1 {
                       return Err(anyhow!("shell->client thread: expected exactly 1 ready fd"));
                   }
  +                // Check for hangup before reading - if the shell exited, we need to
  +                // detect this to avoid busy-looping when read returns 0.
  +                let got_hangup = poll_fds[0]
  +                    .revents()
  +                    .map(|r| r.intersects(poll::PollFlags::POLLHUP | poll::PollFlags::POLLERR))
  +                    .unwrap_or(false);
  +
                   let len = match pty_master.read(&mut buf) {
                       Ok(l) => l,
                       Err(e) => {
  @@ -479,6 +486,10 @@ impl SessionInner {
                       }
                   };
                   if len == 0 {
  +                    if got_hangup {
  +                        info!("pty master hung up, exiting shell->client thread");
  +                        return Ok(());
  +                    }
                       continue;
                   }
                   let mut buf = &buf[..len];

• With the patch applied, I no longer get the hang (the pty master hung up, exiting shell->client thread line does show up in the log).

[ethanpailes]

I see a potential problem here:

shpool/libshpool/src/daemon/server.rs

Lines 310 to 323 in 7cf721b

	let _s = span!(Level::INFO, "2_lock(shells)").entered();
	let mut shells = self.shells.lock().unwrap();
	shells.remove(&header.name);
	// The child shell has exited, so the shell->client thread should
	// attempt to read from its stdout and get an error, causing
	// it to exit. That means we should be safe to join. We use
	// a separate if statement to avoid holding the shells lock
	// while we join the old thread.
	if let Some(h) = inner.shell_to_client_join_h.take() {
	h.join()
	.map_err(|e| anyhow!("joining shell->client after child exit: {:?}", e))?
	.context("within shell->client thread after child exit")?;
	}

I had gemini write me a script to track which threads were contending for the lock at any given time, and focusing on its output in the vicinity of the problem line, we can see that there is only one thread contending at the time we first start blocking:

$ rg '2026-02-05T18:05:59.909228Z' lock_analysis.txt  -C 5
616-  Current shells lock contenders: []
617-2026-02-05T18:05:59.883190Z | Thread 177 WAITING/HOLDING shells lock (handle_conn{cid=77}:handle_attach:2_lock(shells))
618-  Current shells lock contenders: ['177']
619-2026-02-05T18:05:59.883196Z | Thread 177 RELEASED shells lock (handle_conn{cid=77}:handle_attach:2_lock(shells))
620-  Current shells lock contenders: []
621:2026-02-05T18:05:59.909228Z | Thread 168 WAITING/HOLDING shells lock (handle_conn{cid=73}:handle_attach:2_lock(shells)) <---- the first time we start blocking forever.
622-  Current shells lock contenders: ['168']
623-2026-02-05T18:05:59.952665Z | Thread 185 WAITING/HOLDING shells lock (handle_conn{cid=80}:handle_session_message{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}:lock(shells))
624-  Current shells lock contenders: ['168', '185']
625-2026-02-05T18:06:10.303486Z | Thread 187 WAITING/HOLDING shells lock (handle_conn{cid=82}:handle_attach:1_lock(shells))
626-  Current shells lock contenders: ['168', '185', '187']

So it seems like thread 168 is the problem child. What is 168 up to?

$ rg 'ThreadId\(168\)' daemonized-shpool.log | tail -n 5
2026-02-05T18:05:59.909203Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach:bidi_stream{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}: done child_done=true
2026-02-05T18:05:59.909215Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach:bidi_stream{s="persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK"}: close time.busy=59.5s time.idle=3.84µs
2026-02-05T18:05:59.909220Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach: bidi stream loop finished
2026-02-05T18:05:59.909223Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach: 'persistent-ssh-dDU4MC0zMTYwODM2LTE3NzAzMTQ2OTkK' exited, removing from session table
2026-02-05T18:05:59.909228Z  INFO ThreadId(168) handle_conn{cid=73}:handle_attach:2_lock(shells): new

it has just grabbed the lock here, then radio silence.

Do we do anything that could block for a long time with that lock held? Yeah. There is even a comment explaining that we are careful not to hold the lock while doing that 🤦🏻 . We might be able to fix this by just wrapping the above block that removes the entry from the shells table in a scope.

[ethanpailes]

Your fix makes a lot of sense as well. I think these were two seperate bugs, one a global deadlock that we encouter when the shell->client thread is not exiting as it should and one that was causing that thread to not exit as it should in the first place.

Do you mind reverting your fix and seeing if wrapping

shpool/libshpool/src/daemon/server.rs

Lines 310 to 312 in 7cf721b

	let _s = span!(Level::INFO, "2_lock(shells)").entered();
	let mut shells = self.shells.lock().unwrap();
	shells.remove(&header.name);

in an anon scope at least allows you to continue issuing shpool list commands once your shpool daemon has gotten into this mangled state?

[ethanpailes]

If you want to send a PR, I'll merge the fix you found (though one nit: let's move the got_hangup computation directly inside the if len == 0 block so we can avoid doing the work when we don't need to).