martin wrote:

In the log I see that fallback to SCP is enabled, but it is not used, regular SFTP session is started. I'm confused.

Yes, you are right. I am not sure why it did not work the other day, but it works correctly now! Thanks for looking into my problem.

Doug

In the log I see that fallback to SCP is enabled, but it is not used, regular SFTP session is started. I'm confused.

We had to start a job on the server to initiate the SSH.
Below is the log file - SSH working!
Thanks for the information.

2009-06-22 12:00:13.236 WinSCP Version 4.1.9 (Build 416) (OS 5.1.2600 Service Pack 3)
. 2009-06-22 12:00:13.236 Login time: Monday, June 22, 2009 12:00:13 PM
. 2009-06-22 12:00:13.236 --------------------------------------------------------------------------
. 2009-06-22 12:00:13.236 Session name: 192.168.1.6
. 2009-06-22 12:00:13.236 Host name: 192.168.1.6 (Port: 22)
. 2009-06-22 12:00:13.236 User name: (Password: No, Key file: No)
. 2009-06-22 12:00:13.236 Tunnel: No
. 2009-06-22 12:00:13.236 Transfer Protocol: SFTP (SCP)
. 2009-06-22 12:00:13.236 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-06-22 12:00:13.236 Proxy: none
. 2009-06-22 12:00:13.236 SSH protocol version: 2; Compression: No
. 2009-06-22 12:00:13.236 Bypass authentication: No
. 2009-06-22 12:00:13.236 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-06-22 12:00:13.236 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-06-22 12:00:13.236 SSH Bugs: -,-,-,-,-,-,-,-
. 2009-06-22 12:00:13.236 SFTP Bugs: -,-
. 2009-06-22 12:00:13.236 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-06-22 12:00:13.236 Shell: default, EOL: 1
. 2009-06-22 12:00:13.236 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-06-22 12:00:13.236 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-06-22 12:00:13.236 Local directory: C:\Documents and Settings\Doug\My Documents, Remote directory: /home/sftpuser, Update: No, Cache: Yes
. 2009-06-22 12:00:13.236 Cache directory changes: Yes, Permanent: Yes
. 2009-06-22 12:00:13.236 DST mode: 0
. 2009-06-22 12:00:13.236 --------------------------------------------------------------------------
. 2009-06-22 12:00:13.299 Looking up host "192.168.1.6"
. 2009-06-22 12:00:13.314 Connecting to 192.168.1.6 port 22
. 2009-06-22 12:00:14.346 Server version: SSH-1.99-OpenSSH_3.5p1
. 2009-06-22 12:00:14.346 We claim version: SSH-2.0-WinSCP_release_4.1.9
. 2009-06-22 12:00:14.346 SSPI: acquired credentials for: Doug@DOUGPRESTON
. 2009-06-22 12:00:14.346 Cannot convert IP address to SPN: DNS is not trusted
. 2009-06-22 12:00:14.346 GSSKEX disabled: The operation completed successfully.

