Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TPM causes my AppImage build to hang on start if no server is running #189

Open
michaellee8 opened this issue Nov 14, 2020 · 9 comments · May be fixed by #190, tmux-plugins/tmux-sensible#57, tmux-plugins/tmux-yank#148 or christoomey/vim-tmux-navigator#289
Open

TPM causes my AppImage build to hang on start if no server is running #189

michaellee8 opened this issue Nov 14, 2020 · 9 comments · May be fixed by #190, tmux-plugins/tmux-sensible#57, tmux-plugins/tmux-yank#148 or christoomey/vim-tmux-navigator#289

Comments

@michaellee8
Copy link

Steps to reproduce:

  1. Grab my AppImage build here https://github.com/michaellee8/tmux/releases/tag/test or build a flash one with ./tools/genappimage.sh if you don't trust me. It is the only file I have added in my fork, it requires pkg-config, autotools, automake, autoconf and imagemagick.
  2. Make sure there are no tmux server running (kill all running tmux process)
  3. Make sure you have the run tpm entry on your .tmux.conf
  4. ./tmux.appimage -vv (-vv to get server log)
  5. Get hang and not even Crtl+C can help you.
  6. Kill all tmux process.
  7. Comment out the run tpm line on your .tmux.conf
  8. Let's run ./tmux.appimage again, nicely running.
  9. Look at the bottom of the log you can see some TMUX_PLUGIN_MANAGER_PATH not found error.
  • Only breaks if there are no server running. If you let that server running without closing the first client and statrt the second client, the second client works fine.
  • Works fine with the system's tmux, I don't know whether it is because it is old enough to not have the bug or because the system tmux don't need a TMUX_PLUGIN_MANAGER_PATH.
@michaellee8 michaellee8 changed the title Tom causes my AppImage build to hang on start if no server is running TPM causes my AppImage build to hang on start if no server is running Nov 14, 2020
@michaellee8
Copy link
Author

Client log:

