Topic "Unexpected Error: "Element already read to the end""

Author Message
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
Advertisements
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
Please attach a full debug log file showing the problem.

To generate log file, set Session.DebugLogPath. Submit the log with your post as an attachment. You may want to remove other data you consider sensitive though, such as host names, IP addresses, account names or file names (unless they are relevant to the problem). If you do not want to post the log publicly, you can mark the attachment as private.
chevoldavis
[View user's profile]

Joined: 2016-02-25
Posts: 1
Location: NC
I too am experiencing this exact same behavior. I will provide a log file if OP does not.
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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 Sad ), 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
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
WinSCP_debug_166_summary.log (3.76 MB) Private file

Description: (none)

martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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.
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
PeBoe wrote:
Do you already have an idea what the real cause for such behaviour (unexpected closing) is ?

Show us a session log file.

Quote:
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.
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
unluckily the problem is not solved, even with the 5.8 version I still have it and with the same intensity/frequency
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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.
_________________
Martin Prikryl
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
I'm here again, still having to deal with the same problem Crying or Very sad

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
WinSCP_debug_166_20160401154631.log (72.9 KB) Private file

Description: see line 546:
<output value=.....

PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
WinSCP_debug_166_20160401162331.log (90.72 KB) Private file

Description: (none)

martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
"both session log file and debug log file for that" please!
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
WinSCP_session_166_20160405103111.log (86.44 KB) Private file

Description: (none)

WinSCP_debug_166_20160405103111.log (1.01 MB) Private file

Description: (none)

PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
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
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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"?
PeBoe
[View user's profile]

Joined: 2013-11-07
Posts: 14
prikryl 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.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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?

Quote:
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.
http://winscp.net/eng/docs/library_session#timeout
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