Copssh: Cannot initialize SFTP protocol. Is the host running a SFTP server?

12 posts / 0 new
Last post
Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
Copssh: Cannot initialize SFTP protocol. Is the host running a SFTP server?

We are receiving the following error message when attempting a connection through WinSCP with a Domain Account and Public Key Authentication "(ESshFatal) Connection has been unexpectedly closed. Server sent command exit status 128.* 2012-04-03 14:10:46.043 Cannot initialize SFTP protocol. Is the host running a SFTP server?".  We have installed copSSH 4.2.3 on Server 2003 Standard Edition SP2 using a Domain Serivce Account.  The only time we can successfully connect is if we attempt connection with the Domain Service Account itself.  I have checked username / username case.  I have even installed it on a Windows XP SP3 machine that works perfectly and made sure the permissions matched.  Below are our OpenSSH and WinSCP Logs:

OpenSSH Connection Log:
========================
2012.04.03 14:27:07 -  Closing connection to HXX.XXX.XX.XXX port 4749
2012.04.03 14:27:07 -  Transferred: sent 2832, received 2304 bytes
2012.04.03 14:27:07 -  debug1: do_cleanup
2012.04.03 14:27:07 -  Connection closed by HXX.XXX.XX.XXX
2012.04.03 14:27:07 -  debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r256 i3/0 o3/0 fd -1/-1 cc -1)\r\n
2012.04.03 14:27:07 -  debug1: channel 0: free: server-session, nchannels 1
2012.04.03 14:27:07 -  debug2: channel 0: garbage collecting
2012.04.03 14:27:07 -  debug2: channel 0: is dead
2012.04.03 14:27:07 -  debug2: channel 0: gc: user detached
2012.04.03 14:27:07 -  debug3: session_unused: session id 0 unused
2012.04.03 14:27:07 -  debug1: session_close: session 0 pid 0
2012.04.03 14:27:07 -  debug1: session_close_by_channel: channel 0 child 0
2012.04.03 14:27:07 -  debug1: session_by_channel: session 0 channel 0
2012.04.03 14:27:07 -  debug2: channel 0: gc: notify user
2012.04.03 14:27:07 -  debug2: channel 0: is dead
2012.04.03 14:27:07 -  debug3: channel 0: will not send data after close
2012.04.03 14:27:07 -  debug2: channel 0: rcvd close
2012.04.03 14:27:07 -  debug3: channel 0: will not send data after close
2012.04.03 14:27:07 -  debug2: channel 0: send close
2012.04.03 14:27:07 -  debug2: channel 0: input drain -> closed
2012.04.03 14:27:07 -  debug2: channel 0: send eof
2012.04.03 14:27:07 -  debug2: channel 0: ibuf empty
2012.04.03 14:27:07 -  debug2: channel 0: closing read-efd 10
2012.04.03 14:27:07 -  debug2: channel 0: read 0 from efd 10
2012.04.03 14:27:07 -  debug2: channel 0: input open -> drain
2012.04.03 14:27:07 -  debug2: channel 0: close_read
2012.04.03 14:27:07 -  debug2: channel 0: read failed
2012.04.03 14:27:07 -  debug2: channel 0: read<=0 rfd 8 len 0
2012.04.03 14:27:07 -  debug2: notify_done: reading
2012.04.03 14:27:07 -  debug3: channel 0: discard efd
2012.04.03 14:27:07 -  debug2: channel 0: read 1237 from efd 10
2012.04.03 14:27:07 -  debug2: channel 0: output open -> closed
2012.04.03 14:27:07 -  debug2: channel 0: send eow
2012.04.03 14:27:07 -  debug2: channel 0: close_write
2012.04.03 14:27:07 -  debug2: channel 0: write failed
2012.04.03 14:27:07 -  debug1: session_exit_message: release channel 0
2012.04.03 14:27:07 -  debug2: channel 0: request exit-signal confirm 0
2012.04.03 14:27:07 -  debug1: session_exit_message: session 0 channel 0 pid 35488
2012.04.03 14:27:07 -  debug1: session_by_pid: pid 35488
2012.04.03 14:27:07 -  debug1: Received SIGCHLD.
2012.04.03 14:27:07 -  debug3: Copy environment: CYGWIN=nontsec binmode
2012.04.03 14:27:07 -  debug3: Copy environment: WINDIR=C:\\WINDOWS
2012.04.03 14:27:07 -  debug3: Copy environment: SYSTEMROOT=C:\\WINDOWS
2012.04.03 14:27:07 -  debug3: Copy environment: SYSTEMDRIVE=C:
2012.04.03 14:27:07 -  debug3: Copy environment: PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.PSC1
2012.04.03 14:27:07 -  debug3: Copy environment: PATH=/cygdrive/c/Program Files/HP/NCU:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem:/cygdrive/c/Program Files/ActivIdentity/ActivClient:/cygdrive/c/Program Files/HP/HP BTO Software/bin:/cygdrive/c/Program Files/HP/HP BTO Software/bin/OpC:/cygdrive/c/Program Files/Microsoft SQL Server/80/Tools/Binn:/cygdrive/c/Program Files/Microsoft SQL Server/90/DTS/Binn:/cygdrive/c/Program Files/Microsoft SQL Server/90/Tools/binn:/cygdrive/c/Progra
2012.04.03 14:27:07 -  debug3: Copy environment: OS=Windows_NT
2012.04.03 14:27:07 -  debug3: Copy environment: COMSPEC=C:\\WINDOWS\\system32\\cmd.exe
2012.04.03 14:27:07 -  debug3: Copy environment: COMPUTERNAME=xxServerNamexx
2012.04.03 14:27:07 -  debug3: Copy environment: ALLUSERSPROFILE=C:\\Documents and Settings\\All Users
2012.04.03 14:27:07 -  debug1: permanently_set_uid: 1116117/12513
2012.04.03 14:27:07 -  debug2: fd 10 setting O_NONBLOCK
2012.04.03 14:27:07 -  debug2: fd 7 setting O_NONBLOCK
2012.04.03 14:27:07 -  debug2: fd 8 setting O_NONBLOCK
2012.04.03 14:27:07 -  debug2: fd 3 setting TCP_NODELAY
2012.04.03 14:27:07 -  debug1: subsystem: internal-sftp
2012.04.03 14:27:07 -  subsystem request for sftp by user xxUserNamexx
2012.04.03 14:27:07 -  debug1: session_input_channel_req: session 0 req subsystem
2012.04.03 14:27:07 -  debug1: session_by_channel: session 0 channel 0
2012.04.03 14:27:07 -  debug1: server_input_channel_req: channel 0 request subsystem reply 1
2012.04.03 14:27:06 -  debug1: session_input_channel_req: session 0 req simple@putty.projects.tartarus.org
2012.04.03 14:27:06 -  debug1: session_by_channel: session 0 channel 0
2012.04.03 14:27:06 -  debug1: server_input_channel_req: channel 0 request simple@putty.projects.tartarus.org reply 0
2012.04.03 14:27:06 -  debug1: server_input_channel_open: confirm session
2012.04.03 14:27:06 -  debug1: session_open: session 0: link with channel 0
2012.04.03 14:27:06 -  debug1: session_open: channel 0
2012.04.03 14:27:06 -  debug1: session_new: session 0
2012.04.03 14:27:06 -  debug3: session_unused: session id 0 unused
2012.04.03 14:27:06 -  debug2: session_new: allocate (allocated 0 max 10)
2012.04.03 14:27:06 -  debug1: channel 0: new
2012.04.03 14:27:06 -  debug1: input_session_request
2012.04.03 14:27:06 -  debug1: server_input_channel_open: ctype session rchan 256 win 2147483647 max 16384
2012.04.03 14:27:06 -  debug1: server_init_dispatch_20
2012.04.03 14:27:06 -  debug2: fd 5 setting O_NONBLOCK
2012.04.03 14:27:06 -  debug2: fd 4 setting O_NONBLOCK
2012.04.03 14:27:06 -  debug1: Entering interactive session for SSH2.
2012.04.03 14:27:06 -  debug2: cipher_init: set keylen (16 -> 32)
2012.04.03 14:27:06 -  debug2: set_newkeys: mode 1
2012.04.03 14:27:06 -  debug2: cipher_init: set keylen (16 -> 32)
2012.04.03 14:27:06 -  debug2: set_newkeys: mode 0
2012.04.03 14:27:06 -  debug3: mm_share_sync: Share sync end
2012.04.03 14:27:06 -  debug3: mm_share_sync: Share sync
2012.04.03 14:27:06 -  debug3: mm_get_keystate: Getting Network I/O buffers
2012.04.03 14:27:06 -  debug3: mm_get_keystate: Getting compression state
2012.04.03 14:27:06 -  debug2: mac_setup: found hmac-sha1
2012.04.03 14:27:06 -  debug3: mm_newkeys_from_blob: 0x10458030(139)
2012.04.03 14:27:06 -  debug3: mm_get_keystate: Waiting for second key
2012.04.03 14:27:06 -  debug2: mac_setup: found hmac-sha1
2012.04.03 14:27:06 -  debug3: mm_newkeys_from_blob: 0x10458030(139)
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive_expect entering: type 24
2012.04.03 14:27:06 -  debug3: mm_get_keystate: Waiting for new keys
2012.04.03 14:27:06 -  debug1: monitor_child_preauth: xxUserNamexx has been authenticated by privileged process
2012.04.03 14:27:06 -  debug1: monitor_read_log: child log fd closed
2012.04.03 14:27:06 -  debug3: mm_send_keystate: Finished sending state
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 24
2012.04.03 14:27:06 -  debug3: mm_send_keystate: Sending compression state
2012.04.03 14:27:06 -  debug3: mm_send_keystate: New keys have been sent
2012.04.03 14:27:06 -  debug3: mm_newkeys_to_blob: converting 0x10450368
2012.04.03 14:27:06 -  debug3: mm_newkeys_to_blob: converting 0x10450470
2012.04.03 14:27:06 -  debug3: mm_send_keystate: Sending new keys: 0x10450470 0x10450368
2012.04.03 14:27:06 -  debug2: userauth_pubkey: authenticated 1 pkalg ssh-dss
2012.04.03 14:27:06 -  Accepted publickey for xxUserNamexx from HXX.XXX.XX.XXX port 4749 ssh2
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 23
2012.04.03 14:27:06 -  debug3: mm_answer_keyverify: key 0x10458a90 signature verified
2012.04.03 14:27:06 -  debug1: ssh_dss_verify: signature correct
2012.04.03 14:27:06 -  debug3: monitor_read: checking request 22
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive_expect entering: type 23
2012.04.03 14:27:06 -  debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 22
2012.04.03 14:27:06 -  debug3: mm_key_verify entering
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 21
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed: key 0x10457f78 is allowed
2012.04.03 14:27:06 -  debug1: restore_uid: 1254290/545
2012.04.03 14:27:06 -  Found matching DSA key: 78:d8:8c:8a:c2:e7:c6:2b:8d:1f:22:14:32:a4:7e:3a
2012.04.03 14:27:06 -  debug1: matching key found: file /home/xxUserNamexx/.ssh/authorized_keys, line 1
2012.04.03 14:27:06 -  debug1: fd 4 clearing O_NONBLOCK
2012.04.03 14:27:06 -  debug1: trying public key file /home/xxUserNamexx/.ssh/authorized_keys
2012.04.03 14:27:06 -  debug1: temporarily_use_uid: 1116117/12513 (e=1254290/545)
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed: key_from_blob: 0x10457f78
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed entering
2012.04.03 14:27:06 -  debug3: monitor_read: checking request 20
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive_expect entering: type 21
2012.04.03 14:27:06 -  debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 20
2012.04.03 14:27:06 -  debug3: mm_key_allowed entering
2012.04.03 14:27:06 -  debug2: input_userauth_request: try method publickey
2012.04.03 14:27:06 -  debug1: attempt 2 failures 0
2012.04.03 14:27:06 -  debug1: userauth-request for user xxUserNamexx service ssh-connection method publickey
2012.04.03 14:27:06 -  Postponed publickey for xxUserNamexx from HXX.XXX.XX.XXX port 4749 ssh2
2012.04.03 14:27:06 -  debug2: userauth_pubkey: authenticated 0 pkalg ssh-dss
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 21
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed: key 0x10458ac0 is allowed
2012.04.03 14:27:06 -  debug1: restore_uid: 1254290/545
2012.04.03 14:27:06 -  Found matching DSA key: 78:d8:8c:8a:c2:e7:c6:2b:8d:1f:22:14:32:a4:7e:3a
2012.04.03 14:27:06 -  debug1: matching key found: file /home/xxUserNamexx/.ssh/authorized_keys, line 1
2012.04.03 14:27:06 -  debug1: fd 4 clearing O_NONBLOCK
2012.04.03 14:27:06 -  debug1: trying public key file /home/xxUserNamexx/.ssh/authorized_keys
2012.04.03 14:27:06 -  debug1: temporarily_use_uid: 1116117/12513 (e=1254290/545)
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed: key_from_blob: 0x10458ac0
2012.04.03 14:27:06 -  debug3: mm_answer_keyallowed entering
2012.04.03 14:27:06 -  debug3: monitor_read: checking request 20
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive_expect entering: type 21
2012.04.03 14:27:06 -  debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 20
2012.04.03 14:27:06 -  debug3: mm_key_allowed entering
2012.04.03 14:27:06 -  debug1: test whether pkalg/pkblob are acceptable
2012.04.03 14:27:06 -  debug2: input_userauth_request: try method publickey
2012.04.03 14:27:06 -  debug1: attempt 1 failures 0
2012.04.03 14:27:06 -  debug1: userauth-request for user xxUserNamexx service ssh-connection method publickey
2012.04.03 14:27:06 -  debug2: monitor_read: 3 used once, disabling now
2012.04.03 14:27:06 -  debug3: mm_answer_authserv: service=ssh-connection, style=
2012.04.03 14:27:06 -  debug3: monitor_read: checking request 3
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug2: input_userauth_request: try method none
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 3
2012.04.03 14:27:06 -  debug3: mm_inform_authserv entering
2012.04.03 14:27:06 -  debug2: input_userauth_request: setting up authctxt for xxUserNamexx
2012.04.03 14:27:06 -  debug2: monitor_read: 6 used once, disabling now
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 7
2012.04.03 14:27:06 -  debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
2012.04.03 14:27:06 -  debug3: reprocess config:22 setting PubkeyAuthentication no
2012.04.03 14:27:06 -  debug3: reprocess config:21 setting PasswordAuthentication no
2012.04.03 14:27:06 -  debug3: reprocess config:20 setting MaxSessions 0
2012.04.03 14:27:06 -  debug3: reprocess config:19 setting AllowTcpForwarding no
2012.04.03 14:27:06 -  debug3: match found
2012.04.03 14:27:06 -  debug1: user xxUserNamexx matched 'User *' at line 18
2012.04.03 14:27:06 -  debug3: checking match for 'User *' user xxUserNamexx host xxDomainUserxx.xxDomainxx.com addr HXX.XXX.XX.XXX
2012.04.03 14:27:06 -  debug3: reprocess config:15 setting MaxSessions 10
2012.04.03 14:27:06 -  debug3: reprocess config:14 setting AllowTcpForwarding no
2012.04.03 14:27:06 -  debug3: reprocess config:13 setting PubkeyAuthentication yes
2012.04.03 14:27:06 -  debug3: reprocess config:12 setting PasswordAuthentication no
2012.04.03 14:27:06 -  debug3: match found
2012.04.03 14:27:06 -  debug1: user xxUserNamexx matched 'User xxUserNamexx' at line 11
2012.04.03 14:27:06 -  debug3: checking match for 'User xxUserNamexx' user xxUserNamexx host xxDomainUserxx.xxDomainxx.com addr HXX.XXX.XX.XXX
2012.04.03 14:27:06 -  debug2: parse_server_config: config reprocess config len 382
2012.04.03 14:27:06 -  debug3: Trying to reverse map address HXX.XXX.XX.XXX.
2012.04.03 14:27:06 -  debug3: mm_answer_pwnamallow
2012.04.03 14:27:06 -  debug3: monitor_read: checking request 6
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive entering
2012.04.03 14:27:06 -  debug3: mm_request_receive_expect entering: type 7
2012.04.03 14:27:06 -  debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
2012.04.03 14:27:06 -  debug3: mm_request_send entering: type 6
2012.04.03 14:27:06 -  debug3: mm_getpwnamallow entering
2012.04.03 14:27:06 -  debug1: attempt 0 failures 0
2012.04.03 14:27:06 -  debug1: userauth-request for user xxUserNamexx service ssh-connection method none
2012.04.03 14:27:05 -  debug1: KEX done
2012.04.03 14:27:05 -  debug1: SSH2_MSG_NEWKEYS received
2012.04.03 14:27:05 -  debug2: cipher_init: set keylen (16 -> 32)
2012.04.03 14:27:05 -  debug2: set_newkeys: mode 0
2012.04.03 14:27:05 -  debug1: expecting SSH2_MSG_NEWKEYS
2012.04.03 14:27:05 -  debug1: SSH2_MSG_NEWKEYS sent
2012.04.03 14:27:05 -  debug2: cipher_init: set keylen (16 -> 32)
2012.04.03 14:27:05 -  debug2: set_newkeys: mode 1
2012.04.03 14:27:05 -  debug2: kex_derive_keys
2012.04.03 14:27:05 -  debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
2012.04.03 14:27:05 -  debug2: monitor_read: 4 used once, disabling now
2012.04.03 14:27:05 -  debug3: mm_request_send entering: type 5
2012.04.03 14:27:05 -  debug3: mm_answer_sign: signature 0x104588d8(271)
2012.04.03 14:27:05 -  debug3: mm_answer_sign
2012.04.03 14:27:05 -  debug3: monitor_read: checking request 4
2012.04.03 14:27:05 -  debug3: mm_request_receive entering
2012.04.03 14:27:05 -  debug3: mm_request_receive entering
2012.04.03 14:27:05 -  debug3: mm_request_receive_expect entering: type 5
2012.04.03 14:27:05 -  debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
2012.04.03 14:27:05 -  debug3: mm_request_send entering: type 4
2012.04.03 14:27:05 -  debug3: mm_key_sign entering
2012.04.03 14:27:05 -  debug2: bits set: 1013/2048
2012.04.03 14:27:05 -  debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
2012.04.03 14:27:05 -  debug2: bits set: 1019/2048
2012.04.03 14:27:05 -  debug2: dh_gen_key: priv key bits set: 253/512
2012.04.03 14:27:05 -  debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
2012.04.03 14:27:05 -  debug3: mm_choose_dh: remaining 0
2012.04.03 14:27:05 -  debug2: monitor_read: 0 used once, disabling now
2012.04.03 14:27:05 -  debug3: mm_request_send entering: type 1
2012.04.03 14:27:05 -  debug3: mm_answer_moduli: got parameters: 1024 2048 8192
2012.04.03 14:27:05 -  debug3: monitor_read: checking request 0
2012.04.03 14:27:05 -  debug3: mm_request_receive entering
2012.04.03 14:27:05 -  debug3: mm_request_receive entering
2012.04.03 14:27:05 -  debug3: mm_request_receive_expect entering: type 1
2012.04.03 14:27:05 -  debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
2012.04.03 14:27:05 -  debug3: mm_request_send entering: type 0
2012.04.03 14:27:05 -  debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received
2012.04.03 14:27:05 -  debug1: kex: server->client aes256-ctr hmac-sha1 none
2012.04.03 14:27:05 -  debug2: mac_setup: found hmac-sha1
2012.04.03 14:27:05 -  debug1: kex: client->server aes256-ctr hmac-sha1 none
2012.04.03 14:27:05 -  debug2: mac_setup: found hmac-sha1
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: reserved 0 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: first_kex_follows 0 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: none,zlib
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: none,zlib
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96,hmac-md5
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96,hmac-md5
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-sha1
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: reserved 0 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: first_kex_follows 0 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: 
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: none,zlib@openssh.com
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: none,zlib@openssh.com
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
2012.04.03 14:27:05 -  debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
2012.04.03 14:27:05 -  debug1: SSH2_MSG_KEXINIT received
2012.04.03 14:27:05 -  debug1: SSH2_MSG_KEXINIT sent
2012.04.03 14:27:05 -  debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
2012.04.03 14:27:05 -  debug3: preauth child monitor started
2012.04.03 14:27:05 -  debug2: Network child is on pid 36228
2012.04.03 14:27:05 -  debug2: fd 3 setting O_NONBLOCK
2012.04.03 14:27:05 -  debug1: Local version string SSH-2.0-OpenSSH_5.9
2012.04.03 14:27:05 -  debug1: Enabling compatibility mode for protocol 2.0
2012.04.03 14:27:05 -  debug1: no match: WinSCP_release_4.3.7
2012.04.03 14:27:05 -  debug1: Client protocol version 2.0; client software version WinSCP_release_4.3.7
2012.04.03 14:27:05 -  Connection from HXX.XXX.XX.XXX port 4749
2012.04.03 14:27:05 -  debug1: inetd sockets after dupping: 3, 3
2012.04.03 14:27:05 -  debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7
2012.04.03 14:27:05 -  debug3: send_rexec_state: done
2012.04.03 14:27:05 -  debug3: ssh_msg_send: type 0
2012.04.03 14:27:05 -  debug3: send_rexec_state: entering fd = 7 config len 382
2012.04.03 14:27:05 -  debug1: Forked child 32664.
2012.04.03 14:27:05 -  debug1: fd 4 clearing O_NONBLOCK


