Unable to connect to server SFTP
I am trying to connect to a server on a VPN connection with the following code just to see if it will open the connection (using the real hostname, username, password, hostkey, etc on my end):
Try
Dim sessionOptions As New SessionOptions
With sessionOptions
.Protocol = Protocol.Sftp
.HostName = "serverName"
.UserName = "userName"
.Password = "password"
.SshHostKey = "ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx"
End With
Using session As Session = New Session
session.Open(sessionOptions)
End Using
Catch ex As Exception
Console.WriteLine("Error: {0},", ex)
End Try
I get the following log file:
[2012-03-18 16:24:29Z] [0009] Executing Assembly: WinSCP, Version=1.0.0.235, Culture=neutral, PublicKeyToken=b5f19f5762436b89; Path: F:/Windows Dev/GlobalSync/GlobalSync/bin/Debug/WinSCP.DLL; Location: F:\Windows Dev\GlobalSync\GlobalSync\bin\Debug\WinSCP.dll; Product: 5.0.6.0
[2012-03-18 16:24:29Z] [0009] Entry Assembly: GlobalSync, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
[2012-03-18 16:24:29Z] [0009] Operating system: Microsoft Windows NT 6.0.6002 Service Pack 2
[2012-03-18 16:24:29Z] [0009] User: user@user-PC@user-PC; Interactive: True
[2012-03-18 16:24:29Z] [0009] Runtime: 4.0.30319.261
[2012-03-18 16:24:29Z] [0009] Console encoding: Input: Western European (Windows) (1252); Output: Western European (Windows) (1252)
[2012-03-18 16:24:29Z] [0009] Session.Open entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess..ctor entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.GetExecutablePath entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.GetExecutablePath leaving
[2012-03-18 16:24:29Z] [0009] EXE executable path resolved to C:\Program Files (x86)\WinSCP\winscp.exe
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.CheckVersion entering
[2012-03-18 16:24:29Z] [0009] Version of C:\Program Files (x86)\WinSCP\winscp.exe is 5.0.6.2074, product WinSCP version is 5.0.6.0
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.CheckVersion leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess..ctor leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.Start entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeConsole entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeConsole leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeChild entering
[2012-03-18 16:24:29Z] [0009] Starting "C:\Program Files (x86)\WinSCP\winscp.exe" /xmllog="C:\Users\user\AppData\Local\Temp\tmp888A.tmp" /xmlgroups /nointeractiveinput /dotnet=506 /ini=nul /console /consoleinstance=_8752_569
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeChild leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.Start leaving
[2012-03-18 16:24:29Z] [0009] Command: [option batch on]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvents entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [0009] Command: [option confirm off]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenArguments entering
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenSwitches entering
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenSwitches leaving
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenArguments leaving
[2012-03-18 16:24:29Z] [0009] Command: [open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInitEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInitEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> option batch on]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [batch on ]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> option confirm off]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [confirm off ]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [Searching for host...]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:30Z] [0009] Output: [winscp> option batch on]
[2012-03-18 16:24:30Z] [0009] Output: [batch on ]
[2012-03-18 16:24:30Z] [0009] Output: [winscp> option confirm off]
[2012-03-18 16:24:30Z] [0009] Output: [confirm off ]
[2012-03-18 16:24:30Z] [0009] Output: [winscp> open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:30Z] [0009] Output: [Searching for host...]
[2012-03-18 16:24:30Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:30Z] [000a] Scheduling output: [Connecting to host...]
[2012-03-18 16:24:30Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:30Z] [0009] Output: [Connecting to host...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authenticating...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Authenticating...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authenticating with pre-entered password.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Authenticating with pre-entered password.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Connection has been unexpectedly closed. Server sent command exit status 0.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Connection has been unexpectedly closed. Server sent command exit status 0.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authentication log (see session log for details):]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Using username "user".]
[2012-03-18 16:24:31Z] [0009] Output: [Authentication log (see session log for details):]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [
]
[2012-03-18 16:24:31Z] [0009] Output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authentication failed.]
[2012-03-18 16:24:31Z] [0009] Output: [
]
[2012-03-18 16:24:31Z] [0009] Output: [Authentication failed.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---
[2012-03-18 16:24:31Z] [0009] Failed: [WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---]
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---
at WinSCP.SessionLogReader.Read(LogReadFlags flags)
at WinSCP.ElementLogReader.Read(LogReadFlags flags)
at WinSCP.CustomLogReader.TryWaitForNonEmptyElement(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForNonEmptyElement(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForNonEmptyElementAndCreateLogReader(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForGroupAndCreateLogReader()
at WinSCP.Session.Open(SessionOptions sessionOptions)
[2012-03-18 16:24:31Z] [0009] Session.Cleanup entering
[2012-03-18 16:24:31Z] [0009] Command: [exit]
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:31Z] [000a] Scheduling output: [winscp> exit]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.Close entering
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Close leaving
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Dispose entering
[2012-03-18 16:24:32Z] [000a] ExeSessionProcess.ProcessEvents leaving
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Dispose leaving
[2012-03-18 16:24:32Z] [0009] Session.Cleanup leaving
[2012-03-18 16:24:32Z] [0009] Session.Open leaving
[2012-03-18 16:24:32Z] [0009] Session.Dispose entering
[2012-03-18 16:24:32Z] [0009] Session.Cleanup entering
[2012-03-18 16:24:32Z] [0009] Session.Cleanup leaving
I can connect to the server just fine through the GUI, but I do get a security banner and another prompt afterwards I have to click ok for. I tried the command line option to see if it was something I was doing with the .NET assembly. Script file for command line test.txt:
option batch on
option confirm off
open sftp://user:password@server.com
close
exit
winscp.exe /console /script=test.txt
This generated the following log file:
. 2012-03-18 16:16:22.818 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.818 WinSCP Version 5.0.6 (Build 2074) (OS 6.0.6002 Service Pack 2)
. 2012-03-18 16:16:22.818 Configuration: HKEY_CURRENT_USER\Software\Martin Prikryl\WinSCP 2\
. 2012-03-18 16:16:22.818 Local account: user-PC\user
. 2012-03-18 16:16:22.818 Login time: Sunday, March 18, 2012 4:16:22 PM
. 2012-03-18 16:16:22.818 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.818 Session name: user@server.com (Modified stored session)
. 2012-03-18 16:16:22.818 Host name: server.com (Port: 22)
. 2012-03-18 16:16:22.819 User name: user (Password: Yes, Key file: No)
. 2012-03-18 16:16:22.819 Tunnel: No
. 2012-03-18 16:16:22.819 Transfer Protocol: SFTP
. 2012-03-18 16:16:22.819 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2012-03-18 16:16:22.819 Proxy: none
. 2012-03-18 16:16:22.819 SSH protocol version: 2; Compression: No
. 2012-03-18 16:16:22.819 Bypass authentication: No
. 2012-03-18 16:16:22.819 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2012-03-18 16:16:22.819 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2012-03-18 16:16:22.819 SSH Bugs: -,-,-,-,-,-,-,-,-,-
. 2012-03-18 16:16:22.819 SFTP Bugs: -,-
. 2012-03-18 16:16:22.819 Return code variable: Autodetect; Lookup user groups: -
. 2012-03-18 16:16:22.819 Shell: default
. 2012-03-18 16:16:22.819 EOL: 0, UTF: 2
. 2012-03-18 16:16:22.819 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2012-03-18 16:16:22.819 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2012-03-18 16:16:22.819 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2012-03-18 16:16:22.819 Cache directory changes: Yes, Permanent: Yes
. 2012-03-18 16:16:22.819 DST mode: 1
. 2012-03-18 16:16:22.819 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.819 Looking up host "server.com"
. 2012-03-18 16:16:22.828 Connecting to xxx.xx.xx.xx port 22
. 2012-03-18 16:16:23.054 Server version: SSH-2.0-Sun_SSH_1.1.4
. 2012-03-18 16:16:23.054 Using SSH protocol version 2
. 2012-03-18 16:16:23.054 We claim version: SSH-2.0-WinSCP_release_5.0.6
. 2012-03-18 16:16:23.239 Doing Diffie-Hellman group exchange
. 2012-03-18 16:16:23.371 Doing Diffie-Hellman key exchange with hash SHA-1
. 2012-03-18 16:16:24.190 Verifying host key rsa2 (hostkey) with fingerprint ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
. 2012-03-18 16:16:24.190 Host key matches cached key
. 2012-03-18 16:16:24.190 Host key fingerprint is:
. 2012-03-18 16:16:24.191 ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
. 2012-03-18 16:16:24.191 Initialised AES-256 SDCTR client->server encryption
. 2012-03-18 16:16:24.191 Initialised HMAC-SHA1 client->server MAC algorithm
. 2012-03-18 16:16:24.191 Initialised AES-256 SDCTR server->client encryption
. 2012-03-18 16:16:24.191 Initialised HMAC-SHA1 server->client MAC algorithm
! 2012-03-18 16:16:24.498 Using username "user".
. 2012-03-18 16:16:24.601 Attempting keyboard-interactive authentication
. 2012-03-18 16:16:24.703 Prompt (6, SSH server authentication, Using keyboard-interactive authentication., Password: )
. 2012-03-18 16:16:24.703 Using stored password.
. 2012-03-18 16:16:24.828 Prompt (6, SSH server authentication, Using keyboard-interactive authentication.
. 2012-03-18 16:16:24.828 Your Kerberos password will expire in 18 days.
. 2012-03-18 16:16:24.828
. 2012-03-18 16:16:24.828 , <no prompt>)
. 2012-03-18 16:16:24.828 Disconnected: Unable to authenticate
I did as much looking around as I could before posting this and found an old bug that seems to have this behavior. https://winscp.net/tracker/388
Is this the problem I am having or am I doing something else wrong?
Thanks,
Try
Dim sessionOptions As New SessionOptions
With sessionOptions
.Protocol = Protocol.Sftp
.HostName = "serverName"
.UserName = "userName"
.Password = "password"
.SshHostKey = "ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx"
End With
Using session As Session = New Session
session.Open(sessionOptions)
End Using
Catch ex As Exception
Console.WriteLine("Error: {0},", ex)
End Try
I get the following log file:
[2012-03-18 16:24:29Z] [0009] Executing Assembly: WinSCP, Version=1.0.0.235, Culture=neutral, PublicKeyToken=b5f19f5762436b89; Path: F:/Windows Dev/GlobalSync/GlobalSync/bin/Debug/WinSCP.DLL; Location: F:\Windows Dev\GlobalSync\GlobalSync\bin\Debug\WinSCP.dll; Product: 5.0.6.0
[2012-03-18 16:24:29Z] [0009] Entry Assembly: GlobalSync, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
[2012-03-18 16:24:29Z] [0009] Operating system: Microsoft Windows NT 6.0.6002 Service Pack 2
[2012-03-18 16:24:29Z] [0009] User: user@user-PC@user-PC; Interactive: True
[2012-03-18 16:24:29Z] [0009] Runtime: 4.0.30319.261
[2012-03-18 16:24:29Z] [0009] Console encoding: Input: Western European (Windows) (1252); Output: Western European (Windows) (1252)
[2012-03-18 16:24:29Z] [0009] Session.Open entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess..ctor entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.GetExecutablePath entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.GetExecutablePath leaving
[2012-03-18 16:24:29Z] [0009] EXE executable path resolved to C:\Program Files (x86)\WinSCP\winscp.exe
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.CheckVersion entering
[2012-03-18 16:24:29Z] [0009] Version of C:\Program Files (x86)\WinSCP\winscp.exe is 5.0.6.2074, product WinSCP version is 5.0.6.0
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.CheckVersion leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess..ctor leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.Start entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeConsole entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeConsole leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeChild entering
[2012-03-18 16:24:29Z] [0009] Starting "C:\Program Files (x86)\WinSCP\winscp.exe" /xmllog="C:\Users\user\AppData\Local\Temp\tmp888A.tmp" /xmlgroups /nointeractiveinput /dotnet=506 /ini=nul /console /consoleinstance=_8752_569
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.InitializeChild leaving
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.Start leaving
[2012-03-18 16:24:29Z] [0009] Command: [option batch on]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvents entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [0009] Command: [option confirm off]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenArguments entering
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenSwitches entering
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenSwitches leaving
[2012-03-18 16:24:29Z] [0009] Session.SessionOptionsToOpenArguments leaving
[2012-03-18 16:24:29Z] [0009] Command: [open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:29Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInitEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInitEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> option batch on]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [batch on ]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> option confirm off]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [confirm off ]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [winscp> open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:29Z] [000a] Scheduling output: [Searching for host...]
[2012-03-18 16:24:29Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:30Z] [0009] Output: [winscp> option batch on]
[2012-03-18 16:24:30Z] [0009] Output: [batch on ]
[2012-03-18 16:24:30Z] [0009] Output: [winscp> option confirm off]
[2012-03-18 16:24:30Z] [0009] Output: [confirm off ]
[2012-03-18 16:24:30Z] [0009] Output: [winscp> open -hostkey="ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx" -timeout=15 "sftp://user:password@server.com"]
[2012-03-18 16:24:30Z] [0009] Output: [Searching for host...]
[2012-03-18 16:24:30Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:30Z] [000a] Scheduling output: [Connecting to host...]
[2012-03-18 16:24:30Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:30Z] [0009] Output: [Connecting to host...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authenticating...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Authenticating...]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authenticating with pre-entered password.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Authenticating with pre-entered password.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Connection has been unexpectedly closed. Server sent command exit status 0.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] Output: [Connection has been unexpectedly closed. Server sent command exit status 0.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authentication log (see session log for details):]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Using username "user".]
[2012-03-18 16:24:31Z] [0009] Output: [Authentication log (see session log for details):]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [
]
[2012-03-18 16:24:31Z] [0009] Output: [Using username "user".]
[2012-03-18 16:24:31Z] [000a] Scheduling output: [Authentication failed.]
[2012-03-18 16:24:31Z] [0009] Output: [
]
[2012-03-18 16:24:31Z] [0009] Output: [Authentication failed.]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent entering
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessInputEvent entering
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---
[2012-03-18 16:24:31Z] [0009] Failed: [WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---]
[2012-03-18 16:24:31Z] [0009] Exception: WinSCP.SessionRemoteException: Connection has been unexpectedly closed. Server sent command exit status 0. ---> WinSCP.SessionRemoteException: Authentication log (see session log for details):
Using username "user".
Authentication failed.
--- End of inner exception stack trace ---
at WinSCP.SessionLogReader.Read(LogReadFlags flags)
at WinSCP.ElementLogReader.Read(LogReadFlags flags)
at WinSCP.CustomLogReader.TryWaitForNonEmptyElement(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForNonEmptyElement(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForNonEmptyElementAndCreateLogReader(String localName, LogReadFlags flags)
at WinSCP.CustomLogReader.WaitForGroupAndCreateLogReader()
at WinSCP.Session.Open(SessionOptions sessionOptions)
[2012-03-18 16:24:31Z] [0009] Session.Cleanup entering
[2012-03-18 16:24:31Z] [0009] Command: [exit]
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.ExecuteCommand entering
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.ExecuteCommand leaving
[2012-03-18 16:24:31Z] [000a] Scheduling output: [winscp> exit]
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessInputEvent leaving
[2012-03-18 16:24:31Z] [000a] ExeSessionProcess.ProcessEvent leaving
[2012-03-18 16:24:31Z] [0009] ExeSessionProcess.Close entering
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Close leaving
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Dispose entering
[2012-03-18 16:24:32Z] [000a] ExeSessionProcess.ProcessEvents leaving
[2012-03-18 16:24:32Z] [0009] ExeSessionProcess.Dispose leaving
[2012-03-18 16:24:32Z] [0009] Session.Cleanup leaving
[2012-03-18 16:24:32Z] [0009] Session.Open leaving
[2012-03-18 16:24:32Z] [0009] Session.Dispose entering
[2012-03-18 16:24:32Z] [0009] Session.Cleanup entering
[2012-03-18 16:24:32Z] [0009] Session.Cleanup leaving
I can connect to the server just fine through the GUI, but I do get a security banner and another prompt afterwards I have to click ok for. I tried the command line option to see if it was something I was doing with the .NET assembly. Script file for command line test.txt:
option batch on
option confirm off
open sftp://user:password@server.com
close
exit
winscp.exe /console /script=test.txt
This generated the following log file:
. 2012-03-18 16:16:22.818 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.818 WinSCP Version 5.0.6 (Build 2074) (OS 6.0.6002 Service Pack 2)
. 2012-03-18 16:16:22.818 Configuration: HKEY_CURRENT_USER\Software\Martin Prikryl\WinSCP 2\
. 2012-03-18 16:16:22.818 Local account: user-PC\user
. 2012-03-18 16:16:22.818 Login time: Sunday, March 18, 2012 4:16:22 PM
. 2012-03-18 16:16:22.818 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.818 Session name: user@server.com (Modified stored session)
. 2012-03-18 16:16:22.818 Host name: server.com (Port: 22)
. 2012-03-18 16:16:22.819 User name: user (Password: Yes, Key file: No)
. 2012-03-18 16:16:22.819 Tunnel: No
. 2012-03-18 16:16:22.819 Transfer Protocol: SFTP
. 2012-03-18 16:16:22.819 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2012-03-18 16:16:22.819 Proxy: none
. 2012-03-18 16:16:22.819 SSH protocol version: 2; Compression: No
. 2012-03-18 16:16:22.819 Bypass authentication: No
. 2012-03-18 16:16:22.819 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2012-03-18 16:16:22.819 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2012-03-18 16:16:22.819 SSH Bugs: -,-,-,-,-,-,-,-,-,-
. 2012-03-18 16:16:22.819 SFTP Bugs: -,-
. 2012-03-18 16:16:22.819 Return code variable: Autodetect; Lookup user groups: -
. 2012-03-18 16:16:22.819 Shell: default
. 2012-03-18 16:16:22.819 EOL: 0, UTF: 2
. 2012-03-18 16:16:22.819 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2012-03-18 16:16:22.819 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2012-03-18 16:16:22.819 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2012-03-18 16:16:22.819 Cache directory changes: Yes, Permanent: Yes
. 2012-03-18 16:16:22.819 DST mode: 1
. 2012-03-18 16:16:22.819 --------------------------------------------------------------------------
. 2012-03-18 16:16:22.819 Looking up host "server.com"
. 2012-03-18 16:16:22.828 Connecting to xxx.xx.xx.xx port 22
. 2012-03-18 16:16:23.054 Server version: SSH-2.0-Sun_SSH_1.1.4
. 2012-03-18 16:16:23.054 Using SSH protocol version 2
. 2012-03-18 16:16:23.054 We claim version: SSH-2.0-WinSCP_release_5.0.6
. 2012-03-18 16:16:23.239 Doing Diffie-Hellman group exchange
. 2012-03-18 16:16:23.371 Doing Diffie-Hellman key exchange with hash SHA-1
. 2012-03-18 16:16:24.190 Verifying host key rsa2 (hostkey) with fingerprint ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
. 2012-03-18 16:16:24.190 Host key matches cached key
. 2012-03-18 16:16:24.190 Host key fingerprint is:
. 2012-03-18 16:16:24.191 ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
. 2012-03-18 16:16:24.191 Initialised AES-256 SDCTR client->server encryption
. 2012-03-18 16:16:24.191 Initialised HMAC-SHA1 client->server MAC algorithm
. 2012-03-18 16:16:24.191 Initialised AES-256 SDCTR server->client encryption
. 2012-03-18 16:16:24.191 Initialised HMAC-SHA1 server->client MAC algorithm
! 2012-03-18 16:16:24.498 Using username "user".
. 2012-03-18 16:16:24.601 Attempting keyboard-interactive authentication
. 2012-03-18 16:16:24.703 Prompt (6, SSH server authentication, Using keyboard-interactive authentication., Password: )
. 2012-03-18 16:16:24.703 Using stored password.
. 2012-03-18 16:16:24.828 Prompt (6, SSH server authentication, Using keyboard-interactive authentication.
. 2012-03-18 16:16:24.828 Your Kerberos password will expire in 18 days.
. 2012-03-18 16:16:24.828
. 2012-03-18 16:16:24.828 , <no prompt>)
. 2012-03-18 16:16:24.828 Disconnected: Unable to authenticate
I did as much looking around as I could before posting this and found an old bug that seems to have this behavior. https://winscp.net/tracker/388
Is this the problem I am having or am I doing something else wrong?
Thanks,