. 2009-06-22 12:00:14.346 Using SSH protocol version 2
. 2009-06-22 12:00:14.392 Doing Diffie-Hellman group exchange
. 2009-06-22 12:00:15.205 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-06-22 12:00:29.611 Host key fingerprint is:
. 2009-06-22 12:00:29.611 ssh-rsa 1024 36:13:df:83:e3:43:c1:01:f9:00:d7:60:bd:cb:66:de
. 2009-06-22 12:00:29.611 Initialised AES-256 CBC client->server encryption
. 2009-06-22 12:00:29.611 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-06-22 12:00:29.611 Initialised AES-256 CBC server->client encryption
. 2009-06-22 12:00:29.611 Initialised HMAC-SHA1 server->client MAC algorithm
. 2009-06-22 12:00:29.611 Prompt (1, SSH login name, , login as: )
. 2009-06-22 12:00:36.642 Keyboard-interactive authentication refused
. 2009-06-22 12:00:36.642 Prompt (6, SSH password, , &Password: )
. 2009-06-22 12:00:39.158 Sent password
. 2009-06-22 12:00:39.299 Access granted
. 2009-06-22 12:00:39.314 Opened channel for session
. 2009-06-22 12:00:40.392 Started a shell/command
. 2009-06-22 12:00:40.392 --------------------------------------------------------------------------
. 2009-06-22 12:00:40.392 Using SFTP protocol.
. 2009-06-22 12:00:40.392 Doing startup conversation with host.
> 2009-06-22 12:00:40.408 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2009-06-22 12:00:42.392 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2009-06-22 12:00:42.392 SFTP version 3 negotiated.
. 2009-06-22 12:00:42.392 We believe the server has signed timestamps bug
. 2009-06-22 12:00:42.392 We will use UTF-8 strings for status messages only
. 2009-06-22 12:00:42.392 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2009-06-22 12:00:42.392 Changing directory to "/home/sftpuser".
. 2009-06-22 12:00:42.392 Getting real path for '/home/sftpuser'
> 2009-06-22 12:00:42.392 Type: SSH_FXP_REALPATH, Size: 23, Number: 9744
< 2009-06-22 12:00:42.408 Type: SSH_FXP_NAME, Size: 49, Number: 9744
. 2009-06-22 12:00:42.408 Real path is '/home/sftpuser'
. 2009-06-22 12:00:42.408 Trying to open directory "/home/sftpuser".
> 2009-06-22 12:00:42.408 Type: SSH_FXP_LSTAT, Size: 23, Number: 9991
< 2009-06-22 12:00:42.424 Type: SSH_FXP_ATTRS, Size: 37, Number: 9991
. 2009-06-22 12:00:42.424 Getting current directory name.
. 2009-06-22 12:00:42.424 Listing directory "/home/sftpuser".
> 2009-06-22 12:00:42.424 Type: SSH_FXP_OPENDIR, Size: 23, Number: 10251
< 2009-06-22 12:00:42.424 Type: SSH_FXP_HANDLE, Size: 13, Number: 10251
> 2009-06-22 12:00:42.424 Type: SSH_FXP_READDIR, Size: 13, Number: 10508
< 2009-06-22 12:00:42.564 Type: SSH_FXP_NAME, Size: 1019, Number: 10508
> 2009-06-22 12:00:42.564 Type: SSH_FXP_READDIR, Size: 13, Number: 10764
< 2009-06-22 12:00:42.564 Type: SSH_FXP_STATUS, Size: 28, Number: 10764
< 2009-06-22 12:00:42.564 Status/error code: 1
> 2009-06-22 12:00:42.564 Type: SSH_FXP_CLOSE, Size: 13, Number: 11012
. 2009-06-22 12:00:42.564 Startup conversation with host finished.
. 2009-06-22 12:00:47.736 Cached directory change via ".." to "/home".
. 2009-06-22 12:00:47.736 Getting current directory name.
. 2009-06-22 12:00:47.736 Listing directory "/home".
> 2009-06-22 12:00:47.736 Type: SSH_FXP_OPENDIR, Size: 14, Number: 11275
< 2009-06-22 12:00:47.736 Type: SSH_FXP_STATUS, Size: 24, Number: 11012
. 2009-06-22 12:00:47.736 Discarding reserved response
< 2009-06-22 12:00:47.752 Type: SSH_FXP_HANDLE, Size: 13, Number: 11275
> 2009-06-22 12:00:47.752 Type: SSH_FXP_READDIR, Size: 13, Number: 11532
< 2009-06-22 12:00:47.830 Type: SSH_FXP_NAME, Size: 647, Number: 11532
> 2009-06-22 12:00:47.830 Type: SSH_FXP_READDIR, Size: 13, Number: 11788
< 2009-06-22 12:00:47.830 Type: SSH_FXP_STATUS, Size: 28, Number: 11788
< 2009-06-22 12:00:47.830 Status/error code: 1
> 2009-06-22 12:00:47.830 Type: SSH_FXP_CLOSE, Size: 13, Number: 12036
. 2009-06-22 12:00:48.642 Cached directory change via ".." to "/".
. 2009-06-22 12:00:48.642 Getting current directory name.
. 2009-06-22 12:00:48.642 Listing directory "/".
> 2009-06-22 12:00:48.642 Type: SSH_FXP_OPENDIR, Size: 10, Number: 12299
< 2009-06-22 12:00:48.642 Type: SSH_FXP_STATUS, Size: 24, Number: 12036
. 2009-06-22 12:00:48.642 Discarding reserved response
< 2009-06-22 12:00:48.658 Type: SSH_FXP_HANDLE, Size: 13, Number: 12299
> 2009-06-22 12:00:48.658 Type: SSH_FXP_READDIR, Size: 13, Number: 12556
< 2009-06-22 12:00:49.424 Type: SSH_FXP_NAME, Size: 4990, Number: 12556
> 2009-06-22 12:00:49.424 Type: SSH_FXP_READDIR, Size: 13, Number: 12812
. 2009-06-22 12:00:49.424 Reading symlink "bin".
> 2009-06-22 12:00:49.424 Type: SSH_FXP_READLINK, Size: 13, Number: 13075
> 2009-06-22 12:00:49.424 Type: SSH_FXP_STAT, Size: 13, Number: 13329
< 2009-06-22 12:00:49.439 Type: SSH_FXP_STATUS, Size: 28, Number: 12812
. 2009-06-22 12:00:49.439 Storing reserved response
< 2009-06-22 12:00:49.627 Type: SSH_FXP_NAME, Size: 37, Number: 13075
< 2009-06-22 12:00:49.627 Type: SSH_FXP_ATTRS, Size: 37, Number: 13329
. 2009-06-22 12:00:49.627 Reading symlink "lib".
> 2009-06-22 12:00:49.627 Type: SSH_FXP_READLINK, Size: 13, Number: 13587
> 2009-06-22 12:00:49.627 Type: SSH_FXP_STAT, Size: 13, Number: 13841
< 2009-06-22 12:00:49.642 Type: SSH_FXP_NAME, Size: 37, Number: 13587
< 2009-06-22 12:00:49.830 Type: SSH_FXP_ATTRS, Size: 37, Number: 13841
. 2009-06-22 12:00:49.830 Reading symlink "AS400JT".
> 2009-06-22 12:00:49.830 Type: SSH_FXP_READLINK, Size: 17, Number: 14099
> 2009-06-22 12:00:49.830 Type: SSH_FXP_STAT, Size: 17, Number: 14353
< 2009-06-22 12:00:49.846 Type: SSH_FXP_NAME, Size: 73, Number: 14099
< 2009-06-22 12:00:50.033 Type: SSH_FXP_ATTRS, Size: 37, Number: 14353
< 2009-06-22 12:00:50.033 Status/error code: 1
> 2009-06-22 12:00:50.033 Type: SSH_FXP_CLOSE, Size: 13, Number: 14596
. 2009-06-22 12:00:55.033 Changing directory to "Roxanne".
. 2009-06-22 12:00:55.033 Getting real path for '/Roxanne'
> 2009-06-22 12:00:55.033 Type: SSH_FXP_REALPATH, Size: 17, Number: 14864
< 2009-06-22 12:00:55.033 Type: SSH_FXP_STATUS, Size: 24, Number: 14596
. 2009-06-22 12:00:55.033 Discarding reserved response
< 2009-06-22 12:00:55.049 Type: SSH_FXP_NAME, Size: 37, Number: 14864
. 2009-06-22 12:00:55.049 Real path is '/Roxanne'
. 2009-06-22 12:00:55.049 Trying to open directory "/Roxanne".
> 2009-06-22 12:00:55.049 Type: SSH_FXP_LSTAT, Size: 17, Number: 15111
< 2009-06-22 12:00:55.049 Type: SSH_FXP_ATTRS, Size: 37, Number: 15111
. 2009-06-22 12:00:55.049 Getting current directory name.
. 2009-06-22 12:00:55.049 Listing directory "/Roxanne".
> 2009-06-22 12:00:55.049 Type: SSH_FXP_OPENDIR, Size: 17, Number: 15371
< 2009-06-22 12:00:55.111 Type: SSH_FXP_HANDLE, Size: 13, Number: 15371
> 2009-06-22 12:00:55.111 Type: SSH_FXP_READDIR, Size: 13, Number: 15628
< 2009-06-22 12:00:55.939 Type: SSH_FXP_NAME, Size: 2591, Number: 15628
> 2009-06-22 12:00:55.939 Type: SSH_FXP_READDIR, Size: 13, Number: 15884
< 2009-06-22 12:00:55.955 Type: SSH_FXP_STATUS, Size: 28, Number: 15884
< 2009-06-22 12:00:55.955 Status/error code: 1
> 2009-06-22 12:00:55.955 Type: SSH_FXP_CLOSE, Size: 13, Number: 16132
. 2009-06-22 12:01:06.408 File: "/Roxanne/DOBBELAERE.pdf"
. 2009-06-22 12:01:06.408 Copying "/Roxanne/DOBBELAERE.pdf" to local directory started.
. 2009-06-22 12:01:06.408 Binary transfer mode selected.
. 2009-06-22 12:01:06.408 Opening remote file.
> 2009-06-22 12:01:06.408 Type: SSH_FXP_OPEN, Size: 40, Number: 16387
< 2009-06-22 12:01:06.408 Type: SSH_FXP_STATUS, Size: 24, Number: 16132
. 2009-06-22 12:01:06.408 Discarding reserved response
< 2009-06-22 12:01:06.424 Type: SSH_FXP_HANDLE, Size: 13, Number: 16387
> 2009-06-22 12:01:06.424 Type: SSH_FXP_FSTAT, Size: 13, Number: 16648
> 2009-06-22 12:01:06.424 Type: SSH_FXP_READ, Size: 25, Number: 16901
< 2009-06-22 12:01:06.424 Type: SSH_FXP_ATTRS, Size: 37, Number: 16648
. 2009-06-22 12:01:06.424 Storing reserved response
< 2009-06-22 12:01:06.471 Status/error code: 1
. 2009-06-22 12:01:06.471 3 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2009-06-22 12:01:06.471 Type: SSH_FXP_CLOSE, Size: 13, Number: 17412
. 2009-06-22 12:36:25.846 Closing connection.
. 2009-06-22 12:36:25.846 Sending special code: 12
. 2009-06-22 12:36:25.846 Sent EOF message