Client Connection Log:
=======================
. 2012-04-03 14:27:03.865 --------------------------------------------------------------------------
. 2012-04-03 14:27:03.865 WinSCP Version 4.3.7 (Build 1679) (OS 5.1.2600 Service Pack 3)
. 2012-04-03 14:27:03.865 Configuration: C:\Portable\WinSCPPortable\Data\settings\winscp.ini
. 2012-04-03 14:27:03.865 Local account: xxDomainxx\xxDomainUserxx
. 2012-04-03 14:27:03.865 Login time: Tuesday, April 03, 2012 2:27:03 PM
. 2012-04-03 14:27:03.865 --------------------------------------------------------------------------
. 2012-04-03 14:27:03.865 Session name: xxUserNamexx@xxServerNamexx (Stored session)
. 2012-04-03 14:27:03.865 Host name: xxServerNamexx (Port: 22)
. 2012-04-03 14:27:03.865 User name: xxUserNamexx (Password: No, Key file: Yes)
. 2012-04-03 14:27:03.865 Tunnel: No
. 2012-04-03 14:27:03.865 Transfer Protocol: SFTP (SCP)
. 2012-04-03 14:27:03.865 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2012-04-03 14:27:03.865 Proxy: none
. 2012-04-03 14:27:03.865 SSH protocol version: 2; Compression: No
. 2012-04-03 14:27:03.865 Bypass authentication: No
. 2012-04-03 14:27:03.865 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2012-04-03 14:27:03.865 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2012-04-03 14:27:03.865 SSH Bugs: -,-,-,-,-,-,-,-,-
. 2012-04-03 14:27:03.865 SFTP Bugs: -,-
. 2012-04-03 14:27:03.865 Return code variable: Autodetect; Lookup user groups: Yes
. 2012-04-03 14:27:03.865 Shell: default
. 2012-04-03 14:27:03.865 EOL: 0, UTF: 2
. 2012-04-03 14:27:03.865 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2012-04-03 14:27:03.865 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2012-04-03 14:27:03.865 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2012-04-03 14:27:03.865 Cache directory changes: Yes, Permanent: Yes
. 2012-04-03 14:27:03.865 DST mode: 1
. 2012-04-03 14:27:03.865 --------------------------------------------------------------------------
. 2012-04-03 14:27:03.880 Looking up host "xxServerNamexx"
. 2012-04-03 14:27:03.880 Connecting to HXX.XXX.XX.XXX port 22
. 2012-04-03 14:27:03.912 Selecting events 63 for socket 696
. 2012-04-03 14:27:03.912 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:03.912 Looking for incoming data
. 2012-04-03 14:27:03.912 Looking for network events
. 2012-04-03 14:27:03.912 Detected network event
. 2012-04-03 14:27:03.912 Enumerating network events for socket 696
. 2012-04-03 14:27:03.912 Enumerated 18 network events making 18 cumulative events for socket 696
. 2012-04-03 14:27:03.912 Handling network write event on socket 696 with error 0
. 2012-04-03 14:27:03.912 Handling network connect event on socket 696 with error 0
. 2012-04-03 14:27:03.912 Looking for network events
. 2012-04-03 14:27:04.021 Detected network event
. 2012-04-03 14:27:04.021 Enumerating network events for socket 696
. 2012-04-03 14:27:04.021 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.021 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.021 Server version: SSH-2.0-OpenSSH_5.9
. 2012-04-03 14:27:04.021 Using SSH protocol version 2
. 2012-04-03 14:27:04.021 We claim version: SSH-2.0-WinSCP_release_4.3.7
. 2012-04-03 14:27:04.021 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.021 Looking for incoming data
. 2012-04-03 14:27:04.021 Looking for network events
. 2012-04-03 14:27:04.083 Detected network event
. 2012-04-03 14:27:04.083 Enumerating network events for socket 696
. 2012-04-03 14:27:04.083 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.083 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.083 Doing Diffie-Hellman group exchange
. 2012-04-03 14:27:04.083 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.083 Looking for incoming data
. 2012-04-03 14:27:04.083 Looking for network events
. 2012-04-03 14:27:04.302 Detected network event
. 2012-04-03 14:27:04.302 Enumerating network events for socket 696
. 2012-04-03 14:27:04.302 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.302 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.302 Doing Diffie-Hellman key exchange with hash SHA-1
. 2012-04-03 14:27:04.412 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.412 Looking for incoming data
. 2012-04-03 14:27:04.412 Looking for network events
. 2012-04-03 14:27:04.458 Detected network event
. 2012-04-03 14:27:04.458 Enumerating network events for socket 696
. 2012-04-03 14:27:04.458 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.458 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.599 Selecting events 63 for socket 696
. 2012-04-03 14:27:04.599 Host key fingerprint is:
. 2012-04-03 14:27:04.599 ssh-rsa 2048 d3:08:35:2d:2c:58:8b:d1:52:1c:27:9c:6a:49:dd:84
. 2012-04-03 14:27:04.599 Initialised AES-256 SDCTR client->server encryption
. 2012-04-03 14:27:04.599 Initialised HMAC-SHA1 client->server MAC algorithm
. 2012-04-03 14:27:04.599 Initialised AES-256 SDCTR server->client encryption
. 2012-04-03 14:27:04.599 Initialised HMAC-SHA1 server->client MAC algorithm
. 2012-04-03 14:27:04.599 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.599 Looking for incoming data
. 2012-04-03 14:27:04.599 Looking for network events
. 2012-04-03 14:27:04.802 Detected network event
. 2012-04-03 14:27:04.802 Enumerating network events for socket 696
. 2012-04-03 14:27:04.802 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.802 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.802 Reading private key file "C:\Portable\WinSCPPortable\User Keys\xxUserKeyxx.ppk"
! 2012-04-03 14:27:04.802 Using username "xxUserNamexx".
. 2012-04-03 14:27:04.802 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.802 Looking for incoming data
. 2012-04-03 14:27:04.802 Looking for network events
. 2012-04-03 14:27:04.849 Detected network event
. 2012-04-03 14:27:04.849 Enumerating network events for socket 696
. 2012-04-03 14:27:04.849 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:04.849 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:04.849 Offered public key
. 2012-04-03 14:27:04.849 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:04.849 Looking for incoming data
. 2012-04-03 14:27:04.849 Looking for network events
. 2012-04-03 14:27:05.177 Detected network event
. 2012-04-03 14:27:05.177 Enumerating network events for socket 696
. 2012-04-03 14:27:05.177 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.177 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.177 Offer of public key accepted
! 2012-04-03 14:27:05.177 Authenticating with public key "imported-openssh-key"
. 2012-04-03 14:27:05.208 Sent public key signature
. 2012-04-03 14:27:05.208 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:05.208 Looking for incoming data
. 2012-04-03 14:27:05.208 Looking for network events
. 2012-04-03 14:27:05.427 Detected network event
. 2012-04-03 14:27:05.427 Enumerating network events for socket 696
. 2012-04-03 14:27:05.427 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.427 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.427 Access granted
. 2012-04-03 14:27:05.427 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:05.427 Looking for incoming data
. 2012-04-03 14:27:05.427 Looking for network events
. 2012-04-03 14:27:05.458 Detected network event
. 2012-04-03 14:27:05.458 Enumerating network events for socket 696
. 2012-04-03 14:27:05.458 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.458 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.458 Opened channel for session
. 2012-04-03 14:27:05.458 Waiting for the server to continue with the initialisation
. 2012-04-03 14:27:05.458 Looking for incoming data
. 2012-04-03 14:27:05.458 Looking for network events
. 2012-04-03 14:27:05.724 Detected network event
. 2012-04-03 14:27:05.724 Enumerating network events for socket 696
. 2012-04-03 14:27:05.724 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.724 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.724 Started a shell/command
. 2012-04-03 14:27:05.724 --------------------------------------------------------------------------
. 2012-04-03 14:27:05.724 Using SFTP protocol.
. 2012-04-03 14:27:05.724 Doing startup conversation with host.
> 2012-04-03 14:27:05.724 Type: SSH_FXP_INIT, Size: 5, Number: -1
> 2012-04-03 14:27:05.724 01,00,00,00,05,
. 2012-04-03 14:27:05.724 Sent 9 bytes
. 2012-04-03 14:27:05.724 There are 0 bytes remaining in the send buffer
. 2012-04-03 14:27:05.724 Looking for network events
. 2012-04-03 14:27:05.724 Timeout waiting for network events
. 2012-04-03 14:27:05.724 Waiting for another 4 bytes
. 2012-04-03 14:27:05.724 Looking for incoming data
. 2012-04-03 14:27:05.724 Looking for network events
. 2012-04-03 14:27:05.755 Detected network event
. 2012-04-03 14:27:05.755 Enumerating network events for socket 696
. 2012-04-03 14:27:05.755 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.755 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.755 Server exited on signal "HUP"
. 2012-04-03 14:27:05.755 Waiting for another 4 bytes
. 2012-04-03 14:27:05.755 Looking for incoming data
. 2012-04-03 14:27:05.755 Looking for network events
. 2012-04-03 14:27:05.755 Detected network event
. 2012-04-03 14:27:05.755 Enumerating network events for socket 696
. 2012-04-03 14:27:05.755 Enumerated 1 network events making 1 cumulative events for socket 696
. 2012-04-03 14:27:05.755 Handling network read event on socket 696 with error 0
. 2012-04-03 14:27:05.755 Selecting events 0 for socket 696
. 2012-04-03 14:27:05.755 Disconnected: All channels closed
* 2012-04-03 14:27:05.771 (ESshFatal) Connection has been unexpectedly closed. Server sent command exit status 128.
* 2012-04-03 14:27:05.771 Cannot initialize SFTP protocol. Is the host running a SFTP server?


