shpool attach returns immediately with status code 1 and no output

[wade-tregaskis]

AI Policy Ack
Ack.

What happened
After using shpool for a while, with a specific session, it suddenly stopped working. shpool attach -f XYZ started exiting immediately with no output, status code 1.

Using SHPOOL_LOG=debug didn't help (still no output).

Only after I did a killall shpool did it work again.

What I expected to happen
It should work.

To Reproduce
I have no idea how it got into this state.

Version info
shpool 0.9.3 (cl/884794100)

Logs
shpool log tail.txt

That's the end of the log file, from after it broke. I'm reluctant to include more of the log because it contains records of the commands executed in the shell, which are private. But I've saved the full log, for now, so if you want me to look for something specific within it, I can.

[ethanpailes]

That sounds like it is probably an issue on the attach process side. Can you post the attach proc logs by running shpool -l /tmp/shpool-attach.log -vv attach -f XYZ and then posting the resulting /tmp/shpool-attach.log file?

[wade-tregaskis]

If it happens again, I'll do that. Now (since I killall shpool'd) it's attaching fine.

[ethanpailes]

Ok, sounds good. For now, I'll close as no-repro, but please do re-open the thread if it starts to happen again.

[wade-tregaskis]

It happened again. Log file:

2026-04-21T03:22:53.863203Z  INFO ThreadId(01) loading config from "/etc/shpool/config.toml"
2026-04-21T03:22:53.863296Z  WARN ThreadId(01) skip reading config file /etc/shpool/config.toml: Os { code: 2, kind: NotFound, message: "No such file or directory" }
2026-04-21T03:22:53.863331Z  INFO ThreadId(01) loading config from "~/.config/shpool/config.toml"
2026-04-21T03:22:53.863350Z  WARN ThreadId(01) skip reading config file ~/.config/shpool/config.toml: Os { code: 2, kind: NotFound, message: "No such file or directory" }
2026-04-21T03:22:53.863362Z  INFO ThreadId(01) starting with config: Config { norc: None, noecho: None, nosymlink_ssh_auth_sock: None, noread_etc_environment: None, nodaemonize: None, nodaemonize_timeout: None, shell: None, env: None, default_dir: None, forward_env: None, initial_path: None, session_restore_mode: None, session_restore_engine: None, output_spool_lines: None, vt100_output_spool_width: None, keybinding: None, prompt_prefix: None, motd: None, motd_args: None }
2026-04-21T03:22:53.863392Z  INFO ThreadId(01) new: new
2026-04-21T03:22:53.863407Z  INFO ThreadId(01) new:with_debounce: new
2026-04-21T03:22:53.863777Z  INFO ThreadId(01) new:with_debounce: close time.busy=330µs time.idle=39.7µs
2026-04-21T03:22:53.863818Z  INFO ThreadId(01) new: close time.busy=412µs time.idle=13.9µs
2026-04-21T03:22:53.863829Z  INFO ThreadId(01) watch: new
2026-04-21T03:22:53.863908Z  INFO ThreadId(03) run: new
2026-04-21T03:22:53.863979Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 923680962 } select with ddl None
2026-04-21T03:22:53.863996Z DEBUG ThreadId(03) run: addwatch: "/etc/shpool/config.toml"
2026-04-21T03:22:53.864411Z DEBUG ThreadId(03) run: Actually watching /etc, ic Some("shpool")
2026-04-21T03:22:53.864501Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 924203864 } select with ddl None
2026-04-21T03:22:53.864534Z  INFO ThreadId(01) watch: close time.busy=694µs time.idle=9.17µs
2026-04-21T03:22:53.864591Z  INFO ThreadId(01) watch: new
2026-04-21T03:22:53.864648Z DEBUG ThreadId(03) run: addwatch: "~/.config/shpool/config.toml"
2026-04-21T03:22:53.865114Z DEBUG ThreadId(03) run: Actually watching ~/.config, ic Some("shpool")
2026-04-21T03:22:53.865260Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 924962742 } select with ddl None
2026-04-21T03:22:53.865301Z  INFO ThreadId(01) watch: close time.busy=699µs time.idle=11.5µs
2026-04-21T03:22:53.865398Z  INFO ThreadId(01) daemon already running on "/run/user/122247/shpool/shpool.socket", no need to autodaemonize
2026-04-21T03:22:53.865471Z  INFO ThreadId(01) 

