Typing delayed at fish shell prompt after reattaching

[injust]

What happened

I detached at a fish shell prompt (using shpool detach because of #278). After reattaching, my typing was delayed for a few seconds before appearing on screen.

This doesn't always happen (sometimes my typing shows up immediately after attaching). However, once it starts happening for a given session, it happens every time I detach and reattach the same session.

What I expected to happen

My typing should appear immediately as I type.

To Reproduce

1. SSH to an EC2 instance running Amazon Linux 2023 using fish shell
2. shpool attach test
3. shpool detach
4. shpool attach test
5. Type anything

Version info

shpool 0.9.3

Logs

See below

[ethanpailes]

Can you post the shpool logs requested by the bug template? They should include some timing that will help debug.

[injust]

Logs: shpool.log

Logs

2025-12-28T11:03:33.346142Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:33.346285Z  INFO ThreadId(132) handle_conn{cid=61}: new
2025-12-28T11:03:33.346305Z  INFO ThreadId(132) handle_conn{cid=61}: broken pipe while writing version, likely just a daemon presence probe
2025-12-28T11:03:33.346311Z  INFO ThreadId(132) handle_conn{cid=61}: close time.busy=13.1µs time.idle=13.6µs
2025-12-28T11:03:33.346575Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:33.346648Z  INFO ThreadId(133) handle_conn{cid=62}: new
2025-12-28T11:03:33.346667Z  INFO ThreadId(133) handle_conn{cid=62}:parse_connect_header: new
2025-12-28T11:03:33.346828Z  INFO ThreadId(133) handle_conn{cid=62}:parse_connect_header: close time.busy=157µs time.idle=4.00µs
2025-12-28T11:03:33.346862Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: new
2025-12-28T11:03:33.346946Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:build_shell_env: new
2025-12-28T11:03:33.346985Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:build_shell_env: injecting TERM into shell Some("xterm-ghostty")
2025-12-28T11:03:33.347008Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:build_shell_env: close time.busy=28.4µs time.idle=33.6µs
2025-12-28T11:03:33.347014Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells): new
2025-12-28T11:03:33.347017Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells): no existing 'test' session, creating new one
2025-12-28T11:03:33.347021Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells): creating new subshell
2025-12-28T11:03:33.347024Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: new
2025-12-28T11:03:33.347027Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: user_info=Info { default_shell: "/usr/bin/fish", home_dir: "/home/ec2-user", user: "ec2-user" }
2025-12-28T11:03:33.347034Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: spawning shell in '/home/ec2-user'
2025-12-28T11:03:33.347342Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: about to fork subshell noecho=false
2025-12-28T11:03:33.347973Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: injecting prompt prefix
2025-12-28T11:03:33.348062Z  INFO ThreadId(134) child_watcher{s="test" cid=62}: new
2025-12-28T11:03:33.348076Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: new
2025-12-28T11:03:33.348085Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell:maybe_inject_prefix: close time.busy=763ns time.idle=8.85µs
2025-12-28T11:03:33.348107Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: new
2025-12-28T11:03:33.348221Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell:spawn_shell_to_client{s="test"}: close time.busy=110µs time.idle=4.10µs
2025-12-28T11:03:33.348243Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells):spawn_subshell: close time.busy=1.22ms time.idle=3.19µs
2025-12-28T11:03:33.348251Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:1_lock(shells): close time.busy=1.23ms time.idle=3.04µs
2025-12-28T11:03:33.348255Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: released lock on shells table
2025-12-28T11:03:33.348259Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:link_ssh_auth_sock: new
2025-12-28T11:03:33.348262Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:link_ssh_auth_sock: no SSH_AUTH_SOCK in client env, leaving it unlinked
2025-12-28T11:03:33.348265Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:link_ssh_auth_sock: close time.busy=3.70µs time.idle=3.01µs
2025-12-28T11:03:33.348269Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:populate_session_env_file: new
2025-12-28T11:03:33.348286Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:populate_session_env_file: populating "/run/user/1000/shpool/sessions/test/forward.env"
2025-12-28T11:03:33.348319Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:populate_session_env_file: close time.busy=47.1µs time.idle=2.77µs
2025-12-28T11:03:33.348324Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:write_reply: new
2025-12-28T11:03:33.348349Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:write_reply: close time.busy=21.9µs time.idle=2.99µs
2025-12-28T11:03:33.348355Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: starting bidi stream loop
2025-12-28T11:03:33.348359Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}: new
2025-12-28T11:03:33.348367Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): new
2025-12-28T11:03:33.348418Z  INFO ThreadId(135) shell->client{s="test" cid=62}: new
2025-12-28T11:03:33.349279Z  INFO ThreadId(135) shell->client{s="test" cid=62}: waiting for initial client connection
2025-12-28T11:03:33.350165Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): client connection status=New
2025-12-28T11:03:33.350180Z  INFO ThreadId(135) shell->client{s="test" cid=62}: got initial client connection
2025-12-28T11:03:33.350240Z  INFO ThreadId(135) shell->client{s="test" cid=62}: resized fd (rows=61, cols=209)
2025-12-28T11:03:33.350302Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): close time.busy=1.93ms time.idle=4.05µs
2025-12-28T11:03:33.350346Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: new
2025-12-28T11:03:33.350447Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: close time.busy=61.0µs time.idle=39.6µs
2025-12-28T11:03:33.350565Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: new
2025-12-28T11:03:33.350594Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: close time.busy=22.0µs time.idle=7.24µs
2025-12-28T11:03:33.350601Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: new
2025-12-28T11:03:33.350711Z  INFO ThreadId(137) heartbeat{s="test" cid=62}: new
2025-12-28T11:03:33.350545Z  INFO ThreadId(136) client->shell{s="test" cid=62}: new
2025-12-28T11:03:33.350776Z  INFO ThreadId(138) supervisor{s="test" cid=62}: new
2025-12-28T11:03:33.350783Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: close time.busy=178µs time.idle=3.38µs
2025-12-28T11:03:36.233188Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:36.233249Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:36.233305Z  INFO ThreadId(139) handle_conn{cid=63}: new
2025-12-28T11:03:36.233318Z  INFO ThreadId(139) handle_conn{cid=63}: broken pipe while writing version, likely just a daemon presence probe
2025-12-28T11:03:36.233324Z  INFO ThreadId(139) handle_conn{cid=63}: close time.busy=12.3µs time.idle=6.89µs
2025-12-28T11:03:36.233401Z  INFO ThreadId(140) handle_conn{cid=64}: new
2025-12-28T11:03:36.233416Z  INFO ThreadId(140) handle_conn{cid=64}:parse_connect_header: new
2025-12-28T11:03:36.233470Z  INFO ThreadId(140) handle_conn{cid=64}:parse_connect_header: close time.busy=50.0µs time.idle=3.55µs
2025-12-28T11:03:36.233500Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach: new
2025-12-28T11:03:36.233504Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:lock(shells): new
2025-12-28T11:03:36.233509Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: new
2025-12-28T11:03:36.330664Z  INFO ThreadId(135) shell->client{s="test" cid=62}: disconnect, shutting down client stream
2025-12-28T11:03:36.332127Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: detached session(test), status = Detached
2025-12-28T11:03:36.332151Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: close time.busy=98.6ms time.idle=4.10µs
2025-12-28T11:03:36.332160Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:lock(shells): close time.busy=98.7ms time.idle=3.28µs
2025-12-28T11:03:36.332165Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:write_reply: new
2025-12-28T11:03:36.332372Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach:write_reply: close time.busy=203µs time.idle=4.42µs
2025-12-28T11:03:36.332728Z  INFO ThreadId(140) handle_conn{cid=64}:handle_detach: close time.busy=99.2ms time.idle=4.07µs
2025-12-28T11:03:36.332752Z  INFO ThreadId(140) handle_conn{cid=64}: close time.busy=99.3ms time.idle=5.80µs
2025-12-28T11:03:36.447752Z  INFO ThreadId(137) heartbeat{s="test" cid=62}: close time.busy=3.10s time.idle=133µs
2025-12-28T11:03:36.453495Z  INFO ThreadId(136) client->shell{s="test" cid=62}: recvd stop msg (1)
2025-12-28T11:03:36.453499Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): new
2025-12-28T11:03:36.453593Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): telling shell->client to disconnect without reaping
2025-12-28T11:03:36.453571Z  INFO ThreadId(136) client->shell{s="test" cid=62}: close time.busy=3.10s time.idle=259µs
2025-12-28T11:03:36.548032Z  INFO ThreadId(135) shell->client{s="test" cid=62}: disconnect, no client stream to shut down
2025-12-28T11:03:36.548071Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): detached from shell->client, status = DetachNone
2025-12-28T11:03:36.548097Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): close time.busy=94.5ms time.idle=95.4µs
2025-12-28T11:03:36.651964Z  INFO ThreadId(138) supervisor{s="test" cid=62}: recvd stop msg
2025-12-28T11:03:36.652006Z  INFO ThreadId(138) supervisor{s="test" cid=62}: close time.busy=3.30s time.idle=78.5µs
2025-12-28T11:03:36.652125Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}: done child_done=false
2025-12-28T11:03:36.652147Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach:bidi_stream{s="test"}: close time.busy=3.30s time.idle=3.01µs
2025-12-28T11:03:36.652153Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: bidi stream loop finished child_done=false
2025-12-28T11:03:36.652157Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: finished attach streaming section
2025-12-28T11:03:36.652164Z  INFO ThreadId(133) handle_conn{cid=62}:handle_attach: close time.busy=3.31s time.idle=4.55µs
2025-12-28T11:03:36.652169Z  INFO ThreadId(133) handle_conn{cid=62}: close time.busy=3.31s time.idle=7.81µs
2025-12-28T11:03:38.021119Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:38.021185Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:38.021219Z  INFO ThreadId(141) handle_conn{cid=65}: new
2025-12-28T11:03:38.021238Z  INFO ThreadId(141) handle_conn{cid=65}: broken pipe while writing version, likely just a daemon presence probe
2025-12-28T11:03:38.021244Z  INFO ThreadId(141) handle_conn{cid=65}: close time.busy=13.1µs time.idle=12.5µs
2025-12-28T11:03:38.021398Z  INFO ThreadId(142) handle_conn{cid=66}: new
2025-12-28T11:03:38.021466Z  INFO ThreadId(142) handle_conn{cid=66}:parse_connect_header: new
2025-12-28T11:03:38.021782Z  INFO ThreadId(142) handle_conn{cid=66}:parse_connect_header: close time.busy=309µs time.idle=5.83µs
2025-12-28T11:03:38.021833Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: new
2025-12-28T11:03:38.021930Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:build_shell_env: new
2025-12-28T11:03:38.021945Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:build_shell_env: injecting TERM into shell Some("xterm-ghostty")
2025-12-28T11:03:38.021965Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:build_shell_env: close time.busy=25.2µs time.idle=9.69µs
2025-12-28T11:03:38.021971Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells): new
2025-12-28T11:03:38.021974Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells): found entry for 'test'
2025-12-28T11:03:38.021978Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: new
2025-12-28T11:03:38.021983Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: taking over existing session inner
2025-12-28T11:03:38.021987Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: close time.busy=4.88µs time.idle=3.73µs
2025-12-28T11:03:38.021992Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:1_lock(shells): close time.busy=18.9µs time.idle=2.95µs
2025-12-28T11:03:38.021996Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: released lock on shells table
2025-12-28T11:03:38.021998Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:link_ssh_auth_sock: new
2025-12-28T11:03:38.022002Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:link_ssh_auth_sock: no SSH_AUTH_SOCK in client env, leaving it unlinked
2025-12-28T11:03:38.022005Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:link_ssh_auth_sock: close time.busy=3.79µs time.idle=2.94µs
2025-12-28T11:03:38.022009Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:populate_session_env_file: new
2025-12-28T11:03:38.022023Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:populate_session_env_file: populating "/run/user/1000/shpool/sessions/test/forward.env"
2025-12-28T11:03:38.022106Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:populate_session_env_file: close time.busy=93.1µs time.idle=3.41µs
2025-12-28T11:03:38.022114Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:write_reply: new
2025-12-28T11:03:38.022137Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:write_reply: close time.busy=19.4µs time.idle=3.64µs
2025-12-28T11:03:38.022141Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: starting bidi stream loop
2025-12-28T11:03:38.022146Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}: new
2025-12-28T11:03:38.022150Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): new
2025-12-28T11:03:38.050660Z  INFO ThreadId(135) shell->client{s="test" cid=62}: got new connection (rows=61, cols=209)
2025-12-28T11:03:38.050751Z  INFO ThreadId(135) shell->client{s="test" cid=62}: executing reattach protocol (mode=Screen)
2025-12-28T11:03:38.050757Z  INFO ThreadId(135) shell->client{s="test" cid=62}: computing screen restore buf with (rows=61, cols=1024)
2025-12-28T11:03:38.050881Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): client connection status=New
2025-12-28T11:03:38.050906Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): close time.busy=28.8ms time.idle=4.06µs
2025-12-28T11:03:38.050917Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: new
2025-12-28T11:03:38.050985Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: close time.busy=64.7µs time.idle=4.18µs
2025-12-28T11:03:38.050992Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: new
2025-12-28T11:03:38.051018Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: close time.busy=22.8µs time.idle=3.48µs
2025-12-28T11:03:38.051023Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: new
2025-12-28T11:03:38.051040Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: close time.busy=14.2µs time.idle=3.00µs
2025-12-28T11:03:38.051081Z  INFO ThreadId(145) supervisor{s="test" cid=66}: new
2025-12-28T11:03:38.051256Z  INFO ThreadId(143) client->shell{s="test" cid=66}: new
2025-12-28T11:03:38.051339Z  INFO ThreadId(144) heartbeat{s="test" cid=66}: new
2025-12-28T11:03:38.152025Z  INFO ThreadId(135) shell->client{s="test" cid=62}: resized fd (rows=61, cols=209)
2025-12-28T11:03:45.512307Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:45.512365Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:45.512418Z  INFO ThreadId(146) handle_conn{cid=67}: new
2025-12-28T11:03:45.512431Z  INFO ThreadId(146) handle_conn{cid=67}: broken pipe while writing version, likely just a daemon presence probe
2025-12-28T11:03:45.512437Z  INFO ThreadId(146) handle_conn{cid=67}: close time.busy=11.7µs time.idle=6.87µs
2025-12-28T11:03:45.512519Z  INFO ThreadId(147) handle_conn{cid=68}: new
2025-12-28T11:03:45.512536Z  INFO ThreadId(147) handle_conn{cid=68}:parse_connect_header: new
2025-12-28T11:03:45.512592Z  INFO ThreadId(147) handle_conn{cid=68}:parse_connect_header: close time.busy=53.3µs time.idle=3.70µs
2025-12-28T11:03:45.512623Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach: new
2025-12-28T11:03:45.512628Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:lock(shells): new
2025-12-28T11:03:45.512632Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: new
2025-12-28T11:03:45.609747Z  INFO ThreadId(135) shell->client{s="test" cid=62}: disconnect, shutting down client stream
2025-12-28T11:03:45.612075Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: detached session(test), status = Detached
2025-12-28T11:03:45.612105Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:lock(shells):lock(shell_to_client_ctl){s="test"}: close time.busy=99.5ms time.idle=3.49µs
2025-12-28T11:03:45.612113Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:lock(shells): close time.busy=99.5ms time.idle=2.98µs
2025-12-28T11:03:45.612118Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:write_reply: new
2025-12-28T11:03:45.612140Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach:write_reply: close time.busy=19.4µs time.idle=3.75µs
2025-12-28T11:03:45.612146Z  INFO ThreadId(147) handle_conn{cid=68}:handle_detach: close time.busy=99.5ms time.idle=3.76µs
2025-12-28T11:03:45.612159Z  INFO ThreadId(147) handle_conn{cid=68}: close time.busy=99.6ms time.idle=5.83µs
2025-12-28T11:03:45.726098Z  INFO ThreadId(144) heartbeat{s="test" cid=66}: close time.busy=7.67s time.idle=25.2µs
2025-12-28T11:03:45.759420Z  INFO ThreadId(143) client->shell{s="test" cid=66}: recvd stop msg (1)
2025-12-28T11:03:45.759471Z  INFO ThreadId(143) client->shell{s="test" cid=66}: close time.busy=7.71s time.idle=12.7µs
2025-12-28T11:03:45.759424Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): new
2025-12-28T11:03:45.759642Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): telling shell->client to disconnect without reaping
2025-12-28T11:03:45.826473Z  INFO ThreadId(135) shell->client{s="test" cid=62}: disconnect, no client stream to shut down
2025-12-28T11:03:45.826678Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): detached from shell->client, status = DetachNone
2025-12-28T11:03:45.826708Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): close time.busy=67.1ms time.idle=220µs
2025-12-28T11:03:45.854119Z  INFO ThreadId(145) supervisor{s="test" cid=66}: recvd stop msg
2025-12-28T11:03:45.854161Z  INFO ThreadId(145) supervisor{s="test" cid=66}: close time.busy=7.80s time.idle=8.46µs
2025-12-28T11:03:45.854261Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}: done child_done=false
2025-12-28T11:03:45.854284Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach:bidi_stream{s="test"}: close time.busy=7.83s time.idle=3.13µs
2025-12-28T11:03:45.854290Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: bidi stream loop finished child_done=false
2025-12-28T11:03:45.854294Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: finished attach streaming section
2025-12-28T11:03:45.854302Z  INFO ThreadId(142) handle_conn{cid=66}:handle_attach: close time.busy=7.83s time.idle=4.58µs
2025-12-28T11:03:45.854318Z  INFO ThreadId(142) handle_conn{cid=66}: close time.busy=7.83s time.idle=8.37µs
2025-12-28T11:03:47.087115Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:47.087185Z  INFO ThreadId(01) run:serve: socket got a new connection
2025-12-28T11:03:47.087220Z  INFO ThreadId(148) handle_conn{cid=69}: new
2025-12-28T11:03:47.087240Z  INFO ThreadId(148) handle_conn{cid=69}: broken pipe while writing version, likely just a daemon presence probe
2025-12-28T11:03:47.087247Z  INFO ThreadId(148) handle_conn{cid=69}: close time.busy=14.6µs time.idle=13.6µs
2025-12-28T11:03:47.087369Z  INFO ThreadId(149) handle_conn{cid=70}: new
2025-12-28T11:03:47.087478Z  INFO ThreadId(149) handle_conn{cid=70}:parse_connect_header: new
2025-12-28T11:03:47.087648Z  INFO ThreadId(149) handle_conn{cid=70}:parse_connect_header: close time.busy=163µs time.idle=6.63µs
2025-12-28T11:03:47.087681Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: new
2025-12-28T11:03:47.087791Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:build_shell_env: new
2025-12-28T11:03:47.087808Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:build_shell_env: injecting TERM into shell Some("xterm-ghostty")
2025-12-28T11:03:47.087854Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:build_shell_env: close time.busy=50.8µs time.idle=12.6µs
2025-12-28T11:03:47.087863Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells): new
2025-12-28T11:03:47.087867Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells): found entry for 'test'
2025-12-28T11:03:47.087872Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: new
2025-12-28T11:03:47.087875Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: taking over existing session inner
2025-12-28T11:03:47.087880Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells):aquired_lock(session.inner){s="test"}: close time.busy=5.42µs time.idle=3.30µs
2025-12-28T11:03:47.087892Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:1_lock(shells): close time.busy=18.6µs time.idle=11.3µs
2025-12-28T11:03:47.087896Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: released lock on shells table
2025-12-28T11:03:47.087899Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:link_ssh_auth_sock: new
2025-12-28T11:03:47.087902Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:link_ssh_auth_sock: no SSH_AUTH_SOCK in client env, leaving it unlinked
2025-12-28T11:03:47.087905Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:link_ssh_auth_sock: close time.busy=3.40µs time.idle=2.68µs
2025-12-28T11:03:47.087910Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:populate_session_env_file: new
2025-12-28T11:03:47.087926Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:populate_session_env_file: populating "/run/user/1000/shpool/sessions/test/forward.env"
2025-12-28T11:03:47.087956Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:populate_session_env_file: close time.busy=42.8µs time.idle=3.35µs
2025-12-28T11:03:47.087961Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:write_reply: new
2025-12-28T11:03:47.087980Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:write_reply: close time.busy=16.3µs time.idle=3.03µs
2025-12-28T11:03:47.087985Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: starting bidi stream loop
2025-12-28T11:03:47.087989Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}: new
2025-12-28T11:03:47.087993Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): new
2025-12-28T11:03:47.128804Z  INFO ThreadId(135) shell->client{s="test" cid=62}: got new connection (rows=61, cols=209)
2025-12-28T11:03:47.129066Z  INFO ThreadId(135) shell->client{s="test" cid=62}: executing reattach protocol (mode=Screen)
2025-12-28T11:03:47.129076Z  INFO ThreadId(135) shell->client{s="test" cid=62}: computing screen restore buf with (rows=61, cols=1024)
2025-12-28T11:03:47.129129Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): client connection status=New
2025-12-28T11:03:47.129152Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:initial_attach_lock(shell_to_client_ctl): close time.busy=41.2ms time.idle=4.16µs
2025-12-28T11:03:47.129163Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: new
2025-12-28T11:03:47.129221Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_client_to_shell: close time.busy=54.1µs time.idle=4.42µs
2025-12-28T11:03:47.129228Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: new
2025-12-28T11:03:47.129255Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_heartbeat: close time.busy=24.1µs time.idle=3.41µs
2025-12-28T11:03:47.129260Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: new
2025-12-28T11:03:47.129280Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:spawn_supervisor: close time.busy=16.2µs time.idle=3.34µs
2025-12-28T11:03:47.129316Z  INFO ThreadId(152) supervisor{s="test" cid=70}: new
2025-12-28T11:03:47.129337Z  INFO ThreadId(151) heartbeat{s="test" cid=70}: new
2025-12-28T11:03:47.129505Z  INFO ThreadId(150) client->shell{s="test" cid=70}: new
2025-12-28T11:03:47.230077Z  INFO ThreadId(135) shell->client{s="test" cid=62}: resized fd (rows=61, cols=209)
2025-12-28T11:03:52.912190Z  INFO ThreadId(134) child_watcher{s="test" cid=62}: child exited with status 0
2025-12-28T11:03:52.912231Z  INFO ThreadId(134) child_watcher{s="test" cid=62}: close time.busy=19.6s time.idle=23.0µs
2025-12-28T11:03:52.912290Z  INFO ThreadId(152) supervisor{s="test" cid=70}: child shell exited with status 0
2025-12-28T11:03:52.912298Z  INFO ThreadId(152) supervisor{s="test" cid=70}: close time.busy=5.78s time.idle=7.53µs
2025-12-28T11:03:52.935917Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): new
2025-12-28T11:03:52.935957Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): telling shell->client to disconnect with exit status 0
2025-12-28T11:03:52.935969Z  INFO ThreadId(135) shell->client{s="test" cid=62}: disconnectexit(0), shutting down client stream
2025-12-28T11:03:52.936139Z  INFO ThreadId(150) client->shell{s="test" cid=70}: recvd stop msg (1)
2025-12-28T11:03:52.936159Z  INFO ThreadId(150) client->shell{s="test" cid=70}: close time.busy=5.81s time.idle=44.1µs
2025-12-28T11:03:52.936160Z  INFO ThreadId(135) shell->client{s="test" cid=62}: close time.busy=19.6s time.idle=9.72µs
2025-12-28T11:03:52.936276Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): detached from shell->client, status = Detached
2025-12-28T11:03:52.936295Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}:disconnect_lock(shell_to_client_ctl): close time.busy=338µs time.idle=41.3µs
2025-12-28T11:03:53.337678Z  INFO ThreadId(151) heartbeat{s="test" cid=70}: close time.busy=6.21s time.idle=6.46µs
2025-12-28T11:03:53.337804Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}: done child_done=true
2025-12-28T11:03:53.337816Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:bidi_stream{s="test"}: close time.busy=6.25s time.idle=3.02µs
2025-12-28T11:03:53.337821Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: bidi stream loop finished child_done=true
2025-12-28T11:03:53.337825Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: 'test' exited, removing from session table
2025-12-28T11:03:53.337830Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:2_lock(shells): new
2025-12-28T11:03:53.337836Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach:2_lock(shells): close time.busy=2.68µs time.idle=3.50µs
2025-12-28T11:03:53.337840Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: finished attach streaming section
2025-12-28T11:03:53.337904Z  INFO ThreadId(149) handle_conn{cid=70}:handle_attach: close time.busy=6.25s time.idle=4.42µs
2025-12-28T11:03:53.337922Z  INFO ThreadId(149) handle_conn{cid=70}: close time.busy=6.25s time.idle=7.40µs

