search

wez / wezterm

A GPU-accelerated cross-platform terminal emulator and multiplexer written by @wez and implemented in Rust
https://wezfurlong.org/wezterm/
Other
16.98k stars 767 forks source link

ProxyCommand not working on Windows #3083

Open fengjiawang opened 1 year ago

fengjiawang commented 1 year ago

What Operating System(s) are you seeing this problem on?

Windows

Which Wayland compositor or X11 Window manager(s) are you using?

No response

WezTerm version

20221119-145034-49b9839f

Did you try the latest nightly build to see if the issue is better (or worse!) than your current version?

Yes, and I updated the version box above to show the version of the nightly that I tried

Describe the bug

To Reproduce

wezterm ssh "-oProxyCommand=ssh jumpHostIP serverIP:22" serverIP

Configuration

no config

Expected Behavior

No response

Logs

No response

Anything else?

No response

wez commented 1 year ago

What gets logged if you add -v to turn on more verbose logging?

wezterm ssh -v "-oProxyCommand=ssh jumpHostIP serverIP:22" serverIP
fengjiawang commented 1 year ago

Thanks for your response! These are the loggings:

23:31:14.809  INFO   libssh::ssh_connect           > libssh 0.8.90 (c) 2003-2021 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_winlock
23:31:14.830  INFO   libssh::ssh_socket_connect    > Nonblocking connection socket: 1004
23:31:14.832  INFO   libssh::ssh_connect           > Socket connecting, now waiting for the callbacks to work
23:31:14.834  INFO   libssh::ssh_connect           > Actual timeout : 10000
23:31:24.846  INFO   libssh::ssh_connect           > Timeout connecting to [serverIP]
23:31:24.849  INFO   libssh::ssh_connect           > current state : 9
23:31:24.851  ERROR  mux::ssh                      > WrappedSshChild err: RecvError
wez commented 1 year ago

Looks like the underlying libssh doesn't support ProxyCommand on windows

wez commented 1 year ago

This may be resolved now in main.

It typically takes about an hour before commits are available as nightly builds for all platforms. Linux builds are the fastest to build and are often available within about 20 minutes. Windows and macOS builds take a bit longer.

Please take a few moments to try out the fix and let me know how that works out. You can find the nightly downloads for your system in the wezterm installation docs.

If you prefer to use packages provided by your distribution or package manager of choice and don't want to replace that with a nightly download, keep in mind that you can download portable packages (eg: a .dmg file on macOS, a .zip file on Windows and an .AppImage file on Linux) that can be run without permanently installing or replacing an existing package, and can then simply be deleted once you no longer need them.

If you are eager and can build from source then you may be able to try this out more quickly.

fengjiawang commented 1 year ago

Thanks a lot for your rapid response!

Libssh now parses "ProxyCommand" perfectly. However, It still can't connect through an ssh proxy.

The log is:

11:22:08.275  INFO   libssh::ssh_config_parse_file > Reading configuration data from C:\Users\jwfeng/.ssh/config
11:22:08.281  INFO   libssh::ssh_connect           > libssh 0.8.90 (c) 2003-2021 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_winlock
11:22:08.283  INFO   libssh::ssh_connect           > Socket connecting, now waiting for the callbacks to work
11:22:08.285  INFO   libssh::ssh_connect           > Actual timeout : 10000
11:22:08.288  INFO   libssh::ssh_socket_pollcallback > Received POLLOUT in connecting state
11:22:08.289  INFO   libssh::socket_callback_connected > Socket connection callback: 1 (0)
11:22:08.291  INFO   libssh::ssh_socket_unbuffered_write > Enabling POLLOUT for socket
jwfeng@222.195.76.47's password:
11:22:11.858  INFO   libssh::callback_receive_banner     > Received banner: SSH-2.0-OpenSSH_7.4
11:22:11.860  INFO   libssh::ssh_client_connection_callback > SSH server banner: SSH-2.0-OpenSSH_7.4
11:22:11.861  INFO   libssh::ssh_analyze_banner             > Analyzing banner: SSH-2.0-OpenSSH_7.4
11:22:11.863  INFO   libssh::ssh_analyze_banner             > We are talking to an OpenSSH server version: 7.4 (70400)
11:22:11.866  INFO   libssh::ssh_client_select_hostkeys     > Order of wanted host keys: "ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256"
11:22:11.868  INFO   libssh::ssh_known_hosts_read_entries   > Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
11:22:11.869  INFO   libssh::ssh_client_select_hostkeys     > No key found in known_hosts; changing host key method to "ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256"
11:22:11.870  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
11:22:11.872  INFO   libssh::packet_send2                   > packet: wrote [type=20, len=812, padding_size=11, comp=800, payload=800]
11:22:11.874  INFO   libssh::ssh_send_kex                   > SSH_MSG_KEXINIT sent
11:22:11.876  INFO   libssh::ssh_packet_socket_callback     > packet: read type 20 [len=1276,padding=10,comp=1265,payload=1265]
11:22:11.878  INFO   libssh::ssh_packet_process             > Dispatching handler for packet type 20
11:22:11.880  INFO   libssh::ssh_kex_select_methods         > Negotiated curve25519-sha256,ssh-ed25519,chacha20-poly1305@openssh.com,chacha20-poly1305@openssh.com,aead-poly1305,aead-poly1305,none,none,,
11:22:11.882  INFO   libssh::packet_send2                   > packet: wrote [type=30, len=44, padding_size=6, comp=37, payload=37]
11:22:11.885  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
11:22:18.292  INFO   libssh::ssh_connect                    > Timeout connecting to 222.195.79.187
11:22:18.296  INFO   libssh::ssh_connect                    > current state : 9
11:22:18.299  ERROR  mux::ssh

