Francois Gouget : tests: Make sure only one thread prints traces at a time.

[Alexandre Julliard]

Module: wine
Branch: master
Commit: e28d24621d84c930a2873b70515348372f9f401f
URL:    https://gitlab.winehq.org/wine/wine/-/commit/e28d24621d84c930a2873b705153483...

Author: Francois Gouget <fgouget(a)codeweavers.com>
Date:   Tue Aug 30 15:26:25 2022 +0200

tests: Make sure only one thread prints traces at a time.

Some Wine tests are multi-threaded or start child processes which can
result in traces and failure messages being garbled which prevents them
from being recognized by continuous integration tools.
So printing the test messages is now serialized. Note that if a process
crashes while holding the mutex, that mutex will be abandoned and not
cause a deadlock.

---

 include/wine/test.h | 49 +++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 49 insertions(+)

diff --git a/include/wine/test.h b/include/wine/test.h
index 605081607f1..e502c967d9b 100644
--- a/include/wine/test.h
+++ b/include/wine/test.h
@@ -219,6 +219,8 @@ int winetest_mute_threshold = 42;
 /* use ANSI escape codes for output coloring */
 static int winetest_color;
 
+static HANDLE winetest_mutex;
+
 /* passing arguments around */
 static int winetest_argc;
 static char** winetest_argv;
@@ -330,14 +332,36 @@ static void winetest_print_context( const char *msgtype )
         printf( "%s: ", data->context[i] );
 }
 
+static void winetest_print_lock(void)
+{
+    UINT ret;
+
+    if (!winetest_mutex) return;
+    ret = WaitForSingleObject(winetest_mutex, 30000);
+    if (ret != WAIT_OBJECT_0 && ret != WAIT_ABANDONED)
+    {
+        winetest_printf("could not get the print lock: %u\n", ret);
+        winetest_mutex = 0;
+    }
+}
+
+static void winetest_print_unlock(void)
+{
+    if (winetest_mutex) ReleaseMutex(winetest_mutex);
+}
+
 void winetest_subtest( const char* name )
 {
+    winetest_print_lock();
     winetest_printf( "Subtest %s\n", name );
+    winetest_print_unlock();
 }
 
 void winetest_ignore_exceptions( BOOL ignore )
 {
+    winetest_print_lock();
     winetest_printf( "IgnoreExceptions=%d\n", ignore ? 1 : 0 );
+    winetest_print_unlock();
 }
 
 int broken( int condition )
@@ -357,7 +381,11 @@ static LONG winetest_add_line( void )
     index = data->current_line % ARRAY_SIZE(line_counters);
     count = InterlockedIncrement(line_counters + index) - 1;
     if (count == winetest_mute_threshold)
+    {
+        winetest_print_lock();
         winetest_printf( "Line has been silenced after %d occurrences\n", winetest_mute_threshold );
+        winetest_print_unlock();
+    }
 
     return count;
 }
