EnumerateRemoteFiles hangs indefinitely

Advertisement

cjwinn
Joined:
Posts:
9
Location:
USA

EnumerateRemoteFiles hangs indefinitely

Hello,

I am using WinSCP .NET Assembly in Powershell to download files from an SFTP server. I am using $session.EnumerateRemoteFiles to get a list of files from a directory with about 12,000 very small files (1-2kb json files), and it appears to hang forever. Looking at the session log, I see the following.
. 2020-10-29 16:21:30.499 Session upkeep
. 2020-10-29 16:21:30.499 Looking for network events
. 2020-10-29 16:21:30.499 Timeout waiting for network events
In the debug log, around that time, it appears to dump the xml log and then continue logging out the following over and over repeatedly.
[2020-10-29 16:24:19.861] [0011]     Log contents has not changed
[2020-10-29 16:24:19.862] [0011]   SessionLogReader.Read leaving
[2020-10-29 16:24:19.862] [0011]   Session.ReadFile entering
[2020-10-29 16:24:19.862] [0011]   Session.ReadFile leaving
[2020-10-29 16:24:19.863] [0011]   SessionLogReader.Read entering
[2020-10-29 16:24:19.863] [0011]     Read node 1587: Element group
[2020-10-29 16:24:19.982] [0011]     Log contents has not changed
[2020-10-29 16:24:19.983] [0011]   SessionLogReader.Read leaving
[2020-10-29 16:24:19.983] [0011]   Session.ReadFile entering
[2020-10-29 16:24:19.983] [0011]   Session.ReadFile leaving
[2020-10-29 16:24:19.984] [0011]   SessionLogReader.Read entering
[2020-10-29 16:24:19.984] [0011]     Read node 1588: Whitespace
As far as I can tell from the session log, it appears to be listing all the files and then hanging before returning the results to Powershell.
Here's a snippet of my code where this is hanging.
$winSCPLocation = Clean-FolderPath $winSCPLocation "\" -noStart
Add-Type -Path $winSCPLocation
 
try
{
   # Setup session options
   $sessionOptions = New-Object WinSCP.SessionOptions -Property @{
      Protocol = [WinSCP.Protocol]::"sftp"
      HostName = $sourceAddress
      UserName = $sourceUser
      PortNumber = $sourcePort
      GiveUpSecurityAndAcceptAnySshHostKey = 1
   }
 
   $sessionOptions.SshPrivateKeyPath = "$sourceKeyDirectory"
 
   #Set Key Exchange Algorithm Selection Policy
   $sessionOptions.AddRawSettings("KEX", "ecdh,dh-gex-sha1,dh-group14-sha1,rsa,dh-group1-sha1,WARN")
 
   #Set Optimize Connection Buffer Size to off (0) and set SshSimple to 1 to completely disable optimzation of connection buffer size
   $sessionOptions.AddRawSettings("SendBuf",0)
   $sessionOptions.AddRawSettings("SshSimple",1)
 
   $session = New-Object WinSCP.Session
 
   if ($winSCPSessionLogEnabled)
   {
      $sessionLogPathWinSCP = "$logDirectory\WinSCPSession_$fileDate.log"
      $session.SessionLogPath = $sessionLogPathWinSCP
      $winSCPSessionLogLocation = "WinSCP Session Log Location: $sessionLogPathWinSCP"
   }
   else
   {
      $winSCPSessionLogLocation = ""
   }
   if ($winSCPDebugLogEnabled)
   {
      $debugLogPathWinSCP = "$logDirectory\WinSCPDebug_$fileDate.log"
      $session.DebugLogPath = $debugLogPathWinSCP
      $session.DebugLogLevel = 2
      
      $winSCPDebugLogLocation = "WinSCP Debug Log Location: $debugLogPathWinSCP"
   }
   else
   {
      $winSCPSessionLogLocation = ""
   }
}
catch
{
 
   log -statement "Error: $($_.Exception.Message)" RED
   exit 1
}
 
log -statement "Attempting connection for sftp" GREEN
$session.Open($sessionOptions)
log -statement "sftp Connection Established - Still Connected" GREEN
 
$fileList = $session.EnumerateRemoteFiles("/home/test","*.json", [WinSCP.EnumerationOptions]::None)
I have attached the session log. The debug log is too large to upload here, even compressed (~12MB compressed).

Thanks!
  • WinSCPSession_20201029_162017.zip (1.13 MB, Private file)

Reply with quote

Advertisement

cjwinn

Oops, I didn't realize I had that set to 2. I set it to 0 and kicked it off again. It takes about an hour to fail, and I will upload once it is finished.

Reply with quote

cjwinn
Joined:
Posts:
9
Location:
USA

Re: EnumerateRemoteFiles hangs indefinitely

So this is odd. I set the log level to 0, and the debug log file size still shot up to ~250MB pretty quickly. I set it to -1, and the same thing is still happening. Am I doing something wrong?
$debugLogPathWinSCP = "$logDirectory\WinSCPDebug_$fileDate.log"
$session.DebugLogPath = $debugLogPathWinSCP
$session.DebugLogLevel = 0
$debugLogPathWinSCP = "$logDirectory\WinSCPDebug_$fileDate.log"
$session.DebugLogPath = $debugLogPathWinSCP
$session.DebugLogLevel = -1

Reply with quote

cjwinn
Joined:
Posts:
9
Location:
USA

Finally was able to get a more reasonably sized debug log.
  • WinSCPSession_20201030_085157.log (3.56 MB, Private file)
  • WinSCPDebug_20201030_085157.zip (7.39 MB, Private file)

Reply with quote

Advertisement

cjwinn
Joined:
Posts:
9
Location:
USA