In WSL with the same .ssh/config and same empty wezterm configuration, libssh and ssh2 works fine with log like this:

11:28:12.556  INFO   libssh::ssh_connect           > libssh 0.8.90 (c) 2003-2021 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_pthread
11:28:12.556  INFO   libssh::ssh_connect           > Socket connecting, now waiting for the callbacks to work
11:28:12.556  INFO   libssh::ssh_connect           > Actual timeout : 10000
11:28:12.556  INFO   libssh::ssh_socket_pollcallback > Received POLLOUT in connecting state
11:28:12.556  INFO   libssh::socket_callback_connected > Socket connection callback: 1 (0)
11:28:12.556  INFO   libssh::ssh_socket_unbuffered_write > Enabling POLLOUT for socket
jwfeng@222.195.76.47's password:
11:28:16.052  INFO   libssh::callback_receive_banner     > Received banner: SSH-2.0-OpenSSH_7.4
11:28:16.052  INFO   libssh::ssh_client_connection_callback > SSH server banner: SSH-2.0-OpenSSH_7.4
11:28:16.052  INFO   libssh::ssh_analyze_banner             > Analyzing banner: SSH-2.0-OpenSSH_7.4
11:28:16.052  INFO   libssh::ssh_analyze_banner             > We are talking to an OpenSSH server version: 7.4 (70400)
11:28:16.053  INFO   libssh::ssh_client_select_hostkeys     > Order of wanted host keys: "ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256"
11:28:16.054  INFO   libssh::ssh_known_hosts_read_entries   > Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
11:28:16.054  INFO   libssh::ssh_client_select_hostkeys     > Algorithms found in known_hosts files: "ecdsa-sha2-nistp256"
11:28:16.054  INFO   libssh::ssh_client_select_hostkeys     > Changing host key method to "ecdsa-sha2-nistp256,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,rsa-sha2-512,rsa-sha2-256"
11:28:16.054  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
11:28:16.054  INFO   libssh::packet_send2                   > packet: wrote [type=20, len=812, padding_size=11, comp=800, payload=800]
11:28:16.054  INFO   libssh::ssh_send_kex                   > SSH_MSG_KEXINIT sent
11:28:16.061  INFO   libssh::ssh_packet_socket_callback     > packet: read type 20 [len=1276,padding=10,comp=1265,payload=1265]
11:28:16.061  INFO   libssh::ssh_packet_process             > Dispatching handler for packet type 20
11:28:16.062  INFO   libssh::ssh_kex_select_methods         > Negotiated curve25519-sha256,ecdsa-sha2-nistp256,chacha20-poly1305@openssh.com,chacha20-poly1305@openssh.com,aead-poly1305,aead-poly1305,none,none,,
11:28:16.063  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
11:28:16.063  INFO   libssh::packet_send2                   > packet: wrote [type=30, len=44, padding_size=6, comp=37, payload=37]
11:28:16.080  INFO   libssh::ssh_packet_socket_callback     > packet: read type 31 [len=260,padding=9,comp=250,payload=250]
11:28:16.080  INFO   libssh::ssh_packet_process             > Dispatching handler for packet type 31
11:28:16.082  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
11:28:16.082  INFO   libssh::packet_send2                   > packet: wrote [type=21, len=12, padding_size=10, comp=1, payload=1]
11:28:16.082  INFO   libssh::crypt_set_algorithms2          > Set output algorithm to chacha20-poly1305@openssh.com
11:28:16.082  INFO   libssh::crypt_set_algorithms2          > Set HMAC output algorithm to aead-poly1305
11:28:16.082  INFO   libssh::crypt_set_algorithms2          > Set input algorithm to chacha20-poly1305@openssh.com
11:28:16.082  INFO   libssh::crypt_set_algorithms2          > Set HMAC input algorithm to aead-poly1305
11:28:16.082  INFO   libssh::ssh_init_rekey_state           > Set rekey after 134217728 blocks
11:28:16.082  INFO   libssh::ssh_init_rekey_state           > Set rekey after 134217728 blocks
11:28:16.082  INFO   libssh::ssh_packet_client_curve25519_reply > SSH_MSG_NEWKEYS sent
11:28:16.082  INFO   libssh::ssh_packet_socket_callback         > Processing 100 bytes left in socket buffer
11:28:16.082  INFO   libssh::ssh_packet_socket_callback         > packet: read type 21 [len=12,padding=10,comp=1,payload=1]
11:28:16.082  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 21
11:28:16.082  INFO   libssh::ssh_packet_newkeys                 > Received SSH_MSG_NEWKEYS
11:28:16.082  INFO   libssh::ssh_packet_newkeys                 > Signature verified and valid
11:28:16.082  INFO   libssh::ssh_packet_socket_callback         > Processing 84 bytes left in socket buffer
11:28:16.082  INFO   libssh::ssh_packet_socket_callback         > packet: read type 7 [len=64,padding=10,comp=53,payload=53]
11:28:16.082  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 7
11:28:16.082  INFO   libssh::ssh_packet_ext_info                > Received SSH_MSG_EXT_INFO
11:28:16.082  INFO   libssh::ssh_packet_ext_info                > Follows 1 extensions
11:28:16.082  INFO   libssh::ssh_packet_ext_info                > Extension: server-sig-algs=<rsa-sha2-256,rsa-sha2-512>
11:28:16.082  INFO   libssh::ssh_connect                        > current state : 7
11:28:16.082  INFO   libssh::packet_send2                       > packet: wrote [type=5, len=24, padding_size=6, comp=17, payload=17]
11:28:16.083  INFO   libssh::ssh_service_request                > Sent SSH_MSG_SERVICE_REQUEST (service ssh-userauth)
11:28:16.083  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:16.087  INFO   libssh::ssh_packet_socket_callback         > packet: read type 6 [len=24,padding=6,comp=17,payload=17]
11:28:16.087  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 6
11:28:16.087  INFO   libssh::ssh_packet_service_accept          > Received SSH_MSG_SERVICE_ACCEPT
11:28:16.087  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:16.087  INFO   libssh::packet_send2                       > packet: wrote [type=50, len=48, padding_size=10, comp=37, payload=37]
11:28:16.095  INFO   libssh::ssh_packet_socket_callback         > packet: read type 51 [len=96,padding=11,comp=84,payload=84]
11:28:16.095  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 51
11:28:16.095  INFO   libssh::ssh_packet_userauth_failure        > Access denied for 'none'. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive,hostbased
11:28:16.095  INFO   libssh::ssh_packet_userauth_failure        > Access denied for 'none'. Authentication that can continue: publickey,gssapi-keyex,gssapi-with-mic,password,keyboard-interactive,hostbased
11:28:16.095  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_rsa
11:28:16.096  INFO   libssh::ssh_key_algorithm_allowed          > Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256>
11:28:16.096  INFO   libssh::ssh_key_algorithm_allowed          > Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256>
11:28:16.096  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:16.096  INFO   libssh::packet_send2                       > packet: wrote [type=50, len=352, padding_size=9, comp=342, payload=342]
11:28:16.100  INFO   libssh::ssh_packet_socket_callback         > packet: read type 60 [len=312,padding=11,comp=300,payload=300]
11:28:16.101  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 60
11:28:16.101  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_rsa: No such file or directory
11:28:16.101  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_rsa doesn't exist.
11:28:16.101  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_ed25519
11:28:16.101  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_ed25519.pub: No such file or directory
11:28:16.101  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_ed25519: No such file or directory
11:28:16.101  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_ed25519 doesn't exist.
11:28:16.101  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_ecdsa
11:28:16.101  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_ecdsa.pub: No such file or directory
11:28:16.101  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_ecdsa: No such file or directory
11:28:16.101  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_ecdsa doesn't exist.
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_dsa
11:28:16.102  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_dsa.pub: No such file or directory
11:28:16.102  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_dsa: No such file or directory
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_dsa doesn't exist.
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_ed25519
11:28:16.102  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_ed25519.pub: No such file or directory
11:28:16.102  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_ed25519: No such file or directory
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_ed25519 doesn't exist.
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_ecdsa
11:28:16.102  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_ecdsa.pub: No such file or directory
11:28:16.102  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_ecdsa: No such file or directory
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_ecdsa doesn't exist.
11:28:16.102  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_rsa
11:28:16.102  INFO   libssh::ssh_key_algorithm_allowed          > Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256>
11:28:16.102  INFO   libssh::ssh_key_algorithm_allowed          > Checking rsa-sha2-512 with list <ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,rsa-sha2-512,rsa-sha2-256>
11:28:16.102  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:16.102  INFO   libssh::packet_send2                       > packet: wrote [type=50, len=352, padding_size=9, comp=342, payload=342]
11:28:16.107  INFO   libssh::ssh_packet_socket_callback         > packet: read type 60 [len=312,padding=11,comp=300,payload=300]
11:28:16.107  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 60
11:28:16.107  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_rsa: No such file or directory
11:28:16.107  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_rsa doesn't exist.
11:28:16.107  INFO   libssh::ssh_userauth_publickey_auto        > Trying to authenticate with /home/jwfeng/.ssh/id_dsa
11:28:16.107  INFO   libssh::ssh_pki_import_pubkey_file         > Error opening /home/jwfeng/.ssh/id_dsa.pub: No such file or directory
11:28:16.107  INFO   libssh::ssh_pki_import_privkey_file        > Error opening /home/jwfeng/.ssh/id_dsa: No such file or directory
11:28:16.108  INFO   libssh::ssh_userauth_publickey_auto        > Private key /home/jwfeng/.ssh/id_dsa doesn't exist.
11:28:16.108  INFO   libssh::ssh_userauth_publickey_auto        > Tried every public key, none matched
11:28:16.108  INFO   libssh::ssh_userauth_kbdint_init           > Sending keyboard-interactive init request
11:28:16.108  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:16.108  INFO   libssh::packet_send2                       > packet: wrote [type=50, len=72, padding_size=10, comp=61, payload=61]
11:28:16.114  INFO   libssh::ssh_packet_socket_callback         > packet: read type 60 [len=48,padding=6,comp=41,payload=41]
11:28:16.114  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 60
11:28:16.114  INFO   libssh::ssh_packet_userauth_info_request   > 1 keyboard-interactive prompts
11:28:25.487  INFO   libssh::ssh_userauth_kbdint_send           > Sending keyboard-interactive response packet
11:28:25.487  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:25.487  INFO   libssh::packet_send2                       > packet: wrote [type=61, len=24, padding_size=8, comp=15, payload=15]
11:28:25.492  INFO   libssh::ssh_packet_socket_callback         > packet: read type 60 [len=40,padding=7,comp=32,payload=32]
11:28:25.492  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 60
11:28:25.492  INFO   libssh::ssh_packet_userauth_info_request   > 1 keyboard-interactive prompts
11:28:27.816  INFO   libssh::ssh_userauth_kbdint_send           > Sending keyboard-interactive response packet
11:28:27.816  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.816  INFO   libssh::packet_send2                       > packet: wrote [type=61, len=32, padding_size=9, comp=22, payload=22]
11:28:27.853  INFO   libssh::ssh_packet_socket_callback         > packet: read type 60 [len=24,padding=6,comp=17,payload=17]
11:28:27.853  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 60
11:28:27.853  INFO   libssh::ssh_packet_userauth_info_request   > 0 keyboard-interactive prompts
11:28:27.853  INFO   libssh::ssh_userauth_kbdint_send           > Sending keyboard-interactive response packet
11:28:27.853  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.853  INFO   libssh::packet_send2                       > packet: wrote [type=61, len=16, padding_size=10, comp=5, payload=5]
11:28:27.858  INFO   libssh::ssh_packet_socket_callback         > packet: read type 52 [len=8,padding=6,comp=1,payload=1]
11:28:27.858  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 52
11:28:27.858  INFO   libssh::ssh_packet_userauth_success        > Authentication successful
11:28:27.858  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=100, in_blocks=103]
11:28:27.859  INFO   libssh::channel_open                       > Creating a channel 43 with 64000 window and 32768 max packet
11:28:27.859  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=103, in_blocks=106]
11:28:27.859  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.859  INFO   libssh::packet_send2                       > packet: wrote [type=90, len=32, padding_size=7, comp=24, payload=24]
11:28:27.859  INFO   libssh::channel_open                       > Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
11:28:27.877  INFO   libssh::ssh_packet_socket_callback         > packet: read type 80 [len=480,padding=4,comp=475,payload=475]
11:28:27.877  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 80
11:28:27.877  INFO   libssh::ssh_packet_process                 > Couldn't do anything with packet type 80
11:28:27.877  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=103, in_blocks=162]
11:28:27.878  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.878  INFO   libssh::packet_send2                       > packet: wrote [type=3, len=16, padding_size=10, comp=5, payload=5]
11:28:27.878  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=103, in_blocks=162]
11:28:27.880  INFO   libssh::ssh_packet_socket_callback         > packet: read type 91 [len=24,padding=6,comp=17,payload=17]
11:28:27.880  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 91
11:28:27.880  INFO   libssh::ssh_packet_channel_open_conf       > Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
11:28:27.880  INFO   libssh::ssh_packet_channel_open_conf       > Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
11:28:27.880  INFO   libssh::ssh_packet_channel_open_conf       > Remote window : 0, maxpacket : 32768
11:28:27.880  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=103, in_blocks=164]
11:28:27.880  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=110, in_blocks=171]
11:28:27.880  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.880  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=64, padding_size=7, comp=56, payload=56]
11:28:27.880  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST pty-req
11:28:27.885  INFO   libssh::ssh_packet_socket_callback         > packet: read type 99 [len=16,padding=10,comp=5,payload=5]
11:28:27.885  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 99
11:28:27.885  INFO   libssh::ssh_packet_channel_success         > Received SSH_CHANNEL_SUCCESS on channel (43:0)
11:28:27.885  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=110, in_blocks=164]
11:28:27.886  INFO   libssh::channel_request                    > Channel request pty-req success
11:28:27.886  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=114, in_blocks=168]
11:28:27.886  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.886  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=48, padding_size=8, comp=39, payload=39]
11:28:27.886  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.889  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.889  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.889  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.889  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=114, in_blocks=164]
11:28:27.889  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.889  WARN   wezterm_ssh::pty                           > ssh: setenv COLORTERM=truecolor failed: RequestDenied: Channel request env failed. Check the AcceptEnv setting on the ssh server side. Additional errors with setting env vars in this session will be logged at debug log level.
11:28:27.889  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=118, in_blocks=168]
11:28:27.890  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.890  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=48, padding_size=8, comp=39, payload=39]
11:28:27.890  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.894  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.894  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.894  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.894  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=118, in_blocks=164]
11:28:27.894  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.894  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=134, in_blocks=180]
11:28:27.894  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.894  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=144, padding_size=8, comp=135, payload=135]
11:28:27.894  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.897  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.897  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.898  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.898  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=134, in_blocks=164]
11:28:27.898  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.898  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=139, in_blocks=169]
11:28:27.898  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.898  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=48, padding_size=6, comp=41, payload=41]
11:28:27.898  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.901  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.901  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.901  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.901  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=139, in_blocks=164]
11:28:27.902  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.902  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=147, in_blocks=172]
11:28:27.902  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.902  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=72, padding_size=6, comp=65, payload=65]
11:28:27.902  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.904  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.904  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.904  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.904  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=147, in_blocks=164]
11:28:27.904  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.904  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=152, in_blocks=169]
11:28:27.905  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.905  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=48, padding_size=7, comp=40, payload=40]
11:28:27.905  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST env
11:28:27.907  INFO   libssh::ssh_packet_socket_callback         > packet: read type 100 [len=16,padding=10,comp=5,payload=5]
11:28:27.907  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 100
11:28:27.907  INFO   libssh::ssh_packet_channel_failure         > Received SSH_CHANNEL_FAILURE on channel (43:0)
11:28:27.907  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=152, in_blocks=164]
11:28:27.908  INFO   libssh::channel_request                    > Channel request env failed
11:28:27.908  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=153, in_blocks=165]
11:28:27.908  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.908  INFO   libssh::packet_send2                       > packet: wrote [type=98, len=24, padding_size=8, comp=15, payload=15]
11:28:27.908  INFO   libssh::channel_request                    > Sent a SSH_MSG_CHANNEL_REQUEST shell
11:28:27.917  INFO   libssh::ssh_packet_socket_callback         > packet: read type 93 [len=16,padding=6,comp=9,payload=9]
11:28:27.917  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 93
11:28:27.917  INFO   libssh::channel_rcv_change_window          > Adding 2097152 bytes to channel (43:0) (from 0 bytes)
11:28:27.918  INFO   libssh::ssh_packet_socket_callback         > Processing 36 bytes left in socket buffer
11:28:27.918  INFO   libssh::ssh_packet_socket_callback         > packet: read type 99 [len=16,padding=10,comp=5,payload=5]
11:28:27.918  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 99
11:28:27.918  INFO   libssh::ssh_packet_channel_success         > Received SSH_CHANNEL_SUCCESS on channel (43:0)
11:28:27.918  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=153, in_blocks=165]
11:28:27.918  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=153, in_blocks=165]
11:28:27.918  INFO   libssh::channel_request                    > Channel request shell success
11:28:27.918  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 64000
11:28:27.918  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=166]
11:28:27.919  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:27.919  INFO   libssh::packet_send2                       > packet: wrote [type=93, len=16, padding_size=6, comp=9, payload=9]
11:28:27.919  INFO   libssh::grow_window                        > growing window (channel 43:0) to 1280000 bytes
11:28:27.919  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1280000
11:28:27.919  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1280000
11:28:27.919  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=224,padding=6,comp=217,payload=217]
11:28:27.919  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.919  INFO   libssh::channel_rcv_data                   > Channel receiving 208 bytes data in 0 (local win=1280000 remote win=2097152)
11:28:27.919  INFO   libssh::channel_default_bufferize          > placing 208 bytes into channel buffer (stdout)
11:28:27.920  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279792 remote win=2097152)
11:28:27.920  INFO   libssh::ssh_packet_socket_callback         > Processing 204 bytes left in socket buffer
11:28:27.920  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=184,padding=5,comp=178,payload=178]
11:28:27.920  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.920  INFO   libssh::channel_rcv_data                   > Channel receiving 169 bytes data in 0 (local win=1279792 remote win=2097152)
11:28:27.920  INFO   libssh::channel_default_bufferize          > placing 169 bytes into channel buffer (stdout)
11:28:27.920  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279623 remote win=2097152)
11:28:27.920  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=214]
11:28:27.920  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=214]
11:28:27.920  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1279623
11:28:27.920  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1279623
11:28:27.920  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1279623
11:28:27.921  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1279623
11:28:27.921  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=176,padding=9,comp=166,payload=166]
11:28:27.921  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.921  INFO   libssh::channel_rcv_data                   > Channel receiving 157 bytes data in 0 (local win=1279623 remote win=2097152)
11:28:27.921  INFO   libssh::channel_default_bufferize          > placing 157 bytes into channel buffer (stdout)
11:28:27.921  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279466 remote win=2097152)
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > Processing 1980 bytes left in socket buffer
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=112,padding=5,comp=106,payload=106]
11:28:27.922  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel receiving 97 bytes data in 0 (local win=1279466 remote win=2097152)
11:28:27.922  INFO   libssh::channel_default_bufferize          > placing 97 bytes into channel buffer (stdout)
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279369 remote win=2097152)
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > Processing 1848 bytes left in socket buffer
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=120,padding=9,comp=110,payload=110]
11:28:27.922  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel receiving 101 bytes data in 0 (local win=1279369 remote win=2097152)
11:28:27.922  INFO   libssh::channel_default_bufferize          > placing 101 bytes into channel buffer (stdout)
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279268 remote win=2097152)
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > Processing 1708 bytes left in socket buffer
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=112,padding=6,comp=105,payload=105]
11:28:27.922  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel receiving 96 bytes data in 0 (local win=1279268 remote win=2097152)
11:28:27.922  INFO   libssh::channel_default_bufferize          > placing 96 bytes into channel buffer (stdout)
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279172 remote win=2097152)
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > Processing 1576 bytes left in socket buffer
11:28:27.922  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=168,padding=8,comp=159,payload=159]
11:28:27.922  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel receiving 150 bytes data in 0 (local win=1279172 remote win=2097152)
11:28:27.922  INFO   libssh::channel_default_bufferize          > placing 150 bytes into channel buffer (stdout)
11:28:27.922  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1279022 remote win=2097152)
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > Processing 1388 bytes left in socket buffer
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=128,padding=9,comp=118,payload=118]
11:28:27.923  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel receiving 109 bytes data in 0 (local win=1279022 remote win=2097152)
11:28:27.923  INFO   libssh::channel_default_bufferize          > placing 109 bytes into channel buffer (stdout)
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278913 remote win=2097152)
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > Processing 1240 bytes left in socket buffer
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=144,padding=7,comp=136,payload=136]
11:28:27.923  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel receiving 127 bytes data in 0 (local win=1278913 remote win=2097152)
11:28:27.923  INFO   libssh::channel_default_bufferize          > placing 127 bytes into channel buffer (stdout)
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278786 remote win=2097152)
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > Processing 1076 bytes left in socket buffer
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=144,padding=10,comp=133,payload=133]
11:28:27.923  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel receiving 124 bytes data in 0 (local win=1278786 remote win=2097152)
11:28:27.923  INFO   libssh::channel_default_bufferize          > placing 124 bytes into channel buffer (stdout)
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278662 remote win=2097152)
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > Processing 912 bytes left in socket buffer
11:28:27.923  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=80,padding=7,comp=72,payload=72]
11:28:27.923  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel receiving 63 bytes data in 0 (local win=1278662 remote win=2097152)
11:28:27.923  INFO   libssh::channel_default_bufferize          > placing 63 bytes into channel buffer (stdout)
11:28:27.923  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278599 remote win=2097152)
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > Processing 812 bytes left in socket buffer
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=104,padding=11,comp=92,payload=92]
11:28:27.924  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel receiving 83 bytes data in 0 (local win=1278599 remote win=2097152)
11:28:27.924  INFO   libssh::channel_default_bufferize          > placing 83 bytes into channel buffer (stdout)
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278516 remote win=2097152)
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > Processing 688 bytes left in socket buffer
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=160,padding=9,comp=150,payload=150]
11:28:27.924  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel receiving 141 bytes data in 0 (local win=1278516 remote win=2097152)
11:28:27.924  INFO   libssh::channel_default_bufferize          > placing 141 bytes into channel buffer (stdout)
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278375 remote win=2097152)
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > Processing 508 bytes left in socket buffer
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=168,padding=10,comp=157,payload=157]
11:28:27.924  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel receiving 148 bytes data in 0 (local win=1278375 remote win=2097152)
11:28:27.924  INFO   libssh::channel_default_bufferize          > placing 148 bytes into channel buffer (stdout)
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1278227 remote win=2097152)
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > Processing 320 bytes left in socket buffer
11:28:27.924  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=256,padding=9,comp=246,payload=246]
11:28:27.924  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel receiving 237 bytes data in 0 (local win=1278227 remote win=2097152)
11:28:27.924  INFO   libssh::channel_default_bufferize          > placing 237 bytes into channel buffer (stdout)
11:28:27.924  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277990 remote win=2097152)
11:28:27.925  INFO   libssh::ssh_packet_socket_callback         > Processing 44 bytes left in socket buffer
11:28:27.925  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=24,padding=10,comp=13,payload=13]
11:28:27.925  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:27.925  INFO   libssh::channel_rcv_data                   > Channel receiving 4 bytes data in 0 (local win=1277990 remote win=2097152)
11:28:27.925  INFO   libssh::channel_default_bufferize          > placing 4 bytes into channel buffer (stdout)
11:28:27.925  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277986 remote win=2097152)
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=427]
11:28:27.925  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:27.925  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:27.925  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:28.026  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:28.026  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:28.178  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277986
11:28:28.179  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=976,padding=5,comp=970,payload=970]
11:28:28.179  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:28.179  INFO   libssh::channel_rcv_data                   > Channel receiving 961 bytes data in 0 (local win=1277986 remote win=2097152)
11:28:28.179  INFO   libssh::channel_default_bufferize          > placing 961 bytes into channel buffer (stdout)
11:28:28.179  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277025 remote win=2097152)
11:28:28.179  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=154, in_blocks=548]
11:28:28.179  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.179  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.179  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.280  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.280  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.480  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.480  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.881  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.881  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.947  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=155, in_blocks=549]
11:28:28.947  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:28.947  INFO   libssh::packet_send2                       > packet: wrote [type=94, len=16, padding_size=5, comp=10, payload=10]
11:28:28.947  INFO   libssh::channel_write_common               > channel_write wrote 1 bytes
11:28:28.947  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.947  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.952  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277025
11:28:28.952  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=16,padding=5,comp=10,payload=10]
11:28:28.952  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:28.952  INFO   libssh::channel_rcv_data                   > Channel receiving 1 bytes data in 0 (local win=1277025 remote win=2097151)
11:28:28.952  INFO   libssh::channel_default_bufferize          > placing 1 bytes into channel buffer (stdout)
11:28:28.952  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277024 remote win=2097151)
11:28:28.953  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=155, in_blocks=549]
11:28:28.953  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:28.953  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:28.953  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.053  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.053  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.073  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=550]
11:28:29.073  INFO   libssh::ssh_socket_unbuffered_write        > Enabling POLLOUT for socket
11:28:29.073  INFO   libssh::packet_send2                       > packet: wrote [type=94, len=16, padding_size=5, comp=10, payload=10]
11:28:29.073  INFO   libssh::channel_write_common               > channel_write wrote 1 bytes
11:28:29.073  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.073  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.077  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277024
11:28:29.077  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=16,padding=5,comp=10,payload=10]
11:28:29.077  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.077  INFO   libssh::channel_rcv_data                   > Channel receiving 1 bytes data in 0 (local win=1277024 remote win=2097150)
11:28:29.077  INFO   libssh::channel_default_bufferize          > placing 1 bytes into channel buffer (stdout)
11:28:29.077  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277023 remote win=2097150)
11:28:29.077  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=550]
11:28:29.077  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.077  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.077  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.178  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.178  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.265  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277023
11:28:29.265  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=24,padding=8,comp=15,payload=15]
11:28:29.265  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.265  INFO   libssh::channel_rcv_data                   > Channel receiving 6 bytes data in 0 (local win=1277023 remote win=2097150)
11:28:29.265  INFO   libssh::channel_default_bufferize          > placing 6 bytes into channel buffer (stdout)
11:28:29.266  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1277017 remote win=2097150)
11:28:29.266  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=551]
11:28:29.266  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277017
11:28:29.266  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277017
11:28:29.266  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277017
11:28:29.267  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1277017
11:28:29.267  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=48,padding=9,comp=38,payload=38]
11:28:29.268  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.268  INFO   libssh::channel_rcv_data                   > Channel receiving 29 bytes data in 0 (local win=1277017 remote win=2097150)
11:28:29.268  INFO   libssh::channel_default_bufferize          > placing 29 bytes into channel buffer (stdout)
11:28:29.268  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1276988 remote win=2097150)
11:28:29.268  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=555]
11:28:29.268  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276988
11:28:29.268  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276988
11:28:29.268  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276988
11:28:29.270  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276988
11:28:29.270  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=160,padding=7,comp=152,payload=152]
11:28:29.270  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.270  INFO   libssh::channel_rcv_data                   > Channel receiving 143 bytes data in 0 (local win=1276988 remote win=2097150)
11:28:29.270  INFO   libssh::channel_default_bufferize          > placing 143 bytes into channel buffer (stdout)
11:28:29.270  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1276845 remote win=2097150)
11:28:29.271  INFO   libssh::ssh_packet_socket_callback         > Processing 204 bytes left in socket buffer
11:28:29.271  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=184,padding=10,comp=173,payload=173]
11:28:29.271  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.271  INFO   libssh::channel_rcv_data                   > Channel receiving 164 bytes data in 0 (local win=1276845 remote win=2097150)
11:28:29.271  INFO   libssh::channel_default_bufferize          > placing 164 bytes into channel buffer (stdout)
11:28:29.271  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1276681 remote win=2097150)
11:28:29.271  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=595]
11:28:29.271  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=595]
11:28:29.271  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276681
11:28:29.271  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276681
11:28:29.271  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276681
11:28:29.273  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1276681
11:28:29.273  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=904,padding=6,comp=897,payload=897]
11:28:29.273  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.274  INFO   libssh::channel_rcv_data                   > Channel receiving 888 bytes data in 0 (local win=1276681 remote win=2097150)
11:28:29.274  INFO   libssh::channel_default_bufferize          > placing 888 bytes into channel buffer (stdout)
11:28:29.274  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1275793 remote win=2097150)
11:28:29.274  INFO   libssh::ssh_packet_socket_callback         > Processing 132 bytes left in socket buffer
11:28:29.274  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=32,padding=10,comp=21,payload=21]
11:28:29.274  WARN   wezterm_term::terminalstate::performer     > unhandled iterm2: CurrentDir("/home/jwfeng/.ssh")
11:28:29.274  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel receiving 12 bytes data in 0 (local win=1275793 remote win=2097150)
11:28:29.275  INFO   libssh::channel_default_bufferize          > placing 12 bytes into channel buffer (stdout)
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1275781 remote win=2097150)
11:28:29.275  INFO   libssh::ssh_packet_socket_callback         > Processing 80 bytes left in socket buffer
11:28:29.275  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=24,padding=6,comp=17,payload=17]
11:28:29.275  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel receiving 8 bytes data in 0 (local win=1275781 remote win=2097150)
11:28:29.275  INFO   libssh::channel_default_bufferize          > placing 8 bytes into channel buffer (stdout)
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1275773 remote win=2097150)
11:28:29.275  INFO   libssh::ssh_packet_socket_callback         > Processing 36 bytes left in socket buffer
11:28:29.275  INFO   libssh::ssh_packet_socket_callback         > packet: read type 94 [len=16,padding=5,comp=10,payload=10]
11:28:29.275  INFO   libssh::ssh_packet_process                 > Dispatching handler for packet type 94
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel receiving 1 bytes data in 0 (local win=1275773 remote win=2097150)
11:28:29.275  INFO   libssh::channel_default_bufferize          > placing 1 bytes into channel buffer (stdout)
11:28:29.275  INFO   libssh::channel_rcv_data                   > Channel windows are now (local win=1275772 remote win=2097150)
11:28:29.275  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=712]
11:28:29.275  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=712]
11:28:29.276  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=712]
11:28:29.276  INFO   libssh::ssh_packet_need_rekey              > rekey: [data_rekey_needed=0, out_blocks=156, in_blocks=712]
11:28:29.276  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1275772
11:28:29.276  INFO   libssh::ssh_channel_read_timeout           > Read (8192) buffered : 0 bytes. Window: 1275772
wez commented 1 year ago