And a matching asciicast: typing-delayed-after-reattach.cast.json

[tobwen]

For users without knowledge of asciicat

[neurosnap]

I'm just guessing since I don't see the error message, but I dealt with this in zmx: fish will send a DA query on reattach waiting for a response with a 2 second timeout.

Usually you would see this warning message after the terminal failed to reply to the fish DA query:

warning: fish could not read response to Primary Device Attribute query after waiting for 2 seconds. This is often due to a missing feature in your terminal. See 'help terminal-compatibility' or 'man fish-terminal-compatibility'. This fish process will no longer wait for outstanding queries, which disables some optional features.

[injust]

BTW fish 4.6 increased the timeout for the DA query to 10 seconds.

fish-shell/fish-shell@5fe1cfb

[injust]

See #286 for another symptom of the DA query. The repro steps over there should be more reliable, too.

[s-cerevisiae]

Edit: nope, this doesn't work as I expect it to. It seems that UVARs are always persistent so this just disables the feature permanently. A better way would be to make a wrapper (alias) and call fish --features.

A quick workaround:

# $XDG_CONFIG_HOME/fish/conf.d/shpool_workaround.fish 
if test -n "$SHPOOL_SESSION_NAME"
    set -ax fish_features no-query-term
end

so that the query feature is turned off in this shpool session.

