Key Authentication Failure - public-key signature refused :: Support Forum

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

Key Authentication Failure - public-key signature refused

2015-01-09 21:54

Versions of WinSCP impacted: 5.5.3, 5.5.4, 5.5.6 (only these versions were tested)
Versions of WinSCP NOT impacted: 4.3.8, 4.1.9 (only these versions were tested)
Operating System versions: Win 2008, Win 2012, Win 7 (only these versions tested)
Protocol in use: SFTP using key-based authentication, key generated by puttyGen
GUI or Scripting: both
Full Error Message:

Authentication log (see session log for details):
Using username "xxx".
Authenticating with public key "key comment".
Server refused public-key signature despite accepting key!

WinSCP Error log

. 2015-01-09 15:37:32.181 Waiting for the server to continue with the initialization
. 2015-01-09 15:37:32.181 Looking for incoming data
. 2015-01-09 15:37:32.181 Looking for network events
. 2015-01-09 15:37:32.212 Detected network event
. 2015-01-09 15:37:32.212 Enumerating network events for socket 964
. 2015-01-09 15:37:32.212 Enumerated 1 network events making 1 cumulative events for socket 964
. 2015-01-09 15:37:32.212 Handling network read event on socket 964 with error 0
. 2015-01-09 15:37:32.212 Offer of public key accepted
! 2015-01-09 15:37:32.212 Authenticating with public key "key comment"
. 2015-01-09 15:37:32.384 Sent public key signature
. 2015-01-09 15:37:32.384 Waiting for the server to continue with the initialization
. 2015-01-09 15:37:32.384 Looking for incoming data
. 2015-01-09 15:37:32.384 Looking for network events
. 2015-01-09 15:37:32.415 Detected network event
. 2015-01-09 15:37:32.415 Enumerating network events for socket 964
. 2015-01-09 15:37:32.415 Enumerated 1 network events making 1 cumulative events for socket 964
. 2015-01-09 15:37:32.415 Handling network read event on socket 964 with error 0
! 2015-01-09 15:37:32.415 Server refused public-key signature despite accepting key!
. 2015-01-09 15:37:32.462 Server refused public-key signature despite accepting key!
. 2015-01-09 15:37:32.462 Selecting events 0 for socket 964
. 2015-01-09 15:37:32.462 Disconnected: No supported authentication methods available (server sent: )
* 2015-01-09 15:37:32.525 (EFatal) Disconnected: No supported authentication methods available (server sent: )
* 2015-01-09 15:37:32.525 Authentication log (see session log for details):
* 2015-01-09 15:37:32.525 Using username "xxx".
* 2015-01-09 15:37:32.525 Authenticating with public key "key comment".
* 2015-01-09 15:37:32.525 Server refused public-key signature despite accepting key!
* 2015-01-09 15:37:32.525 
* 2015-01-09 15:37:32.525 Authentication failed.

We ran into an issue where the same automated script/job was deployed to two different client systems.\
System-A: Windows 2008, WinSCP 4.3.8 (works)
System-B: Windows 2012, WinSCP 5.5.3 (does not work, gives errors above)

The remote server, in both instances is the same.
The user account on the remote SFTP server, in both instances is the same.
The private key file is the same file on both servers. I even went so far as deleting the private key file from System-B and copying it to System-A. Re-tested. Same results.

Testing using GUI from each server, using same user/server settings. Same results. Success on System-A, Failure on System-B.

Upgraded System-A to WinSCP 5.5.6 and retested script and GUI.
Now System-A is getting the same error messages as above.

To test further, installed WinSCP 5.5.6 on my Win7 laptop. Copied private key file from System-A.
Tested from laptop using GUI and script. Get same error message as above.