I tried changing my approach by moving the files to an archive folder first so that I could then compress them into a .tar.gz file. This is necessary because a new file is dropped into the main directory every 10-20 seconds or so, and I want to make sure that anything I download also gets archived. I figured by moving all the files to an archive folder first and then creating the .tar.gz file off of that directory, I could avoid any issues of archiving files that aren't included in the .tar.gz.

When I tested my code with a small number of files (5–10), it worked just fine. However, when I pointed it at the directory with ~22k files, it completed the move to the archive folder and then appears to hang. My PowerShell script is sitting there not doing anything. The session log (attached) hasn't updated for the past 10 minutes. The debug log, even though it's set to a DebugLogLevel of 0, is currently sitting at about 27GB in size, meaning there's no chance I can upload it or even open it to view it for that matter.

Below is the line of code where I move the files. It appears to complete this command and then hang.
$session.MoveFile("$remoteFileDirectory/*","$archiveFolder/")
Is it possible this volume of files is just too high for the WinSCP .NET Assembly to handle?
  • WinSCPSession_20201030_131927.zip (1.09 MB, Private file)

Reply with quote

cjwinn
Joined:
Posts:
9
Location:
USA

Well, this is also strange. I let the PowerShell script continue to run. Almost 9.5 hours later, the WinSCP session log resumes logging activity with the tar command that is next in my script, but it errors out before proceeding to download the compressed file. The relevant code from my script is below.
$session.MoveFile("$remoteFileDirectory/*","$archiveFolder/")
 
$archiveFileName = "archive_$fileDate.tar.gz"
 
$archiveCommand = 'cd "' + $archiveFolder + '/" ; tar -czvf "' + $archiveFileName + '" "' + $archiveFolder + '/"'
 
log "Archive Command: $archiveCommand"
 
$result = $session.ExecuteCommand($archiveCommand)
$result.Check()
 
log $result.ErrorOutput
log $result.Output
 
$transferResult = $session.GetFiles("$archiveFolder/$archiveFileName", "$stagingDirectoryFull\", $false, $transferOptions)
 
$transferResultJson = ConvertTo-Json $transferResult
 
Expand-Tar "$stagingDirectoryFull\$archiveFileName" $stagingDirectoryFull -targzExtract
 
log "Download Complete. Archiving Downloaded Files..."
Below is the section of the WinSCP Session log where the log pauses at 14:07:56.358 and then resumes at 23:32:19:187 on line 134105 by connecting to the FTP server again.
. 2020-10-30 14:07:56.286 Moving file "/home/<redacted>-prod/outbound/<file name redacted>.json" to "/home/<redacted>-prod/archive/2020/10/30/<file name redacted>.json".
> 2020-10-30 14:07:56.286 Type: SSH_FXP_RENAME, Size: 105, Number: 5755922
< 2020-10-30 14:07:56.357 Type: SSH_FXP_STATUS, Size: 24, Number: 5755922
< 2020-10-30 14:07:56.357 Status code: 0
< 2020-10-30 14:07:56.358 Script: /home/<redacted>-prod/outbound/<file name redacted>.json
> 2020-10-30 23:32:19.187 Script: call cd "/home/<redacted>-prod/archive/2020/10/30/" ; tar -czvf "archive_20201030_131927.tar.gz" "/home/<redacted>-prod/archive/2020/10/30/"
< 2020-10-30 23:32:19.188 Script: Searching for host...
. 2020-10-30 23:32:19.189 [Shell] Looking up host "<url redacted>" for SSH connection
. 2020-10-30 23:32:19.248 [Shell] Connecting to <IP Address redacted> port 22
< 2020-10-30 23:32:19.319 Script: Connecting to host...
I have attached the Session Log. Unfortunately, even with the debug log level set at 0, the size of the debug log is still over 25GB, so I cannot upload it or open it.

I received the following error in the PowerShell session.
2020-10-30 23:32:16 - Archive Command: cd "/home/<redacted>-prod/archive/2020/10/30/" ; tar -czvf "archive_20201030_131927.tar.gz" "/home/<redacted>-prod/archive/2020/10/30/"
PS D:\Temp\Script\Miscellaneous> TerminatingError(archive.ps1): "Exception calling "Check" with "0" argument(s): "Network error: Software caused connection abort
Error changing directory to '/home/<redacted>-prod/archive/2020/10/30'.""
D:\Temp\Script\Miscellaneous\archive.ps1 : Exception calling "Check" with "0" argument(s): "Network 
error: Software caused connection abort
Error changing directory to '/home/<redacted>-prod/archive/2020/10/30'."
At line:1 char:1
+ D:\Temp\Script\Miscellaneous\archive.ps1 `
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [archive.ps1], MethodInvocationException
    + FullyQualifiedErrorId : SessionRemoteException,archive.ps1
D:\Temp\Script\Miscellaneous\archive.ps1 : Exception calling "Check" with "0" argument(s): "Network
error: Software caused connection abort
Error changing directory to '/home/<redacted>-prod/archive/2020/10/30'."
At line:1 char:1
+ D:\Temp\Script\Miscellaneous\archive.ps1 `
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [archive.ps1], MethodInvocationException
    + FullyQualifiedErrorId : SessionRemoteException,archive.ps1
  • WinSCPSession_20201030_131927.zip (1.34 MB, Private file)

Reply with quote

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

First, try to disable the debug logging (both DebugLogPath and DebugLogLevel). It's likely that it is, what makes the process so long.

Regarding:
I want to make sure that anything I download also gets archived
Just enumerate the results of the download.
See Moving (not copying) remote files after download with WinSCP .NET assembly
Or similar article in documentation (while for upload):
Moving local files to different location after successful upload

Reply with quote

Advertisement

You can post new topics in this forum