It would probably become the solution if it's not possible to answer the query in shpool...

Might also make sense to include the line in the injected fish script if there's no better idea.

[s-cerevisiae]

Made a mini binary shim to do that (okay it's just exec $SHELL --features no-query-term with extra steps because I don't want to start fish twice) and it's working well for me:

use std::{env, os::unix::process::CommandExt, path::PathBuf, process::Command};

fn main() {
    let shell: PathBuf = env::var_os("SHELL").expect("$SHELL is unset").into();
    assert!(
        shell.ends_with("fish"),
        "$SHELL (`{}`) does not end with fish",
        shell.display()
    );
    panic!(
        "failed to start `{}`: {:?}",
        shell.display(),
        Command::new(&shell)
            .args(["--features", "no-query-term"])
            .exec(),
    );
}

I think it would make sense to allow arguments for shell in shpool config.

[ethanpailes]

Nice find, thanks! We should probably add something about this to the troubleshooting wiki page.

Also, might be worth setting no-query-term in the fish shell hook, though just silently doing that is a bit suspicious. Maybe it is ok to do if we first extend the motd mechanism to include the custom warnings warning and auto-enable pager motd mode for fish sessions.

Obviously a fix for the root cause would be best, but that likely means swaping out the vterm engine (which I am slowly working on)

