1

I'd installed CYGWIN for SFTP purpose few weeks ago in a few Win 2003 R2 x64 server and initially all of them are working without problem. However this week problem rises where users are not able to SFTP to 2 of the servers. When connecting, error "Connection closed" prompt immediately after authentication. For the first server we reinstalled & reconfigured CYGWIN and it start working again. However today another server hitting the same error again, so i'm thinking to find out what's wrong to prevent other servers run into the same problem. I did a SFTP -v and the out put is as below:

OpenSSH_6.7p1, OpenSSL 1.0.1k 8 Jan 2015
debug1: Reading configuration data /etc/ssh_config
debug2: ssh_connect: needpriv 0
debug1: Connecting to 192.168.1.1 [192.168.1.1] port 22.
--truncated due to characters limitation--
debug1: Next authentication method: password
MYSERVER+sftpuser5@192.168.1.1's password:
debug2: we sent a password packet, wait for reply
debug1: Authentication succeeded (password).
Authenticated to 192.168.1.1 ([192.168.1.1]:22).
debug2: fd 4 setting O_NONBLOCK
debug2: fd 5 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug2: channel 0: send open
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug2: client_session2_setup: id 0
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0

(I compare the debug messages with those servers which SFTP is still working, the different start from here..)

debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow@openssh.com reply 0
debug2: channel 0: rcvd eow
debug2: channel 0: close_read
debug2: channel 0: input open -> closed
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: channel 0: close_write
debug2: channel 0: output drain -> closed
debug2: channel 0: rcvd close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
Transferred: sent 2584, received 2544 bytes, in 0.2 seconds
Bytes per second: sent 11233.7, received 11059.8
debug1: Exit status 1
Connection closed


And below is the sshd_config
--Removed due to characters limitation--

Googled and see some mentioned problem of /etc/passwd but I tried mkpasswd again and it doesn't work.
Any help would be greatly appreciated.


Edited 23/07/2015
Here is the syslog-ng but can't seem able to find useful info here.

Jul 23 10:07:39 MYSERVER syslog-ng[1044]: syslog-ng starting up; version='3.2.5'
Jul 23 10:07:40 MYSERVER syslog-ng: PID 1668: `syslog-ng' service started
Jul 23 10:07:56 MYSERVER sshd: PID 4364: Server listening on 0.0.0.0 port 22.
Jul 23 10:07:57 MYSERVER sshd: PID 4288: `sshd' service started
Jul 23 10:08:07 MYSERVER sshd: PID 4140: Accepted password for MYSERVER+sftpuser5 from 192.168.1.185 port 5432 ssh2
Jul 23 10:08:08 MYSERVER sshd: PID 4140: Received disconnect from 192.168.1.185: 11: disconnected by user
Jul 23 10:08:08 MYSERVER sshd: PID 4140: Disconnected from 192.168.1.185
Jul 23 10:08:15 MYSERVER syslog-ng[1044]: Termination requested via signal, terminating;
Jul 23 10:08:15 MYSERVER syslog-ng[1044]: syslog-ng shutting down; version='3.2.5'

It said received disconnect from the client however at the client side the connection closed immediately after authenticated.
Thank you.


Edit again, added DEBUG3 log level.

