Strange error while connecting to sftp server

Question

I'm trying to connect to an sftp server (openssh on opensuse) but I'm getting a very strange error _after_ ssh auth.
I'm using edtFTPnetPRO for .NET 2.0+ (version 6.1.0.20)

Does anybody have any suggestions? Here's my trace-output (the lines of interest are marked with *):

INFO [LicenseProperties] Licence expiry date: 2958465
INFO [LicenseProperties] Production license
DEBUG [SSHFTPClient] Setting up fallback kbi prompt based on supplied password
DEBUG [HostNameResolver] xxx.xxx.xxx.xxx resolved to xxx.xxx.xxx.xxx
DEBUG [SSHFTPClient] Connecting directly to SFTP server xxx.xxx.xxx.xxx:22
DEBUG [SSHFTPClient] Connected successfully to SFTP server xxx.xxx.xxx.xxx:22
DEBUG [SSHConnection] Beginning protocol negotiation
DEBUG [PlainSocket] RepeatCallback received 21 bytes
DEBUG [ProtocolNegotiationHandler] offset=0,length=21
DEBUG [ProtocolNegotiationHandler] pos=20
INFO [ProtocolNegotiationHandler] Server version = 'SSH-2.0-OpenSSH_5.1'
DEBUG [SSHUtil] Major string = '2'
DEBUG [SSHUtil] Minor string = '0'
DEBUG [SSHUtil] Version 2.0
DEBUG [SSHUtil] Protocol compatible
DEBUG [SSHConnection] Server version=SSH-2.0-OpenSSH_5.1
DEBUG [SSH2Connection] Timeout=5000
DEBUG [SSHConnection] Sending client version=SSH-2.0-edtFTPnet/PRO-6.1.0.20
DEBUG [SSH2Connection] Starting key exchange
DEBUG [AbstractKeyExchanger] Sending SSH_MSG_KEXINIT
DEBUG [AbstractKeyExchanger] hostkey algorithms=ssh-dss,ssh-rsa
DEBUG [AbstractKeyExchanger] ciphers=aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc
DEBUG [AbstractKeyExchanger] ciphers=aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc
DEBUG [AbstractKeyExchanger] MACs=hmac-sha1,hmac-md5
DEBUG [AbstractKeyExchanger] MACs=hmac-sha1,hmac-md5
DEBUG [AbstractKeyExchanger] compression algorithms=none,zlib
DEBUG [PlainSocket] RepeatCallback received 784 bytes
DEBUG [AbstractKeyExchanger] compression algorithms=none,zlib
DEBUG [AbstractKeyExchanger] Sent SSH_MSG_KEXINIT
DEBUG [ClientKeyExchanger] Reading SSH_MSG_KEXINIT reply
DEBUG [AbstractKeyExchanger] Processing SSH_MSG_KEXINIT reply
DEBUG [AbstractKeyExchanger] Kex alg=diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
DEBUG [AbstractKeyExchanger] Hostkey alg=ssh-rsa,ssh-dss
DEBUG [ClientKeyExchanger] Cipher CS=aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [ClientKeyExchanger] Cipher C->S= AES128
DEBUG [ClientKeyExchanger] Cipher SC=aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [ClientKeyExchanger] Cipher S->C= AES128
DEBUG [ClientKeyExchanger] MAC CS=hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG [ClientKeyExchanger] MAC C->S= HMACSHA1
DEBUG [ClientKeyExchanger] MAC SC=hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG [ClientKeyExchanger] MAC S->C= HMACSHA1
DEBUG [ClientKeyExchanger] Comp CS=none,zlib@openssh.com
DEBUG [ClientKeyExchanger] Comp C->S=None
DEBUG [ClientKeyExchanger] Comp SC=none,zlib@openssh.com
DEBUG [ClientKeyExchanger] Comp S->C=None
INFO [ClientKeyExchanger] first_kex_packet_follows=False
DEBUG [AbstractKeyExchanger] Processed SSH_MSG_KEXINIT reply
DEBUG [ClientKeyExchanger] Sending SSH_MSG_KEXDH_INIT
DEBUG [ClientKeyExchanger] Sent SSH_MSG_KEXDH_INIT
DEBUG [ClientKeyExchanger] Reading SSH_MSG_KEXDH_INIT reply
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 656 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [ClientKeyExchanger] Processing SSH_MSG_KEXDH_INIT reply
DEBUG [ClientKeyExchanger] Processed SSH_MSG_KEXDH_INIT reply successfully
DEBUG [ClientKeyExchanger] Sending SSH_MSG_NEWKEYS
DEBUG [ClientKeyExchanger] Sent SSH_MSG_NEWKEYS
DEBUG [ClientKeyExchanger] Established ciphers
DEBUG [ClientKeyExchanger] Established MACs
DEBUG [ClientKeyExchanger] Reading SSH_MSG_NEWKEYS reply
DEBUG [AbstractKeyExchanger] Processing SSH_MSG_NEWKEYS reply
DEBUG [AbstractKeyExchanger] Processed SSH_MSG_NEWKEYS reply
DEBUG [SSH2Connection] Key exchange complete
DEBUG [SSH2Connection] Sent SSH_MSG_SERVICE_REQUEST 'ssh-userauth'
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 52 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [SSH2Connection] Starting user authentication
DEBUG [SSH2Connection] Password authentication
DEBUG [SSH2Connection] Sent SSH_MSG_USERAUTH_REQUEST
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 68 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [SSH2Connection] ProcessAuthenticationResponse: SSH_MSG_USERAUTH_FAILURE
ERROR [SSH2Connection] Auth failure. Try: publickey,keyboard-interactive
DEBUG [SSH2Connection] Trying keyboard-interactive authentication
DEBUG [SSH2Connection] Starting user authentication
DEBUG [SSH2Connection] Keyboard interactive authentication
DEBUG [SSH2Connection] Sent SSH_MSG_USERAUTH_REQUEST
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 68 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [SSH2Connection] ProcessAuthenticationResponse: SSH_MSG_USERAUTH_INFO_REQUEST
DEBUG [SSH2Connection] Prompt count = 1
DEBUG [SSH2Connection] Prompt: Password:
DEBUG [SSH2Connection] Sent SSH_MSG_USERAUTH_INFO_RESPONSE
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 52 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [SSH2Connection] ProcessAuthenticationResponse: SSH_MSG_USERAUTH_INFO_REQUEST
DEBUG [SSH2Connection] Prompt count = 0
DEBUG [SSH2Connection] Sent SSH_MSG_USERAUTH_INFO_RESPONSE
DEBUG [SSH2Connection] Waiting for packet
DEBUG [PlainSocket] RepeatCallback received 36 bytes
DEBUG [SSH2Connection] Packet arrived
DEBUG [SSH2Connection] ProcessAuthenticationResponse: SSH_MSG_USERAUTH_SUCCESS
DEBUG [SSH2Connection] User authentication successful
DEBUG [SSH2Connection] Sent SSH_MSG_CHANNEL_OPEN
INFO [SSHFTPClient] Waiting for SSH channel to be opened
DEBUG [PlainSocket] RepeatCallback received 52 bytes
DEBUG [SSH2Connection] ProcessPacket pt=SSH_MSG_CHANNEL_OPEN_CONFIRMATION
DEBUG [SSH2Channel] ProcessPacket: status= 2 pt=SSH_MSG_CHANNEL_OPEN_CONFIRM

