Topic "PowerShell appears to hang when performing most Session methods"

Author Message
JefferMC
[View user's profile]

Joined: 2016-11-23
Posts: 3
Location: SC, USA
I am connecting to a IIS 8.5 FTP site secured by SSL.
I am using 5.9.2 of WinSCP.
I can transfer files using the GUI.
I can connect using PowerShell using the example scripts.

Here is the first script
Code:
Add-Type -Path "D:\Program Files (x86)\WinSCP\WinSCPnet.dll"
$sessionOptions = New-Object WinSCP.SessionOptions -Property @{ Protocol=[WinSCP.Protocol]::Ftp; HostName="host"; username="user"; password="pass"; FtpSecure = [WinSCP.FtpSecure]::Explicit; FtpMode = [WinSCP.FtpMode]::Active }
$session = New-Object WinSCP.Session
$session.Open($sessionOptions)
$TransferOptions = new-Object WinSCP.TransferOptions
$transferOptions.TransferMode = [WinSCP.TransferMode]::Binary
$result = $session.PutFiles("V:\ORAFLASH\PRODG\BACKUPS\test.7z","\PRODG\Ctrl.7z",$false,$TransferOptions)


When I had an invalid path for the second argument of PutFiles, it would return control and I could examine the $result object.
When I put a Valid path, then control doesn't return. Powershell says "Running script / selection..." and I have to crash Powershell.

I also tried ListDirectory("path") with the same effect (i.e. bad paths return an error, good paths lock up Powershell).

The FTP log on the server looks like everything is fine.
I added the debug file path to the session object and I note that on a non-error attempt it looks like this when it hangs up (no XML log, etc., just this sort of thing)
Code:
[2016-11-23 16:18:55.412Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:55.646Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:55.646Z] [0025]     Scheduling output: [Lost connection.]
[2016-11-23 16:18:55.646Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:55.646Z] [000c]     Output: [Lost connection.]
[2016-11-23 16:18:55.646Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:55.646Z] [0025]     Scheduling output: [Timeout detected. (data connection)
]
[2016-11-23 16:18:55.646Z] [0025]     Scheduling output: [Could not retrieve directory listing]
[2016-11-23 16:18:55.646Z] [000c]     Output: [Timeout detected. (data connection)
]
[2016-11-23 16:18:55.646Z] [000c]     Output: [Could not retrieve directory listing]
[2016-11-23 16:18:55.646Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:55.646Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:55.647Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:55.647Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:55.649Z] [0025]     ExeSessionProcess.ProcessChoiceEvent entering
[2016-11-23 16:18:56.225Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:56.650Z] [0025]       Options: [AR], Timer: [1000], Timeouting: [True], Timeouted: [-2], Break: [-1], Result: [-2]
[2016-11-23 16:18:56.650Z] [0025]     ExeSessionProcess.ProcessChoiceEvent leaving
[2016-11-23 16:18:56.650Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:56.650Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:56.650Z] [0025]     ExeSessionProcess.ProcessChoiceEvent entering
[2016-11-23 16:18:57.038Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:57.651Z] [0025]       Options: [AR], Timer: [1000], Timeouting: [True], Timeouted: [-2], Break: [-1], Result: [-2]
[2016-11-23 16:18:57.651Z] [0025]     ExeSessionProcess.ProcessChoiceEvent leaving
[2016-11-23 16:18:57.651Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:57.651Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:57.651Z] [0025]     ExeSessionProcess.ProcessChoiceEvent entering
[2016-11-23 16:18:57.850Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:58.652Z] [0025]       Options: [AR], Timer: [1000], Timeouting: [True], Timeouted: [-2], Break: [-1], Result: [-2]
[2016-11-23 16:18:58.652Z] [0025]     ExeSessionProcess.ProcessChoiceEvent leaving
[2016-11-23 16:18:58.652Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:58.652Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:58.652Z] [0025]     ExeSessionProcess.ProcessChoiceEvent entering
[2016-11-23 16:18:58.660Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:59.475Z] [000c]     Waiting for log update and dispatching events for 800
[2016-11-23 16:18:59.653Z] [0025]       Options: [AR], Timer: [1000], Timeouting: [True], Timeouted: [-2], Break: [-1], Result: [-2]
[2016-11-23 16:18:59.653Z] [0025]     ExeSessionProcess.ProcessChoiceEvent leaving
[2016-11-23 16:18:59.653Z] [0025]   ExeSessionProcess.ProcessEvent leaving
[2016-11-23 16:18:59.653Z] [0025]   ExeSessionProcess.ProcessEvent entering
[2016-11-23 16:18:59.653Z] [0025]     ExeSessionProcess.ProcessChoiceEvent entering
Advertisements
martin◆
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 26705
Location: Prague, Czechia
Please attach a full session log file showing the problem (using the latest version of WinSCP).

To generate the session log file, set Session.SessionLogPath. Submit the log with your post as an attachment. Note that passwords and passphrases not stored in the log. 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.
JefferMC
[View user's profile]

Joined: 2016-11-23
Posts: 3
Location: SC, USA
Here is the script that the logs reflect:
Code:
Add-Type -Path "D:\Program Files (x86)\WinSCP\WinSCPnet.dll"
$sessionOptions = New-Object WinSCP.SessionOptions -Property @{ Protocol=[WinSCP.Protocol]::Ftp; HostName="host"; username="user"; password="pass"; FtpSecure = [WinSCP.FtpSecure]::Explicit; FtpMode = [WinSCP.FtpMode]::Active }
$session = New-Object WinSCP.Session
$session.SessionLogPath = "C:\users\user\documents\WinSCP.txt"
$session.Open($sessionOptions)
$TransferOptions = new-Object WinSCP.TransferOptions
$transferOptions.TransferMode = [WinSCP.TransferMode]::Binary
$result = $session.ListDirectory("BADNAME")
$result = $session.ListDirectory("PRODG")

I let this run about 2.5 minutes and then hit CTRL/PAUSE on the PS window, which closed after a few seconds.

I'm including the .TMP file from the TEMP path and the log you requested. Reading the log it appears that there's some timeout in the FTP communication between the client and the server, but when using the GUI directly, I have no such issues. I reconfirmed that the GUI logged in and will navigate to the PRODG folder and will send files successfully.

I tried reducing the session timeout value thinking that would make the .NET library return with an error if an operation was retrying over and over again, but wasn't able to produce any result that returned control to PowerShell.

Thanks for your help!
wscp36C4.02A0CBF5.tmp.txt (1.09 KB) Private file

Description: Temp XML log file

WinSCP.txt (26.25 KB) Private file

Description: Log file as requested

JefferMC
[View user's profile]

Joined: 2016-11-23
Posts: 3
Location: SC, USA
A little more information

Code:
. 2016-11-24 09:45:22.910 Cached directory change via "PRODG" to "/PRODG".
. 2016-11-24 09:45:22.910 Getting current directory name.
. 2016-11-24 09:45:22.912 Retrieving directory listing...
> 2016-11-24 09:45:22.912 CWD /PRODG/
< 2016-11-24 09:45:22.947 250 CWD command successful.
> 2016-11-24 09:45:22.947 PWD
< 2016-11-24 09:45:22.980 257 "/PRODG" is current directory.
> 2016-11-24 09:45:22.980 TYPE A
< 2016-11-24 09:45:23.013 200 Type set to A.
> 2016-11-24 09:45:23.013 PASV
< 2016-11-24 09:45:23.046 227 Entering Passive Mode (lo,ca,l,ip,220,238).
. 2016-11-24 09:45:23.046 Server sent passive reply with unroutable address lo,ca,l,ip, using host address instead.
> 2016-11-24 09:45:23.046 LIST -a
. 2016-11-24 09:45:23.046 Connecting to pu.bl.ic.ip:56558 ...
< 2016-11-24 09:45:23.083 150 Opening ASCII mode data connection.
. 2016-11-24 09:45:23.112 Session ID reused
. 2016-11-24 09:45:23.113 Using TLSv1.2, cipher TLSv1/SSLv3: ECDHE-RSA-AES256-SHA384, 2048 bit RSA, ECDHE-RSA-AES256-SHA384 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AES(256)  Mac=SHA384
. 2016-11-24 09:45:23.113 TLS connection established
. 2016-11-24 09:45:23.146 11-21-16  02:46PM       <DIR>          ARCH
. 2016-11-24 09:45:23.146 11-21-16  02:46PM       <DIR>          INC0
. 2016-11-24 09:45:23.146 11-23-16  03:06PM       <DIR>          INC1
. 2016-11-24 09:45:23.146 09-09-16  11:30AM                  303 IndexMaintenance.config
< 2016-11-24 09:45:23.146 226 Transfer complete.

What I found interesting is the implicit switch to Passive Mode. I had initially had to specify Active mode to get the session established. However, now I find if I set it to Passive Mode, it connects and seems to work. Apparently leaving it to determine it automatically doesn't work. Setting it to active works, but the data connection won't work properly, and just setting it to Passive works.

So, my immediate issue is resolved. However, I would ask if there's any way to keep the method from wandering away in the dark during the failure/retry cycle.
martin◆
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 26705
Location: Prague, Czechia
JefferMC wrote:
So, my immediate issue is resolved. However, I would ask if there's any way to keep the method from wandering away in the dark during the failure/retry cycle.

This issue is being tracked already:
https://winscp.net/tracker/show_bug.cgi?id=1169
Advertisements

You can post new topics in this forum

Search

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