1605358725.194670 client started (678): version 3.1c, socket /tmp//tmux-1000/default, protocol 8
1605358725.194698 on Linux 5.4.49+ #1 SMP Sun Oct 18 19:43:35 PDT 2020; libevent 2.1.12-stable (poll)
1605358725.194726 socket is /tmp//tmux-1000/default
1605358725.194740 trying connect
1605358725.194763 connect failed: No such file or directory
1605358725.194774 lock file is /tmp//tmux-1000/default.lock
1605358725.194809 flock succeeded
1605358725.194813 got lock (8)
1605358725.194818 trying connect
1605358725.194825 connect failed: No such file or directory
1605358725.195061 add peer 0x55e0d26de460: 9 ((nil))
1605358725.195212 sending message 100 to peer 0x55e0d26de460 (4 bytes)
1605358725.195219 sending message 101 to peer 0x55e0d26de460 (15 bytes)
1605358725.195223 sending message 102 to peer 0x55e0d26de460 (11 bytes)
1605358725.195228 sending message 108 to peer 0x55e0d26de460 (35 bytes)
1605358725.195234 sending message 104 to peer 0x55e0d26de460 (0 bytes)
1605358725.195240 sending message 107 to peer 0x55e0d26de460 (4 bytes)
1605358725.195245 sending message 105 to peer 0x55e0d26de460 (16 bytes)
1605358725.195250 sending message 105 to peer 0x55e0d26de460 (27 bytes)
1605358725.195255 sending message 105 to peer 0x55e0d26de460 (22 bytes)
1605358725.195259 sending message 105 to peer 0x55e0d26de460 (14 bytes)
1605358725.195264 sending message 105 to peer 0x55e0d26de460 (45 bytes)
1605358725.195269 sending message 105 to peer 0x55e0d26de460 (17 bytes)
1605358725.195273 sending message 105 to peer 0x55e0d26de460 (45 bytes)
1605358725.195278 sending message 105 to peer 0x55e0d26de460 (36 bytes)
1605358725.195283 sending message 105 to peer 0x55e0d26de460 (52 bytes)
1605358725.195288 sending message 105 to peer 0x55e0d26de460 (30 bytes)
1605358725.195293 sending message 105 to peer 0x55e0d26de460 (39 bytes)
1605358725.195313 sending message 105 to peer 0x55e0d26de460 (19 bytes)
1605358725.195318 sending message 105 to peer 0x55e0d26de460 (29 bytes)
1605358725.195323 sending message 105 to peer 0x55e0d26de460 (46 bytes)
1605358725.195327 sending message 105 to peer 0x55e0d26de460 (22 bytes)
1605358725.195332 sending message 105 to peer 0x55e0d26de460 (17 bytes)
1605358725.195337 sending message 105 to peer 0x55e0d26de460 (1506 bytes)
1605358725.195353 sending message 105 to peer 0x55e0d26de460 (36 bytes)
1605358725.195358 sending message 105 to peer 0x55e0d26de460 (28 bytes)
1605358725.195362 sending message 105 to peer 0x55e0d26de460 (49 bytes)
1605358725.195368 sending message 105 to peer 0x55e0d26de460 (25 bytes)
1605358725.195373 sending message 105 to peer 0x55e0d26de460 (66 bytes)
1605358725.195378 sending message 105 to peer 0x55e0d26de460 (44 bytes)
1605358725.195383 sending message 105 to peer 0x55e0d26de460 (32 bytes)
1605358725.195388 sending message 105 to peer 0x55e0d26de460 (24 bytes)
1605358725.195393 sending message 105 to peer 0x55e0d26de460 (32 bytes)
1605358725.195397 sending message 105 to peer 0x55e0d26de460 (20 bytes)
1605358725.195403 sending message 105 to peer 0x55e0d26de460 (64 bytes)
1605358725.195408 sending message 105 to peer 0x55e0d26de460 (32 bytes)
1605358725.195412 sending message 105 to peer 0x55e0d26de460 (36 bytes)
1605358725.195418 sending message 105 to peer 0x55e0d26de460 (53 bytes)
1605358725.195423 sending message 105 to peer 0x55e0d26de460 (20 bytes)
1605358725.195428 sending message 105 to peer 0x55e0d26de460 (16 bytes)
1605358725.195433 sending message 105 to peer 0x55e0d26de460 (27 bytes)
1605358725.195438 sending message 105 to peer 0x55e0d26de460 (39 bytes)
1605358725.195442 sending message 105 to peer 0x55e0d26de460 (34 bytes)                                                                                                   1605358725.195447 sending message 105 to peer 0x55e0d26de460 (30 bytes)
1605358725.195451 sending message 105 to peer 0x55e0d26de460 (37 bytes)
1605358725.195456 sending message 105 to peer 0x55e0d26de460 (85 bytes)
1605358725.195461 sending message 105 to peer 0x55e0d26de460 (8 bytes)
1605358725.195466 sending message 105 to peer 0x55e0d26de460 (25 bytes)
1605358725.195471 sending message 105 to peer 0x55e0d26de460 (42 bytes)
1605358725.195476 sending message 105 to peer 0x55e0d26de460 (46 bytes)
1605358725.195489 sending message 105 to peer 0x55e0d26de460 (21 bytes)
1605358725.195494 sending message 105 to peer 0x55e0d26de460 (58 bytes)
1605358725.195499 sending message 105 to peer 0x55e0d26de460 (50 bytes)
1605358725.195504 sending message 105 to peer 0x55e0d26de460 (30 bytes)
1605358725.195508 sending message 105 to peer 0x55e0d26de460 (31 bytes)
1605358725.195513 sending message 105 to peer 0x55e0d26de460 (40 bytes)
1605358725.195517 sending message 105 to peer 0x55e0d26de460 (21 bytes)
1605358725.195522 sending message 105 to peer 0x55e0d26de460 (13 bytes)
1605358725.195527 sending message 105 to peer 0x55e0d26de460 (367 bytes)
1605358725.195532 sending message 105 to peer 0x55e0d26de460 (18 bytes)
1605358725.195537 sending message 105 to peer 0x55e0d26de460 (24 bytes)
1605358725.195542 sending message 105 to peer 0x55e0d26de460 (26 bytes)
1605358725.195547 sending message 105 to peer 0x55e0d26de460 (19 bytes)
1605358725.195552 sending message 105 to peer 0x55e0d26de460 (40 bytes)
1605358725.195557 sending message 105 to peer 0x55e0d26de460 (24 bytes)
1605358725.195561 sending message 105 to peer 0x55e0d26de460 (13 bytes)
1605358725.195566 sending message 105 to peer 0x55e0d26de460 (24 bytes)
1605358725.195571 sending message 105 to peer 0x55e0d26de460 (38 bytes)                                                                                                   1605358725.195576 sending message 105 to peer 0x55e0d26de460 (46 bytes)
1605358725.195582 sending message 105 to peer 0x55e0d26de460 (30 bytes)
1605358725.195587 sending message 106 to peer 0x55e0d26de460 (0 bytes)
1605358725.195594 sending message 200 to peer 0x55e0d26de460 (4 bytes)
1605358725.195598 client loop enter

