ConPTY fails to launch in WoW64 due to filesystem redirection
OpenSSH Version
v7.9.0.0p1-Beta
Server OperatingSystem
((Get-ItemProperty "HKLM:\SOFTWARE\Microsoft\Windows nt\CurrentVersion" -Name ProductName).ProductName)
Windows Server 2019 Standard
Client OperatingSystem
cat /etc/os-release
NAME="Ubuntu"
VERSION="18.04.1 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.1 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic
What is failing
shell request failed on channel 0
With both password and publickey
Actual output
ssh -n -vvv [email protected]
OpenSSH_7.6p1 Ubuntu-4ubuntu0.2, OpenSSL 1.0.2n 7 Dec 2017
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
Pseudo-terminal will not be allocated because stdin is not a terminal.
debug2: resolving "10.0.2.23" port 22
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to 10.0.2.23 [10.0.2.23] port 22.
debug1: Connection established.
debug1: identity file /home/john/.ssh/id_rsa type 0
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_rsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_dsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/john/.ssh/id_ed25519-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_7.6p1 Ubuntu-4ubuntu0.2
debug1: Remote protocol version 2.0, remote software version OpenSSH_for_Windows_7.9
debug1: match: OpenSSH_for_Windows_7.9 pat OpenSSH* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 10.0.2.23:22 as 'administrator'
debug3: hostkeys_foreach: reading file "/home/john/.ssh/known_hosts"
debug3: record_hostkey: found key type ECDSA in file /home/john/.ssh/known_hosts:1
debug3: load_hostkeys: loaded 1 keys from 10.0.2.23
debug3: order_hostkeyalgs: prefer hostkeyalgs: [email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: [email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,[email protected],zlib
debug2: compression stoc: none,[email protected],zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1
debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519
debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected]
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ecdsa-sha2-nistp256
debug1: kex: server->client cipher: [email protected] MAC: compression: none
debug1: kex: client->server cipher: [email protected] MAC: compression: none
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: Server host key: ecdsa-sha2-nistp256 SHA256:UNH8/rlqjTPFjIRI4DLBCCD4ptV8wDZ49FUNRtfwwhs
debug3: hostkeys_foreach: reading file "/home/john/.ssh/known_hosts"
debug3: record_hostkey: found key type ECDSA in file /home/john/.ssh/known_hosts:1
debug3: load_hostkeys: loaded 1 keys from 10.0.2.23
debug1: Host '10.0.2.23' is known and matches the ECDSA host key.
debug1: Found key in /home/john/.ssh/known_hosts:1
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey after 134217728 blocks
debug2: key: /home/john/.ssh/id_rsa (0x5575b74deef0), agent
debug2: key: /home/john/.ssh/id_dsa ((nil))
debug2: key: /home/john/.ssh/id_ecdsa ((nil))
debug2: key: /home/john/.ssh/id_ed25519 ((nil))
debug3: send packet: type 5
debug3: receive packet: type 7
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521>
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: password,keyboard-interactive
debug3: start over, passed a different list password,keyboard-interactive
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup keyboard-interactive
debug3: remaining preferred: password
debug3: authmethod_is_enabled keyboard-interactive
debug1: Next authentication method: keyboard-interactive
debug2: userauth_kbdint
debug3: send packet: type 50
debug2: we sent a keyboard-interactive packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: password,keyboard-interactive
debug3: userauth_kbdint: disable: no info_req_seen
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred:
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
[email protected]'s password:
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 52
debug1: Authentication succeeded (password).
Authenticated to 10.0.2.23 ([10.0.2.23]:22).
debug2: fd 5 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Requesting [email protected]
debug3: send packet: type 80
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 80
debug1: client_input_global_request: rtype [email protected] want_reply 0
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 0: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x08
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env CLUTTER_IM_MODULE
debug3: Ignored env LS_COLORS
debug3: Ignored env LESSCLOSE
debug3: Ignored env XDG_MENU_PREFIX
debug1: Sending env LANG = en_CA.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env DISPLAY
debug3: Ignored env GNOME_SHELL_SESSION_MODE
debug3: Ignored env COLORTERM
debug3: Ignored env DESKTOP_AUTOSTART_ID
debug3: Ignored env USERNAME
debug3: Ignored env XDG_VTNR
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env XDG_SESSION_ID
debug3: Ignored env USER
debug3: Ignored env DESKTOP_SESSION
debug3: Ignored env QT4_IM_MODULE
debug3: Ignored env TEXTDOMAINDIR
debug3: Ignored env GNOME_TERMINAL_SCREEN
debug3: Ignored env PWD
debug3: Ignored env HOME
debug3: Ignored env TEXTDOMAIN
debug3: Ignored env SSH_AGENT_PID
debug3: Ignored env QT_ACCESSIBILITY
debug3: Ignored env XDG_SESSION_TYPE
debug3: Ignored env XDG_DATA_DIRS
debug3: Ignored env XDG_SESSION_DESKTOP
debug3: Ignored env GTK_MODULES
debug3: Ignored env WINDOWPATH
debug3: Ignored env TERM
debug3: Ignored env SHELL
debug3: Ignored env VTE_VERSION
debug3: Ignored env QT_IM_MODULE
debug3: Ignored env XMODIFIERS
debug3: Ignored env IM_CONFIG_PHASE
debug3: Ignored env XDG_CURRENT_DESKTOP
debug3: Ignored env GPG_AGENT_INFO
debug3: Ignored env GNOME_TERMINAL_SERVICE
debug3: Ignored env XDG_SEAT
debug3: Ignored env SHLVL
debug3: Ignored env GDMSESSION
debug3: Ignored env GNOME_DESKTOP_SESSION_ID
debug3: Ignored env LOGNAME
debug3: Ignored env DBUS_SESSION_BUS_ADDRESS
debug3: Ignored env XDG_RUNTIME_DIR
debug3: Ignored env XAUTHORITY
debug3: Ignored env XDG_CONFIG_DIRS
debug3: Ignored env PATH
debug3: Ignored env SESSION_MANAGER
debug3: Ignored env LESSOPEN
debug3: Ignored env GTK_IM_MODULE
debug3: Ignored env _
debug3: Ignored env OLDPWD
debug2: channel 0: request shell confirm 1
debug3: send packet: type 98
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug3: receive packet: type 100
debug2: channel_input_status_confirm: type 100 id 0
shell request failed on channel 0
Can you turn on server-side logging and provide the sshd.log from that after a single connection attempt?
Use LOCAL0 / DEBUG3 in sshd_config as described in https://github.com/PowerShell/Win32-OpenSSH/wiki/Troubleshooting-Steps
Here's the log, one attempt only ;)
sshd log
3508 2019-02-09 07:58:35.044 debug2: fd 3 setting O_NONBLOCK
3508 2019-02-09 07:58:35.044 debug3: sock_set_v6only: set socket 3 IPV6_V6ONLY
3508 2019-02-09 07:58:35.044 debug1: Bind to port 22 on ::.
3508 2019-02-09 07:58:35.044 Server listening on :: port 22.
3508 2019-02-09 07:58:35.044 debug2: fd 4 setting O_NONBLOCK
3508 2019-02-09 07:58:35.044 debug1: Bind to port 22 on 0.0.0.0.
3508 2019-02-09 07:58:35.044 Server listening on 0.0.0.0 port 22.
3508 2019-02-09 07:58:40.608 debug3: fd 5 is not O_NONBLOCK
3508 2019-02-09 07:58:40.608 debug3: spawning "C:\Program Files\OpenSSH\OpenSSH-Win32\sshd.exe" -R
3508 2019-02-09 07:58:40.608 debug3: send_rexec_state: entering fd = 8 config len 245
3508 2019-02-09 07:58:40.608 debug3: ssh_msg_send: type 0
3508 2019-02-09 07:58:40.622 debug3: send_rexec_state: done
2312 2019-02-09 07:58:40.699 debug1: inetd sockets after dupping: 3, 3
2312 2019-02-09 07:58:40.699 Connection from 10.0.2.15 port 39948 on 10.0.2.23 port 22
2312 2019-02-09 07:58:40.699 debug1: Client protocol version 2.0; client software version OpenSSH_7.6p1 Ubuntu-4ubuntu0.2
2312 2019-02-09 07:58:40.699 debug1: match: OpenSSH_7.6p1 Ubuntu-4ubuntu0.2 pat OpenSSH_7.0*,OpenSSH_7.1*,OpenSSH_7.2*,OpenSSH_7.3*,OpenSSH_7.4*,OpenSSH_7.5*,OpenSSH_7.6*,OpenSSH_7.7* compat 0x04000002
2312 2019-02-09 07:58:40.699 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_7.9
2312 2019-02-09 07:58:40.699 debug2: fd 3 setting O_NONBLOCK
2312 2019-02-09 07:58:40.714 debug3: spawning "C:\Program Files\OpenSSH\OpenSSH-Win32\sshd.exe" -y
2312 2019-02-09 07:58:40.714 debug2: Network child is on pid 4008
2312 2019-02-09 07:58:40.714 debug3: send_rexec_state: entering fd = 6 config len 245
2312 2019-02-09 07:58:40.714 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:40.714 debug3: send_rexec_state: done
2312 2019-02-09 07:58:40.714 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:40.714 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:40.731 debug3: preauth child monitor started
2312 2019-02-09 07:58:40.746 debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
2312 2019-02-09 07:58:40.746 debug3: send packet: type 20 [preauth]
2312 2019-02-09 07:58:40.746 debug1: SSH2_MSG_KEXINIT sent [preauth]
2312 2019-02-09 07:58:40.746 debug3: receive packet: type 20 [preauth]
2312 2019-02-09 07:58:40.746 debug1: SSH2_MSG_KEXINIT received [preauth]
2312 2019-02-09 07:58:40.746 debug2: local server KEXINIT proposal [preauth]
2312 2019-02-09 07:58:40.746 debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
2312 2019-02-09 07:58:40.746 debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
2312 2019-02-09 07:58:40.746 debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
2312 2019-02-09 07:58:40.746 debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
2312 2019-02-09 07:58:40.746 debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
2312 2019-02-09 07:58:40.746 debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
2312 2019-02-09 07:58:40.746 debug2: compression ctos: none [preauth]
2312 2019-02-09 07:58:40.746 debug2: compression stoc: none [preauth]
2312 2019-02-09 07:58:40.746 debug2: languages ctos: [preauth]
2312 2019-02-09 07:58:40.746 debug2: languages stoc: [preauth]
2312 2019-02-09 07:58:40.746 debug2: first_kex_follows 0 [preauth]
2312 2019-02-09 07:58:40.746 debug2: reserved 0 [preauth]
2312 2019-02-09 07:58:40.746 debug2: peer client KEXINIT proposal [preauth]
2312 2019-02-09 07:58:40.746 debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c [preauth]
2312 2019-02-09 07:58:40.746 debug2: host key algorithms: [email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
2312 2019-02-09 07:58:40.746 debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
2312 2019-02-09 07:58:40.746 debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
2312 2019-02-09 07:58:40.746 debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
2312 2019-02-09 07:58:40.746 debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
2312 2019-02-09 07:58:40.746 debug2: compression ctos: none,[email protected],zlib [preauth]
2312 2019-02-09 07:58:40.746 debug2: compression stoc: none,[email protected],zlib [preauth]
2312 2019-02-09 07:58:40.746 debug2: languages ctos: [preauth]
2312 2019-02-09 07:58:40.746 debug2: languages stoc: [preauth]
2312 2019-02-09 07:58:40.746 debug2: first_kex_follows 0 [preauth]
2312 2019-02-09 07:58:40.746 debug2: reserved 0 [preauth]
2312 2019-02-09 07:58:40.746 debug1: kex: algorithm: curve25519-sha256 [preauth]
2312 2019-02-09 07:58:40.746 debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
2312 2019-02-09 07:58:40.746 debug1: kex: client->server cipher: [email protected] MAC: compression: none [preauth]
2312 2019-02-09 07:58:40.746 debug1: kex: server->client cipher: [email protected] MAC: compression: none [preauth]
2312 2019-02-09 07:58:40.746 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
2312 2019-02-09 07:58:40.763 debug3: receive packet: type 30 [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_sshkey_sign entering [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_request_send entering: type 6 [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_request_receive_expect entering: type 7 [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_request_receive entering [preauth]
2312 2019-02-09 07:58:40.763 debug3: mm_request_receive entering
2312 2019-02-09 07:58:40.763 debug3: monitor_read: checking request 6
2312 2019-02-09 07:58:40.763 debug3: mm_answer_sign
2312 2019-02-09 07:58:40.763 debug3: mm_answer_sign: hostkey proof signature 002003C0(99)
2312 2019-02-09 07:58:40.763 debug3: mm_request_send entering: type 7
2312 2019-02-09 07:58:40.763 debug2: monitor_read: 6 used once, disabling now
2312 2019-02-09 07:58:40.763 debug3: send packet: type 31 [preauth]
2312 2019-02-09 07:58:40.763 debug3: send packet: type 21 [preauth]
2312 2019-02-09 07:58:40.763 debug2: set_newkeys: mode 1 [preauth]
2312 2019-02-09 07:58:40.763 debug1: rekey after 134217728 blocks [preauth]
2312 2019-02-09 07:58:40.763 debug1: SSH2_MSG_NEWKEYS sent [preauth]
2312 2019-02-09 07:58:40.763 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
2312 2019-02-09 07:58:40.763 debug3: send packet: type 7 [preauth]
2312 2019-02-09 07:58:40.777 debug3: receive packet: type 21 [preauth]
2312 2019-02-09 07:58:40.777 debug1: SSH2_MSG_NEWKEYS received [preauth]
2312 2019-02-09 07:58:40.777 debug2: set_newkeys: mode 0 [preauth]
2312 2019-02-09 07:58:40.777 debug1: rekey after 134217728 blocks [preauth]
2312 2019-02-09 07:58:40.777 debug1: KEX done [preauth]
2312 2019-02-09 07:58:40.793 debug3: receive packet: type 5 [preauth]
2312 2019-02-09 07:58:40.793 debug3: send packet: type 6 [preauth]
2312 2019-02-09 07:58:40.793 debug3: receive packet: type 50 [preauth]
2312 2019-02-09 07:58:40.793 debug1: userauth-request for user administrator service ssh-connection method none [preauth]
2312 2019-02-09 07:58:40.793 debug1: attempt 0 failures 0 [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_getpwnamallow entering [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_send entering: type 8 [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_receive_expect entering: type 9 [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_receive entering [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_receive entering
2312 2019-02-09 07:58:40.793 debug3: monitor_read: checking request 8
2312 2019-02-09 07:58:40.793 debug3: mm_answer_pwnamallow
2312 2019-02-09 07:58:40.793 debug2: parse_server_config: config reprocess config len 245
2312 2019-02-09 07:58:40.793 debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
2312 2019-02-09 07:58:40.793 debug3: mm_request_send entering: type 9
2312 2019-02-09 07:58:40.793 debug2: monitor_read: 8 used once, disabling now
2312 2019-02-09 07:58:40.793 debug2: input_userauth_request: setting up authctxt for administrator [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_inform_authserv entering [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_send entering: type 4 [preauth]
2312 2019-02-09 07:58:40.793 debug2: input_userauth_request: try method none [preauth]
2312 2019-02-09 07:58:40.793 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
2312 2019-02-09 07:58:40.793 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 6.253ms (requested 6.253ms) [preauth]
2312 2019-02-09 07:58:40.793 debug3: mm_request_receive entering
2312 2019-02-09 07:58:40.793 debug3: monitor_read: checking request 4
2312 2019-02-09 07:58:40.793 debug3: mm_answer_authserv: service=ssh-connection, style=
2312 2019-02-09 07:58:40.793 debug2: monitor_read: 4 used once, disabling now
2312 2019-02-09 07:58:40.808 debug3: userauth_finish: failure partial=0 next methods="password,keyboard-interactive" [preauth]
2312 2019-02-09 07:58:40.808 debug3: send packet: type 51 [preauth]
2312 2019-02-09 07:58:40.808 debug3: receive packet: type 50 [preauth]
2312 2019-02-09 07:58:40.808 debug1: userauth-request for user administrator service ssh-connection method keyboard-interactive [preauth]
2312 2019-02-09 07:58:40.808 debug1: attempt 1 failures 0 [preauth]
2312 2019-02-09 07:58:40.808 debug2: input_userauth_request: try method keyboard-interactive [preauth]
2312 2019-02-09 07:58:40.808 debug1: keyboard-interactive devs [preauth]
2312 2019-02-09 07:58:40.808 debug1: auth2_challenge: user=administrator devs= [preauth]
2312 2019-02-09 07:58:40.808 debug1: kbdint_alloc: devices '' [preauth]
2312 2019-02-09 07:58:40.808 debug2: auth2_challenge_start: devices [preauth]
2312 2019-02-09 07:58:40.808 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
2312 2019-02-09 07:58:40.808 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 6.253ms (requested 6.253ms) [preauth]
2312 2019-02-09 07:58:40.824 debug3: userauth_finish: failure partial=0 next methods="password,keyboard-interactive" [preauth]
2312 2019-02-09 07:58:40.824 debug3: send packet: type 51 [preauth]
2312 2019-02-09 07:58:44.964 debug3: receive packet: type 50 [preauth]
2312 2019-02-09 07:58:44.964 debug1: userauth-request for user administrator service ssh-connection method password [preauth]
2312 2019-02-09 07:58:44.964 debug1: attempt 2 failures 1 [preauth]
2312 2019-02-09 07:58:44.964 debug2: input_userauth_request: try method password [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_auth_password entering [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_request_send entering: type 12 [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_request_receive_expect entering: type 13 [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_request_receive entering [preauth]
2312 2019-02-09 07:58:44.964 debug3: mm_request_receive entering
2312 2019-02-09 07:58:44.964 debug3: monitor_read: checking request 12
2312 2019-02-09 07:58:44.980 debug3: mm_answer_authpassword: sending result 1
2312 2019-02-09 07:58:44.980 debug3: mm_request_send entering: type 13
2312 2019-02-09 07:58:44.980 Accepted password for administrator from 10.0.2.15 port 39948 ssh2
2312 2019-02-09 07:58:44.980 debug1: monitor_child_preauth: administrator has been authenticated by privileged process
2312 2019-02-09 07:58:44.980 debug3: mm_get_keystate: Waiting for new keys
2312 2019-02-09 07:58:44.980 debug3: mm_request_receive_expect entering: type 26
2312 2019-02-09 07:58:44.980 debug3: mm_request_receive entering
2312 2019-02-09 07:58:44.996 debug3: mm_get_keystate: GOT new keys
2312 2019-02-09 07:58:44.996 debug3: mm_auth_password: user authenticated [preauth]
2312 2019-02-09 07:58:44.996 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
2312 2019-02-09 07:58:44.996 debug3: ensure_minimum_time_since: elapsed 15.690ms, delaying 9.322ms (requested 6.253ms) [preauth]
2312 2019-02-09 07:58:44.996 debug3: send packet: type 52 [preauth]
2312 2019-02-09 07:58:44.996 debug3: mm_request_send entering: type 26 [preauth]
2312 2019-02-09 07:58:44.996 debug3: mm_send_keystate: Finished sending state [preauth]
2312 2019-02-09 07:58:44.996 debug1: monitor_read_log: child log fd closed
2312 2019-02-09 07:58:45.058 debug3: spawning "C:\Program Files\OpenSSH\OpenSSH-Win32\sshd.exe" -z
2312 2019-02-09 07:58:45.058 User child is on pid 4036
2312 2019-02-09 07:58:45.058 debug3: send_rexec_state: entering fd = 5 config len 245
2312 2019-02-09 07:58:45.058 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:45.058 debug3: send_rexec_state: done
2312 2019-02-09 07:58:45.058 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:45.058 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:45.074 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:45.074 debug3: ssh_msg_send: type 0
2312 2019-02-09 07:58:45.074 debug3: ssh_msg_send: type 0
4036 2019-02-09 07:58:45.091 debug3: recv_idexch_state: entering fd = 3
4036 2019-02-09 07:58:45.091 debug3: ssh_msg_recv entering
4036 2019-02-09 07:58:45.091 debug3: recv_idexch_state: done
4036 2019-02-09 07:58:45.091 debug2: fd 4 setting O_NONBLOCK
4036 2019-02-09 07:58:45.091 debug3: recv_autxctx_state: entering fd = 3
4036 2019-02-09 07:58:45.091 debug3: ssh_msg_recv entering
4036 2019-02-09 07:58:45.091 debug3: recv_autxctx_state: done
4036 2019-02-09 07:58:45.091 debug2: parse_server_config: config reprocess config len 245
4036 2019-02-09 07:58:45.091 debug3: monitor_recv_keystate: entering
4036 2019-02-09 07:58:45.091 debug3: ssh_msg_recv entering
4036 2019-02-09 07:58:45.091 debug3: monitor_recv_keystate: done
4036 2019-02-09 07:58:45.091 debug3: monitor_apply_keystate: packet_set_state
4036 2019-02-09 07:58:45.091 debug2: set_newkeys: mode 0
4036 2019-02-09 07:58:45.091 debug1: rekey after 134217728 blocks
4036 2019-02-09 07:58:45.091 debug2: set_newkeys: mode 1
4036 2019-02-09 07:58:45.091 debug1: rekey after 134217728 blocks
4036 2019-02-09 07:58:45.091 debug1: ssh_packet_set_postauth: called
4036 2019-02-09 07:58:45.091 debug3: ssh_packet_set_state: done
4036 2019-02-09 07:58:45.091 debug3: monitor_recv_authopt: entering
4036 2019-02-09 07:58:45.091 debug3: ssh_msg_recv entering
4036 2019-02-09 07:58:45.091 debug3: monitor_recv_authopt: done
4036 2019-02-09 07:58:45.091 debug3: notify_hostkeys: key 0: ssh-rsa SHA256:KIbXLIwYV4e/0E1r6us1mCKMaGI/GzdawOsY3RV4+cM
4036 2019-02-09 07:58:45.091 debug3: notify_hostkeys: key 1: ecdsa-sha2-nistp256 SHA256:UNH8/rlqjTPFjIRI4DLBCCD4ptV8wDZ49FUNRtfwwhs
4036 2019-02-09 07:58:45.091 debug3: notify_hostkeys: key 2: ssh-ed25519 SHA256:oH8Gn9Ch8iwlzbN/M53l+dT+R5Q7yJ8bTk792/SqH9M
4036 2019-02-09 07:58:45.091 debug3: notify_hostkeys: sent 3 hostkeys
4036 2019-02-09 07:58:45.091 debug3: send packet: type 80
4036 2019-02-09 07:58:45.106 debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
4036 2019-02-09 07:58:45.106 debug1: Entering interactive session for SSH2.
4036 2019-02-09 07:58:45.106 debug2: fd 7 setting O_NONBLOCK
4036 2019-02-09 07:58:45.106 debug2: fd 8 setting O_NONBLOCK
4036 2019-02-09 07:58:45.106 debug1: server_init_dispatch
4036 2019-02-09 07:58:45.106 debug3: receive packet: type 90
4036 2019-02-09 07:58:45.106 debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
4036 2019-02-09 07:58:45.106 debug1: input_session_request
4036 2019-02-09 07:58:45.106 debug1: channel 0: new [server-session]
4036 2019-02-09 07:58:45.106 debug2: session_new: allocate (allocated 0 max 10)
4036 2019-02-09 07:58:45.106 debug3: session_unused: session id 0 unused
4036 2019-02-09 07:58:45.106 debug1: session_new: session 0
4036 2019-02-09 07:58:45.106 debug1: session_open: channel 0
4036 2019-02-09 07:58:45.106 debug1: session_open: session 0: link with channel 0
4036 2019-02-09 07:58:45.106 debug1: server_input_channel_open: confirm session
4036 2019-02-09 07:58:45.106 debug3: send packet: type 91
4036 2019-02-09 07:58:45.106 debug3: receive packet: type 80
4036 2019-02-09 07:58:45.106 debug1: server_input_global_request: rtype [email protected] want_reply 0
4036 2019-02-09 07:58:45.136 debug3: receive packet: type 98
4036 2019-02-09 07:58:45.136 debug1: server_input_channel_req: channel 0 request pty-req reply 1
4036 2019-02-09 07:58:45.136 debug1: session_by_channel: session 0 channel 0
4036 2019-02-09 07:58:45.136 debug1: session_input_channel_req: session 0 req pty-req
4036 2019-02-09 07:58:45.136 debug1: Allocating pty.
4036 2019-02-09 07:58:45.136 debug3: fd 9 is not O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug3: fd 10 is not O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug1: session_pty_req: session 0 alloc windows-pty
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 1 (0x1)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 2 (0x2)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 3 (0x3)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 4 (0x4)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 5 (0x5)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 6 (0x6)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 7 (0x7)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 8 (0x8)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 9 (0x9)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 10 (0xa)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 12 (0xc)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 13 (0xd)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 14 (0xe)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 18 (0x12)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 30 (0x1e)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 31 (0x1f)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 32 (0x20)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 33 (0x21)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 34 (0x22)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 35 (0x23)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 36 (0x24)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 37 (0x25)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 38 (0x26)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 39 (0x27)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 40 (0x28)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 41 (0x29)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 42 (0x2a)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 50 (0x32)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 51 (0x33)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 52 (0x34)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 53 (0x35)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 54 (0x36)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 55 (0x37)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 56 (0x38)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 57 (0x39)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 58 (0x3a)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 59 (0x3b)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 60 (0x3c)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 61 (0x3d)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 62 (0x3e)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 70 (0x46)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 71 (0x47)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 72 (0x48)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 73 (0x49)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 74 (0x4a)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 75 (0x4b)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 90 (0x5a)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 91 (0x5b)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 92 (0x5c)
4036 2019-02-09 07:58:45.136 debug1: Ignoring unsupported tty mode opcode 93 (0x5d)
4036 2019-02-09 07:58:45.136 debug3: send packet: type 99
4036 2019-02-09 07:58:45.136 debug3: receive packet: type 98
4036 2019-02-09 07:58:45.136 debug1: server_input_channel_req: channel 0 request env reply 0
4036 2019-02-09 07:58:45.136 debug1: session_by_channel: session 0 channel 0
4036 2019-02-09 07:58:45.136 debug1: session_input_channel_req: session 0 req env
4036 2019-02-09 07:58:45.136 debug2: Ignoring env request LANG: disallowed name
4036 2019-02-09 07:58:45.136 debug3: receive packet: type 98
4036 2019-02-09 07:58:45.136 debug1: server_input_channel_req: channel 0 request shell reply 1
4036 2019-02-09 07:58:45.136 debug1: session_by_channel: session 0 channel 0
4036 2019-02-09 07:58:45.136 debug1: session_input_channel_req: session 0 req shell
4036 2019-02-09 07:58:45.136 Starting session: shell on windows-pty for administrator from 10.0.2.15 port 39948 id 0
4036 2019-02-09 07:58:45.136 debug2: fd 11 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug2: fd 12 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug2: fd 13 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug2: fd 14 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug2: fd 15 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug2: fd 16 setting O_NONBLOCK
4036 2019-02-09 07:58:45.136 debug3: shell: "c:\windows\system32\cmd.exe"
4036 2019-02-09 07:58:45.136 debug3: shell_option: /c
4036 2019-02-09 07:58:45.136 debug3: This windows OS supports conpty
4036 2019-02-09 07:58:45.136 debug3: pty commandline: C:\Windows\system32\conhost.exe --headless --width 80 --height 24 --signal 0x214 -- "c:\windows\system32\cmd.exe"
4036 2019-02-09 07:58:45.136 debug1: exec_command_with_pty - failed to execute C:\Windows\system32\conhost.exe --headless --width 80 --height 24 --signal 0x214 -- "c:\windows\system32\cmd.exe", error:2
4036 2019-02-09 07:58:45.136 debug3: send packet: type 100
4036 2019-02-09 07:58:45.136 Connection closed by 10.0.2.15 port 39948
4036 2019-02-09 07:58:45.136 debug1: channel 0: free: server-session, nchannels 1
4036 2019-02-09 07:58:45.136 debug3: channel 0: status: The following connections are open:\r\n #0 server-session (t10 r0 i0/0 o0/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1)\r\n
4036 2019-02-09 07:58:45.136 Close session: user administrator from 10.0.2.15 port 39948 id 0
4036 2019-02-09 07:58:45.136 debug3: mm_request_send entering: type 30
4036 2019-02-09 07:58:45.136 debug3: session_unused: session id 0 unused
4036 2019-02-09 07:58:45.136 debug1: do_cleanup
2312 2019-02-09 07:58:45.136 debug3: mm_request_receive entering
bytes
4036 2019-02-09 07:58:45.136 Closing connection to 10.0.2.15 port 39948
2312 2019-02-09 07:58:45.136 debug3: monitor_read: checking request 30
2312 2019-02-09 07:58:45.136 debug3: mm_answer_pty_cleanup entering
0
2312 2019-02-09 07:58:45.136 debug1: session_by_tty: unknown tty windows-pty
2312 2019-02-09 07:58:45.136 debug3: mm_request_receive entering
2312 2019-02-09 07:58:45.136 debug3: monitor_read: checking request 50
2312 2019-02-09 07:58:45.136 debug3: mm_answer_term: tearing down sessions
On the server in a command prompt, can you verify the following doesn't produce any error messages:
C:\Windows\system32\conhost.exe --headless --width 80 --height 24 --signal 0x214 -- "c:\windows\system32\cmd.exe"
No error on the command prompt, no output at all.
A bit of psychic debugging here:
Are you using the 32-bit version or the 64-bit version of Win32-OpenSSH? If you're using the 32-bit version on a 64-bit OS, I'm willing to bet that C:\Windows\System32\conhost.exe is being redirected to C:\Windows\SysWOW64\conhost.exe, which doesn't exist.
If so, there're two fixes, one short term and one long term:
Side note: we had this exact problem when we implemented CreatePseudoConsole and friends, and I ended up fixing it ;)
(and for the engineer who has to fix this: please switch to CreatePseudoConsole. In the absence of time to do that, however, the offending block of code is here and you'll have to use Wow64DisableWow64FsRedirection immediately before (but only on WOW64 builds) and Wow64RevertWow64FsRedirection immediately after creating the process.)
Thanks for the pointer I've switched the 32-bit for the 64-bit package and all works.
Both password and public key now work fine.
@HealisticEngineer Excellent! I've not been deputized to do issue management on this repository, so would you mind renaming the bug to ConPTY fails to launch in WoW64 due to filesystem redirection?
/cc @manojampalam
Thanks!
@bagajjal Any particular reason by CreatePseudoConsole() wasn't used as @DHowett-MSFT suggests? Obviously disabling file system redirection is easy, but curious why the function wasn't used.
@NoMoreFood We worked with the win32-openssh team to light up pseudoconsole support before our APIs were ready with the public release of RS5. That's all :)
@bagajjal (since this is still an actual issue, would you mind reopening it? thanks!)
Win32-OpenSSH copied to clipboard
PowerShell
