Forum » .NET assembly / COM library »

PowerShell appears to hang when performing most Session methods

Advertisement

JefferMC
Joined:
Posts:
3
Location:
SC, USA

PowerShell appears to hang when performing most Session methods

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 
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) 
[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

Reply with quote

Advertisement

martin◆
Site Admin
martin avatar
Joined:
Posts:
41,518
Location:
Prague, Czechia

Re: PowerShell appears to hang when performing most Session methods

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.

Reply with quote

JefferMC
Joined:
Posts:
3
Location:
SC, USA

Requested information

Here is the script that the logs reflect: 
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

Reply with quote

JefferMC
Joined:
Posts:
3
Location:
SC, USA

Information from GUI log

A little more information 

. 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.

Reply with quote

Advertisement

You can post new topics in this forum

Documentation

Support

Associations

Follow Us