It looks like it is successfully connecting and receiving the ssh banner.

If you manually run ssh jumpHostIP serverIP:22 from your windows box, does it require any interactivity to make progress?

fengjiawang commented 1 year ago

It works on Windows with:

ssh -o "ProxyCommand=ssh jwfeng@jumpHostIP -W serverIP:22" serverIP
fengjiawang commented 1 year ago

Manually run ssh -o "ProxyCommand=ssh jwfeng@jumpHostIP -W serverIP:22" serverIP from my windows box:

skuwriyk commented 1 year ago

I have also encountered this problem. I tested with two tools: socat and ncat on Windows, which both worked with CLI. But when I used with wezterm-ssh, neither worker.

The socat log was as follows:

2023/03/14 00:11:12 socat[692] E xiopoll({0,1}{-1,4}{5,1}{-1,4}, 4, {0.4294967296}): Bad address

Does it imply that the socketpair cannot be used as stdio directly? 

           let comspec = std::env::var("COMSPEC").unwrap_or_else(|_| "cmd".to_string());
            let mut cmd = std::process::Command::new(comspec);

            let (a, b) = socketpair().unwrap();

            cmd.stdin(b.as_stdio().unwrap());                     // with these two lines commented, it will not report error, 
            cmd.stdout(b.as_stdio().unwrap());                  // though it cannot work obviously
            cmd.stderr(std::process::Stdio::inherit());
            let _child = cmd.args(&["/c", proxy.as_str()]).spawn();
            let result = unsafe {
                use std::os::windows::io::{FromRawSocket, IntoRawSocket};
                Socket::from_raw_socket(a.into_raw_socket())
            };