@michaellee8
Copy link
Author

Server log :

1605358725.414072 cmd_unpack_argv: argv[0]=show-environment
1605358725.414075 cmd_unpack_argv: argv[1]=-g                                                                                                       1605358725.414085 cmd_unpack_argv: argv[2]=TMUX_PLUGIN_MANAGER_PATH
1605358725.414089 cmd_parse_from_arguments: argv[0]=show-environment
1605358725.414092 cmd_parse_from_arguments: argv[1]=-g
1605358725.414095 cmd_parse_from_arguments: argv[2]=TMUX_PLUGIN_MANAGER_PATH
1605358725.414099 cmd_parse_from_arguments: at 0: argv[0]=show-environment
1605358725.414102 cmd_parse_from_arguments: at 0: argv[1]=-g
1605358725.414105 cmd_parse_from_arguments: at 0: argv[2]=TMUX_PLUGIN_MANAGER_PATH
1605358725.414111 cmd_parse_build_commands: 0 show-environment
1605358725.414114 cmd_parse_build_commands: argv[0]=-g
1605358725.414116 cmd_parse_build_commands: argv[1]=TMUX_PLUGIN_MANAGER_PATH
1605358725.414125 cmd_parse: show-environment: argv[0]=show-environment
1605358725.414128 cmd_parse: show-environment: argv[1]=-g
1605358725.414131 cmd_parse: show-environment: argv[2]=TMUX_PLUGIN_MANAGER_PATH
1605358725.414140 cmd_parse_build_commands: show-environment -g TMUX_PLUGIN_MANAGER_PATH
1605358725.414145 cmdq_get_command: [show-environment/0x55e0d26d50b0] group 1489
1605358725.414148 cmdq_append <client-701>: [show-environment/0x55e0d26d50b0]
1605358725.414153 cmdq_append <client-701>: [server_client_command_done/0x55e0d273c9a0]
1605358725.414157 cmdq_next <global>: waiting                                                                                                       1605358725.414160 cmdq_next </dev/pts/0>: waiting                                                                                                   1605358725.414163 cmdq_next <client-701>: enter
1605358725.414167 cmdq_next <client-701>: [show-environment/0x55e0d26d50b0] (0), flags 0
1605358725.414173 cmdq_fire_command <client-701>: (1489) show-environment -g TMUX_PLUGIN_MANAGER_PATH
1605358725.414178 cmd_find_target: target none, type session, item 0x55e0d26d50b0, flags QUIET,CANFAIL
1605358725.414181 cmd_find_best_session: 0 sessions to try
1605358725.414184 cmd_find_target: error
1605358725.414189 cmdq_error: unknown variable: TMUX_PLUGIN_MANAGER_PATH
1605358725.414208 sending message 303 to peer 0x55e0d275e190 (12 bytes)                                                                             1605358725.414213 unref client 0x55e0d275cfc0 (4 references)                                                                                        1605358725.414217 cmdq_next <client-701>: [server_client_command_done/0x55e0d273c9a0] (1), flags 0
1605358725.414221 unref client 0x55e0d275cfc0 (3 references)
1605358725.414224 cmdq_next <client-701>: exit (empty)
1605358725.414226 cmdq_next <global>: waiting
1605358725.414229 cmdq_next </dev/pts/0>: waiting
1605358725.414232 cmdq_next <client-701>: empty
1605358725.414261 cmdq_next <global>: waiting
1605358725.414266 cmdq_next </dev/pts/0>: waiting
1605358725.414270 cmdq_next <client-701>: empty                                                                                                     1605358785.317664 cmdq_next <global>: waiting
1605358785.317701 cmdq_next </dev/pts/0>: waiting
1605358785.317706 cmdq_next <client-701>: empty
1605358845.377846 cmdq_next <global>: waiting
1605358845.377890 cmdq_next </dev/pts/0>: waiting
1605358845.377896 cmdq_next <client-701>: empty
1605358905.438007 cmdq_next <global>: waiting
1605358905.438051 cmdq_next </dev/pts/0>: waiting
1605358905.438055 cmdq_next <client-701>: empty
1605358965.457190 cmdq_next <global>: waiting
1605358965.457235 cmdq_next </dev/pts/0>: waiting
1605358965.457241 cmdq_next <client-701>: empty
1605359025.480917 cmdq_next <global>: waiting
1605359025.480964 cmdq_next </dev/pts/0>: waiting
1605359025.480969 cmdq_next <client-701>: empty
1605359085.520763 cmdq_next <global>: waiting
1605359085.520805 cmdq_next </dev/pts/0>: waiting
1605359085.520811 cmdq_next <client-701>: empty