@@ -380,6 +408,7 @@ int winetest_vok( int condition, const char *msg, va_list args )
     {
         if (condition)
         {
+            winetest_print_lock();
             if (data->flaky_level)
             {
                 if (winetest_color) printf( color_dark_purple );
@@ -395,6 +424,7 @@ int winetest_vok( int condition, const char *msg, va_list args )
                 InterlockedIncrement(&todo_failures);
             }
             if (winetest_color) printf( color_reset );
+            winetest_print_unlock();
             return 0;
         }
         else
@@ -404,10 +434,12 @@ int winetest_vok( int condition, const char *msg, va_list args )
             {
                 if (winetest_debug > 0)
                 {
+                    winetest_print_lock();
                     if (winetest_color) printf( color_yellow );
                     winetest_print_context( "Test marked todo: " );
                     vprintf(msg, args);
                     if (winetest_color) printf( color_reset );
+                    winetest_print_unlock();
                 }
                 InterlockedIncrement(&todo_successes);
             }
@@ -420,6 +452,7 @@ int winetest_vok( int condition, const char *msg, va_list args )
     {
         if (!condition)
         {
+            winetest_print_lock();
             if (data->flaky_level)
             {
                 if (winetest_color) printf( color_bright_purple );
@@ -435,6 +468,7 @@ int winetest_vok( int condition, const char *msg, va_list args )
                 InterlockedIncrement(&failures);
             }
             if (winetest_color) printf( color_reset );
+            winetest_print_unlock();
             return 0;
         }
         else
@@ -442,9 +476,11 @@ int winetest_vok( int condition, const char *msg, va_list args )
             if (winetest_report_success ||
                 (winetest_time && GetTickCount() >= winetest_last_time + 1000))
             {
+                winetest_print_lock();
                 if (winetest_color) printf( color_green );
                 winetest_printf("Test succeeded\n");
                 if (winetest_color) printf( color_reset );
+                winetest_print_unlock();
             }
             InterlockedIncrement(&successes);
             return 1;
@@ -469,10 +505,12 @@ void winetest_trace( const char *msg, ... )
         return;
     if (winetest_add_line() < winetest_mute_threshold)
     {
+        winetest_print_lock();
         winetest_print_context( "" );
         va_start(valist, msg);
         vprintf( msg, valist );
         va_end(valist);
+        winetest_print_unlock();
     }
     else
         InterlockedIncrement(&muted_traces);
@@ -482,10 +520,12 @@ void winetest_vskip( const char *msg, va_list args )
 {
     if (winetest_add_line() < winetest_mute_threshold)
     {
+        winetest_print_lock();
         if (winetest_color) printf( color_blue );
         winetest_print_context( "Tests skipped: " );
         vprintf(msg, args);
         if (winetest_color) printf( color_reset );
+        winetest_print_unlock();
         InterlockedIncrement(&skipped);
     }
     else
@@ -613,12 +653,16 @@ void winetest_wait_child_process( HANDLE process )
         if (exit_code > 255)
         {
             DWORD pid = GetProcessId( process );
+            winetest_print_lock();
             winetest_printf( "unhandled exception %08x in child process %04x\n", (UINT)exit_code, (UINT)pid );
+            winetest_print_unlock();
             InterlockedIncrement( &failures );
         }
         else if (exit_code)
         {
+            winetest_print_lock();
             winetest_printf( "%u failures in child process\n", (UINT)exit_code );
+            winetest_print_unlock();
             while (exit_code-- > 0)
                 InterlockedIncrement(&failures);
         }
@@ -673,6 +717,7 @@ static int run_test( const char *name )
 
     if (winetest_debug)
     {
+        winetest_print_lock();
         if (muted_todo_successes || muted_skipped || muted_traces)
             printf( "%04x:%s:%s Silenced %d todos, %d skips and %d traces.\n",
                     (UINT)GetCurrentProcessId(), test->name, winetest_elapsed(),
@@ -683,6 +728,7 @@ static int run_test( const char *name )
                 (UINT)todo_successes, (UINT)flaky_failures, (UINT)(failures + todo_failures),
                 (failures + todo_failures != 1) ? "failures" : "failure",
                 (UINT)skipped );
+        winetest_print_unlock();
     }
     status = failures + todo_failures;
     if (!winetest_allow_flaky) status += flaky_failures;
@@ -704,6 +750,7 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs )
 {
     struct tls_data *data = get_tls_data();
 
+    winetest_print_lock();
     if (data->current_file)
         printf( "%s:%d: this is the last test seen before the exception\n",
                 data->current_file, data->current_line );
@@ -711,6 +758,7 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs )
             (UINT)GetCurrentProcessId(), current_test->name, winetest_elapsed(),
             (UINT)ptrs->ExceptionRecord->ExceptionCode, ptrs->ExceptionRecord->ExceptionAddress );
     fflush( stdout );
+    winetest_print_unlock();
     return EXCEPTION_EXECUTE_HANDLER;
 }
 
@@ -732,6 +780,7 @@ int main( int argc, char **argv )
     char p[128];
 
     setvbuf (stdout, NULL, _IONBF, 0);
+    winetest_mutex = CreateMutexA(NULL, FALSE, "winetest_print_mutex");
 
     winetest_argc = argc;
     winetest_argv = argv;