search

shell-pool / shpool

Think tmux, then aim... lower
Apache License 2.0
1.14k stars 20 forks source link

Reattaching to existing session dumps logic for setting PROMPT_COMMAND to screen #120

Closed rlue closed 1 week ago

rlue commented 1 month ago

What happened

$ shpool attach main

shpool:main $ shpool detach
$ shpool attach main
# <REDRAWS SCREEN>
$
$             if [[ -z "${PROMPT_COMMAND+x}" ]]; then
>                PS1="shpool:main ${PS1}"
>             else
>                SHPOOL__OLD_PROMPT_COMMAND="${PROMPT_COMMAND}"
>                SHPOOL__OLD_PS1="${PS1}"
>                function __shpool__prompt_command() {
>                   PS1="${SHPOOL__OLD_PS1}"
>                   for prompt_hook in ${SHPOOL__OLD_PROMPT_COMMAND}
>                   do
>                     ${prompt_hook}
>                   done
>                   PS1="shpool:main ${PS1}"
>                }
>                PROMPT_COMMAND=__shpool__prompt_command
>             fi
shpool:main $
shpool:main $ SHPOOL__INTERNAL__PRINT_SENTINEL=prompt /proc/1284690/exe daemon
SHPOOL_PROMPT_SETUP_SENTINEL
shpool:main $ shpool detach
shpool:main $

What I expected to happen

$ shpool attach main

shpool:main $ shpool detach
$ shpool attach main
# <REDRAWS SCREEN>
shpool:main $ shpool detach
shpool:main $

Version info

0.6.3

Logs