@michaellee8
Copy link
Author

tmux-server-686.log

@michaellee8
Copy link
Author

Actually it breaks in the same way even for https://github.com/nelsonenzo/tmux-appimage

@michaellee8
Copy link
Author

michaellee8 commented Nov 14, 2020 •
edited
Loading

This is a successful log from my system installation of tmux 2.3.

1605368065.946366 client 0x5591a030b640 IDENTIFY_ENVIRON _=/usr/bin/tmux
1605368065.946368 peer 0x5591a030fb50 message 105
1605368065.946373 client 0x5591a030b640 IDENTIFY_ENVIRON EVENT_NOEPOLL=1
1605368065.946376 peer 0x5591a030fb50 message 106
1605368065.946383 peer 0x5591a030fb50 message 200
1605368065.946393 continuing cmdq 0x5591a02f2820: flags 0, client 0x5591a030b640
1605368065.946400 cmdq 0x5591a02f2820: show-environment -g TMUX_PLUGIN_MANAGER_PATH
1605368065.946406 preparing state for show-environment -g TMUX_PLUGIN_MANAGER_PATH (client 0x5591a030b640)
1605368065.946410 cmd_find_current_session: have client 0x5591a030b640
1605368065.946421 client 0x5591a030b640 TMUX is /tmp/tmux-1000/default,1215,4294967295 (session @4294967295)
1605368065.946425 cmd_find_client: no target, return (nil)
1605368065.946427 preparing -t state: target none
1605368065.946430 cmd_prepare_state_flag: flag t 4 0x2
1605368065.946433 cmd_find_current_session: have client 0x5591a030b640
1605368065.946438 client 0x5591a030b640 TMUX is /tmp/tmux-1000/default,1215,4294967295 (session @4294967295)
1605368065.946441 cmd_find_target: target none, type 2
1605368065.946444 cmd_find_target: cmdq 0x5591a02f2820, flags 0x2
1605368065.946447 cmd_find_target: s=none
1605368065.946449 cmd_find_target: wl=none                                                                                                          1605368065.946451 cmd_find_target: wp=none                                                                                                          1605368065.946454 cmd_find_target: idx=none                                                                                                         1605368065.946462 preparing -s state: target none                                                                                                   1605368065.946470 preparing state for show-environment -g TMUX_PLUGIN_MANAGER_PATH (client 0x5591a030b640)                                          1605368065.946473 cmd_find_current_session: have client 0x5591a030b640                                                                              1605368065.946478 client 0x5591a030b640 TMUX is /tmp/tmux-1000/default,1215,4294967295 (session @4294967295)                                        1605368065.946480 cmd_find_client: no target, return (nil)                                                                                          1605368065.946483 preparing -t state: target none                                                                                                   1605368065.946486 cmd_prepare_state_flag: flag t 4 0x2                                                                                              1605368065.946489 cmd_find_current_session: have client 0x5591a030b640                                                                              1605368065.946493 client 0x5591a030b640 TMUX is /tmp/tmux-1000/default,1215,4294967295 (session @4294967295)                                        1605368065.946496 cmd_find_target: target none, type 2                                                                                              1605368065.946498 cmd_find_target: cmdq 0x5591a02f2820, flags 0x2                                                                                   1605368065.946501 cmd_find_target: s=none                                                                                                           1605368065.946503 cmd_find_target: wl=none                                                                                                          1605368065.946506 cmd_find_target: wp=none                                                                                                          1605368065.946508 cmd_find_target: idx=none                                                                                                         1605368065.946510 preparing -s state: target none                                                                                                   1605368065.946522 sending message 211 to peer 0x5591a030fb50 (8200 bytes)                                                                           1605368065.946528 server_client_push_stderr: client 0x5591a030b640, sent 43, left 0
1605368065.946533 sending message 203 to peer 0x5591a030fb50 (4 bytes)
1605368065.946784 lost client 0x5591a030b640
1605368065.946806 remove peer 0x5591a030fb50
1605368065.946825 unref client 0x5591a030b640 (1 references)
1605368065.946835 free client 0x5591a030b640 (0 references)
1605368065.948725 add peer 0x5591a030fb50: 11 (0x5591a030b640)
1605368065.948744 new client 0x5591a030b640

