Session.FileExists not always throwing exception

Hi,

I am using the WinSCP .Net library and want to bring something to your attention and to get help resolving it. Currently, before downloading a file, I call the Session.FileExists() method to check the existence of a file. I've been doing some testing where I am booting myself from the SFTP server and then making sure I am able to reconnect, retry the download and keep track of successes/failures. Funny thing is that I boot the connection and then the first time through my loop Session.FileExists() doesn't throw an exception, but rather says that the file doesn't exist. Second time through the loop however, the expected exception ("Session has unexpectedly closed") is thrown and handled appropriately. The issue is that I rely on this exception to be thrown so that my retry logic is initiated. I have stepped through my code with a debugger and analyzed my log files to confirm that this is indeed what is happening

Please attach a full session and debug log files showing the problem (using the latest version of WinSCP).

This sounds very similar. I use powershell scripts with the WinSCPnet.dll (of 7/28/2016) and call the fileexists() method before a PUT in an SFTP session. The remote file does not (yet) exist, so it rightfully fails.

Here is the part of the session log where it shows the reaction to the missing part and the error code followed by the PUT attempt (which later fails although the file makes it across).
< 2016-08-23 13:51:41.214 Status code: 2, Message: 4103, Server: Error: No such file or directory, Language: Error: No such file or directory
< 2016-08-23 13:51:41.214 Script: Can't get attributes of file '(filename)'.
< 2016-08-23 13:51:41.214 No such file or directory.
< 2016-08-23 13:51:41.214 Error code: 2
< 2016-08-23 13:51:41.214 Error message from server ( Error: No such file or directory): Error: No such file or directory
. 2016-08-23 13:51:41.214 Script: Failed
> 2016-08-23 13:51:41.526 Script: put -nopermissions -preservetime -transfer="binary" -- "(filename)" "(filename)"
Note: I snipped the actual file names because they contained sensitive information.

I tried the debug log, too, but it ended in a loop repeating the below chunk where I had to kill the process after the file was over 10Mb big...
[2016-08-22 18:18:02.368Z] [0003] Closing log
[2016-08-22 18:18:02.368Z] [0003] Error parsing session log file, but it is not closed yet, will retry
[2016-08-22 18:18:02.368Z] [0003] Waiting for log update and dispatching events for 50
[2016-08-22 18:18:02.430Z] [0003] Opening log without write sharing
[2016-08-22 18:18:02.430Z] [0003] Opening log with write sharing
[2016-08-22 18:18:02.430Z] [0003] Log opened
[2016-08-22 18:18:02.430Z] [0003] Skipping 399 nodes

I narrowed it down to where the PUT method returns $false, and I suspect it is from the error code 2. Without the existence check it worked. Oddly, the same exact script portion to another site in an FTP worked despite the existence check. Maybe it varies by server and cannot handle all possible responses?

Anyway, if I can 'reset' the error before the PUT or if this can get fixed, I can avoid having to recode the check with a remote DIR construct.

I'd appreciate your feedback on this.

Regards,
Wolfgang

I hope I put this in the right forum as I am using the WinSCP net assembly...

I just upgraded WinSCP to 5.9.1 and keep getting the error I posted about. I write out an exception to the log (WGP are my initials, zLogLine and the global variable are for logging):
try {
zLogLine $global:FTP.Log "WGP: RFileExist $pv_FileName"
return $global:FTP.Session.FileExists($pv_FileName)
}
catch [Exception] {
zLogLine $global:FTP.Log "WGP: Exception $($_.Exception.Message)"
return $false
}

My log shows this (filename snipped):
0000004036 08/24/2016 10:44:37 000064 WGP: RFileExist (filename)
0000004036 08/24/2016 10:44:37 000065 WGP: Exception '.', hexadecimal value 0x00, is an invalid character. Line 264, position 28.

It's odd, because the remote file does not yet exist before the PUT and it only has 64 lines locally. Not sure where that message comes from and what line 264 pos 28 refers to.

Lastly, the end of the session log looks like this:
> 2016-08-24 10:44:38.405 Script: exit
. 2016-08-24 10:44:38.405 Script: Exit code: 1
. 2016-08-24 10:44:38.405 Closing connection.
. 2016-08-24 10:44:38.405 Sending special code: 12
. 2016-08-24 10:44:38.405 Sent EOF message

I'm surprised about lines after the connection is closed, and in another interface using the same PUT routine successfully, I don't get the last two lines.

Maybe this is something small, but I do not understand what is going on here. Help is much appreciated.

Regards,
Wolfgang

Please attach a complete session log file showing the problem. Both with and without the FileExists call.

I attached logs and code snippets as private due to sensitive data. I could not isolate a test because it's part of a 'framework'. I attached the two relevant routines and the main job. It's all in Powershell.

The logs 'with' are with the file check, the ones 'without' have it commented out and replaced with a hard 'false' as the file is new.

My FTP log shows a 'true' and a 'false' returned in those two cases. The only change was the remote file check. I generate new file names with date/time stamps, so the files do not exist for sure.

Thank you very much for having a look. I like WinSCP and hope that it holds up well across FTP sites.

Regards,
Wolfgang

Thanks for the logs. Though I do not see any problem there.
I was not even able to reproduce the problem with your code.
Can you repeat the test and collect even debug logs this time?
Set the Session.DebugLogPath.

Dear Martin:
Thanks for having a look. I tried debug (see my first post), but it hung up in a loop and I needed to kill the process.

I had a problem isolating the case, too. It only failed with one partner, but removing the fileexist() check worked consistently. I came up with a workaround now where I don't check the file existence, so it is not a big problem. Maybe if you get more reports of this method causing odd behavior, you can narrow down the problem - if it even is within WinSCP.

Again, thanks for your help.
Wolfgang

Possibly related to:
https://winscp.net/tracker/1583