======================== STARTING ATTACH ============================


2026-04-21T03:22:53.866617Z  INFO ThreadId(01) read daemon version header: VersionHeader { version: "0.3.4" }
2026-04-21T03:22:53.866658Z  INFO ThreadId(01) local env keys: ["TERM", "DISPLAY", "LANG", "SSH_AUTH_SOCK"]
2026-04-21T03:22:53.867412Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/passwd"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.867468Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/passwd"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.867488Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.867498Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 927201705 } select with ddl None
2026-04-21T03:22:53.867509Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/passwd.cache.ixuid"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.867524Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/passwd.cache.ixuid"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.867535Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.867554Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 927257310 } select with ddl None
2026-04-21T03:22:53.867794Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/passwd.cache"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.867833Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/passwd.cache"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.867850Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.867860Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 927562735 } select with ddl None
2026-04-21T03:22:53.868052Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/environment"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.868073Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/environment"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.868084Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.868093Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 927795758 } select with ddl None
2026-04-21T03:22:53.868469Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.868512Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.868524Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.868533Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 928235801 } select with ddl None
2026-04-21T03:22:53.872049Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:53.872084Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:53.872096Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:53.872106Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43648, tv_nsec: 931809475 } select with ddl None
2026-04-21T03:22:53.875604Z  INFO ThreadId(01) attach_resp.status=Attached { warnings: [] }
2026-04-21T03:22:53.875636Z  INFO ThreadId(01) attached to an existing session: 'SertRunner'
2026-04-21T03:22:53.875650Z  INFO ThreadId(01) pipe_bytes: new
2026-04-21T03:22:53.876049Z  INFO ThreadId(05) stdin->sock: new
2026-04-21T03:22:53.876230Z  INFO ThreadId(06) sock->stdout: new
2026-04-21T03:22:54.175967Z ERROR ThreadId(06) sock->stdout: reading chunk: failed to fill whole buffer
2026-04-21T03:22:54.176034Z  INFO ThreadId(06) sock->stdout: close time.busy=300ms time.idle=45.4µs
2026-04-21T03:22:54.176431Z DEBUG ThreadId(03) run: event: Ok(Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None })
2026-04-21T03:22:54.176505Z DEBUG ThreadId(03) run: ignore Event { kind: Access(Open(Any)), paths: ["/etc/hosts"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
2026-04-21T03:22:54.176551Z DEBUG ThreadId(03) run: rewatch = Some([]), reload = false
2026-04-21T03:22:54.176566Z DEBUG ThreadId(03) run: now Instant { tv_sec: 43649, tv_nsec: 236269429 } select with ddl None
2026-04-21T03:22:54.186896Z  WARN ThreadId(01) pipe_bytes: exiting due to a stuck IO thread stdin_to_sock_finished=false sock_to_stdout_finished=true

[wade-tregaskis]

It's happened a few times in recent days.

Is there any way to unstick it without having to kill shpool entirely (and everything running in my sessions)? It's very disruptive to have to do so.

[ethanpailes]

That looks like the logs for the attach proc. I bet the issue is in the daemon proc. Do you mind running shpool set-log-level trace, then attempting to attach a few times and posting the resulting daemon logs (you may want to shpool set-log-level info afterwards to reduce log volume).

As long as you are running shpool with systemd, you should be able to get at the daemon logs with:

journalctl --output cat --user -u shpool

[wade-tregaskis]

shpool.log

[ethanpailes]

Hmm, the very last thing I see in that log file is the handle_set_log_level call. There is nothing after that from when you tried to attach. I guess that does mean it is probably all in the attach proc. Seems like it isn't even getting to the point of talking to the daemon.

[ethanpailes]

If you're still in that state and haven't restarted your daemon in annoyance, can you try doing shpool -vv -l /tmp/shpool-attach.log attach test and then attaching the resulting /tmp/shpool-attach.log file? There is nothing obvious in the initial attach file snippet you included so it would be nice to crank the log level.

[wade-tregaskis]

The attach log I provided earlier was from that command already. I gather, then, that you're not seeing something expected in it either?

[ethanpailes]

Yeah, it's not that informative. I just posted #351 which would have helped a little.

It looks like from the attach proc's perspective, the daemon is hanging up on it, and the daemon isn't seeing the traffic at all.