Home → Problems →

Robocopy does not report errors when run on AppVeyor

• Edit

Rob

09 Mar, 2022 02:07 PM

I create a post on GitHub community before finding this link.

https://github.community/t/robocopy-unit-test-fails-on-github-succeeds-locally-robocopy-does-not-report-errors-when-run-on-appveyor/234777

Essentially, my project is a wrapper for RoboCopy. It has a ‘live updater’ that shows file stats live by intercepting t he Std:out of the robocopy process.

The unit tests that are failing because the live update results do not match robocopy’s final tally.

But these unit tests pass just fine when run locally. The unit test is also working properly, since robocopy itself shows 1 file as failing, which is intended in the test.

The issue here is that when GitHub commits tell the tests to run automatically on AppVeyor, the tests fail because robocopy is not reporting errors to it’s std:out, meaning the live results never catch that an error occurred, because one was never recorded into the log.

This issue appears to be exclusive to when running robocopy on AppVeyor

1. Support Staff 1 Posted by Feodor Fitsner on 09 Mar, 2022 06:23 PM

   

   Hi Rob,

   The process of collecting output from the process programmatically is different from that in Windows console. You collect the output using event handlers of Process class. It is triggered on a new line only. AppVeyor uses the same approach, but it constantly reads an output stream. So, there could be some quirks with double redirect, like buffering issues. It's hard to tell you what's wrong and where without digging into your code. Maybe you can do a simple repro, like a small console program or test with Process class calling some robocopy command and catching the output.

   • Edit

2. 2 Posted by Rob on 09 Mar, 2022 06:57 PM

   

   So that is where it gets odd though. The entire log being written into the test results is captured using the same event.

   We subscribe to the process events, start the process, wait for it to exit. As the process outputs the data, it gets added to a list<string> object.

   That list is then written into the test log at the end with a ForEach—loop.

   The log is identical between local and AppVeyor, other than the fact that robocopy is not outputting the error lines in the AppVeyor log. That is the actual issue, since the project relies on all items being written to the log.

   So AppVeyor is doing it’s job fine, no arguments here. The issue is whatever executable of robocopy AppVeyor has is not writing errors into its std:out.

   I’m on mobile, so can’t copy-paste the log here, but it’s available in the link and in the AppVeyor logs, which were also linked (atleast in the GHC thread)

   • Edit

3. Support Staff 3 Posted by Feodor Fitsner on 09 Mar, 2022 08:33 PM

   

   OK, can you give me a sample of robocopy command, its expected output and actual output on AppVeyor?

   • Edit

4. 4 Posted by Rob on 10 Mar, 2022 01:46 AM

   

   I would've replied hours ago, but I couldn't get appveyor to build my test repo that displays the issue. Turns out VS was not providing a reference in the CSProj file to a nuget package that was being downloaded....But now that its working, I can reply:

   The issue at hand is that RoboCopy wasn't generating an error in its std:out, sometimes?

   Here is the link to the new repo that I finally got working that displays the issue:
   https://github.com/RFBomb/RoboCopyErrorTesting/tree/master/RoboCopy...

   In it I have two tests. Everything related to robocopy is run identical, the only thing that changes is the source folder as far as robocopy is concerned.

   here are the test results, not sure if you can see them.
   https://ci.appveyor.com/project/RFBomb/robocopyerrortesting/build/t...

   RoboCopy Command:
   

   robocopy  "C:\SomeSourceThatDoesNotExist" "C:\DestDoesNotMatter" /V /R:0 /W:10
   

   Expected Output:

   -------------------------------------------------------------------------------
   // Header omitted for brevity
   ------------------------------------------------------------------------------
   2022/03/09 20:32:00 ERROR 2 (0x00000002) Accessing Source Directory C:\SourceDirDoesNotExist\
   The system cannot find the file specified.
   

   According to my repo, the test above works fine.

   The test we have in our other repo though is simulating a file that is locked by another process. That test fails due to no error being reported.

   Same RoboCommand, except have it point at a valid source and destination.
   Use File.Open() to lock a file, run robocopy, unlock the file, print results.

   Expected Results:

   Running the Test
   - Creating Destination Directory
   - Locking File Path: C:\DEST\1024_Bytes.txt
   Setting Up RoboCopy Process
   - RoboCopy Executable Path: Robocopy.exe
   - Starting RoboCopy Process
   - RoboCopy Process has Exited
   - Unlocking the Locked file path.
   - No Error Data Received from Process (via Process.ErrorDataReceived)
   - Writing Log Lines: 
   
   
   -------------------------------------------------------------------------------
   Options : *.* /V /S /COPY:DAT /R:0 /W:3 
   ------------------------------------------------------------------------------
   
                      4    C:\RoboCopyValidation\RoboCopyErrorTesting\RoboCopyUnitTest\bin\Debug\SourceFiles\
       New File               0    0_Bytes.txt
   100%  
       Older               1024    1024_Bytes.txt
   2022/03/09 20:37:59 ERROR 32 (0x00000020) Copying File C:\RoboCopyValidation\RoboCopyErrorTesting\RoboCopyUnitTest\bin\Debug\SourceFiles\1024_Bytes.txt
   The process cannot access the file because it is being used by another process.
   
   
       New File               4    4_Bytes.htm
   0%  
   100%  
   ------------------------------------------------------------------------------
              Total    Copied   Skipped  Mismatch    FAILED    Extras
   Dirs :         2         1         1         0         0         0
   Files :         8         7         0         0         1         0
   Bytes :     2.0 k     1.0 k         0         0     1.0 k         0
   Times :   0:00:00   0:00:00                       0:00:00   0:00:00
   
   
   Speed :               37142 Bytes/sec.
   Speed :               2.125 MegaBytes/min.
   
   Ended : Wed Mar 09 20:37:59 2022
   

   Appveyor Results:

   - Creating Destination Directory
   - Locking File Path: C:\DEST\1024_Bytes.txt
   Setting Up RoboCopy Process
   - RoboCopy Executable Path: Robocopy.exe
   - Starting RoboCopy Process
   - RoboCopy Process has Exited
   - Unlocking the Locked file path.
   - Assertion Failed: No Error reported in the log.
   - No Error Data Received from Process (via Process.ErrorDataReceived)
   - Writing Log Lines: 
   
   
   -------------------------------------------------------------------------------
     Options : *.* /V /S /DCOPY:DA /COPY:DAT /R:0 /W:3 
   ------------------------------------------------------------------------------
                          4    C:\projects\robocopyerrortesting\RoboCopyUnitTest\bin\Debug\SourceFiles\
           New File               0    0_Bytes.txt
           Older               1015    1024_Bytes.txt
           New File               4    4_Bytes.htm
   100%  
   ------------------------------------------------------------------------------
   
                  Total    Copied   Skipped  Mismatch    FAILED    Extras
       Dirs :         2         1         1         0         0         0
      Files :         8         7         0         0         1         0
      Bytes :     1.9 k     1.0 k         0         0      1015         0
      Times :   0:00:00   0:00:00                       0:00:00   0:00:00
      Ended : Thursday, March 10, 2022 1:25:26 AM
   

   I've condensed both logs for brevity, showing only the files immediately before and after the expected error. The file marked as 'older' is the file that is locked and unable to be written to by robocopy. As you can see, the error is reported locally, but not on appveyor.
   Since the source not existing test reported an error, I have no idea what the issue could be.

   • Edit