Forum » Support and Bug Reports »

Odd error after running for 6+ hours

Advertisement

NottaSmartMan
Joined:
Posts:
15

Odd error after running for 6+ hours

I'm getting a WinSCP/PowerShell error. The odd thing is, it happens after the script has been running for 6+ hours without issue. It seemed to happen in the middle of a copy.

My script output: 
Session Open   - 08/30/2024 06:31:20
Synching files for <removed>...
Exception calling "SynchronizeDirectories" with "7" argument(s): "Error formatting a string: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.."
Session Closed - 08/30/2024 12:47:55
Time difference: 0 days, 6 hours, 16 minutes, 36 seconds
The WinSCP Log is nothing remarkable.. here are the last few lines: 
. 2024-08-30 12:47:53.253 File: '<removed>' [2021-04-25T09:11:46.796Z] [0]
. 2024-08-30 12:47:53.253 Listing file "<removed>".
. 2024-08-30 12:47:53.332 Creating directory "<removed>".
. 2024-08-30 12:47:53.332 Canonifying: "<removed>"
. 2024-08-30 12:47:53.441 Canonified: "<removed>"
. 2024-08-30 12:47:53.644 File: '<removed>' [2020-04-29T17:49:32.000Z] [14412304]
. 2024-08-30 12:47:54.910 Copying "<removed>" to remote directory started.
... and then the log just stops abruptly

Reply with quote

Advertisement

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

Re: Odd error after running for 6+ hours

Please enable Session.DebugLogPath and post the log (the complete session log might still be useful too)

Reply with quote

NottaSmartMan
Joined:
Posts:
15

What session.DebugLogLevel setting works best for you? I tried setting is to 2, but it's then full of all sorts of seemingly worthless data.

Also, before I could share any data, I would need to sanitize the logs to remove any identifiable information (IE: remove/obfuscate filenames so you don't see something like "SecretCancerCure.txt") By chance, do you happen to have a script already written that automatically sanitizes the logs?

Reply with quote

NottaSmartMan
Joined:
Posts:
15

okay... I have one regular log and debug log, however the debug level was set to -1. I'll re-run it at '0'.

The one I have now did end with the error:
Exception calling "SynchronizeDirectories" with "7" argument(s): "Error formatting a string: Index (zero based) must be greater than or equal to zero and less than the size of the argument list..
and the log size for each file is less than a meg.

These log sizes are all over the board though. I have a different debug log for a different copy that is currently at 356gig and growing.

Do you have a private dropbox/email that I can send this to? Even if I'm able to clean up these files, I'm not comfortable posting them to a forum for everyone to see.

Reply with quote

Advertisement

NottaSmartMan
Joined:
Posts:
15

Given that one of my debug logs was 500meg, I attempted to truncate the information for you. Attached are the truncated logs for 2 uploads that each failed with the "Exception calling "SynchronizeDirectories" with "7" argument(s): "Error formatting a string: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.."" error.

At the top of each document is data from the normal log file (essentially the header and the bit about the last copy being attempted before the error occurred). At the bottom of each document is the data from the debug log (header and info about last file being copied).

Let me know if you need more info. I attempted to sanitize the logs while not going overboard.
  • Sanitized Files.zip (11.07 KB, Private file)

Reply with quote

martin◆
Site Admin
martin avatar

Ok, thanks. But do you have the "full stack trace" I've asked for in my last post? The exception is not present in any of the logs.

Reply with quote

Advertisement

NottaSmartMan
Joined:
Posts:
15

I stumbled across something that will hopefully help you.

For one of my test cases, I noticed I had a type-o in my code. I used a double quote rather than a single quote.

It changed my $transferOptions.FileMask to resolve to:
|*\.BIN\;*\System Volume Information\;\\servername\E$\folder\Subfolder\
instead of:
|*\$RECYCLE.BIN\;*\System Volume Information\;\\servername\E$\folder\subfolder\

(*\.BIN\ rather than *\$RECYCLE.BIN\)

I change it and the code ran longer than 10 minutes. I'm letting it run again now to see if/when it aborts. Is it possible that scanning the 'recycle.bin' and getting so many 'access denied' or potentially other access errors caused the script to error out?

I ask because the debug code shows is working on the $recycle.bin folder at the time of the last error.

Reply with quote

martin◆
Site Admin
martin avatar

The stacktrace suggests the error might be coming from your own code – your Session.FileTransferProgress handler.

My guess is that you use a string with a filename inadvertently as a format string. And some specific file (possibly in recycle bin) contains a formatting sequence, such as {0}.

Reply with quote

Advertisement

NottaSmartMan
Joined:
Posts:
15

Well, I'm not too proud to say that it wouldn't be the first time my code had an error.

My FileTransferProgress Function is: 
function FileTransferProgress {
   param ($e)
   Write-Progress -Id 0 -Activity "Synching" -CurrentOperation ("$($e.FileName) - {0:P0}" -f $e.FileProgress) -Status ("{0:P0} complete at $($e.CPS) bps" -f $e.OverallProgress) -PercentComplete ($e.OverallProgress * 100)
}

It's referenced (?) further down in the code before the connection is established via the command: 
$session.add_FileTransferProgress( { FileTransferProgress($_) } )

I think I pulled that function off a forum, I didn't write it myself. Do you see a problem with the way it's coded?

Reply with quote

NottaSmartMan
Joined:
Posts:
15

Confirmed.. the { and } appear to be causing me issues.

This appears to be where I pulled the original code from:
https://winscp.net/forum/viewtopic.php?t=25223#79401

I expanded upon and updated my code to account for the { and } characters and added some alerting. I'm re-testing but I think you may have figured this one out.

The new code is now: 
function FileTransferProgress {
param ($e)
   try {
        # Escape each special character's
        $Escaped_Filename = $e.FileName -replace '\{', '{{' -replace '\}', '}}'

        $Current_FileProgress = $e.FileProgress
        $Current_CPS = $e.CPS
        $Current_OverallProgress = $e.OverallProgress

        Write-Progress -Id 0 -Activity "Synching" -CurrentOperation ("$Escaped_Filename - {0:P0}" -f $Current_FileProgress) -Status ("{0:P0} complete at $Current_CPS bps" -f $Current_OverallProgress) -PercentComplete ($Current_OverallProgress * 100)
   }
   catch {
        Write-Host "Error Hit in FileTransferProgress"
        Write-Host "Escaped_Filename: $Escaped_Filename"
        Write-Host "Current_FileProgress: $Current_FileProgress"
        Write-Host "Current_CPS: $Current_CPS"
        Write-Host "Current_OverallProgress: $Current_OverallProgress"
   } 
}

Reply with quote

Advertisement

You can post new topics in this forum

Documentation

Support

Associations

Follow Us