Unexpected Error: "Element already read to the end"

Hi
I'm using the .NET/COM object in a big automation project. Things worked very well until I installed a new WinCSP version (5.7.6 (Build 5874)). Since then I'm getting error "Element already read to the end" all the time ! When my tool starts, it opens WinSCP connections to various servers using corresponding WinSCP Object instances. Interesting is, this problem does not arise at the beginning of my tool's usage, but at a random time (which can be even hours !) later; but as soon as the problem pops up nothing goes anymore and no recovery possible other than restarting the tool itself.

I would be very gratfull to get your immediate support on this, because it is preventing us from running highly important Test-Automation processes

Thanks in advance for your support

Peter

Please attach a full debug log file showing the problem.

I too am experiencing this exact same behavior. I will provide a log file if OP does not.

I've been analyzing the problem for days, trying to correlate the error happenings with the Session Log infos. It seems to be, that under certain circumstances, for example when running remote commands that take longer times to execute in UNIX, a timeout (session timeout ??) triggers and the session is broken (bye bye :-( ), so all subsequent session operations throw the error "element already read to the end". As soon as my analysis is definitive I will send the LOG infos to the OP

Attached is a summary Session Log File. Problematic areas are those containing text like:
1) Host is not communicating for more than 15 seconds
2) If the problem repeats, try turning off 'Optimize connection buffer size'
3) Scheduling output: [(A)bort (60 s): Abort]
4) Exception: WinSCP.SessionLocalException: Session has unexpectedly closed

These problems seem to be correlated to commands like:
Command: [call /home/mtx/Automation_Framework/listFiles.pl '/mnt/shared/exchange/preBx/*.tlc' 'BSC:SUB:2051619' 10000 '(split(/-/,$a))[4] <=> (split(/-/,$b))[4]']
Which very often take even several minutes to complete

Thanks for your report.

What version of WinSCP are you using? Can you try 5.8.x beta?
Also I believe that in general your problem is that you do not check result of the ExecuteCommand call, before calling other methods. So you do not detect that the session is closed.

5.7.6 (Build 5874)
This is the version I'm using.

You say i do not check result of the ExecuteCommand call. Of course I could do, but still, this does address the cause for the unexpected session closure.
Do you already have an idea what the real cause for such behaviour (unexpected closing) is ? have you had other customers experiencing the same problem ? Is the problem related to the latest version like 5.7.6 ?

You really think the problem could be solved on the 5.8 beta version ?

Thanks for your support
Kind regards
Peter

PeBoe wrote:

Do you already have an idea what the real cause for such behaviour (unexpected closing) is ?

Show us a session log file.

You really think the problem could be solved on the 5.8 beta version ?

The problem with "Element already read to the end" might be solved in 5.8.

unluckily the problem is not solved, even with the 5.8 version I still have it and with the same intensity/frequency

PeBoe wrote:

unluckily the problem is not solved, even with the 5.8 version I still have it and with the same intensity/frequency

So show us both session log file and debug log file for that.

I'm here again, still having to deal with the same problem :cry:

using the session option TimeoutInMilliseconds = 2100000 I run a command taking around 1,5 minutes to complete. If I do this manually using putty, this command runs correctly, giving the right result: a list of files

Through automation, and looking at the Debug Log (attached), it also seems to run correctly (the files are indeed found, according to the LOG file). But the command throws an error:
Error Description : "Timeout waiting for WinSCP to respond" : String : DiameterInterface.save_DelayedFiles
And in fact the output of the command (cmdExecResult.output) is empty.

This ugly problem with "time outs" is getting extremely delicate for our company, since we are basing some Test Automation Tools on the use of WinSCP .NET/COM object, so PLEASE, WE NEED YOUR SUPPORT AND A DEFINITIVE SOLUTION AS SOON AS POSSIBLE !!!

Thank you in advance

Additional information:

if I leave the timeout to its default (15 sec) then:

No VBA error is generated at all
but taking a look into the Debug Log we see:
<result success="false">
<message>Terminated by user.</message>
</result>

Of course, in this case, too, the output is empty

"both session log file and debug log file for that" please!

OK, now including Session Log. For this run I set:
.TimeoutInMilliseconds = 35000 * 60 (=> 35 min)

Again, I get a Run time error: "Timeout waiting for WinSCP to respond" and the expected (existing) list of files which is expected as STDOUT from the command:
/home/mtx/Automation_Framework/listFiles.pl '/mnt/shared/event_files_processed/*.mef*' 'BSC:SUB:2052083' 10000 '(($a =~ /(\d+)\.mef/)[0] <=> ($b =~ /(\d+)\.mef/)[0])'
is not being output at all, that is:

cmdExecResult.output is inexistent because cmdExecResult = nothing

I just run the same on my local PC(Windows 7 Enterprise - Service Pack 1) and here I don't have this problem: if I use a big timeout, then I get the output without problems.

On the Server I have the problem: Windows Server 2008 R2 Standard - Service Pack 1


I hope this is another important hint for you to find the source of the problem

Can we go back to the "Element already read to the end"? I need logs for that.
What did you do that you are now getting "Timeout waiting for WinSCP to respond"? Can you reproduce the "Element already read to the end"?

martin wrote:

Can we go back to the "Element already read to the end"? I need logs for that.
What did you do that you are now getting "Timeout waiting for WinSCP to respond"? Can you reproduce the "Element already read to the end"?

"Element already read to the end" is a consequence of the timeout hitting, if the SW tries to use the session just closed previously because of the timeout. Lately I've been using my SW in a "special" way, so that it doesn't come to try to use the "dead" session, that's all.
But the underlying problem remains, that is: in case of remote commands taking several minutes to complete, even if I set TimeoutInMilliseconds to a very long time (i.e: 30 min), I don't get output at all.

PeBoe wrote:

"Element already read to the end" is a consequence of the timeout hitting, if the SW tries to use the session just closed previously because of the timeout. Lately I've been using my SW in a "special" way, so that it doesn't come to try to use the "dead" session, that's all.

OK. But I would still like to fix that. Can you reproduce it?

But the underlying problem remains, that is: in case of remote commands taking several minutes to complete, even if I set TimeoutInMilliseconds to a very long time (i.e: 30 min), I don't get output at all.

Increase Session.Timeout too.
https://winscp.net/eng/docs/library_session#timeout