tmux-server-1113.log

@michaellee8
Copy link
Author

Well it turns out it has nothing to do with AppImage, it breaks for all vesion >= 3.1, even for my non-appimage binary. I will look if there are some bugs preventing from working.

@michaellee8 michaellee8 mentioned this issue Nov 14, 2020
Closed
@michaellee8
Copy link
Author

michaellee8 commented Nov 15, 2020 •
edited
Loading

working server log at 3.0a
tmux-server-2162.log

You may want to do a tmux split for both less tmux-server-686.log and then less tmux-server-2162.log, run /show-environment on both of them. I saw something interesting there.

image

It looks like sending message 303 to peer 0x55e0d275e190 (12 bytes) in new version vs sending message 211 to peer 0x557e04ed7350 (8200 bytes) is the culprit.

There is a server_client_push_stderr in https://github.com/tmux/tmux/blob/3.0a/server-client.c#L2049 but not https://github.com/tmux/tmux/blob/3.1/server-client.c, looks like changed in tmux/tmux@7922f4e#diff-ea06b9ec74ec81be7b034016d6c272203a36aeee30300b9865170429a9d5b999L2075, which looks like from ThomasAdam/tmux@c284ebe, tmux/tmux@c284ebe

Some notes:
Reading https://github.com/tmux/tmux/blob/970e8f734c996e6a1402be1181c48abd14b6404a/tmux.h#L489 shows that in 3.0a a 211 MSG_OLDSTDERR following a large message (should be the error message) is send followed by a 203 MSG_DETACHKILL, while in 3.1 it only sends a 303 MSG_WRITE_OPEN. It looks like there are difference between server_client_push_stderr and file_error here https://github.com/tmux/tmux/blob/3.1/cmd-queue.c#L557

@michaellee8
Copy link
Author

michaellee8 commented Nov 15, 2020 •
edited
Loading

Full logs for both working 3.0a and broken 3.1:

working 3.0a:
tmux-client-1287.log
tmux-server-1295.log
tmux-out-1295.log

broken 3.1, which is killed with SIGTERM:
tmux-server-1638.log
tmux-client-1630.log
(out is not avilable since it is empty, i.e. 0 bytes)

broken 3.1 with the inner tmux logged in -vv, killed with SIGTERM:
tmux-client-2387.log
tmux-client-2410.log
htop.txt
tmux-server-2395.log

working 3.0a with the inner tmux logged in -vv:
tmux-client-1287.log
tmux-server-1295.log
tmux-out-1295.log
tmux-client-3033.log
htop.txt

All these logs are produced in my Google Cloud Shell instance, 3.0a logs are produced with my working 3.0a AppImage, 3.1 logs are produced with 3.1b AppImage here https://github.com/nelsonenzo/tmux-appimage/releases/tag/tmux3.1b

@michaellee8
Copy link
Author

After one Sunday of debug now I understand this problem now. When I start an AppImage instance of tmux (3.1b), it uses the newer file-based protocol that uses MSG_WRITE suite of commands to communicate with the client, which the system version of old tmux (2.3 in this case) will not understand. In ~/.tmux/plugins/tpm/tpm script, the system version of tmux is used, which won't understand that is the server doing. In that case, the code will run until this line https://github.com/tmux/tmux/blob/52869ed182482c26163799a7215139f4d81b6fca/client.c#L635 and wait indefinitely for the server to send new commands, which the server won't send any commands since the client haven't read the stderr yet, that is something like a deadlock. I have verified my theory by putting export PATH="/home/ckmichael8/.local/bin:$PATH" into my .bashrc and do a ln -s ~/tmux-3.1b-x86_64.AppImage ~/.local/bin/tmux. It just works after using this workaround.

What can we do to resolve this problem:

  1. All scripts currently uses tmux, which is the system installation directly, we should provide some guard to make sure the tmux we use matches the binary the server is actually using. Perharps we should try to get the server binary path and them use an change all our call to tmux to something like $TMUX_PATH.

@bruno- can you have a look at this? I can help landing a PR if you can think of how should we work this out.

This was referenced Nov 15, 2020
Open
Open
Open
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
1 participant
@michaellee8