Topic "what does it mean exit code 3?"

Author Message
suchanv
[View user's profile]

Joined: 2013-01-30
Posts: 3
Location: Praha
I'm using version 1.0.4.2881 WinSCP.dll (v 5.1.3) in c# code. I calling command: "WinSCP.Session.Open(SessionOptions sessionOptions)" and this command return error: WinSCP process terminated with exit code 3 and output "", without creating a log file.
Please Help. What does mean "Exit code 3"?
Thanks
Advertisements
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
WinSCP does not have an exit code 3.
Please attach or email me a debug log file. (set Session.DebugLogPath).
ronaldbroens
[View user's profile]

Joined: 2013-02-13
Posts: 3
Location: The Netherlands
I have also this problem with the .net library. The winscp library is included in an Windows service application an has worked for a week or so. Without any code changes the implemented solution stopped working. Restarting this windows service does not help. No processes of winSCP seems to be running at that time. Only a full system reboot seems to resolve this issue.

WinSCP.SessionLocalException: WinSCP process terminated with exit code 3 and output "", without creating a log file.
at WinSCP.Session.Open(SessionOptions sessionOptions)

Problems has now been seen on two different different servers. Used software versions 5.1.2 and 5.1.3 both have this problem. Windows server 2008 R2 64 bit

Windows Event log does not show anything, no more error logging than this.

Please help!
ronaldbroens
[View user's profile]

Joined: 2013-02-13
Posts: 3
Location: The Netherlands
Here is the logfile that is created. It does give any more details what is going wrong here, but hopefully this will lead to an solution. Note that i have changed the real url, username and password for security reasons.
ssh - Copy.log (5.21 KB) [Download]

Description: Logging file

ronaldbroens
[View user's profile]

Joined: 2013-02-13
Posts: 3
Location: The Netherlands
I also see in the logging of my own Windows server that the download task sometimes also fails because it seems to be started multiple times. This does not happen al the time but I see at random times that the Winscp logfile cannot be writen because it already in use. All the other times i receive an eror code 3
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
I have sent you an email with dev version for additional debugging.

Also can you provide me a log file or exception dump for the scenarion where the log file cannot be written to?
suchanv
[View user's profile]

Joined: 2013-01-30
Posts: 3
Location: Praha
Hi,
I tried a new version but I have the same message:
WinSCP.SessionLocalException: WinSCP process terminated with exit code 3 and output "", without creating a log file.

WinSCP version 5.1.4 with WinSCP.dll version 1.0.5.2937
On Windows Server 2008 R2 64 bit

My C# app is 32 bit. When it runs as console all is OK. When it runs as service fails with this error message.

Please help
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
suchanv wrote:
I tried a new version but I have the same message:
WinSCP.SessionLocalException: WinSCP process terminated with exit code 3 and output "", without creating a log file.

WinSCP version 5.1.4 with WinSCP.dll version 1.0.5.2937
On Windows Server 2008 R2 64 bit

My C# app is 32 bit. When it runs as console all is OK. When it runs as service fails with this error message.

Duplicate post:
https://winscp.net/forum/viewtopic.php?p=44432#44432
_________________
Martin Prikryl
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
I have also experienced this issue and have been working on gathering more data before reporting it.

It looks like Error code 3 is caused when the "abort()" function is called in windows, this may not be in WinSCP, since it can happen in lowel level system libraries, but it's at least something extra.

Once this issue began I started reading up on possible causes. The symptoms are the same for me, so I started recording as much information as I could to a csv file every minute. Right now it records program run time, memory use, open handles, and how many times winscp has been called.

Interestingly enough we made it through more than 10,000 runs of winscp this time before the issue happened, but on previous attempts it lasted only a day (probably around 1,000 runs or so).

Interestingly enough when this issue happened the handle activity became highly erratic, nominal usage for my program was around 430 handles, once this issue came up the server suddenly started using as many as 800 handles. Interestingly enough, this persisted for several hours even though I stopped calling winscp.

This may, perhaps, indicate that the issue is instead in the .net layer and not winscp itself (which is my assumption anyway, winscp seems to be failing to open it's i/o channels).

Included is the graph showing handle usage and the csv file it was generated from. I would be more than happy to help debug this issue in any way that I can.
winscp-handle-usage.png (51.74 KB) [Download]

Description: Graph showing winscp starts vs handles used on the system.

black-box.zip (141.56 KB) [Download]

Description: Recording of various program stats, taken at minute intervals for the entire runtime.

martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
I have also experienced this issue and have been working on gathering more data before reporting it.

It looks like Error code 3 is caused when the "abort()" function is called in windows, this may not be in WinSCP, since it can happen in lowel level system libraries, but it's at least something extra.

Once this issue began I started reading up on possible causes. The symptoms are the same for me, so I started recording as much information as I could to a csv file every minute. Right now it records program run time, memory use, open handles, and how many times winscp has been called.

...

Thanks for sharing this. I've too found that WinSCP process exits in low level libraies, well before any actually WinSCP code runs.

What does your handle counter actually counts? Handles of WinSCP only? How does it count them?
_________________
Martin Prikryl
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
I couldn't find a way to measure WinSCP's usage, but originally I was afraid I had a handle leak, as the version of windows we use has a hard limit on the number of handles a process can have. We're not even approaching the 10,000 handle limit, but it seems like this activity is telling.

I'm measuring the "current" process from .net using:

Code:

Process p = Process.GetCurrentProcess();
...p.HandleCount...


At the point where this happens WinSCP is no longer able to run for any length of time, so I didn't think to try to capture data from the WinSCP processes. I'm not sure that I could very well, unless the .net library allows access to the process info.

The one thing I haven't tested yet that was on my list was if WinSCP can be started interactively once this has happened. I know that even restarting the service won't fix the problem, being able to run it by hand will help to indicate if this is some sort of system wide issue or if it's actually the service manager in windows causing a "leak" of some sort.

If you can think of any other data that I can track, I'm more than happy to try it out.

Oh, one other note, it seems to happen at irregular intervals. It took nearly two weeks once, and only one day in another instance. It usually takes about a week however.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
So you have one continuously running .NET process/service that references winscp.dll and regularly opens and closes WinSCP.Session, is that correct? And that .NET process seems keep increasing its allocated handles. But once the problem occurs, restarting that .NET process does not help. Do I understand right?
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
prikryl wrote:
So you have one continuously running .NET process/service that references winscp.dll and regularly opens and closes WinSCP.Session, is that correct? And that .NET process seems keep increasing its allocated handles. But once the problem occurs, restarting that .NET process does not help. Do I understand right?


Very close. The service would run forever, except we have to reboot when this issue happens.

There is one very long running .net service that spawns thousands of WinSCP processes via the WenSCP .net assembly, it does this on a schedule, we have maybe 35-40 different servers that it connects to. It makes a connection about every 10 minutes (depending on host).

At first I thought the issue may be with handles not being cleaned up correctly, but as the graph shows, the handles in my process are being cleaned up, so that isn't the issue. However, when the issue that we're discussing happens the WinSCP assembly throws a unique error. I've added an extra handler in my program that actually stops the main thread when this exception is caught, so I stopped trying to run WinSCP after the first error.

At that point, after WinSCP got that error, and my main thread has stopped (which prevents the program from running WinSCP anymore) then we see very erratic behaviour in the number of used handles, almost like something persistant in the WinSCP .net assembly is still trying to recover and/or run a WinSCP process.

When this happens stopping and restarting the service does not help the situation. I have actually stopped the service, made sure the process wasn't running at all anymore, and then restarted it only to get the same error again.

There are a couple of tests I intend to perform the next time this happens to isolate the situation further. It seems like when this happens the program is always running as a service, my program has the ability to also run as a console program, so I will try running it interactively outside of the windows service manager, which may help the situation. I am also curious if this is only effecting .net programs trying to run WinSCP or if WinSCP itself will have trouble starting. My guess is that WinSCP will start just fine if run interactively once this happens, but I will try it myself the next time it happens and I will let you know.

I hope that helped. I'm happy to elaborate on any aspect of the program or process here.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
Very close. The service would run forever, except we have to reboot when this issue happens.
...

Thanks for retailed response.
Let me know if you find something.
Also can you check Windows Event Log, once the problem occurs?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
prikryl wrote:
mjfirm wrote:
Very close. The service would run forever, except we have to reboot when this issue happens.
...

Thanks for retailed response.
Let me know if you find something.
Also can you check Windows Event Log, once the problem occurs?

I'm sending you an email with additional questions.
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
Hello,

My service finally ran into this same problem again. This time after running WinSCP 26,423 times. (those last couple of times may have been failures). It took it 1,034,200.985 seconds, or just under 12 days.

I ran my additional tests this time, running WinSCP manually as another user, and as the account that my service was running as passed, WinSCP itself started just fine (this wasn't too surprising). I also tried running my service manually, I added a bit of code to it long ago that detects if you're running the program interactively and if so, creates a console and fakes running as a service so you can see the debugging output. It ran perfectly as both users.

This means that the problem only exhibits itself when run as a service, or perhaps when run for long periods under a supervisor program of some sort. It looks like the issue does have something to do with the fact that it was running as a service. Potentially a buildup or leak that is never being cleaned up by the OS because of the way the service manager works in windows?

The results of my program stats recorder shows the same sudden spike in handle usage the moment we experience the first failure, the average handles open at a given moment spikes to more than double what it was to nearly 800 (with spikes nearly to 900).
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
My service finally ran into this same problem again. This time after running WinSCP 26,423 times. (those last couple of times may have been failures). It took it 1,034,200.985 seconds, or just under 12 days.

Thanks for the investigation!
Would you please switch to the dev version, I've sent you?
Do not forget to set the property as suggested in my email.
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
Oh, yes. I already have. Along with the suggested changes. So far so good. It could be a week or two before we get an error, if ever. I'll keep you posted Smile
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
Oh, yes. I already have. Along with the suggested changes. So far so good. It could be a week or two before we get an error, if ever. I'll keep you posted Smile

Thanks! Let me know.
_________________
Martin Prikryl
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
This issue has been added to the tracker:
https://winscp.net/tracker/show_bug.cgi?id=996
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
My service just died with the exact same behaviour. Once again it continues even after restarting the service, but running the program interactively worked fine.

I did make the changes that you requested, but I'm afraid I can't find any additional information that may have been left behind by the debugging version of the program, and I was, unfortunately, unable to attach a debugger before the machine was restarted.

The issue is still happening, this time it took approx 8.25 days and 19,248 sessions before it failed.

When it failed it exhibited the exact same symptoms.

What do you propose going forward? I can certainly put a remote debugger on the server hosting the service and try attaching to it the next time this happens. Is there something else I can do to provide you with better information?
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
Today I was trying to figure out a way to keep one of the hosts that we connect to from constantly timing out and behaving poorly.

This one host fails every time we try to connect, without fail. Usually it seems like a timeout, but it doesn't always behave like a timeout. Using the standard client I connected interactively and tried doing a recursive size check on one of the massive root folders.

WinSCP used 100% of one of my core's CPU, and the transfer speed started low and kept dropping until there was no transfer. After that I got a chance to reconnect or give up, I tried to reconnect and was presented with a dialog telling me there was an "Invalid access to memory" error (https://winscp.net/eng/docs/message_invalid_access_to_memory).

This also happened after connecting to this site, doing some work, and then letting it sit idle for a little while.

I also got this to happen with the debugging version, however less frequently.

The host is running FTP and we're using explicit SSL encryption. Interestingly when I set it to TLS encryption WinSCP does not saturate the CPU. All other results are the same.

It looks like the host is running windows 2003 or 2000 and is using FileZilla, but what version it is I don't know. (this came from nmap).

This is the result of SYST and FEAT in the winscp log:

> 2013-04-29 08:54:41.174 SYST
< 2013-04-29 08:54:41.258 215 UNIX emulated by FileZilla
> 2013-04-29 08:54:41.258 FEAT
< 2013-04-29 08:54:41.325 211-Features:
< 2013-04-29 08:54:41.325 MDTM
< 2013-04-29 08:54:41.325 REST STREAM
< 2013-04-29 08:54:41.325 SIZE
< 2013-04-29 08:54:41.325 MLST type*;size*;modify*;
< 2013-04-29 08:54:41.325 MLSD
< 2013-04-29 08:54:41.325 AUTH SSL
< 2013-04-29 08:54:41.325 AUTH TLS
< 2013-04-29 08:54:41.325 PROT
< 2013-04-29 08:54:41.325 PBSZ
< 2013-04-29 08:54:41.325 UTF8
< 2013-04-29 08:54:41.325 CLNT
< 2013-04-29 08:54:41.325 MFMT
< 2013-04-29 08:54:41.325 211 End

I can post more of the log after running through it to censor some, unfortunately we can't release most of this information.

I'm posting this here because I think that it may be related. If we're getting some sort of memory violation when connecting to this one host, that could easilly cause issues in the svchost process over time.

If there's more I can do to help track this down, let me know.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
WinSCP used 100% of one of my core's CPU, and the transfer speed started low and kept dropping until there was no transfer. After that I got a chance to reconnect or give up, I tried to reconnect and was presented with a dialog telling me there was an "Invalid access to memory" error (https://winscp.net/eng/docs/message_invalid_access_to_memory).

Thanks for your report.
I have sent you an email with a debug version of WinSCP to address you have used to register on this forum.
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
Sorry, I was using the debugging version. I didn't get any additional core dumps or tracelogs or anything that I'm aware of though. Is there something extra I should do to get those?

I could also run it through the visual studio debugger, but the program seems to catch the error itself.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
Sorry, I was using the debugging version. I didn't get any additional core dumps or tracelogs or anything that I'm aware of though. Is there something extra I should do to get those?

It logs to C:\ by default. Possibly you do not have a write access there. Please read instructions linked from my email to learn how to change logging folder.
_________________
Martin Prikryl
jmccallav
[View user's profile]

Joined: 2013-05-09
Posts: 1
Location: usa
prikryl wrote:
mjfirm wrote:
Sorry, I was using the debugging version. I didn't get any additional core dumps or tracelogs or anything that I'm aware of though. Is there something extra I should do to get those?

It logs to C:\ by default. Possibly you do not have a write access there. Please read instructions linked from my email to learn how to change logging folder.


It seems that the solution by now is to use the DEV version, will you be so kind to provide it to me.
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
jmccallav wrote:
prikryl wrote:
mjfirm wrote:
Sorry, I was using the debugging version. I didn't get any additional core dumps or tracelogs or anything that I'm aware of though. Is there something extra I should do to get those?

It logs to C:\ by default. Possibly you do not have a write access there. Please read instructions linked from my email to learn how to change logging folder.


It seems that the solution by now is to use the DEV version, will you be so kind to provide it to me.


I'm sorry, but it did not solve the problem. It simply wasn't producing a tracelog because the service did not have access to C:\.

The problem persists.
rbedger
[View user's profile]

Joined: 2013-05-10
Posts: 1
Location: United States
I have a Windows Scheduled task that runs every 10 minutes (usually - it depends on which machine it is installed on). I have this task running my executable on 9 different servers across the continental US. My executable might make between 5 and 20 connections each time it runs.

2 of the 9 servers recently started failing with the error message mentioned above. How may I assist in the resolution of this bug?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
rbedger wrote:
2 of the 9 servers recently started failing with the error message mentioned above. How may I assist in the resolution of this bug?

It's not clear yet that is a cause of the problem. It looks like some system-level leak. The only known solution seems to be restart of the machine.
_________________
Martin Prikryl
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
Can some of you (the more the better) describe in very details, how do you use WinSCP .NET assembly? What environment? How long does a single session last on avarage? How frequently do you open session and in what intervals? How many sessions does it take before the error start happening? Is the process using WinSCP .NET assembly running continuously or not?

I'm trying to find out how to reproduce the problem.
mjfirm
[View user's profile]

Joined: 2013-04-02
Posts: 12
Location: Denver, CO
It's very difficult to reproduce. It's happening here under windows 2008 R2 Datacenter Edition on a virtual server. It's happened on at least two different virtual servers. The process that uses the WinSCP .NET assembly is installed as a system service and runs forever.

It's been nearly a month since we've run into this issue now, which is nice. However, we run on a very regular schedule, so this would seem to indicate that something more chaotic is happening, which is what lead me to my guess about it being related to a particular kind of failure experinced connecting to a client.

Our sessions are usually fairly short, but we connect to something like 50+ different hosts at intervals of as small as 10 minutes. Each time we connect we scan their system for particular types of changes and download the differences. The host process is taking advantage of the ThreadPool system and can have many hosts active at once (I suppose concurrency could also be an issue).

It generally takes around 23,000-26,000 connections to start to get this error, or about two weeks. However in this last run, as of this posting, we had made it through 49,847 connections.

We have hosts that get random errors periodically or that we just can't connect to for a while because they're down or having other issues, but there is one host that we get an error from every single time we connect. WinSCP reports that they're dropping our connection part way through listing files. It was this host that caused the other memory issues I have been trying te report, but the more debugging in the test client the less likely this error seems to be.

I hope that helps Smile

Edit: After posting this it occured to me that while we always get the final debilitating error on a random host, what event happened immediately before this error. It looks like it's not host specific, but the connection attempt in the logs immediately before the connection that gets this error is always a "Connection failed" message. I can try to get more detail, but that's the .Message field in the exception that WinSCP throws.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
mjfirm wrote:
It's very difficult to reproduce....

Thanks for your detailed post. I have sent you an email.

I'd appreciate, if others post a similar description as mjfirm, so we can find what's common. Thanks in advance!
_________________
Martin Prikryl
drbergeron
[View user's profile]

Joined: 2012-08-18
Posts: 1
Here's our current setup causing this error:

Windows 2008R2 machine. I am running multiple wsf scripts using cscript being kicked off by task scheduler. When I run the task scheduler, it aborts. When I run via cmd, it works without issue.

In these scripts, we're connecting to the same FTP site as the same user, but just pulling files of different names. the process is failing on the session.Open command in the script.

here is the code of the function that's being called that I've added some other debugs to on my side to figure out what command was failing.

Code:

Sub FTPGetWinSCP( ByVal poDebugInfo, ByVal poErrorInfo, ByVal poFTPInfo )
   ' Retrieves files via FTP using WinSCP; supports wildcard search; FTP or SFTP or SCP
   ' Dependency: Sub WriteDebug( ByVal poDebugInfo, ByVal poErrorInfo, ByVal psMessage )
   ' Dependency: WinSCP and WinSCP .NET Assembly ( registered dll )
   '             1 ) WinSCP Client: https://winscp.net/eng/download.php
   '            2 ) .dll: https://winscp.net/eng/docs/library_install
   '            3 ) .dll Register: https://winscp.net/eng/docs/library_install#registering
   '             4 ) The line below is required after <job> in the main .wsf that calls this subroutine
   '               <reference object = "WinSCP.Session" />
   '            Additional Notes:
   '               poFTPInfo.sProtocol: Sftp ( default ), Scp and Ftp
   '               For additional info on WinSCP capabilities: https://winscp.net/eng/docs/library_sessionoptions
   ' poFTPInfo.sFileNameSearch:
   '   * If blank then all files in the remote FTP folder will be downloaded
   '   * Supports wildcard * in filename searches such as "*.txt"

   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Starting FTPGetWinSCP" )

   Dim sErrDesc, iErrNo
   Dim oSession, oSessionOptions
   Dim bDeleteAfterGet, oFile, sFinalCount, sFoundRemoteFileName, oFso, i, sNewLocalFilePathName, oDirectory, oDirectoryFiles
   Dim oRegExp, aRegExMatches
   wscript.echo "getting from ftp"
   dim winscplog, winscplogpath,winscpname, fso, scpfile
   winscplog = true
   winscplogpath="D:\VendorNet\Logs\"
   winscpname = month(now) & day(now) & "winscp_Log.xml"
      
   set fso = CreateObject("Scripting.FileSystemObject")
   set scpfile = fso.OpenTextFile(winscplogpath & winscpname,8,True)
   
   if winscplog then scpfile.writeline("<run> - Start function for " & WScript.ScriptName &" - " & now)
   
   If Not poFTPInfo.bDoNotDeleteAfterGet Then bDeleteAfterGet = True

   If Right( RTrim( poFTPInfo.sFTPRemoteGetFolder ), 1 ) <> "/" Then poFTPInfo.sFTPRemoteGetFolder = poFTPInfo.sFTPRemoteGetFolder & "/"

   if winscplog then scpfile.writeline("begin creating winscp sessionOptions - " & now)
   Set oSessionOptions = WScript.CreateObject( "WinSCP.SessionOptions" )
   if winscplog then scpfile.writeline("finish creating winscp sessionOptions - " & now)
   
   If poFTPInfo.sProtocol = "Ftp" Then oSessionOptions.Protocol = Protocol_Ftp
   If poFTPInfo.sProtocol = "Scp" Then oSessionOptions.Protocol = Protocol_Scp
   If poFTPInfo.bFTPPassive Then oSessionOptions.FtpMode = FtpMode_Passive
   If poFTPInfo.sProtocol = "Sftp" Or poFTPInfo.sProtocol = "Scp" Then oSessionOptions.SshHostKey = poFTPInfo.sSshHostKey

   With oSessionOptions
      .HostName = poFTPInfo.sFTPServer
      .UserName = poFTPInfo.sFTPUser
      .Password = poFTPInfo.sFTPPass
      .PortNumber = poFTPInfo.iFTPPort
   End With

   if winscplog then scpfile.writeline("finish setting properties sessionOptions, begin create session - " & now)
   Set oSession = WScript.CreateObject( "WinSCP.Session" )
   if winscplog then scpfile.writeline("finish creating session - " & now)

oSession.DebugLogPath = winscplogpath & "winSCP_Native.txt"

   On Error Resume Next
      if winscplog then scpfile.writeline("Before Open Session - " & now)
      oSession.Open oSessionOptions ' failing here
      if winscplog then scpfile.writeline("after open session - " & now)
      iErrNo = Err.Number : sErrDesc = Err.Description
   On Error GoTo 0
   If iErrNo <> 0 Then
      if winscplog then scpfile.writeline("after open session, error when opening session - " & now & sErrdesc)
      Call WriteFile( poErrorInfo, poErrorInfo.sFilePath, poErrorInfo.sFileName, now & " - Error connecting to FTP server; WinSCP: " & iErrNo & "; " & sErrDesc )
      Call SendEmail( poDebugInfo, poErrorInfo, poErrorInfo )
   End If

   Set oFso = CreateObject( "Scripting.FileSystemObject" )

   Dim sFileSuffix, sAggregateName, sNewName, ext, iCount
   sAggregateName = poFTPInfo.sFTPRemoteGetFolder
   sFileSuffix = "[_DL"

   If Right( sAggregateName,1 ) <> "/" Then sAggregateName = sAggregateName & "/"
   If poFTPInfo.sFileNameSearch = "" Then poFTPInfo.sFileNameSearch = "*"
   If Right( poFTPInfo.sLocalGetFolder,1 ) <> "\" Then poFTPInfo.sLocalGetFolder = poFTPInfo.sLocalGetFolder & "\"
   sAggregateName = sAggregateName & poFTPInfo.sFileNameSearch

   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Searching remote FTP for " & poFTPInfo.sFileNameSearch )

   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Downloading using WinSCP from " & sAggregateName & " to " & poFTPInfo.sLocalGetFolder )
   
   if winscplog then scpfile.writeline("before get files - " & now)
   oSession.GetFiles sAggregateName, poFTPInfo.sLocalGetFolder & "*" & sFileSuffix, bDeleteAfterGet
   if winscplog then scpfile.writeline("finish getting files- " & now)
   
   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Getting files from " & poFTPInfo.sLocalGetFolder )
   Set oDirectoryFiles = oFso.GetFolder( poFTPInfo.sLocalGetFolder ).Files

   ext= ""
   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Processing " & oDirectoryFiles.Count & " files" )
   For Each oFile In oDirectoryFiles
      Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Name is " & Right( oFile.Name,4 ) & " t/f: " & ( Right( oFile.Name,4 ) = sFileSuffix ) )
      If Right( oFile.Name,4 ) = sFileSuffix Then
         sNewName = Replace(oFile.Name,sFileSuffix,"")

         Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; sNewName is " & sNewName )
         ' make sure the file does not already exist in the local directory when downloading, append with .1, .2, etc.
         iCount = 1
         Do While oFso.FileExists( poFTPInfo.sLocalGetFolder & sNewName & ext)
            ext=  "." & cstr(iCount)
            iCount = iCount + 1
         Loop
         sNewName = sNewName & ext

         Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Setting name to " & sNewName )
         oFile.Name = sNewName
      End If
   Next

   if winscplog then scpfile.writeline("before disposing session - " & now)
   oSession.Dispose
   if winscplog then scpfile.writeline("after dispose session - " & now)
   
   if winscplog then scpfile.writeline("</run> - End function for " & WScript.ScriptName & " - " & now)
   scpfile.close
   set fso = nothing
   Set aRegExMatches = Nothing
   Set oRegExp = Nothing
   Set oFso = Nothing
   Set oDirectory = Nothing
   Set oDirectoryFiles = Nothing
   Set oSession = Nothing
   Set oSessionOptions = Nothing

   Call WriteDebug( poDebugInfo, poErrorInfo, 2, Now & "; Finished FTPGetWinSCP" )
End Sub


Each .wsf script running connects around 4-5 times to the same site pulling different files. There are 5 of these all running, which can create 20+ connections to the same FTP site in close proximity to one another.

I believe by running these scripts simultaneously I can reproduce this fairly close to on-demand. I have this installed in a test environment right now, please let me know if there's any more debug I can provide. I've attached the debug from a failed run with session.debuglogpath set.
debug.txt (7.17 KB) [Download]

Description: (none)

martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
@drbergeron: Thanks for your report.

I read all the new and old reports over and over again. I seems the problem is occurring on Windows 2008 (R2 SP1) only (though for some reports where I know Windows version number 6.1.7601, it can also be Windows 7 SP1).

That may explain why I was not able to reproduce the problem on my Windows 8 test machine, where I have a task scheduled every minute for over 4 months without a single problem. I have tried now to intensify the test by running multiple sessions in parallel as @iverchenko suggested.

Can others test suggestion by @agriffin (post here) to set process to run in 2003 compatibility mode?
agriffin
[View user's profile]

Joined: 2013-05-09
Posts: 7
Per the below- it did run fine for a couple weeks while set to 2003SP1 compatibility mode, but eventually we ran into the same behavior again.
Sad



prikryl wrote:
@drbergeron: Thanks for your report.

I read all the new and old reports over and over again. I seems the problem is occurring on Windows 2008 (R2 SP1) only (though for some reports where I know Windows version number 6.1.7601, it can also be Windows 7 SP1).

That may explain why I was not able to reproduce the problem on my Windows 8 test machine, where I have a task scheduled every minute for over 4 months without a single problem. I have tried now to intensify the test by running multiple sessions in parallel as @iverchenko suggested.

Can others test suggestion by @agriffin (post here) to set process to run in 2003 compatibility mode?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
agriffin wrote:
Per the below- it did run fine for a couple weeks while set to 2003SP1 compatibility mode, but eventually we ran into the same behavior again.
Sad

Thanks for your feedback.

Did you set BOTH winscp.exe and your application to the compatibility mode?
agriffin
[View user's profile]

Joined: 2013-05-09
Posts: 7
prikryl wrote:
agriffin wrote:
Per the below- it did run fine for a couple weeks while set to 2003SP1 compatibility mode, but eventually we ran into the same behavior again.
Sad

Thanks for your feedback.

Did you set BOTH winscp.exe and your application to the compatibility mode?


the application is just a perl script that does a command line call to winscp, run through visual cron. since I get the same behavior from the windows task scheduler when it happens, I think that rules out the visual cron aspect, and since it runs reliably in userspace even when is won't run as a task I thinkperl is probably safe(perl is also being used to run other tasks that do not stop when we run into this problem. for giggles I used powershell to replicate what the perl script did and ran into the same problem, as well as juct using a a plain old batch file)
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
agriffin wrote:
the application is just a perl script that does a command line call to winscp, run through visual cron. since I get the same behavior from the windows task scheduler when it happens, I think that rules out the visual cron aspect, and since it runs reliably in userspace even when is won't run as a task I thinkperl is probably safe(perl is also being used to run other tasks that do not stop when we run into this problem. for giggles I used powershell to replicate what the perl script did and ran into the same problem, as well as juct using a a plain old batch file)

What do you mean by "command line call to winscp"? Do you use WinSCP .NET assembly at all?
_________________
Martin Prikryl
agriffin
[View user's profile]

Joined: 2013-05-09
Posts: 7
Sorry, I guess I didn't make it clear. As far as I can tell any automation of this eventually causes problems. I'm not using any .net assemblies here, just command line. I saw from running through the related threads, however, that whether or not someone is using the assemblies, once the problem crops up, winscp doesn't work in *any* automated context, command line or assemblies. I *do* get exit code three from any automated process that calls it after that. To be clear, in windows scheduler this is "path not found" and is a result of winscp failing to build an FTP session. I have been presuming this is the same for others as well, since winscp does not have an exit code three itself.



prikryl wrote:
agriffin wrote:
the application is just a perl script that does a command line call to winscp, run through visual cron. since I get the same behavior from the windows task scheduler when it happens, I think that rules out the visual cron aspect, and since it runs reliably in userspace even when is won't run as a task I thinkperl is probably safe(perl is also being used to run other tasks that do not stop when we run into this problem. for giggles I used powershell to replicate what the perl script did and ran into the same problem, as well as juct using a a plain old batch file)

What do you mean by "command line call to winscp"? Do you use WinSCP .NET assembly at all?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
agriffin wrote:
Sorry, I guess I didn't make it clear. As far as I can tell any automation of this eventually causes problems. I'm not using any .net assemblies here, just command line. I saw from running through the related threads, however, that whether or not someone is using the assemblies, once the problem crops up, winscp doesn't work in *any* automated context, command line or assemblies. I *do* get exit code three from any automated process that calls it after that. To be clear, in windows scheduler this is "path not found" and is a result of winscp failing to build an FTP session. I have been presuming this is the same for others as well, since winscp does not have an exit code three itself.

Yes, you are probably correct that this issue exist for any kind of frequent use of WinSCP. It just seems to be more common with .NET. Though it can just be a coincidence.

I was finally able to reproduce this myself (after 100 000 runs). I'm going to debug this soon.
agriffin
[View user's profile]

Joined: 2013-05-09
Posts: 7
I imagine the .net users are tending to do high frequency multifile downloads and just run into it sooner.





prikryl wrote:
agriffin wrote:
Sorry, I guess I didn't make it clear. As far as I can tell any automation of this eventually causes problems. I'm not using any .net assemblies here, just command line. I saw from running through the related threads, however, that whether or not someone is using the assemblies, once the problem crops up, winscp doesn't work in *any* automated context, command line or assemblies. I *do* get exit code three from any automated process that calls it after that. To be clear, in windows scheduler this is "path not found" and is a result of winscp failing to build an FTP session. I have been presuming this is the same for others as well, since winscp does not have an exit code three itself.

Yes, you are probably correct that this issue exist for any kind of frequent use of WinSCP. It just seems to be more common with .NET. Though it can just be a coincidence.

I was finally able to reproduce this myself (after 100 000 runs). I'm going to debug this soon.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
agriffin wrote:
I imagine the .net users are tending to do high frequency multifile downloads and just run into it sooner.

Probably.

Btw, are you running winscp.com or winscp.exe?
agriffin
[View user's profile]

Joined: 2013-05-09
Posts: 7
prikryl wrote:
agriffin wrote:
I imagine the .net users are tending to do high frequency multifile downloads and just run into it sooner.

Probably.

Btw, are you running winscp.com or winscp.exe?


Our scripts reference the exe, but I tried it with the com as well, to no avail.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24993
Location: Prague, Czechia
agriffin wrote:
Our scripts reference the exe, but I tried it with the com as well, to no avail.

Thanks. This also narrows down the possible causes.
_________________
Martin Prikryl
Wompus
[View user's profile]

Joined: 2013-08-26
Posts: 2
I've also run into this issue (Windows Server 2008 R2, scheduled file transfers every 5/10 minutes).
Also had a consistent connection failed error because the server was offline.
Also have a very regular process combined with irregular connection fails.
Tried the 2003 compatibility, did not work.

Very similar situation to mjfirm.
Advertisements

You can post new topics in this forum






Search Site

What is WinSCP?

It is award-winning SFTP client, SCP client, FTPS client and FTP client integrated into one software program for file transfer to FTP server or secure SFTP server. [More]

And it's free!

Donate

About donations

$9   $19   $49   $99

About donations

Recommend

WinSCP Privacy Policy

WinSCP License