Uninstall WinSCP 5.5.6 from my Win7 laptop. Reboot.
Install WinSCP 4.1.9 (didn't have an installer for 4.3.8)
Copied private key file from System-A.
Tested from laptop using GUI and script.
Can login/authenticate with no issues.

I'm waiting for detailed error messages from the administrator of the remote system as we also use WinSCP 5.5.* for exchanges with other SFTP servers and have no issues.

Wondering what differences in the version of WinSCP may be contributing to the problem. I've found precious few references on the Internet with others experiencing the same issue and finding an appropriate solution.

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-11 20:22

Determined remote SFTP server is Core FTP Server. Notes on key setup and support
http://www.coreftp.com/server/help/ssh_keypairs.htm

I can confirm the keypair in use is an SSH v2 keypair

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,454
Location:: Prague, Czechia

Re: Key Authentication Failure - public-key signature refused

2015-01-12

Thanks for your report. I'll try to reproduce it. Though it's likely the problem is related to some specifics of your private key.

Is there any relevant record in server's log?
Can you attach a full session log file both from WinSCP 4.x and 5.x? Can you try also some earlier version of 5.x? (5.1.8) Can you try to reproduce the problem with newly generated key (using the latest version of PuTTYgen)? What version of PuTTYgen are you using?

Last edited by martin on 2015-01-20; edited 1 time in total

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-12 19:04

We've requested logs from the owner of the SFTP server - still waiting. It's a third party organization so it might take a day or two.

We generated a new key pair (again using PuttyGen and specifically using System-A while it was still working). When the remote server admin installed the new public key and we sent the new private key, the results were the same: System-A succeeded (with version 4.3.8) and System-B failed with (5.5.3).

When I tested with my laptop, the new key worked on 4.1.9 and failed with 5.5.6

I downloaded 5.1.1 from Source forge. I'll install and test with it and report back.

Thanks for looking at this. Hope to have more data soon.

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-16 23:15

PuTTYgen Version is 0.63 (distributed with WinSCP it looks like)

Server logs aren't helping much – example (stripped out user name). This is what the 3rd party server came up with. Looking at the minimal CoreFTP documentation, they don't expand on logging. I see complaints in the CoreFTP "support" forum where CoreFTP users have requested more detailed log data and get nothing.

    {
      "_index" : "logstash-2015.01.07",
      "_type" : "FTPLog",
      "_id" : "yfp4ULgsQKy3o6H1CoyO1w",
      "_score" : 9.629678,
      "fields" : {
        "message" : [ "[20150107 04:10:04] [our.Ip.Address.ok] connecting\r\r" ]
      }
    }, {
      "_index" : "logstash-2015.01.07",
      "_type" : "FTPLog",
      "_id" : "SWaTB69HSOSX6JticvuNVg",
      "_score" : 9.629678,
      "fields" : {
        "message" : [ "[20150107 04:10:05] [our.Ip.Address.ok] user (username) granted access\r\r" ]
      }
    },  {
      "_index" : "logstash-2015.01.07",
      "_type" : "FTPLog",
      "_id" : "iaPoekSlRyK1A6vF8lCdYA",
      "_score" : 9.629678,
      "fields" : {
        "message" : [ "[20150107 04:10:06] [our.Ip.Address.ok] disconnected (username)\r\r" ]
      },

The job log (from our side) for the same connection looks like this:

Job Start: 20150107 04:10 AM 
RUN: "D:\Program Files (x86)\WinSCP\winscp.com" /script="SendFiles_prod.commands.txt" /log="SendFiles_prod.20150107.ftp.log" /xmllog="\SendFiles_prod.20150107.ftp.log" /xmlgroups 
batch           abort     
confirm         off       
Searching for host...
Connecting to host...
Authenticating...
Using username "username".
Authenticating with public key "key-comment".
Server refused public-key signature despite accepting key!
Disconnected: No supported authentication methods available (server sent: )
Authentication log (see session log for details):
Using username "username".
Authenticating with public key "key-comment".
Server refused public-key signature despite accepting key!


Authentication failed.
## Error ## 
FTP Error 
Job end: 20150107 04:10 AM

The batch script: SendFiles_prod.commands.txt (replaced confidential info) is simple. The only thing that changes from client to client is the destination directory on the remote server for the PUT

option batch abort
option confirm off
open sftp://username@sftp.remotehost.com -privatekey=PrivateKey.ppk -hostkey="ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06"
option transfer binary
ls
put \outbound\ToSend\*.* -nopreservetime -nopermissions
close
exit

I don't have the exact FTP log for the transaction time (we overwrite with each connection per day), but they all look like this with only the time markers changes. (again, masked out sensitive data)

<?xml version="1.0" encoding="UTF-8"?>
<session xmlns="http://winscp.net/schema/session/1.0" name="username@sftp.remotehost.com" start="2015-01-08T04:10:10.118Z">
  <failure>
    <message>Disconnected: No supported authentication methods available (server sent: )</message>
    <message>Authentication log (see session log for details):
Using username &quot;username&quot;.
Authenticating with public key &quot;key-comment&quot;.
Server refused public-key signature despite accepting key!
</message>
    <message>Authentication failed.</message>
  </failure>
</session>

. 2015-01-07 23:10:10.118 Process ID: 8944
. 2015-01-07 23:10:10.118 Command-line: "D:\Program Files (x86)\WinSCP\WinSCP.exe" /console=553 /consoleinstance=_6680_992 "/script=SendFiles_prod.commands.txt" "/log=SendFiles_prod.20150107.ftp.log" "/xmllog=SendFiles_prod.20150107.ftp.log" "/xmlgroups" 
. 2015-01-07 23:10:10.118 Time zone: Current: GMT-5, Standard: GMT-5 (Eastern Standard Time), DST: GMT-4 (Eastern Daylight Time), DST Start: 3/8/2015, DST End: 11/1/2015
. 2015-01-07 23:10:10.118 Login time: Wednesday, January 7, 2015 11:10:10 PM
. 2015-01-07 23:10:10.118 --------------------------------------------------------------------------
. 2015-01-07 23:10:10.118 Script: Retrospectively logging previous script records:
> 2015-01-07 23:10:10.118 Script: option batch abort
< 2015-01-07 23:10:10.118 Script: batch           abort     
> 2015-01-07 23:10:10.118 Script: option confirm off
< 2015-01-07 23:10:10.118 Script: confirm         off       
> 2015-01-07 23:10:10.118 Script: open sftp://username@sftp.remotehost.com -privatekey=PrivateKey.ppk -hostkey="ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06"
. 2015-01-07 23:10:10.118 --------------------------------------------------------------------------
. 2015-01-07 23:10:10.118 Session name: username@sftp.remotehost.com (Ad-Hoc site)
. 2015-01-07 23:10:10.118 Host name: sftp.remotehost.com (Port: 22)
. 2015-01-07 23:10:10.118 User name: username (Password: No, Key file: Yes)
. 2015-01-07 23:10:10.118 Tunnel: No
. 2015-01-07 23:10:10.118 Transfer Protocol: SFTP
. 2015-01-07 23:10:10.118 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2015-01-07 23:10:10.118 Proxy: none
. 2015-01-07 23:10:10.118 Send buffer: 262144
. 2015-01-07 23:10:10.118 SSH protocol version: 2; Compression: No
. 2015-01-07 23:10:10.118 Bypass authentication: No
. 2015-01-07 23:10:10.118 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2015-01-07 23:10:10.118 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2015-01-07 23:10:10.118 SSH Bugs: A,A,A,A,A,A,A,A,A,A
. 2015-01-07 23:10:10.118 Simple channel: Yes
. 2015-01-07 23:10:10.118 Return code variable: Autodetect; Lookup user groups: A
. 2015-01-07 23:10:10.118 Shell: default
. 2015-01-07 23:10:10.118 EOL: 0, UTF: 2
. 2015-01-07 23:10:10.118 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2015-01-07 23:10:10.118 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2015-01-07 23:10:10.118 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2015-01-07 23:10:10.118 Cache directory changes: Yes, Permanent: Yes
. 2015-01-07 23:10:10.118 DST mode: 1; Timezone offset: 0h 0m
. 2015-01-07 23:10:10.118 --------------------------------------------------------------------------
. 2015-01-07 23:10:10.118 Looking up host "sftp.remotehost.com"
. 2015-01-07 23:10:10.133 Connecting to 99.99.99.99 port 22
. 2015-01-07 23:10:10.196 Server version: SSH-2.0-CoreFTP-0.3.3
. 2015-01-07 23:10:10.196 Using SSH protocol version 2
. 2015-01-07 23:10:10.196 We claim version: SSH-2.0-WinSCP_release_5.5.3
. 2015-01-07 23:10:10.227 Doing Diffie-Hellman group exchange
. 2015-01-07 23:10:10.508 Doing Diffie-Hellman key exchange with hash SHA-256
. 2015-01-07 23:10:12.805 Verifying host key rsa2 0x10001,0xbc9fc42d0eaa32c6 9999999999999999 0000000000000000 3333333333333333 e75de71eb0ac7c64 a8874bea879fede0 eeba1dc9e6272bb9 823de17fad4eb614 79b209a6a5db678e 0aed49eb097d8958 0fcdf30c619de177 1eed2b962996f573 655e126f9b59d774 cb1fcf394c0061d0 4ce945b2ab47055a 9bdff104f68c1c0f  with fingerprint ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06
. 2015-01-07 23:10:12.805 Host key matches configured key
. 2015-01-07 23:10:12.805 Host key fingerprint is:
. 2015-01-07 23:10:12.805 ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06
. 2015-01-07 23:10:12.805 Initialised AES-256 SDCTR client->server encryption
. 2015-01-07 23:10:12.805 Initialised HMAC-SHA-256 client->server MAC algorithm
. 2015-01-07 23:10:12.837 Initialised AES-256 SDCTR server->client encryption
. 2015-01-07 23:10:12.837 Initialised HMAC-SHA-256 server->client MAC algorithm
. 2015-01-07 23:10:12.868 Reading private key file "PrivateKey.ppk"
! 2015-01-07 23:10:12.868 Using username "username".
. 2015-01-07 23:10:12.899 Offered public key
. 2015-01-07 23:10:12.930 Offer of public key accepted
! 2015-01-07 23:10:12.930 Authenticating with public key "key-comment"
. 2015-01-07 23:10:12.962 Sent public key signature
! 2015-01-07 23:10:12.993 Server refused public-key signature despite accepting key!
. 2015-01-07 23:10:12.993 Server refused public-key signature despite accepting key!
. 2015-01-07 23:10:12.993 Disconnected: No supported authentication methods available (server sent: )

Going to try version 5.1.1 next. Need to reboot :)

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-16 23:34

Version 5.1.1 Works without issue.

With debug (x2) logging below and a manual connection (same username, site, port, and private key).
Let me know if a manual connection with the same debug (x2) from a broken version helps.

. 2015-01-16 17:24:03.651 --------------------------------------------------------------------------
. 2015-01-16 17:24:03.651 WinSCP Version 5.1.1 (Build 2735) (OS 6.1.7601 Service Pack 1)
. 2015-01-16 17:24:03.651 Configuration: HKEY_CURRENT_USER\Software\Martin Prikryl\WinSCP 2\
. 2015-01-16 17:24:03.651 Local account: me
. 2015-01-16 17:24:03.651 Working directory: C:\Program Files (x86)\WinSCP
. 2015-01-16 17:24:03.651 Command-line: "C:\Program Files (x86)\WinSCP\WinSCP.exe" 
. 2015-01-16 17:24:03.651 Time zone: Current: GMT-5, Standard: GMT-5, DST: GMT-4, DST Start: 3/8/2015, DST End: 11/1/2015
. 2015-01-16 17:24:03.651 Login time: Friday, January 16, 2015 5:24:03 PM
. 2015-01-16 17:24:03.651 --------------------------------------------------------------------------
. 2015-01-16 17:24:03.651 Session name: username@sftp.remotehost.com (Stored session)
. 2015-01-16 17:24:03.651 Host name: sftp.remotehost.com (Port: 22)
. 2015-01-16 17:24:03.651 User name: username (Password: No, Key file: Yes)
. 2015-01-16 17:24:03.651 Tunnel: No
. 2015-01-16 17:24:03.651 Transfer Protocol: SFTP (SCP)
. 2015-01-16 17:24:03.651 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2015-01-16 17:24:03.651 Proxy: none
. 2015-01-16 17:24:03.651 SSH protocol version: 2; Compression: No
. 2015-01-16 17:24:03.651 Bypass authentication: No
. 2015-01-16 17:24:03.651 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2015-01-16 17:24:03.651 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2015-01-16 17:24:03.651 SSH Bugs: A,A,A,A,A,A,A,A,A,A
. 2015-01-16 17:24:03.651 SFTP Bugs: A,A
. 2015-01-16 17:24:03.651 Return code variable: Autodetect; Lookup user groups: A
. 2015-01-16 17:24:03.651 Shell: default
. 2015-01-16 17:24:03.651 EOL: 0, UTF: 2
. 2015-01-16 17:24:03.651 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2015-01-16 17:24:03.651 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2015-01-16 17:24:03.651 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2015-01-16 17:24:03.651 Cache directory changes: Yes, Permanent: Yes
. 2015-01-16 17:24:03.651 DST mode: 1
. 2015-01-16 17:24:03.651 --------------------------------------------------------------------------
. 2015-01-16 17:24:03.713 Looking up host "sftp.remotehost.com"
. 2015-01-16 17:24:03.807 Connecting to 99.99.99.99 port 22
. 2015-01-16 17:24:03.870 Selecting events 63 for socket 840
. 2015-01-16 17:24:03.932 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:03.932 Looking for incoming data
. 2015-01-16 17:24:03.932 Looking for network events
. 2015-01-16 17:24:03.932 Detected network event
. 2015-01-16 17:24:03.932 Enumerating network events for socket 840
. 2015-01-16 17:24:03.932 Enumerated 19 network events making 19 cumulative events for socket 840
. 2015-01-16 17:24:03.932 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:03.932 Server version: SSH-2.0-CoreFTP-0.3.3
. 2015-01-16 17:24:03.932 Using SSH protocol version 2
. 2015-01-16 17:24:03.932 We claim version: SSH-2.0-WinSCP_release_5.1.1
. 2015-01-16 17:24:03.932 Handling network write event on socket 840 with error 0
. 2015-01-16 17:24:03.932 Handling network connect event on socket 840 with error 0
. 2015-01-16 17:24:03.932 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:03.932 Looking for incoming data
. 2015-01-16 17:24:03.932 Looking for network events
. 2015-01-16 17:24:03.979 Detected network event
. 2015-01-16 17:24:03.979 Enumerating network events for socket 840
. 2015-01-16 17:24:03.979 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:03.979 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:03.979 Using Diffie-Hellman with standard group "group14"
. 2015-01-16 17:24:03.979 Doing Diffie-Hellman key exchange with hash SHA-1
. 2015-01-16 17:24:04.057 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:04.057 Looking for incoming data
. 2015-01-16 17:24:04.057 Looking for network events
. 2015-01-16 17:24:04.463 Detected network event
. 2015-01-16 17:24:04.463 Enumerating network events for socket 840
. 2015-01-16 17:24:04.463 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:04.463 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:04.542 Verifying host key rsa2 0x10001,0xbc000000000000000000000000000000000000d3333333333333333333333333333333333333333333333333333333333333333333333bb9823de17fad4eb61479b209a6a5db678e0aed49eb097d89580fcdf30c619de1771eed2b962996f573655e126f9b59d774cb1fcf394c0061d04ce945b2ab47055a9bdff104f68c1c0f with fingerprint ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06
. 2015-01-16 17:24:04.573 Asking user:
. 2015-01-16 17:24:04.573 The server's host key was not found in the cache. You have no guarantee that the server is the computer you think it is.
. 2015-01-16 17:24:04.573 
. 2015-01-16 17:24:04.573 The server's rsa2 key fingerprint is:
. 2015-01-16 17:24:04.573 ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06
. 2015-01-16 17:24:04.573 
. 2015-01-16 17:24:04.573 If you trust this host, press Yes. To connect without adding host key to the cache, press No. To abandon the connection press Cancel.
. 2015-01-16 17:24:04.573 
. 2015-01-16 17:24:04.573 Continue connecting and add host key to the cache? ()
. 2015-01-16 17:24:08.369 Selecting events 63 for socket 840
. 2015-01-16 17:24:08.369 Host key fingerprint is:
. 2015-01-16 17:24:08.369 ssh-rsa 1024 06:06:06:06:06:06:06:06:06:06:06:06:06:06:06:06
. 2015-01-16 17:24:08.369 Initialised AES-256 SDCTR client->server encryption
. 2015-01-16 17:24:08.369 Initialised HMAC-SHA1 client->server MAC algorithm
. 2015-01-16 17:24:08.369 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:08.369 Looking for incoming data
. 2015-01-16 17:24:08.369 Looking for network events
. 2015-01-16 17:24:08.416 Detected network event
. 2015-01-16 17:24:08.416 Enumerating network events for socket 840
. 2015-01-16 17:24:08.416 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:08.416 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:08.416 Initialised AES-256 SDCTR server->client encryption
. 2015-01-16 17:24:08.416 Initialised HMAC-SHA1 server->client MAC algorithm
. 2015-01-16 17:24:08.416 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:08.416 Looking for incoming data
. 2015-01-16 17:24:08.416 Looking for network events
. 2015-01-16 17:24:08.541 Detected network event
. 2015-01-16 17:24:08.541 Enumerating network events for socket 840
. 2015-01-16 17:24:08.541 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:08.541 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:08.541 Reading private key file "PrivateKey.ppk"
! 2015-01-16 17:24:08.541 Using username "username".
. 2015-01-16 17:24:08.604 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:08.604 Looking for incoming data
. 2015-01-16 17:24:08.604 Looking for network events
. 2015-01-16 17:24:08.651 Detected network event
. 2015-01-16 17:24:08.651 Enumerating network events for socket 840
. 2015-01-16 17:24:08.651 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:08.651 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:08.651 Offered public key
. 2015-01-16 17:24:08.651 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:08.651 Looking for incoming data
. 2015-01-16 17:24:08.651 Looking for network events
. 2015-01-16 17:24:08.776 Detected network event
. 2015-01-16 17:24:08.776 Enumerating network events for socket 840
. 2015-01-16 17:24:08.776 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:08.776 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:08.776 Offer of public key accepted
! 2015-01-16 17:24:08.776 Authenticating with public key "key-comment"
. 2015-01-16 17:24:08.947 Sent public key signature
. 2015-01-16 17:24:08.947 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:08.947 Looking for incoming data
. 2015-01-16 17:24:08.947 Looking for network events
. 2015-01-16 17:24:09.322 Detected network event
. 2015-01-16 17:24:09.322 Enumerating network events for socket 840
. 2015-01-16 17:24:09.322 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:09.322 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:09.322 Access granted
. 2015-01-16 17:24:09.322 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:09.322 Looking for incoming data
. 2015-01-16 17:24:09.322 Looking for network events
. 2015-01-16 17:24:09.432 Detected network event
. 2015-01-16 17:24:09.432 Enumerating network events for socket 840
. 2015-01-16 17:24:09.432 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:09.432 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:09.432 Opened channel for session
. 2015-01-16 17:24:09.432 Waiting for the server to continue with the initialisation
. 2015-01-16 17:24:09.432 Looking for incoming data
. 2015-01-16 17:24:09.432 Looking for network events
. 2015-01-16 17:24:09.744 Detected network event
. 2015-01-16 17:24:09.744 Enumerating network events for socket 840
. 2015-01-16 17:24:09.744 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:09.744 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:09.744 Started a shell/command
. 2015-01-16 17:24:09.760 --------------------------------------------------------------------------
. 2015-01-16 17:24:09.760 Using SFTP protocol.
. 2015-01-16 17:24:09.760 Doing startup conversation with host.
> 2015-01-16 17:24:09.822 Type: SSH_FXP_INIT, Size: 5, Number: -1
> 2015-01-16 17:24:09.822 01,00,00,00,05,
. 2015-01-16 17:24:09.822 Sent 9 bytes
. 2015-01-16 17:24:09.822 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:09.822 Looking for network events
. 2015-01-16 17:24:09.822 Timeout waiting for network events
. 2015-01-16 17:24:09.822 Waiting for another 4 bytes
. 2015-01-16 17:24:09.822 Looking for incoming data
. 2015-01-16 17:24:09.822 Looking for network events
. 2015-01-16 17:24:09.869 Detected network event
. 2015-01-16 17:24:09.869 Enumerating network events for socket 840
. 2015-01-16 17:24:09.869 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:09.869 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:09.869 Waiting for another 4 bytes
. 2015-01-16 17:24:09.869 Looking for incoming data
. 2015-01-16 17:24:09.869 Looking for network events
. 2015-01-16 17:24:10.135 Detected network event
. 2015-01-16 17:24:10.135 Enumerating network events for socket 840
. 2015-01-16 17:24:10.135 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:10.135 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:10.135 Received 9 bytes (0)
. 2015-01-16 17:24:10.135 Read 4 bytes (5 pending)
. 2015-01-16 17:24:10.135 Read 5 bytes (0 pending)
< 2015-01-16 17:24:10.135 Type: SSH_FXP_VERSION, Size: 5, Number: -1
< 2015-01-16 17:24:10.135 02,00,00,00,03,
. 2015-01-16 17:24:10.135 SFTP version 3 negotiated.
. 2015-01-16 17:24:10.135 We believe the server has signed timestamps bug
. 2015-01-16 17:24:10.135 We will use UTF-8 strings for status messages only
. 2015-01-16 17:24:10.166 Getting current directory name.
. 2015-01-16 17:24:10.166 Getting real path for '.'
> 2015-01-16 17:24:10.166 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
> 2015-01-16 17:24:10.166 10,00,00,00,10,00,00,00,01,2E,
. 2015-01-16 17:24:10.166 Sent 14 bytes
. 2015-01-16 17:24:10.166 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:10.166 Looking for network events
. 2015-01-16 17:24:10.166 Timeout waiting for network events
. 2015-01-16 17:24:10.166 Waiting for another 4 bytes
. 2015-01-16 17:24:10.166 Looking for incoming data
. 2015-01-16 17:24:10.166 Looking for network events
. 2015-01-16 17:24:10.213 Detected network event
. 2015-01-16 17:24:10.213 Enumerating network events for socket 840
. 2015-01-16 17:24:10.213 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:10.213 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:10.213 Received 27 bytes (0)
. 2015-01-16 17:24:10.213 Read 4 bytes (23 pending)
. 2015-01-16 17:24:10.213 Read 23 bytes (0 pending)
< 2015-01-16 17:24:10.213 Type: SSH_FXP_NAME, Size: 23, Number: 16
< 2015-01-16 17:24:10.213 68,00,00,00,10,00,00,00,01,00,00,00,01,2F,00,00,00,01,2F,00,00,00,00,
. 2015-01-16 17:24:10.213 Real path is '/'
. 2015-01-16 17:24:10.353 Listing directory "/".
> 2015-01-16 17:24:10.353 Type: SSH_FXP_OPENDIR, Size: 10, Number: 267
> 2015-01-16 17:24:10.353 0B,00,00,01,0B,00,00,00,01,2F,
. 2015-01-16 17:24:10.353 Sent 14 bytes
. 2015-01-16 17:24:10.353 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:10.353 Looking for network events
. 2015-01-16 17:24:10.353 Timeout waiting for network events
. 2015-01-16 17:24:10.353 Waiting for another 4 bytes
. 2015-01-16 17:24:10.353 Looking for incoming data
. 2015-01-16 17:24:10.353 Looking for network events
. 2015-01-16 17:24:10.400 Detected network event
. 2015-01-16 17:24:10.400 Enumerating network events for socket 840
. 2015-01-16 17:24:10.400 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:10.400 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:10.400 Received 26 bytes (0)
. 2015-01-16 17:24:10.400 Read 4 bytes (22 pending)
. 2015-01-16 17:24:10.400 Read 22 bytes (0 pending)
< 2015-01-16 17:24:10.400 Type: SSH_FXP_HANDLE, Size: 22, Number: 267
< 2015-01-16 17:24:10.400 66,00,00,01,0B,00,00,00,0D,4F,70,65,6E,44,69,72,48,61,6E,64,6C,65,
> 2015-01-16 17:24:10.400 Type: SSH_FXP_READDIR, Size: 22, Number: 524
> 2015-01-16 17:24:10.400 0C,00,00,02,0C,00,00,00,0D,4F,70,65,6E,44,69,72,48,61,6E,64,6C,65,
. 2015-01-16 17:24:10.400 Sent 26 bytes
. 2015-01-16 17:24:10.400 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:10.400 Looking for network events
. 2015-01-16 17:24:10.400 Timeout waiting for network events
. 2015-01-16 17:24:10.400 Waiting for another 4 bytes
. 2015-01-16 17:24:10.400 Looking for incoming data
. 2015-01-16 17:24:10.400 Looking for network events
. 2015-01-16 17:24:11.103 Detected network event
. 2015-01-16 17:24:11.103 Enumerating network events for socket 840
. 2015-01-16 17:24:11.103 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:11.103 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:11.103 Received 681 bytes (0)
. 2015-01-16 17:24:11.103 Read 4 bytes (677 pending)
. 2015-01-16 17:24:11.103 Read 677 bytes (0 pending)
< 2015-01-16 17:24:11.103 Type: SSH_FXP_NAME, Size: 677, Number: 524
< 2015-01-16 17:24:11.103 68,00,00,02,0C,00,00,00,06,00,00,00,08,61,72,63,68,69,76,65,64,00,00,00,3F,
< 2015-01-16 17:24:11.103 64,72,77,2D,72,77,2D,72,77,20,20,20,31,20,20,20,20,20,72,6F,6F,74,20,20,20,
< 2015-01-16 17:24:11.103 20,20,72,6F,6F,74,20,20,20,20,20,20,20,20,20,30,20,44,65,63,20,32,33,20,20,
< 2015-01-16 17:24:11.103 32,30,31,34,20,61,72,63,68,69,76,65,64,00,00,00,0F,00,00,00,00,00,00,00,00,
< 2015-01-16 17:24:11.103 00,00,00,00,00,00,00,00,00,00,41,B6,53,CE,7F,5E,54,99,68,41,00,00,00,05,48,
< 2015-01-16 17:24:11.103 49,54,53,33,00,00,00,3C,64,72,77,2D,72,77,2D,72,77,20,20,20,31,20,20,20,20,
< 2015-01-16 17:24:11.103 20,72,6F,6F,74,20,20,20,20,20,72,6F,6F,74,20,20,20,20,20,20,20,20,20,30,20,
< 2015-01-16 17:24:11.103 44,65,63,20,20,39,20,20,32,30,31,34,20,48,49,54,53,33,00,00,00,0F,00,00,00,
< 2015-01-16 17:24:11.103 00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,41,B6,54,87,0D,AB,54,87,0D,E2,
< 2015-01-16 17:24:11.103 00,00,00,0A,4E,65,77,20,66,6F,6C,64,65,72,00,00,00,41,64,72,77,2D,72,77,2D,
< 2015-01-16 17:24:11.103 72,77,20,20,20,31,20,20,20,20,20,72,6F,6F,74,20,20,20,20,20,72,6F,6F,74,20,
< 2015-01-16 17:24:11.103 20,20,20,20,20,20,20,20,30,20,44,65,63,20,31,31,20,20,32,30,31,34,20,4E,65,
< 2015-01-16 17:24:11.103 77,20,66,6F,6C,64,65,72,00,00,00,0F,00,00,00,00,00,00,00,00,00,00,00,00,00,
< 2015-01-16 17:24:11.103 00,00,00,00,00,41,B6,54,89,E4,21,54,89,E4,24,00,00,00,09,72,65,70,6F,72,74,
< 2015-01-16 17:24:11.103 69,6E,67,00,00,00,40,64,72,77,2D,72,77,2D,72,77,20,20,20,31,20,20,20,20,20,
< 2015-01-16 17:24:11.103 72,6F,6F,74,20,20,20,20,20,72,6F,6F,74,20,20,20,20,20,20,20,20,20,30,20,44,
< 2015-01-16 17:24:11.103 65,63,20,33,30,20,20,32,30,31,34,20,72,65,70,6F,72,74,69,6E,67,00,00,00,0F,
< 2015-01-16 17:24:11.103 00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,41,B6,54,3E,BD,53,54,
< 2015-01-16 17:24:11.103 A3,58,B8,00,00,00,07,73,74,61,67,69,6E,67,00,00,00,3E,64,72,77,2D,72,77,2D,
< 2015-01-16 17:24:11.103 72,77,20,20,20,31,20,20,20,20,20,72,6F,6F,74,20,20,20,20,20,72,6F,6F,74,20,
< 2015-01-16 17:24:11.103 20,20,20,20,20,20,20,20,30,20,4A,75,6C,20,32,32,20,20,32,30,31,34,20,73,74,
< 2015-01-16 17:24:11.103 61,67,69,6E,67,00,00,00,0F,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,
< 2015-01-16 17:24:11.103 00,00,41,B6,53,CE,8D,75,53,CE,7F,65,00,00,00,0A,74,65,6D,70,5F,66,69,6C,65,
< 2015-01-16 17:24:11.103 73,00,00,00,41,64,72,77,2D,72,77,2D,72,77,20,20,20,31,20,20,20,20,20,72,6F,
< 2015-01-16 17:24:11.103 6F,74,20,20,20,20,20,72,6F,6F,74,20,20,20,20,20,20,20,20,20,30,20,4E,6F,76,
< 2015-01-16 17:24:11.103 20,31,38,20,20,32,30,31,34,20,74,65,6D,70,5F,66,69,6C,65,73,00,00,00,0F,00,
< 2015-01-16 17:24:11.103 00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,00,41,B6,54,69,FF,22,54,6B,
< 2015-01-16 17:24:11.103 79,47,
> 2015-01-16 17:24:11.103 Type: SSH_FXP_READDIR, Size: 22, Number: 780
> 2015-01-16 17:24:11.103 0C,00,00,03,0C,00,00,00,0D,4F,70,65,6E,44,69,72,48,61,6E,64,6C,65,
. 2015-01-16 17:24:11.103 Sent 26 bytes
. 2015-01-16 17:24:11.103 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:11.103 Looking for network events
. 2015-01-16 17:24:11.103 Timeout waiting for network events
. 2015-01-16 17:24:11.103 Read file 'archived' from listing
. 2015-01-16 17:24:11.103 Read file 'New folder' from listing
. 2015-01-16 17:24:11.103 Read file 'reporting' from listing
. 2015-01-16 17:24:11.103 Read file 'staging' from listing
. 2015-01-16 17:24:11.103 Read file 'temp_files' from listing
. 2015-01-16 17:24:11.103 Waiting for another 4 bytes
. 2015-01-16 17:24:11.103 Looking for incoming data
. 2015-01-16 17:24:11.103 Looking for network events
. 2015-01-16 17:24:11.150 Detected network event
. 2015-01-16 17:24:11.150 Enumerating network events for socket 840
. 2015-01-16 17:24:11.150 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:11.150 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:11.150 Received 32 bytes (0)
. 2015-01-16 17:24:11.150 Read 4 bytes (28 pending)
. 2015-01-16 17:24:11.150 Read 28 bytes (0 pending)
< 2015-01-16 17:24:11.150 Type: SSH_FXP_STATUS, Size: 28, Number: 780
< 2015-01-16 17:24:11.150 65,00,00,03,0C,00,00,00,01,00,00,00,0B,45,6E,64,20,6F,66,20,66,69,6C,65,00,
< 2015-01-16 17:24:11.150 00,00,00,
< 2015-01-16 17:24:11.150 Status code: 1
> 2015-01-16 17:24:11.150 Type: SSH_FXP_CLOSE, Size: 22, Number: 1028
> 2015-01-16 17:24:11.150 04,00,00,04,04,00,00,00,0D,4F,70,65,6E,44,69,72,48,61,6E,64,6C,65,
. 2015-01-16 17:24:11.150 Sent 26 bytes
. 2015-01-16 17:24:11.150 There are 0 bytes remaining in the send buffer
. 2015-01-16 17:24:11.150 Looking for network events
. 2015-01-16 17:24:11.150 Timeout waiting for network events
. 2015-01-16 17:24:11.150 archived;D;0;2014-12-23T13:04:01.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2015-01-16 17:24:11.150 New folder;D;0;2014-12-11T18:36:20.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2015-01-16 17:24:11.150 reporting;D;0;2014-12-31T02:00:24.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2015-01-16 17:24:11.150 staging;D;0;2014-07-22T15:12:37.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2015-01-16 17:24:11.150 temp_files;D;0;2014-11-18T16:52:23.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2015-01-16 17:24:11.228 Startup conversation with host finished.
. 2015-01-16 17:24:12.698 Session upkeep
. 2015-01-16 17:24:12.714 Looking for network events
. 2015-01-16 17:24:12.714 Detected network event
. 2015-01-16 17:24:12.714 Enumerating network events for socket 840
. 2015-01-16 17:24:12.714 Enumerated 1 network events making 1 cumulative events for socket 840
. 2015-01-16 17:24:12.714 Handling network read event on socket 840 with error 0
. 2015-01-16 17:24:12.714 Received 28 bytes (0)

Reply with quote

martin◆ Site Admin

2015-01-20

Thanks for all the details. Will install the Core FTP server to try to reproduce the problem.

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,454
Location:: Prague, Czechia

2015-01-21

The problem arises when Diffie-Hellman group key exchange (kex) is used. It is supported by WinSCP since 5.2.5
https://winscp.net/tracker/1067

CoreFTP SFTP server has likely some bug in the kex implementation.
You can workaround that by decreasing preference of the kex.
See https://winscp.net/eng/docs/ui_login_kex

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-21 17:32

Ok - working in manual mode using WinSCP version 5.5.6 on Server-B (was not working before):
Results with the key-exchange settings:

Default (listed order below) - failed. This is what we were using in all cases prior to now

Diffie-Hellman group exchange
Diffie-Hellman group 14
Diffie-Hellman group 1
RSA-based key exchange
-- warn below here --

RSA-First, DH 1 elevated - success

RSA-based key exchange
Diffie-Hellman group 1
Diffie-Hellman group exchange
Diffie-Hellman group 14

DH1 first, default otherwise - success

Diffie-Hellman group 1
Diffie-Hellman group exchange
Diffie-Hellman group 14
RSA-based key exchange

DH14 first, DH1 second, group exchange demoted - success

Diffie-Hellman group 1
Diffie-Hellman group 14
Diffie-Hellman group exchange
RSA-based key exchange

So we have a solution for fixing the key exchange. Now, we're having an issue with the job not picking up the configuration change. (job is still getting error). My understanding is that with the same username/URL configuration, the script should pick up the settings from the GUI configuration per https://winscp.net/eng/docs/scripting#hostkey

I checked that the protocol, host name, port number, and user name are identical between the GUI and the open statement on the script. Are there other parameters/settings that must match.

Would you suggest exporting the GUI settings and using the /INI= flag in calling the script?

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-21 18:02

Made a mistake in my previous post. The last configuration section should be:

DH14 first, DH1 second, group exchange demoted - success

Diffie-Hellman group 14
Diffie-Hellman group 1
Diffie-Hellman group exchange
RSA-based key exchange

Reply with quote

JJAnderson
Joined:: 2015-01-09
Posts:: 11
Location:: USA

2015-01-22 20:05

Exporting the config from the WinSCP GUI to an .ini file and passing the file in as /ini=file.ini parameter to winscp.com got the automated script up and running.

Tried this first, but it didn't work (single line) same auth error message. Also tried with double quotes around "KEX...,WARN"

winscp.com /rawconfig=KEX=dh-group14-sha1,dh-group1-sha1,dh-gex-sha1,rsa,WARN /script=commands.txt /log=output.log /xmllog=output.xml" /xmlgroups

I copied the value of /rawconfig from the exported INI file. As that's the only option change really needed (and the only option changed in the GUI), it would be more of an ideal situation from the standpoint of keeping the job settings isolated, but the INI fix will work for now, and accomplishes the same thing if kept out of the winscp.com home directory.

Thank you again for your diligence and support in helping solve this issue.

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,454
Location:: Prague, Czechia

2015-01-23

@JJAnderson: The syntax is:

/rawsettings KEX=dh-group14-sha1,dh-group1-sha1,dh-gex-sha1,rsa,WARN

(it's /rawsettings<space>, not /rawconfig=)
But anyway, this syntax is for GUI sessions opened from command-line. Not for scripting. For scripting use -rawsettings switch of open command:

open sftp://... -privatekey=... -hostkey="..." -rawsettings KEX=dh-group14-sha1,dh-group1-sha1,dh-gex-sha1,rsa,WARN

See https://winscp.net/eng/docs/scriptcommand_open

If there's anything in the documentation that you find confusing, and made you make the mistake, please let us know! (or even improve it yourself, it's wiki)

WinSCP GUI can generate a code template with all the necessary settings for you:
https://winscp.net/eng/docs/ui_generateurl#script

Reply with quote

santiazpi Donor
Joined:: 2015-11-11
Posts:: 1

PermitRootLogin

2015-11-11 23:14

In case this is valuable for someone:

My issue was that I was trying to SFTP as root and the SSH server had been setup (/etc/ssh/sshd_config) with:

PermitRootLogin no

Cheers

Reply with quote

Key Authentication Failure - public-key signature refused