RFC: Flushing the test reports

[Francois Gouget]

When a test causes Windows to crash the test output is often lost, even 
if it was redirected to a file : said file is often either 0-byte long 
or is missing a huge chunk.

This is particularly annoying when the crash happens as part of WineTest 
as then one has to manually run a bunch of tests to try and find which 
one caused the issue. And it's not always which test caused the crash as 
shown by the rasapi32:rasapi case (bug 42185).

So I have tested a couple of approaches to better pinpoint which test is 
causing trouble, and possibly even which chunk of code in that test 
causes the crash.

The first approach is simple: flush the WineTest report to disk between 
each test (in Unix terms sync). It has little impact on performance and 
in case of a crash the last 'dll:test start' line would clearly identify 
the test responsible.

diff --git a/programs/winetest/main.c b/programs/winetest/main.c
index 50ebf4fd52a..df527734bb8 100644
--- a/programs/winetest/main.c
+++ b/programs/winetest/main.c
@@ -626,6 +626,11 @@ run_ex (char *cmd, HANDLE out_file, const char 
*tempdir, DWORD ms)
     PROCESS_INFORMATION pi;
     DWORD wait, status;

+    /* Flush to disk so we know which test caused Windows to crash if it does */
+    if (out_file)
+        FlushFileBuffers(out_file);
+    FlushFileBuffers(GetStdHandle( STD_ERROR_HANDLE ));
+
     GetStartupInfoA (&si);
     si.dwFlags    = STARTF_USESTDHANDLES;
     si.hStdInput  = GetStdHandle( STD_INPUT_HANDLE );

(the second flush is so WineTest's output too is flushed to disk in case 
stdout is redirected to a file though I did not really check that this 
part works)

Another approach is to add these calls in wine/test.h. This narrows the 
location of the Windows crash down to an ok()/trace() interval, even 
more narrow if WINETEST_REPORT_SUCCESS is set.

However this has quite an impact on performance:
 * WineTest normally takes about 19 minutes.
 * With the extra flushing this goes up to 29 minutes.
 * With no flushing but report success I get 45 minutes.
 * With both flushing and report success this shoots up to 315+ minutes.

The report success cases can be ignored but even in the normal case 
the extra 10 minutes are probably not acceptable.

So I set the flushing code behind a $WINETEST_FLUSH check. So once 
you've identified that, for instance, rasapi32:rasapi is causing 
trouble, you can run it on its own with report success and flushing 
to pinpoint where it goes wrong.

Of course on the TestBot you still won't get the report (until the 
TestBot is changed appropriately), and you'll have to contend with the 2 
minutes timeout but even with those options 88% of the tests completed 
within the time limit on my machine.

That approach could be done with the patch below.

commit ef211f6480fe84fd7660314c27bcaa5630dd0c16
Author: Francois Gouget 
Date:   Sun Jan 22 02:57:23 2017 +0100

tests: Flush after each message if WINETEST_FLUSH is set.

Signed-off-by: Francois Gouget

diff --git a/include/wine/test.h b/include/wine/test.h
index aa89c55ca07..149b0a9ae14 100644
--- a/include/wine/test.h
+++ b/include/wine/test.h
@@ -52,6 +52,9 @@ extern int winetest_debug;
 /* running in interactive mode? */
 extern int winetest_interactive;

+/* flush after each trace */
+extern int winetest_flush;
+
 /* current platform */
 extern const char *winetest_platform;

@@ -199,6 +202,9 @@ int winetest_debug = 1;
 /* interactive mode? */
 int winetest_interactive = 0;

+/* flush to disk after every message? */
+int winetest_flush = 0;
+
 /* current platform */
 const char *winetest_platform = "windows";

@@ -291,6 +297,11 @@ int broken( int condition )
 {
     return (strcmp(winetest_platform, "windows") == 0) && condition;
 }
+static void winetest_do_flush( void )
+{
+    if (winetest_flush)
+        FlushFileBuffers(GetStdHandle( STD_ERROR_HANDLE ));
+}