[neurosnap]

I usually only see this issue when the user first creates a session and the terminal hasn't attached yet, not sure why fish would be sending DA queries when re-attaching to a session.

Regardless, in case this helps, this is what we do in zmx:

• https://github.com/neurosnap/zmx/blob/ce66992eacccc986ee59afc3956fdc136324b7c9/src/main.zig#L2566-L2576
• https://github.com/neurosnap/zmx/blob/ce66992eacccc986ee59afc3956fdc136324b7c9/src/util.zig#L142-L180

[s-cerevisiae]

setting no-query-term in the fish shell hook

Doesn't quite work as fish features are universal vars (always persisted for any modifications and loaded for each session). That's how my first attempt failed.

[s-cerevisiae]

I've looked at zmx code but I'm not sure if there is any fixed response that makes sense. (Although it's certainly better than manually or automatically turning the query feature off from the shell side.) For example on termux it's ^[[?64;1;2;6;9;15;18;21;22c and on wezterm it's ^[[?65;4;6;18;22;52c.

Since without prompt injection (more specifically the waiting and scanning for sentinel after it) the query just works, it would be best if shpool attach is able to forward the query and bring back the response during the wait_for_startup part, in my opinion.

(I'm no expert on this tho, take it with a grain of salt)

[ethanpailes]

shpool ought to just be passing all the bytes through to the underlying terminal emulator without modification or dealy, so it's pretty strange that it is interfearing. There is definitely something weird going on here. I don't have the time to dig into this super soon, but I'll try to dig into it eventually. You might have some luck just cranking up the logging verbosity and dumping the logs into an agent to see what it thinks.