Answer 1

Are you sure SFTP is enabled?

Your error message is "Opening SFTP subsystem failed" - it may be disabled or the path to the sftp binary in the config file is incorrect.

Answer 2

Yes, SFTP is running on the server - but it seems to be a strange config... While Filezilla doesn't care and always connects, WinSCP behaves slightly different:

When using SCP as Fileprotocol (or even "SFTP with SCP as fallback"), it does not connect

[ img ]

When using SFTP (explictly and only!), I can connect with WinSCP.

I guess, there is no real shell (bash or something) available, but I do not understand how this works... Does edtFTPnetPRO support this case? If so, how?

Answer 3

Could you try logzilla, and post the log file of what happens when you log in? that should help figure out the problem.

http://www.enterprisedt.com/tools/LogZilla.zip

Also, take a look at the server logs - they will probably tell you what the error is.

Is it the same user every time?

Answer 4

I neither know how to use nor how to build logzilla - could you provide me some asstistance with that? (I'm using VS.net 2008 - when I open the .sln files, I have to convert the project and then get a lot of compiler errors... No to forget: I'm not so smart with C++, but with C#)

Anyway: 1) I meanwhile was able to talk to a server admin and he confirmed, that there is no shell available. When opening an ssh connection, I'll have to use sftp protocoll (and nothing else) - Do you know, wether this is possible with edtFTPnetPRO?
2) According to the admin, the logs show _no_ error on the server
3) Yes, I use the same user for all tries and all tools...

Answer 5

Download http://www.enterprisedt.com/tools/LogZilla.zip
Unzip
Run Filezilla.exe

There's no building required.

The WinSCP log would be very useful too.

edtFTPnet/PRO doesn't require a shell on the server. Just need to find out why the server isn't starting the SFTP subsystem.

If you are able to create a test account we can use to connect to let us know. That should make it easy to resolve. Email those details of course.

Answer 6

I've created 3 logfiles:
- Filezilla (successful connection)
- WinSCP (SFTP Only, successfull connection)
- WinSCP (SFTP with SCP fallback, no connection)
They can be downloaded at http://sharpcoder.freehosting.net/Logs.zip

I'm not sure, wether I can manage to get a testing account on the server - if it's possible, where should I send the credentials? Via a private message? Or to an email adress (which)?

Answer 7

Sure, only if it's possible - email support or send a pm.

Re the log files:

You do not have permission to access http://sharpcoder.freehosting.net/Logs.zip

Data files must be stored on the same site they are linked from.

Answer 8

Sorry - I forgot the %$%! security settings... Just go to http://sharpcoder.freehosting.net and click on the link...

Answer 9

Doesn't work for me, please email to support at enterprisedt dot com

Answer 10

Ok, thanks for the logs. I can see a solution - will build you a new DLL hopefully tomorrow that I think will work.