Unexpected Error: "Element already read to the end"

Advertisement

PeBoe
Joined:
Posts:
14

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

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

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

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.

Reply with quote

PeBoe
Joined:
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 :-( ), 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

Reply with quote

PeBoe
Joined:
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)

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
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.

Reply with quote

PeBoe
Joined:
Posts:
14

WinSCP / Object Version

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

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

Re: WinSCP / Object Version

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.

Reply with quote

PeBoe
Joined:
Posts:
14

not solved

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

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

Re: not solved

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

Reply with quote

PeBoe
Joined:
Posts:
14

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
  • WinSCP_debug_166_20160401154631.log (72.9 KB, Private file)
Description: see line 546:
<output value=.....

Reply with quote

PeBoe
Joined:
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)

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

Re: not solved

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

Reply with quote

PeBoe
Joined:
Posts:
14

Now including Session Logs

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)
  • WinSCP_debug_166_20160405103111.log (1.01 MB, Private file)

Reply with quote

PeBoe
Joined:
Posts:
14

Strange behaviour...

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

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

Re: Now including Session Logs

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"?

Reply with quote

PeBoe
Joined:
Posts:
14

Re: Now including Session Logs

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.

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
27,459
Location:
Prague, Czechia

Re: Now including Session Logs

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

Reply with quote

Advertisement

You can post new topics in this forum