Forum » .NET assembly / COM library »

Post a reply

Options
Add an Attachment

If you do not want to add an Attachment to your Post, please leave the Fields blank.

(maximum 10 MB; please compress large files; only common media, archive, text and programming file formats are allowed)

Options

Topic review

martin

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

If you do FileVersionInfo.GetVersionInfo(@"\\server\path\tools\WinSCP.exe") just before using WinSCP .NET assembly code, what do you get?
prefect73

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

I´ve shortened the path within the post, actually it is something like \\server\path\tools\WinSCP. The details from the context menu are Fileversion: 1.8.3.11614 and Product version: 5.19.2.0
Is there any hint in the log, to tell what´s going wrong?
martin

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

If the .NET assembly says that \Tools\WinSCP.exe (what is not fully qualified) is 5.13.2, then it is 5.13.2. That's all can say about it.
prefect73

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

As described in the title, it occurs only in the deployed package. The WinSCP GUI version works fine on the server, so it´s not a firewall issue. The SQL Agent Service account has of course access to the tmp directory. When I interpret the log right, then the process is invoked successfully and even the connection is opened, but then the timeout occurs.

How is it possible that the old executable is used, although it´s path is completely qualified in the code?
martin

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

I know little about SSIS. Anyway, when do you get the error? In VS? Or after deploying your project? The updated .exe probably did not make it to the real environment where the code runs.
prefect73

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

No, according your advice, I haven't used NuGet. Besides, SSIS Projects don´t seem to support Nuget. I just downloaded the WinSCP-automation pack and placed the DLL and executable manually in the Tools directory, which works fine in Visual Studio.
Is there another explanation why the versions can be confused, although the reference to the executable is fully qualified in the code?
martin

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

The reference to Tools suggests that you originally used NuGet to add WinSCP to your project. So use NuGet to upgrade it. Do not download/install anything manually.
prefect73

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

I downloaded the latest package WinSCP-5.19.2-Setup.exe and replaced the DLL and the EXE,
but though I get the error:
The version of \Tools\WinSCP.exe (5.13.2.0) does not match version of this assembly \Tools\WinSCPnet.dll (5.19.2.0).

The referenced executable in the Tools directory is definitely version 5.19. Am I missing something?
martin

Re: WinSCP.net Timeout when run from SSIS SQL Server Agent, but fine from Visual Studio

At your (now deleted) duplicate question on Stack Overflow, I've asked you:
Did you try upgrading WinSCP? 5.13.2 is rather dated.
prefect73

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: 
Waiting for log update and dispatching events for 800

From the assembly log I can see, that the assembly is correctly installed: 
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

But the output from the job step shows the timeout, although the connection has obviously been established: 
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

And the debug output: 
[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

Documentation

Support

Associations

Follow Us