Last 100 lines: ``` 2024-08-11T00:56:03.628170Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:spawn_subshell:spawn_reader{s="main"}: new 2024-08-11T00:56:03.628429Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:spawn_subshell:spawn_reader{s="main"}: close time.busy=81.3µs time.idle=177µs 2024-08-11T00:56:03.628509Z INFO ThreadId(212) reader{s="main" cid=57}: new 2024-08-11T00:56:03.628589Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:spawn_subshell: close time.busy=260ms time.idle=6.90µs 2024-08-11T00:56:03.628847Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach: released lock on shells table 2024-08-11T00:56:03.628981Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:link_ssh_auth_sock: new 2024-08-11T00:56:03.629179Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:link_ssh_auth_sock: close time.busy=62.1µs time.idle=136µs 2024-08-11T00:56:03.629334Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:write_reply: new 2024-08-11T00:56:03.629506Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:write_reply: close time.busy=25.7µs time.idle=146µs 2024-08-11T00:56:03.629654Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach: starting bidi stream loop 2024-08-11T00:56:03.629938Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: new 2024-08-11T00:56:03.644074Z INFO ThreadId(212) reader{s="main" cid=57}: waiting for initial client connection 2024-08-11T00:56:03.644435Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: client connection status=New 2024-08-11T00:56:03.644475Z INFO ThreadId(212) reader{s="main" cid=57}: got initial client connection 2024-08-11T00:56:03.644695Z INFO ThreadId(212) reader{s="main" cid=57}: resized fd (rows=46, cols=86) 2024-08-11T00:56:03.644783Z INFO ThreadId(212) reader{s="main" cid=57}: saw prompt sentinel 2024-08-11T00:56:03.644633Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_client_to_shell: new 2024-08-11T00:56:03.645236Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_client_to_shell: close time.busy=145µs time.idle=468µs 2024-08-11T00:56:03.645418Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_heartbeat: new 2024-08-11T00:56:03.645304Z INFO ThreadId(213) client->shell{s="main" cid=57}: new 2024-08-11T00:56:03.645703Z INFO ThreadId(214) heartbeat{s="main" cid=57}: new 2024-08-11T00:56:03.645617Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_heartbeat: close time.busy=41.1µs time.idle=158µs 2024-08-11T00:56:03.645983Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_supervisor: new 2024-08-11T00:56:03.646167Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}:spawn_supervisor: close time.busy=51.4µs time.idle=133µs 2024-08-11T00:56:03.646250Z INFO ThreadId(215) supervisor{s="main" cid=57}: new 2024-08-11T00:56:12.258104Z INFO ThreadId(01) run:serve: socket got a new connection 2024-08-11T00:56:12.258300Z INFO ThreadId(216) handle_conn{cid=58}: new 2024-08-11T00:56:12.258334Z INFO ThreadId(216) handle_conn{cid=58}:parse_connect_header: new 2024-08-11T00:56:12.258379Z INFO ThreadId(216) handle_conn{cid=58}:parse_connect_header: close time.busy=33.8µs time.idle=12.3µs 2024-08-11T00:56:12.258443Z INFO ThreadId(216) handle_conn{cid=58}:handle_detach: new 2024-08-11T00:56:12.356109Z INFO ThreadId(212) reader{s="main" cid=57}: disconnect, shutting down client stream 2024-08-11T00:56:12.356166Z INFO ThreadId(216) handle_conn{cid=58}:handle_detach: detached session(main), status = Detached 2024-08-11T00:56:12.356211Z INFO ThreadId(216) handle_conn{cid=58}:handle_detach:write_reply: new 2024-08-11T00:56:12.356258Z INFO ThreadId(216) handle_conn{cid=58}:handle_detach:write_reply: close time.busy=31.3µs time.idle=15.5µs 2024-08-11T00:56:12.356277Z INFO ThreadId(216) handle_conn{cid=58}:handle_detach: close time.busy=97.8ms time.idle=9.21µs 2024-08-11T00:56:12.356331Z INFO ThreadId(216) handle_conn{cid=58}: close time.busy=98.0ms time.idle=26.0µs 2024-08-11T00:56:12.648106Z INFO ThreadId(214) heartbeat{s="main" cid=57}: close time.busy=9.00s time.idle=18.0µs 2024-08-11T00:56:12.655595Z INFO ThreadId(213) client->shell{s="main" cid=57}: recvd stop msg (1) 2024-08-11T00:56:12.655595Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: telling reader to disconnect without reaping 2024-08-11T00:56:12.655625Z INFO ThreadId(213) client->shell{s="main" cid=57}: close time.busy=9.01s time.idle=337µs 2024-08-11T00:56:12.657681Z INFO ThreadId(212) reader{s="main" cid=57}: disconnect, no client stream to shut down 2024-08-11T00:56:12.657738Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: detached from reader, status = DetachNone 2024-08-11T00:56:12.949492Z INFO ThreadId(215) supervisor{s="main" cid=57}: recvd stop msg 2024-08-11T00:56:12.949548Z INFO ThreadId(215) supervisor{s="main" cid=57}: close time.busy=9.30s time.idle=88.2µs 2024-08-11T00:56:12.949686Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: bidi_stream: done child_done=false 2024-08-11T00:56:12.949751Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach:bidi_stream{s="main"}: close time.busy=9.32s time.idle=150µs 2024-08-11T00:56:12.949764Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach: bidi stream loop finished 2024-08-11T00:56:12.949772Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach: finished attach streaming section 2024-08-11T00:56:12.949778Z INFO ThreadId(210) handle_conn{cid=57}:handle_attach: close time.busy=9.58s time.idle=8.68µs 2024-08-11T00:56:12.949786Z INFO ThreadId(210) handle_conn{cid=57}: close time.busy=9.58s time.idle=40.4µs 2024-08-11T00:56:20.014617Z INFO ThreadId(01) run:serve: socket got a new connection 2024-08-11T00:56:20.014896Z INFO ThreadId(217) handle_conn{cid=59}: new 2024-08-11T00:56:20.014937Z INFO ThreadId(217) handle_conn{cid=59}:parse_connect_header: new 2024-08-11T00:56:20.015605Z INFO ThreadId(217) handle_conn{cid=59}:parse_connect_header: close time.busy=656µs time.idle=11.6µs 2024-08-11T00:56:20.015682Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: new 2024-08-11T00:56:20.015692Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: locked shells table 2024-08-11T00:56:20.015702Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: found entry for 'main' 2024-08-11T00:56:20.015707Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: session 'main': locked inner 2024-08-11T00:56:20.015712Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: taking over existing session inner 2024-08-11T00:56:20.015719Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: released lock on shells table 2024-08-11T00:56:20.015729Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:link_ssh_auth_sock: new 2024-08-11T00:56:20.015816Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:link_ssh_auth_sock: close time.busy=76.6µs time.idle=10.6µs 2024-08-11T00:56:20.015832Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:write_reply: new 2024-08-11T00:56:20.015852Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:write_reply: close time.busy=10.3µs time.idle=9.75µs 2024-08-11T00:56:20.015859Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: starting bidi stream loop 2024-08-11T00:56:20.015870Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: new 2024-08-11T00:56:20.070503Z INFO ThreadId(212) reader{s="main" cid=57}: got new connection (rows=46, cols=86) 2024-08-11T00:56:20.241046Z INFO ThreadId(212) reader{s="main" cid=57}: executing reattach protocol (mode=Screen) 2024-08-11T00:56:20.241099Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: client connection status=New 2024-08-11T00:56:20.241147Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_client_to_shell: new 2024-08-11T00:56:20.241116Z INFO ThreadId(212) reader{s="main" cid=57}: computing screen restore buf with (rows=46, cols=65535) 2024-08-11T00:56:20.241249Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_client_to_shell: close time.busy=93.2µs time.idle=8.62µs 2024-08-11T00:56:20.241265Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_heartbeat: new 2024-08-11T00:56:20.241308Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_heartbeat: close time.busy=36.7µs time.idle=5.81µs 2024-08-11T00:56:20.241325Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_supervisor: new 2024-08-11T00:56:20.241372Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}:spawn_supervisor: close time.busy=31.3µs time.idle=16.0µs 2024-08-11T00:56:20.241315Z INFO ThreadId(218) client->shell{s="main" cid=59}: new 2024-08-11T00:56:20.241426Z INFO ThreadId(219) heartbeat{s="main" cid=59}: new 2024-08-11T00:56:20.241524Z INFO ThreadId(220) supervisor{s="main" cid=59}: new 2024-08-11T00:56:20.373166Z INFO ThreadId(212) reader{s="main" cid=57}: resized fd (rows=46, cols=86) 2024-08-11T01:00:21.519359Z INFO ThreadId(211) child_watcher{s="main" cid=57}: child exited with status 0 2024-08-11T01:00:21.519508Z INFO ThreadId(211) child_watcher{s="main" cid=57}: reaped child shell: Parent(1408374, Master { pty: Some(11) }) 2024-08-11T01:00:21.519526Z INFO ThreadId(220) supervisor{s="main" cid=59}: child shell exited with status 0 2024-08-11T01:00:21.519557Z INFO ThreadId(220) supervisor{s="main" cid=59}: close time.busy=241s time.idle=13.0µs 2024-08-11T01:00:21.519544Z INFO ThreadId(211) child_watcher{s="main" cid=57}: close time.busy=258s time.idle=41.0µs 2024-08-11T01:00:21.589310Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: telling reader to disconnect with exit status 0 2024-08-11T01:00:21.589408Z INFO ThreadId(212) reader{s="main" cid=57}: disconnectexit(0), shutting down client stream 2024-08-11T01:00:21.589644Z INFO ThreadId(218) client->shell{s="main" cid=59}: recvd stop msg (1) 2024-08-11T01:00:21.589715Z INFO ThreadId(218) client->shell{s="main" cid=59}: close time.busy=241s time.idle=118µs 2024-08-11T01:00:21.589819Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: detached from reader, status = Detached 2024-08-11T01:00:21.591366Z INFO ThreadId(212) reader{s="main" cid=57}: close time.busy=258s time.idle=112µs 2024-08-11T01:00:21.807824Z INFO ThreadId(219) heartbeat{s="main" cid=59}: close time.busy=242s time.idle=13.9µs 2024-08-11T01:00:21.807990Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: bidi_stream: done child_done=true 2024-08-11T01:00:21.808028Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach:bidi_stream{s="main"}: close time.busy=242s time.idle=9.13µs 2024-08-11T01:00:21.808065Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: bidi stream loop finished 2024-08-11T01:00:21.808072Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: 'main' exited, removing from session table 2024-08-11T01:00:21.808203Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: finished attach streaming section 2024-08-11T01:00:21.808230Z WARN ThreadId(217) handle_conn{cid=59}:handle_attach: error closing fd: CloseFail 2024-08-11T01:00:21.808262Z INFO ThreadId(217) handle_conn{cid=59}:handle_attach: close time.busy=242s time.idle=10.8µs 2024-08-11T01:00:21.808306Z INFO ThreadId(217) handle_conn{cid=59}: close time.busy=242s time.idle=36.6µs ```
rlue commented 3 weeks ago