Any assistance you can offer is greatly appreciated.

Thank you,

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
Please check if that

Please check if that particular domain user has local login rights on the server side. Check FAQ 

  for a recipe

Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
The domain account is part of

The domain account is part of a local group that has local login rights to the server.

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
It seems that you use PKA. Do

It seems that you use PKA. Do you have the same problem if you use password authentication ?

Can you also send me copies of etc/passwd, etc/groups, etc/sshd_config and bin/copsshcp.config ?

Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
Yes, we have the same exact

Yes, we have the same exact problem with password authentication.  I can't post those files on the web is there an email address i can send them to?

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
You can send files to (post

You can send files to (post --at-- itefix.no) or use the contact form. Thanks.

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
Thanks for the files. I think

Thanks for the files. I think the main source of the problem is the limitation of the public key authentication on Cygwin/Windows: Upon a successful authentication, credentials of the service account are used for the new process serving the request. Log entry below shows that behaviuor:

 

2012.04.03 14:27:06 -  debug1: temporarily_use_uid: 1116117/12513 (e=1254290/545)

 

You may have a look at a related discussion at the Cygwin mailing list for more detailed information.

Please make sure that the service account has required rights to work on behalf of the ftp user (write access to home directory for example.)

Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
I've set the service account

I've set the service account as administrator of the server and have haven given the service account full control to the home directory of the sftp user.  Still the same problem.

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
We have tried to implement

We have tried to implement your configuration in our testlab. Our findings are:

 

  • Everything (WinScp in SFTP mode with public key authentication against Copssh server) works as expected when Copssh runs by the local service account SvcCopssh.
  • Problems have arosen when we run Copssh by a domain based service account (domain\svccopssh). The solution was to make Domain\Svccopssh account a member of local Administrators group. We verified also that the service account has following local user rights (should be handled by the installer automatically):
  • act as part of the operating system
  • adjust memory quotas for a process
  • Create a token object
  • Logon as a service
  • Replace a process level token
Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
We have uninstalled and

We have uninstalled and reinstalled Copssh taking all of the defaults so that the service is run by local service account SvcCopssh and still have the same problem.  We have also verified all permissions that you have metioned with the domain service account.  After some further testing we have found that if we shell into the server and then start a sftp connection from the shell it connects without any issues.  We would also like to note that permissions within cygwin are odd and dont match windows.  It appears cygwin reports drwxr-x--- for the home direcotry and also reports the owner and group equal to that of the current connected user.

Dubler
Offline
Last seen: 9 years 2 months ago
Joined: 14.03.2012 - 21:27
We just installed an older

We just installed an older version of Copssh version 3.0.3 and it worked perfeclty after we changed Subsystem sftp internal-sftp.  Based on this analysis it appears there is something different with Copssh version 4.2.3 versus Copssh version 3.0.3.  How can we get Copssh version 4.2.3 running so we maintain support that we paid for?

itefix
Offline
Last seen: 18 min 33 sec ago
Joined: 01.05.2008 - 21:33
Thanks for your observations.

Thanks for your observations. I could reproduce the problem on a Windows 2003 system. The problem is not related to OpenSSH but to underlying Cygwin layer. After having tested several previous base packages, I could verify that base versions 2.1.7 and up will create the problem on 2003 systems (Version 4.2.3 has base 2.2.0). Base 2.1.6 is now available to customers.

Please do the following:

  • Stop OpenSSH service
  • Run the installer directly on your 4.2.3 installation. This will downgrade Cygwin and some other tools. There will be no changes in Openssh configuration and versions.
  • Start OpenSSH service again