Jul 23 16:35:16 MYSERVER syslog-ng[1776]: syslog-ng starting up; version='3.2.5'
Jul 23 16:35:17 MYSERVER syslog-ng: PID 5004: `syslog-ng' service started
Jul 23 16:35:23 MYSERVER sshd: PID 4936: debug2: fd 3 setting O_NONBLOCK
Jul 23 16:35:23 MYSERVER sshd: PID 4936: debug1: Bind to port 22 on 0.0.0.0.
Jul 23 16:35:23 MYSERVER sshd: PID 4936: Server listening on 0.0.0.0 port 22.
Jul 23 16:35:24 MYSERVER sshd: PID 840: `sshd' service started
Jul 23 16:35:29 MYSERVER sshd: PID 4936: debug1: fd 4 clearing O_NONBLOCK
Jul 23 16:35:29 MYSERVER sshd: PID 4936: debug1: Forked child 1708.
Jul 23 16:35:29 MYSERVER sshd: PID 4936: debug3: send_rexec_state: entering fd = 7 config len 271
Jul 23 16:35:30 MYSERVER sshd: PID 4936: debug3: ssh_msg_send: type 0
Jul 23 16:35:30 MYSERVER sshd: PID 4936: debug3: send_rexec_state: done
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: inetd sockets after dupping: 3, 3
Jul 23 16:35:30 MYSERVER sshd: PID 1708: Connection from 192.168.1.185 port 8551 on 192.168.1.81 port 22
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: Client protocol version 2.0; client software version OpenSSH_6.7
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: match: OpenSSH_6.7 pat OpenSSH* compat 0x04000000
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: Enabling compatibility mode for protocol 2.0
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: Local version string SSH-2.0-OpenSSH_6.9
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: fd 3 setting O_NONBLOCK
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: Network child is on pid 5048
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: preauth child monitor started
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: SSH2_MSG_KEXINIT received [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit:  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit:  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-dss-cert-v00@openssh.com,ssh-ed25519,ssh-rsa,ssh-dss [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit:  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit:  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: kex_parse_kexinit: reserved 0  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: kex: client->server aes128-ctr umac-64-etm@openssh.com none [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: kex: server->client aes128-ctr umac-64-etm@openssh.com none [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_key_sign entering [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 6 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive_expect entering: type 7 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: monitor_read: checking request 6
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_answer_sign
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_answer_sign: hostkey proof signature 0x60005a630(100)
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 7
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: monitor_read: 6 used once, disabling now
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: set_newkeys: mode 1 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: set_newkeys: mode 0 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: KEX done [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: userauth-request for user MYSERVER+sftpuser5 service ssh-connection method none [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: attempt 0 failures 0 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_getpwnamallow entering [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 8 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive_expect entering: type 9 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: monitor_read: checking request 8
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_answer_pwnamallow
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: parse_server_config: config reprocess config len 271
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 9
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: monitor_read: 8 used once, disabling now
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: input_userauth_request: setting up authctxt for MYSERVER+sftpuser5 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_inform_authserv entering [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 4 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: input_userauth_request: try method none [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: monitor_read: checking request 4
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: mm_answer_authserv: service=ssh-connection, style=
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: monitor_read: 4 used once, disabling now
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: userauth-request for user MYSERVER+sftpuser5 service ssh-connection method keyboard-interactive [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: attempt 1 failures 0 [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: input_userauth_request: try method keyboard-interactive [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: keyboard-interactive devs  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: auth2_challenge: user=MYSERVER+sftpuser5 devs= [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug1: kbdint_alloc: devices '' [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug2: auth2_challenge_start: devices  [preauth]
Jul 23 16:35:30 MYSERVER sshd: PID 1708: debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: userauth-request for user MYSERVER+sftpuser5 service ssh-connection method password [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: attempt 2 failures 1 [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: input_userauth_request: try method password [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_auth_password entering [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 12 [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_receive_expect entering: type 13 [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: monitor_read: checking request 12
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_answer_authpassword: sending result 1
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 13
Jul 23 16:35:33 MYSERVER sshd: PID 1708: Accepted password for MYSERVER+sftpuser5 from 192.168.1.185 port 8551 ssh2
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: monitor_child_preauth: MYSERVER+sftpuser5 has been authenticated by privileged process
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_get_keystate: Waiting for new keys
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_receive_expect entering: type 26
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_receive entering
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_get_keystate: GOT new keys
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_auth_password: user authenticated [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_request_send entering: type 26 [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_send_keystate: Finished sending state [preauth]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: monitor_read_log: child log fd closed
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_share_sync: Share sync
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: mm_share_sync: Share sync end
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: monitor_apply_keystate: packet_set_state
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: set_newkeys: mode 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: set_newkeys: mode 1
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: ssh_packet_set_postauth: called
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: ssh_packet_set_state: done
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: notify_hostkeys: key 0: ssh-rsa SHA256:h3LXugxWx25fkGJza4crq2RycpAyar+rXw5Az/24AEM
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: notify_hostkeys: key 1: ssh-dss SHA256:O2azzz4M9NSFNkd4I4xVxRzn+v0zt8p7SWa1e/BWCm0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: notify_hostkeys: key 2: ecdsa-sha2-nistp256 SHA256:6N/B4zyClH7siICVp7IbkNeDFuOdZT/GwAEpnP4yfso
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: notify_hostkeys: key 3: ssh-ed25519 SHA256:pASE9g1ir6BOsEqAtX2Iu9JPudkI1Vj+/ZZ17zttoL0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: notify_hostkeys: sent 4 hostkeys
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: Entering interactive session for SSH2.
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 4 setting O_NONBLOCK
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 5 setting O_NONBLOCK
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: server_init_dispatch_20
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: input_session_request
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: channel 0: new [server-session]
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: session_new: allocate (allocated 0 max 10)
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: session_unused: session id 0 unused
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_new: session 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_open: channel 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_open: session 0: link with channel 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: server_input_channel_open: confirm session
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_by_channel: session 0 channel 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_input_channel_req: session 0 req subsystem
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: subsystem request for sftp by user MYSERVER+sftpuser5
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: subsystem: exec() /usr/sbin/sftp-server
Jul 23 16:35:33 MYSERVER sshd: PID 1708: Starting session: subsystem 'sftp' for MYSERVER+sftpuser5 from 192.168.1.185 port 8551
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 3 setting TCP_NODELAY
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: ssh_packet_set_tos: set IP_TOS 0x08
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 8 setting O_NONBLOCK
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 7 setting O_NONBLOCK
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: fd 10 setting O_NONBLOCK
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug1: permanently_set_uid: 197617/197121
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: ALLUSERSPROFILE=C:\\Documents and Settings\\All Users
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: COMPUTERNAME=MYSERVER
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: COMSPEC=C:\\WINDOWS\\system32\\cmd.exe
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: OS=Windows_NT
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: PATH=/bin:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: PROGRAMFILES=C:\\Program Files
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: SYSTEMDRIVE=C:
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: SYSTEMROOT=C:\\WINDOWS
Jul 23 16:35:33 MYSERVER sshd: PID 3328: debug3: Copy environment: WINDIR=C:\\WINDOWS
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: Received SIGCHLD.
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_by_pid: pid 3328
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_exit_message: session 0 channel 0 pid 3328
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: request exit-status confirm 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug1: session_exit_message: release channel 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: write failed
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: close_write
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: send eow
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: output open -> closed
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: read 35 from efd 10
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug3: channel 0: discard efd
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: notify_done: reading
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: read<=0 rfd 8 len 0
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: read failed
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: close_read
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: input open -> drain
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: read 0 from efd 10
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: closing read-efd 10
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: ibuf empty
Jul 23 16:35:33 MYSERVER sshd: PID 1708: debug2: channel 0: send eof
Jul 23 16:35:34 MYSERVER sshd: PID 1708: debug2: channel 0: input drain -> closed
Jul 23 16:35:34 MYSERVER sshd: PID 1708: debug2: channel 0: send close
Jul 23 16:35:34 MYSERVER sshd: PID 1708: debug3: channel 0: will not send data after close
Jul 23 16:35:34 MYSERVER sshd: PID 1708: debug2: channel 0: rcvd close
Jul 23 16:35:34 MYSERVER sshd: PID 1708: Received disconnect from 192.168.1.185: 11: disconnected by user
Jul 23 16:35:34 MYSERVER sshd: PID 1708: Disconnected from 192.168.1.185
Jul 23 16:35:34 MYSERVER sshd: PID 1708: debug1: do_cleanup
Jul 23 16:35:43 MYSERVER syslog-ng[1776]: Termination requested via signal, terminating;
Jul 23 16:35:43 MYSERVER syslog-ng[1776]: syslog-ng shutting down; version='3.2.5'

Thank you.

  • server log would be more helpful, since it provides more information that can't be presented to user. – Jakuje Jul 22 '15 at 6:13
  • @Jakuje Hi I enabled the syslog-ng however can't seem able to find useful info in there :( – nlks Jul 23 '15 at 2:11
  • Can you turn on verbose logging on server using LogLevel DEBUG3 in sshd_config and post the log? It looks like problem with initialization of sftp server. Is it really available in /usr/sbin/sftp-server? Does it work with internal-sftp? – Jakuje Jul 23 '15 at 6:58
  • Hi @Jakuje, include the debug3 level log but this time I cant really understand it. Beside that, do you means whether the file sftp-server exist in folder /usr/sbin? Yes file sftp-server.exe does exist in /usr/sbin. and how can I check whether it work with internal-sftp? Thank you. – nlks Jul 23 '15 at 8:47
  • Hi @Jakuje, I just tried internal-sftp and it works! I changed the sshd_config to from Subsystem sftp /usr/sbin/sftp-server to Subsystem sftp internal-sftp (I hope this is what u mean), and the SFTP session can be established. I still googling what's the different between these 2 and whether should I keep it as internal-sftp.. – nlks Jul 23 '15 at 9:45
1

It seems like internal-sftp instead of full executable path works. There is probably problem with executing external binary when running under cygwin.

  • Hi @Jakuje, first of all thank you very much for your advice :) The problem is solved now but unable to figure out the root cause. Today the first server that I reconfigured last week (which it works until yesterday) hitting the same problem again, refuse to allow connection. Changing it to internal-sftp solved the problem however I'm thinking whether someone else can give some clues what's wrong with the /sbin/sftp-server (always works initially but not later). Will mark yours as answer if there is no input from others tomorrow. Thank you! – nlks Jul 24 '15 at 1:38

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.