I actually just noticed that after reattaching to an existing session, the following commands are added to the shell history, as well? Probably related, but I'm not entirely sure how, since these commands don't print anything to the screen:

# re-attach
$ shpool attach main
# <C-p>
shpool:main $ SHPOOL__INTERNAL__PRINT_SENTINEL=prompt /proc/747/exe daemon
# <C-p> again
shpool:main $ SHPOOL__INTERNAL__PRINT_SENTINEL=startup /proc/747/exe daemon
ethanpailes commented 2 weeks ago

I think what is going on here is that while we strip that promp hook setup code from the data stream sent to the local terminal, we are not stripping it from the stream we send to the in-memory terminal that shpool uses to re-render on reattach. The fix is probably just to do the stripping for the stream sent into the in-mem term as well.

The SHPOOL__INTERNAL__PRINT_SENTINEL=prompt /proc/747/exe daemon stuff is working as intended since it is how shpool figures out when it is safe to begin prompt setup and when prompt setup is complete and we can stop dropping shell output. We might want to prefix the commands with a space to keep them out of the history file though (that will work for at least bash, but might not for other shells).

ethanpailes commented 2 weeks ago

https://github.com/shell-pool/shpool/pull/139 should hopefully fix the history issue. I'll try to tackle the main problem in a seperate patch.

ethanpailes commented 1 week ago

https://github.com/shell-pool/shpool/tree/fix-prompt-setup-in-session-restore should fix it. I haven't opened the PR yet since I want to merge what it's on top of first.