WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio
I´m trying to download from an SFTP Server using WinSCP.dll in a C# Script component in SSIS. In Visual Studio everything works fine, but when running the deployed package, the SQL Server Agent gets a timeout. I'm using WinSCP-5.19.2-Automation.zip. The debug log (see below for complete log) says the following, right before the timeout:
From the assembly log I can see, that the assembly is correctly installed:
But the output from the job step shows the timeout, although the connection has obviously been established:
I've already set
Here is the SessionLog output:
And the debug output:
Waiting for log update and dispatching events for 800
3:01:46 PM: Setting up assembly resolve handler 3:01:46 PM: Resolving assembly WinSCPnet, Version=1.5.5.8455, Culture=neutral, PublicKeyToken=2271ec4a3c56d0bf 3:01:46 PM: Assembly name WinSCPnet 3:01:46 PM: Loading WinSCPnet from \\server002\Tools\WinSCPnet.dll 3:01:47 PM: Loaded
Error: 2021-08-16 14:21:00.31 Code: 0x00000000 Source: FTP C# Description: Error using WinSCP to download files: System.TimeoutException: Timeout waiting for WinSCP to respond at WinSCP.Session.CheckForTimeout(String additional) at WinSCP.PatientFileStream.Wait(Int32& interval) at WinSCP.PatientFileStream.Read(Byte[] array, Int32 offset, Int32 count) at System.Xml.XmlTextReaderImpl.ReadData() at System.Xml.XmlTextReaderImpl.ParseText(Int32& startPos, Int32& endPos, Int32& outOrChars) at System.Xml.XmlTextReaderImpl.ParseText() at System.Xml.XmlTextReaderImpl.ParseElementContent() at WinSCP.SessionLogReader.DoRead() at WinSCP.SessionLogReader.Read(LogReadFlags flags) at WinSCP.ElementLogReader.Read(LogReadFlags flags) at WinSCP.SessionElementLogReader.Read(LogReadFlags flags) at WinSCP.CustomLogReader.TryWaitForNonEmptyElement(String localName, LogReadFlags flags) at WinSCP.CustomLogReader.WaitForNonEmptyElement(String localName, LogReadFlags flags) at WinSCP.Session.WaitForGroup() at WinSCP.Session.Open(SessionOptions sessionOptions) at ST_6dc974d6b4dd4cb0bef2ef07fc31cc07.ScriptMain.Main() End Error Error: 2021-08-16 14:21:00.32 Code: 0x00000006 Source: FTP C# Description: The script returned a failure result. End Error DTExec: The package execution returned DTSER_FAILURE (1).
I've already set
"SendBuf" = 0, as recommended at the WinSCP site.
Here is the SessionLog output:
. 2021-08-25 10:05:24.316 -------------------------------------------------------------------------- . 2021-08-25 10:05:24.316 WinSCP Version 5.13.2 (Build 8455) (OS 6.3.9600 - Windows Server 2012 R2 Standard) . 2021-08-25 10:05:24.316 Configuration: nul . 2021-08-25 10:05:24.316 Log level: Normal . 2021-08-25 10:05:24.317 Local account: DMSYS\SVC.SQL037 . 2021-08-25 10:05:24.317 Working directory: \Tools . 2021-08-25 10:05:24.317 Process ID: 65392 . 2021-08-25 10:05:24.318 Command-line: "\Tools\winscp.exe" /xmllog="C:\Users\SVC.SQL037\AppData\Local\Temp\wscpD9FC.03A89AAA.tmp" /xmlgroups /xmllogrequired /nointeractiveinput /dotnet=5.13.2 /ini=nul /log="\Tools\sessionLog.log" /console /consoleinstance=_55804_36848977_134 . 2021-08-25 10:05:24.318 Time zone: Current: GMT+2, Standard: GMT+1 (W. Europe Standard Time), DST: GMT+2 (W. Europe Daylight Time), DST Start: 3/28/2021, DST End: 10/31/2021 . 2021-08-25 10:05:24.318 Login time: Wednesday, August 25, 2021 10:05:24 AM . 2021-08-25 10:05:24.319 -------------------------------------------------------------------------- . 2021-08-25 10:05:24.320 Script: Retrospectively logging previous script records: > 2021-08-25 10:05:24.321 Script: option batch on < 2021-08-25 10:05:24.325 Script: batch on < 2021-08-25 10:05:24.325 Script: reconnecttime 120 > 2021-08-25 10:05:24.325 Script: option confirm off < 2021-08-25 10:05:24.325 Script: confirm off > 2021-08-25 10:05:24.326 Script: option reconnecttime 120 < 2021-08-25 10:05:24.326 Script: reconnecttime 120 > 2021-08-25 10:05:24.326 Script: open sftp://sftp:***@ftp2.sys.de -hostkey="xxx" -timeout=15 -rawsettings SendBuf="0" . 2021-08-25 10:05:24.326 -------------------------------------------------------------------------- . 2021-08-25 10:05:24.327 Session name: sftp@ftp2.sys.de (Ad-Hoc site) . 2021-08-25 10:05:24.327 Host name: ftp2.sys.de (Port: 22) . 2021-08-25 10:05:24.327 User name: sftp (Password: Yes, Key file: No, Passphrase: No) . 2021-08-25 10:05:24.327 Tunnel: No . 2021-08-25 10:05:24.328 Transfer Protocol: SFTP . 2021-08-25 10:05:24.328 Ping type: Off, Ping interval: 30 sec; Timeout: 15 sec . 2021-08-25 10:05:24.328 Disable Nagle: No . 2021-08-25 10:05:24.328 Proxy: None . 2021-08-25 10:05:24.329 Send buffer: 0 . 2021-08-25 10:05:24.329 SSH protocol version: 2; Compression: No . 2021-08-25 10:05:24.329 Bypass authentication: No . 2021-08-25 10:05:24.330 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: Yes . 2021-08-25 10:05:24.330 GSSAPI: Forwarding: No; Libs: gssapi32,sspi,custom; Custom: . 2021-08-25 10:05:24.330 Ciphers: aes,chacha20,blowfish,3des,WARN,arcfour,des; Ssh2DES: No . 2021-08-25 10:05:24.330 KEX: ecdh,dh-gex-sha1,dh-group14-sha1,rsa,WARN,dh-group1-sha1 . 2021-08-25 10:05:24.331 SSH Bugs: Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto . 2021-08-25 10:05:24.331 Simple channel: Yes . 2021-08-25 10:05:24.331 Return code variable: Autodetect; Lookup user groups: Auto . 2021-08-25 10:05:24.331 Shell: default . 2021-08-25 10:05:24.332 EOL: LF, UTF: Auto . 2021-08-25 10:05:24.332 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes; Follow directory symlinks: No . 2021-08-25 10:05:24.332 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No . 2021-08-25 10:05:24.332 SFTP Bugs: Auto,Auto . 2021-08-25 10:05:24.333 SFTP Server: default . 2021-08-25 10:05:24.333 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes . 2021-08-25 10:05:24.333 Cache directory changes: Yes, Permanent: Yes . 2021-08-25 10:05:24.333 Recycle bin: Delete to: No, Overwritten to: No, Bin path: . 2021-08-25 10:05:24.334 DST mode: Unix . 2021-08-25 10:05:24.334 -------------------------------------------------------------------------- . 2021-08-25 10:05:24.334 Looking up host "ftp2.sys.de" for SSH connection . 2021-08-25 10:05:24.340 Connecting to 192.168.49.13 port 22 . 2021-08-25 10:05:24.341 We claim version: SSH-2.0-WinSCP_release_5.13.2 . 2021-08-25 10:05:24.354 Server version: SSH-2.0-OpenSSH_7.4 . 2021-08-25 10:05:24.354 Using SSH protocol version 2 . 2021-08-25 10:05:24.354 Have a known host key of type ssh-ed25519 . 2021-08-25 10:05:24.357 Doing ECDH key exchange with curve Curve25519 and hash SHA-256 . 2021-08-25 10:05:24.738 Server also has ecdsa-sha2-nistp256/ssh-rsa host keys, but we don't know any of them . 2021-08-25 10:05:24.740 Host key fingerprint is: . 2021-08-25 10:05:24.740 ssh-ed25519 256 xxx . 2021-08-25 10:05:24.740 Host key matches configured key . 2021-08-25 10:05:24.741 Initialised AES-256 SDCTR client->server encryption . 2021-08-25 10:05:24.741 Initialised HMAC-SHA-256 client->server MAC algorithm . 2021-08-25 10:05:24.741 Initialised AES-256 SDCTR server->client encryption . 2021-08-25 10:05:24.741 Initialised HMAC-SHA-256 server->client MAC algorithm ! 2021-08-25 10:05:24.781 Using username "sftp". . 2021-08-25 10:05:24.794 Server offered these authentication methods: publickey,gssapi-keyex,gssapi-with-mic,password . 2021-08-25 10:05:24.795 Using SSPI from SECUR32.DLL . 2021-08-25 10:05:24.795 Attempting GSSAPI authentication . 2021-08-25 10:05:24.798 GSSAPI authentication request refused . 2021-08-25 10:05:24.798 Server offered these authentication methods: publickey,gssapi-keyex,gssapi-with-mic,password . 2021-08-25 10:05:24.798 Prompt (password, "SSH password", <no instructions>, "&Password: ") . 2021-08-25 10:05:24.798 Using stored password. . 2021-08-25 10:05:24.798 Sent password . 2021-08-25 10:05:24.837 Access granted . 2021-08-25 10:05:24.837 Opening session as main channel . 2021-08-25 10:05:25.196 Opened main channel . 2021-08-25 10:05:25.202 Started a shell/command . 2021-08-25 10:05:25.202 -------------------------------------------------------------------------- . 2021-08-25 10:05:25.202 Using SFTP protocol. . 2021-08-25 10:05:25.203 Doing startup conversation with host. > 2021-08-25 10:05:25.203 Type: SSH_FXP_INIT, Size: 5, Number: -1 < 2021-08-25 10:05:25.203 Type: SSH_FXP_VERSION, Size: 150, Number: -1 . 2021-08-25 10:05:25.204 SFTP version 3 negotiated. . 2021-08-25 10:05:25.204 Unknown server extension posix-rename@openssh.com="1" . 2021-08-25 10:05:25.204 Supports statvfs@openssh.com extension version "2" . 2021-08-25 10:05:25.204 Unknown server extension fstatvfs@openssh.com="2" . 2021-08-25 10:05:25.204 Supports hardlink@openssh.com extension version "1" . 2021-08-25 10:05:25.204 Unknown server extension fsync@openssh.com="1" . 2021-08-25 10:05:25.204 We believe the server has signed timestamps bug . 2021-08-25 10:05:25.205 We will use UTF-8 strings until server sends an invalid UTF-8 string as with SFTP version 3 and older UTF-8 strings are not mandatory . 2021-08-25 10:05:25.205 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes . 2021-08-25 10:05:25.205 Getting current directory name. . 2021-08-25 10:05:25.205 Getting real path for '.' > 2021-08-25 10:05:25.205 Type: SSH_FXP_REALPATH, Size: 10, Number: 16 < 2021-08-25 10:05:25.206 Type: SSH_FXP_NAME, Size: 47, Number: 16 . 2021-08-25 10:05:25.206 Real path is '/sftp' . 2021-08-25 10:05:25.206 Startup conversation with host finished. < 2021-08-25 10:05:25.206 Script: Active session: [1] sftp@ftp2.sys.de
[2021-08-25 15:15:17.557Z] [0003] Executing assembly: WinSCPnet, Version=1.5.5.8455, Culture=neutral, PublicKeyToken=2271ec4a3c56d0bf [2021-08-25 15:15:17.557Z] [0003] Executing assembly codebase: file://applsmdynp002/Dymatrix/SolutionFramework/Tools/WinSCPnet.dll [2021-08-25 15:15:17.558Z] [0003] Executing assembly location: \Tools\WinSCPnet.dll [2021-08-25 15:15:17.558Z] [0003] Entry Assembly: unmanaged [2021-08-25 15:15:17.561Z] [0003] Operating system: Microsoft Windows NT 6.2.9200.0 [2021-08-25 15:15:17.562Z] [0003] User: SVC.SQL037@DMSYS@DABACMSQL037; Interactive: False [2021-08-25 15:15:17.562Z] [0003] Runtime: 4.0.30319.42000 [2021-08-25 15:15:17.563Z] [0003] Console encoding: Input: OE United States (437); Output: OE United States (437) [2021-08-25 15:15:17.563Z] [0003] Working directory: C:\Windows\system32 [2021-08-25 15:15:17.565Z] [0003] Assembly path: \Tools\WinSCPnet.dll [2021-08-25 15:15:17.565Z] [0003] Assembly product version: 5.13.2.0 [2021-08-25 15:15:17.570Z] [0003] Session.Open entering [2021-08-25 15:15:17.572Z] [0003] Session.SetupTempPath entering [2021-08-25 15:15:17.573Z] [0003] Temporary folder: C:\Users\SVC.SQL037\AppData\Local\Temp\ [2021-08-25 15:15:17.573Z] [0003] Temporary file [C:\Users\SVC.SQL037\AppData\Local\Temp\wscpC734.03A89AAA.tmp] - Exists [False] [2021-08-25 15:15:17.574Z] [0003] Session.SetupTempPath leaving [2021-08-25 15:15:17.577Z] [0003] ExeSessionProcess..ctor entering [2021-08-25 15:15:17.578Z] [0003] ExeSessionProcess.GetExecutablePath entering [2021-08-25 15:15:17.579Z] [0003] ExeSessionProcess.GetExecutablePath leaving [2021-08-25 15:15:17.579Z] [0003] EXE executable path resolved to \Tools\winscp.exe [2021-08-25 15:15:17.582Z] [0003] ExeSessionProcess.CheckVersion entering [2021-08-25 15:15:17.584Z] [0003] Version of \Tools\winscp.exe is 5.13.2.8455, product WinSCP version is 5.13.2.0 [2021-08-25 15:15:17.584Z] [0003] ExeSessionProcess.CheckVersion leaving [2021-08-25 15:15:17.586Z] [0003] ExeSessionProcess..ctor leaving [2021-08-25 15:15:17.586Z] [0003] ExeSessionProcess.Start entering [2021-08-25 15:15:17.589Z] [0003] ExeSessionProcess.InitializeConsole entering [2021-08-25 15:15:17.589Z] [0003] Trying event _50996_36848977_393 [2021-08-25 15:15:17.589Z] [0003] Creating event WinSCPConsoleEventRequest_50996_36848977_393 [2021-08-25 15:15:17.590Z] [0003] Created event WinSCPConsoleEventRequest_50996_36848977_393 with handle 6004 with security none, new True [2021-08-25 15:15:17.590Z] [0003] Event _50996_36848977_393 is unique [2021-08-25 15:15:17.591Z] [0003] Creating event WinSCPConsoleEventResponse_50996_36848977_393 [2021-08-25 15:15:17.591Z] [0003] Created event WinSCPConsoleEventResponse_50996_36848977_393 with handle 6008 with security none, new True [2021-08-25 15:15:17.591Z] [0003] Creating event WinSCPConsoleEventCancel_50996_36848977_393 [2021-08-25 15:15:17.591Z] [0003] Created event WinSCPConsoleEventCancel_50996_36848977_393 with handle 6012 with security none, new True [2021-08-25 15:15:17.598Z] [0003] Job created [2021-08-25 15:15:17.599Z] [0003] Job set to kill all processes [2021-08-25 15:15:17.599Z] [0003] ExeSessionProcess.InitializeConsole leaving [2021-08-25 15:15:17.601Z] [0003] ExeSessionProcess.InitializeChild entering [2021-08-25 15:15:17.601Z] [0003] Starting "\Tools\winscp.exe" /xmllog="C:\Users\SVC.SQL037\AppData\Local\Temp\wscpC734.03A89AAA.tmp" /xmlgroups /xmllogrequired /nointeractiveinput /dotnet=5.13.2 /ini=nul /log="\Tools\sessionLog.log" /console /consoleinstance=_50996_36848977_393 [2021-08-25 15:15:17.615Z] [0003] Started process 62644 [2021-08-25 15:15:17.617Z] [0003] ExeSessionProcess.InitializeChild leaving [2021-08-25 15:15:17.617Z] [0003] ExeSessionProcess.Start leaving [2021-08-25 15:15:17.618Z] [0004] ExeSessionProcess.ProcessEvents entering [2021-08-25 15:15:17.620Z] [0003] Command: [option batch on] [2021-08-25 15:15:17.620Z] [0003] ExeSessionProcess.ExecuteCommand entering [2021-08-25 15:15:17.621Z] [0003] ExeSessionProcess.ExecuteCommand leaving [2021-08-25 15:15:17.621Z] [0003] Command: [option confirm off] [2021-08-25 15:15:17.622Z] [0003] ExeSessionProcess.ExecuteCommand entering [2021-08-25 15:15:17.622Z] [0003] ExeSessionProcess.ExecuteCommand leaving [2021-08-25 15:15:17.622Z] [0003] Command: [option reconnecttime 120] [2021-08-25 15:15:17.622Z] [0003] ExeSessionProcess.ExecuteCommand entering [2021-08-25 15:15:17.623Z] [0003] ExeSessionProcess.ExecuteCommand leaving [2021-08-25 15:15:17.625Z] [0003] Session.SessionOptionsToUrlAndSwitches entering [2021-08-25 15:15:17.628Z] [0003] Session.SessionOptionsToSwitches entering [2021-08-25 15:15:17.630Z] [0003] Session.SessionOptionsToSwitches leaving [2021-08-25 15:15:17.630Z] [0003] Session.SessionOptionsToUrlAndSwitches leaving [2021-08-25 15:15:17.630Z] [0003] Command: [open "sftp://sftp:***@ftp2.sys.de" -hostkey="ssh-ed25519 256 xxx" -timeout=15 -rawsettings SendBuf="0"] [2021-08-25 15:15:17.630Z] [0003] ExeSessionProcess.ExecuteCommand entering [2021-08-25 15:15:17.630Z] [0003] ExeSessionProcess.ExecuteCommand leaving [2021-08-25 15:15:17.694Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.695Z] [0004] ExeSessionProcess.ProcessInitEvent entering [2021-08-25 15:15:17.695Z] [0004] ExeSessionProcess.ProcessInitEvent leaving [2021-08-25 15:15:17.696Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.696Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.697Z] [0004] ExeSessionProcess.ProcessTitleEvent entering [2021-08-25 15:15:17.697Z] [0004] Not-supported title event [WinSCP] [2021-08-25 15:15:17.697Z] [0004] ExeSessionProcess.ProcessTitleEvent leaving [2021-08-25 15:15:17.697Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.697Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.697Z] [0004] ExeSessionProcess.ProcessTitleEvent entering [2021-08-25 15:15:17.698Z] [0004] Not-supported title event [WinSCP] [2021-08-25 15:15:17.698Z] [0004] ExeSessionProcess.ProcessTitleEvent leaving [2021-08-25 15:15:17.698Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.698Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.700Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.700Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.701Z] [0004] ExeSessionProcess.ProcessInputEvent entering [2021-08-25 15:15:17.702Z] [0004] Scheduling output: [winscp> option batch on] [2021-08-25 15:15:17.702Z] [0004] ExeSessionProcess.ProcessInputEvent leaving [2021-08-25 15:15:17.703Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.703Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.703Z] [0004] Scheduling output: [batch on ] [2021-08-25 15:15:17.703Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.703Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.703Z] [0004] Scheduling output: [reconnecttime 120 ] [2021-08-25 15:15:17.703Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.704Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.704Z] [0004] ExeSessionProcess.ProcessTitleEvent entering [2021-08-25 15:15:17.704Z] [0004] Not-supported title event [WinSCP] [2021-08-25 15:15:17.704Z] [0004] ExeSessionProcess.ProcessTitleEvent leaving [2021-08-25 15:15:17.704Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.704Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.705Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.705Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.705Z] [0004] ExeSessionProcess.ProcessInputEvent entering [2021-08-25 15:15:17.705Z] [0004] Scheduling output: [winscp> option confirm off] [2021-08-25 15:15:17.705Z] [0004] ExeSessionProcess.ProcessInputEvent leaving [2021-08-25 15:15:17.706Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.706Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.706Z] [0004] Scheduling output: [confirm off ] [2021-08-25 15:15:17.706Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.706Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.706Z] [0004] ExeSessionProcess.ProcessTitleEvent entering [2021-08-25 15:15:17.707Z] [0004] Not-supported title event [WinSCP] [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessTitleEvent leaving [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.707Z] [0004] ExeSessionProcess.ProcessInputEvent entering [2021-08-25 15:15:17.708Z] [0004] Scheduling output: [winscp> option reconnecttime 120] [2021-08-25 15:15:17.708Z] [0004] ExeSessionProcess.ProcessInputEvent leaving [2021-08-25 15:15:17.708Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.708Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.708Z] [0004] Scheduling output: [reconnecttime 120 ] [2021-08-25 15:15:17.708Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.709Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.709Z] [0004] ExeSessionProcess.ProcessTitleEvent entering [2021-08-25 15:15:17.709Z] [0004] Not-supported title event [WinSCP] [2021-08-25 15:15:17.709Z] [0004] ExeSessionProcess.ProcessTitleEvent leaving [2021-08-25 15:15:17.709Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.709Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.710Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.710Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.710Z] [0004] ExeSessionProcess.ProcessInputEvent entering [2021-08-25 15:15:17.710Z] [0004] Scheduling output: [winscp> open "sftp://sftp:***@ftp2.sys.de" -hostkey="ssh-ed25519 256 xxx" -timeout=15 -rawsettings SendBuf="0"] [2021-08-25 15:15:17.710Z] [0004] ExeSessionProcess.ProcessInputEvent leaving [2021-08-25 15:15:17.711Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.724Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.724Z] [0004] Scheduling output: [Searching for host...] [2021-08-25 15:15:17.724Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.730Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:17.730Z] [0004] Scheduling output: [Connecting to host...] [2021-08-25 15:15:17.730Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:17.733Z] [0003] SessionLogReader.Read entering [2021-08-25 15:15:17.735Z] [0003] Opening log without write sharing [2021-08-25 15:15:17.736Z] [0003] Opening log with write sharing [2021-08-25 15:15:17.741Z] [0003] Log opened [2021-08-25 15:15:17.742Z] [0003] Skipping 0 nodes [2021-08-25 15:15:17.742Z] [0003] Read node 1: XmlDeclaration xml=version="1.0" encoding="UTF-8" [2021-08-25 15:15:17.743Z] [0003] Log contents: <?xml version="1.0" encoding="UTF-8"?> <session xmlns="http://winscp.net/schema/session/1.0" name="sftp@ftp2.sys.de" start="2021-08-25T13:15:17.712Z"> [2021-08-25 15:15:17.743Z] [0003] SessionLogReader.Read leaving [2021-08-25 15:15:17.743Z] [0003] SessionLogReader.Read entering [2021-08-25 15:15:17.744Z] [0003] Read node 2: Whitespace [2021-08-25 15:15:17.744Z] [0003] Log contents has not changed [2021-08-25 15:15:17.744Z] [0003] SessionLogReader.Read leaving [2021-08-25 15:15:17.744Z] [0003] SessionLogReader.Read entering [2021-08-25 15:15:17.744Z] [0003] Read node 3: Element session [2021-08-25 15:15:17.745Z] [0003] Log contents has not changed [2021-08-25 15:15:17.745Z] [0003] SessionLogReader.Read leaving [2021-08-25 15:15:17.746Z] [0003] SessionLogReader.Read entering [2021-08-25 15:15:17.747Z] [0003] Waiting for log update and dispatching events for 50 [2021-08-25 15:15:17.748Z] [0003] Output: [winscp> option batch on] [2021-08-25 15:15:17.748Z] [0003] Output: [batch on ] [2021-08-25 15:15:17.748Z] [0003] Output: [reconnecttime 120 ] [2021-08-25 15:15:17.748Z] [0003] Output: [winscp> option confirm off] [2021-08-25 15:15:17.748Z] [0003] Output: [confirm off ] [2021-08-25 15:15:17.748Z] [0003] Output: [winscp> option reconnecttime 120] [2021-08-25 15:15:17.748Z] [0003] Output: [reconnecttime 120 ] [2021-08-25 15:15:17.749Z] [0003] Output: [winscp> open "sftp://sftp:***@ftp2.sys.de" -hostkey="ssh-ed25519 256 xxx" -timeout=15 -rawsettings SendBuf="0"] [2021-08-25 15:15:17.749Z] [0003] Output: [Searching for host...] [2021-08-25 15:15:17.749Z] [0003] Output: [Connecting to host...] [2021-08-25 15:15:17.797Z] [0003] Waiting for log update and dispatching events for 100 [2021-08-25 15:15:17.897Z] [0003] Waiting for log update and dispatching events for 200 [2021-08-25 15:15:18.097Z] [0003] Waiting for log update and dispatching events for 400 [2021-08-25 15:15:18.103Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.103Z] [0004] Scheduling output: [Authenticating...] [2021-08-25 15:15:18.103Z] [0003] Output: [Authenticating...] [2021-08-25 15:15:18.103Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.145Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.145Z] [0004] Scheduling output: [Using username "sftp".] [2021-08-25 15:15:18.146Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.146Z] [0003] Output: [Using username "sftp".] [2021-08-25 15:15:18.161Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.161Z] [0004] Scheduling output: [Authenticating with pre-entered password.] [2021-08-25 15:15:18.161Z] [0003] Output: [Authenticating with pre-entered password.] [2021-08-25 15:15:18.161Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.497Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:18.550Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.551Z] [0004] Scheduling output: [Authenticated.] [2021-08-25 15:15:18.551Z] [0003] Output: [Authenticated.] [2021-08-25 15:15:18.551Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.552Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.552Z] [0004] Scheduling output: [Starting the session...] [2021-08-25 15:15:18.552Z] [0003] Output: [Starting the session...] [2021-08-25 15:15:18.553Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.557Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.557Z] [0004] Scheduling output: [Session started.] [2021-08-25 15:15:18.558Z] [0003] Output: [Session started.] [2021-08-25 15:15:18.558Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.558Z] [0004] ExeSessionProcess.ProcessEvent entering [2021-08-25 15:15:18.559Z] [0004] Scheduling output: [Active session: [1] sftp@ftp2.sys.de] [2021-08-25 15:15:18.559Z] [0003] Output: [Active session: [1] sftp@ftp2.sys.de] [2021-08-25 15:15:18.559Z] [0004] ExeSessionProcess.ProcessEvent leaving [2021-08-25 15:15:18.760Z] [0004] Process 62644 exited with exit code 255 [2021-08-25 15:15:18.761Z] [0004] Exited [2021-08-25 15:15:18.761Z] [0004] ExeSessionProcess.ProcessEvents leaving [2021-08-25 15:15:19.298Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:20.099Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:20.899Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:21.700Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:22.500Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:23.301Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:24.102Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:24.902Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:25.703Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:26.504Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:27.304Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:28.105Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:28.906Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:29.706Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:30.507Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:31.308Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:32.108Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:32.909Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:33.710Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:34.510Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:35.311Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:36.112Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:36.912Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:37.713Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:38.514Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:39.321Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:40.122Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:40.923Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:41.723Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:42.524Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:43.325Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:44.125Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:44.926Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:45.727Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:46.527Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:47.328Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:48.129Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:48.929Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:49.730Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:50.531Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:51.331Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:52.132Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:52.932Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:53.733Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:54.534Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:55.334Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:56.135Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:56.937Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:57.737Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:58.538Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:15:59.339Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:00.139Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:00.940Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:01.741Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:02.541Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:03.342Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:04.143Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:04.943Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:05.744Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:06.545Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:07.345Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:08.146Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:08.947Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:09.747Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:10.548Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:11.349Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:12.149Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:12.950Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:13.751Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:14.551Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:15.352Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:16.153Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:16.954Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:17.755Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:18.556Z] [0003] Waiting for log update and dispatching events for 800 [2021-08-25 15:16:19.356Z] [0003] Timeout waiting for WinSCP to respond - asking for callstack [2021-08-25 15:16:19.357Z] [0003] ExeSessionProcess.RequestCallstack entering [2021-08-25 15:16:19.361Z] [0003] Exception: System.Threading.WaitHandleCannotBeOpenedException: No handle of the given name exists. at System.Threading.EventWaitHandle.OpenExisting(String name, EventWaitHandleRights rights) at WinSCP.ExeSessionProcess.RequestCallstack() [2021-08-25 15:16:19.361Z] [0003] ExeSessionProcess.RequestCallstack leaving [2021-08-25 15:16:19.361Z] [0003] Exception: System.TimeoutException: Timeout waiting for WinSCP to respond [2021-08-25 15:16:19.361Z] [0003] SessionLogReader.Read leaving [2021-08-25 15:16:19.362Z] [0003] Exception: System.TimeoutException: Timeout waiting for WinSCP to respond at WinSCP.Session.CheckForTimeout(String additional) at WinSCP.PatientFileStream.Wait(Int32& interval) at WinSCP.PatientFileStream.Read(Byte[] array, Int32 offset, Int32 count) at System.Xml.XmlTextReaderImpl.ReadData() at System.Xml.XmlTextReaderImpl.ParseText(Int32& startPos, Int32& endPos, Int32& outOrChars) at System.Xml.XmlTextReaderImpl.ParseText() at System.Xml.XmlTextReaderImpl.ParseElementContent() at WinSCP.SessionLogReader.DoRead() at WinSCP.SessionLogReader.Read(LogReadFlags flags) at WinSCP.ElementLogReader.Read(LogReadFlags flags) at WinSCP.SessionElementLogReader.Read(LogReadFlags flags) at WinSCP.CustomLogReader.TryWaitForNonEmptyElement(String localName, LogReadFlags flags) at WinSCP.CustomLogReader.WaitForNonEmptyElement(String localName, LogReadFlags flags) at WinSCP.Session.WaitForGroup() at WinSCP.Session.Open(SessionOptions sessionOptions) [2021-08-25 15:16:19.363Z] [0003] Session.Cleanup entering [2021-08-25 15:16:19.363Z] [0003] Terminating process [2021-08-25 15:16:19.363Z] [0003] Command: [exit] [2021-08-25 15:16:19.367Z] [0003] ExeSessionProcess.ExecuteCommand entering [2021-08-25 15:16:19.367Z] [0003] ExeSessionProcess.ExecuteCommand leaving [2021-08-25 15:16:19.368Z] [0003] ExeSessionProcess.Close entering [2021-08-25 15:16:19.368Z] [0003] Waiting for process to exit (2000 ms) [2021-08-25 15:16:19.368Z] [0003] ExeSessionProcess.Close leaving [2021-08-25 15:16:19.369Z] [0003] ExeSessionProcess.Dispose entering [2021-08-25 15:16:19.370Z] [0003] Closing job [2021-08-25 15:16:19.370Z] [0003] ExeSessionProcess.Dispose leaving [2021-08-25 15:16:19.370Z] [0003] Disposing log readers [2021-08-25 15:16:19.371Z] [0003] SessionElementLogReader.Dispose entering [2021-08-25 15:16:19.371Z] [0003] ElementLogReader.Dispose(session@0) entering [2021-08-25 15:16:19.372Z] [0003] ElementLogReader.ReadToEnd(session@0) entering [2021-08-25 15:16:19.372Z] [0003] SessionLogReader.Read entering [2021-08-25 15:16:19.372Z] [0003] Closing log [2021-08-25 15:16:19.373Z] [0003] Log contents has not changed [2021-08-25 15:16:19.574Z] [0003] Exception: WinSCP.SessionLocalException: Error parsing session log file ---> System.Xml.XmlException: Unexpected XML declaration. The XML declaration must be the first node in the document, and no white space characters are allowed to appear before it. Line 3, position 3. at System.Xml.XmlTextReaderImpl.Throw(Exception e) at System.Xml.XmlTextReaderImpl.ParsePI(StringBuilder piInDtdStringBuilder) at System.Xml.XmlTextReaderImpl.ParseElementContent() at WinSCP.SessionLogReader.DoRead() --- End of inner exception stack trace --- [2021-08-25 15:16:19.575Z] [0003] SessionLogReader.Read leaving [2021-08-25 15:16:19.575Z] [0003] ElementLogReader.ReadToEnd(session@0) leaving [2021-08-25 15:16:19.575Z] [0003] Swallowing exception [2021-08-25 15:16:19.575Z] [0003] ElementLogReader.Dispose(session@0) leaving [2021-08-25 15:16:19.575Z] [0003] SessionElementLogReader.Dispose leaving [2021-08-25 15:16:19.576Z] [0003] SessionLogReader.Dispose entering [2021-08-25 15:16:19.576Z] [0003] Log contents has not changed [2021-08-25 15:16:19.576Z] [0003] SessionLogReader.Dispose leaving [2021-08-25 15:16:19.576Z] [0003] Deleting XML log file [C:\Users\SVC.SQL037\AppData\Local\Temp\wscpC734.03A89AAA.tmp] [2021-08-25 15:16:19.576Z] [0003] Session.Cleanup leaving [2021-08-25 15:16:19.577Z] [0003] Session.Open leaving [2021-08-25 15:16:19.577Z] [0003] Session.Dispose entering [2021-08-25 15:16:19.577Z] [0003] Session.Cleanup entering [2021-08-25 15:16:19.577Z] [0003] Disposing log readers [2021-08-25 15:16:19.578Z] [0003] Session.Cleanup leaving