I found out 2 things. The SFTP connection via the GUI interface was falling back to SCP. When I unchecked the fallback box it would not connect at all.

Today I cant connect at all except FTP. The server is running but not responding to windows requests.

Thanks, Doug

Can you post a log file from successful session? You can also try to use "open your_session_name".

I am using winscp: 4.1.9 on Windows XP.
I created a session which works fine, I receive a error command 'groups' failed with return code 1 and error message -bsh: groups: not found. I press OK.
Then the session opens.
I can transfer files using SFTP.
The SFTP server is an AS400 v 5.3.
The winscp.com version will not connect. I created a script file and execute by: winscp.com /script:=winscpscr.txt /log=winscplog.txt
I received the error: connection has been unexpectedly closed. Server sent command exit status 1.
my script file:
open sftp://sftpusr2:sftpuser@192.168.1.6:22
option transfer binary
option confirm off
lcd c:\dictfldr\
cd /home/sftpuser
put -delete *.*
exit

the log file:
WinSCP Version 4.1.9 (Build 416) (OS 5.1.2600 Service Pack 3)
Login time: Monday, June 15, 2009 2:48:02 PM
--------------------------------------------------------------------------
Session name: sftpusr2@192.168.1.6
Host name: 192.168.1.6 (Port: 22)
User name: sftpusr2 (Password: Yes, Key file: No)
Tunnel: No
Transfer Protocol: SFTP
Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
Proxy: none
SSH protocol version: 2; Compression: No
Bypass authentication: No
Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
SSH Bugs: -,-,-,-,-,-,-,-
SFTP Bugs: -,-
Return code variable: Autodetect; Lookup user groups: Yes
Shell: default, EOL: 0
Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
Local directory: default, Remote directory: home, Update: No, Cache: Yes
Cache directory changes: Yes, Permanent: Yes
DST mode: 1
--------------------------------------------------------------------------
Looking up host "192.168.1.6"
Connecting to 192.168.1.6 port 22
Server version: SSH-1.5-OpenSSH_3.5p1
We claim version: SSH-1.5-WinSCP_release_4.1.9
Using SSH protocol version 1
Received public keys
Host key fingerprint is:
2048 e8:c4:5e:75:8f:cc:69:02:40:b3:94:e1:b9:db:4b:3d
Encrypted session key
AES not supported in SSH-1, skipping
Using Blowfish encryption
Trying to enable encryption...
Initialised Blowfish-128 CBC encryption
Installing CRC compensation attack detector
Successfully started encryption
Sent username "sftpusr2"
Prompt (6, SSH password, , &Password: )
Using stored password.
Sending password with camouflage packets
Sent password
Authentication successful
Started session
--------------------------------------------------------------------------
Using SFTP protocol.
Doing startup conversation with host.
Type: SSH_FXP_INIT, Size: 5, Number: -1
! bsh: sftp-server: not found
Server sent command exit status 1
Disconnected