/*
  * Checks condition.
@@ -313,6 +324,7 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
             printf( "%s:%d: Test succeeded inside todo block: ",
                     data->current_file, data->current_line );
             vprintf(msg, args);
+            winetest_do_flush();
             InterlockedIncrement(&todo_failures);
             return 0;
         }
@@ -323,6 +335,7 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
                 printf( "%s:%d: Test marked todo: ",
                         data->current_file, data->current_line );
                 vprintf(msg, args);
+                winetest_do_flush();
             }
             InterlockedIncrement(&todo_successes);
             return 1;
@@ -335,14 +348,18 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
             printf( "%s:%d: Test failed: ",
                     data->current_file, data->current_line );
             vprintf(msg, args);
+            winetest_do_flush();
             InterlockedIncrement(&failures);
             return 0;
         }
         else
         {
             if (report_success)
+            {
                 printf( "%s:%d: Test succeeded\n",
                         data->current_file, data->current_line);
+                winetest_do_flush();
+            }
             InterlockedIncrement(&successes);
             return 1;
         }
@@ -369,6 +386,7 @@ void __winetest_cdecl winetest_trace( const char *msg, ... )
         __winetest_va_start(valist, msg);
         vprintf(msg, valist);
         __winetest_va_end(valist);
+        winetest_do_flush();
     }
 }

@@ -378,6 +396,7 @@ void winetest_vskip( const char *msg, __winetest_va_list args )

printf( "%s:%d: Tests skipped: ", data->current_file, data->current_line );
     vprintf(msg, args);
+    winetest_do_flush();
     skipped++;
 }

@@ -443,7 +462,10 @@ void winetest_wait_child_process( HANDLE process )
     DWORD exit_code = 1;

if (WaitForSingleObject( process, 30000 ))
+    {
         printf( "%s: child process wait failed\n", current_test->name );
+        winetest_do_flush();
+    }
     else
         GetExitCodeProcess( process, &exit_code );

@@ -452,12 +474,14 @@ void winetest_wait_child_process( HANDLE process )
         if (exit_code > 255)
         {
             printf( "%s: exception 0x%08x in child process\n", current_test->name, exit_code );
+            winetest_do_flush();
             InterlockedIncrement( &failures );
         }
         else
         {
             printf( "%s: %u failures in child process\n",
                     current_test->name, exit_code );
+            winetest_do_flush();
             while (exit_code-- > 0)
                 InterlockedIncrement(&failures);
         }
@@ -599,6 +623,7 @@ static int run_test( const char *name )
                 todo_successes, failures + todo_failures,
                 (failures + todo_failures != 1) ? "failures" : "failure",
                 skipped );
+        winetest_do_flush();
     }
     status = (failures + todo_failures < 255) ? failures + todo_failures : 255;
     return status;
@@ -624,6 +649,7 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs )
     printf( "%s: unhandled exception %08x at %p\n", current_test->name,
             ptrs->ExceptionRecord->ExceptionCode, ptrs->ExceptionRecord->ExceptionAddress );
     fflush( stdout );
+    winetest_do_flush();
     return EXCEPTION_EXECUTE_HANDLER;
 }

@@ -660,6 +686,7 @@ int main( int argc, char **argv )
     if (GetEnvironmentVariableA( "WINETEST_IS_CHILD", p, sizeof(p) )) winetest_is_child = atoi(p);
     /* Identify any future process as a child of this one */
     SetEnvironmentVariableA( "WINETEST_IS_CHILD", "1" );
+    if (GetEnvironmentVariableA( "WINETEST_FLUSH", p, sizeof(p) )) winetest_flush = atoi(p);

if (!strcmp( winetest_platform, "windows" )) SetUnhandledExceptionFilter( exc_filter );
     if (!winetest_interactive) SetErrorMode( SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX );

Both approaches could be combined.

Comments?
Suggestions?