The ncat reported:

NCAT DEBUG: Proxy returned status code 200.
write: Invalid argument

I hope that the above information be kind of helpful.

ZodiacWind commented 1 year ago

AFAIK, the issue is related with the poll mechanism. Maybe socat or ncat will check "fds" by polling. And the socket as fd just cannot return correct value. Therefore, maybe some further improvement of the filedescriptor crate? @wez And thanks in advance :D

jaromil commented 1 year ago

I also experience this issue, using proxycommand to access cloudflare tunnels through cloudflared

07:25:05.554  INFO   libssh::ssh_connect                 > current state : 9

if it helps you reproducing the bug, send me your ssh public key and install cloudflared, then I'm happy to provide a shell to test.

lkhphuc commented 1 year ago

Same issue from a Mac client to Ubuntu machine, both using wezterm 20230712-072601-f4abf8fd

I've set up ProxyCommand in ssh config, and running pure ssh remote jump through the proxy server just fine, but wezterm ssh remote failed. These are the log when ran with verbose:

...
16:22:52.246  INFO   libssh::ssh_connect           > Socket connecting, now waiting for the callbacks to work
16:22:52.246  INFO   libssh::ssh_connect           > Actual timeout : 10000
16:22:52.246  INFO   libssh::ssh_socket_pollcallback > Received POLLOUT in connecting state
16:22:52.246  INFO   libssh::socket_callback_connected > Socket connection callback: 1 (0)
16:22:52.246  INFO   libssh::ssh_client_connection_callback > session_state=2
16:22:52.246  INFO   libssh::ssh_socket_unbuffered_write    > Enabling POLLOUT for socket
channel 0: open failed: connect failed: Name or service not known
stdio forwarding failed
16:22:52.912  INFO   libssh::ssh_socket_exception_callback  > Socket exception callback: 1 (0)
16:22:52.912  INFO   libssh::ssh_socket_exception_callback  > Socket error: disconnected
16:22:52.912  INFO   libssh::ssh_client_connection_callback > session_state=9
16:22:52.912  INFO   libssh::ssh_connect                    > current state : 9