[PATCH 0/1] MR734: tests: Make sure only one thread prints traces at a time.

[Francois Gouget (＠fgouget)]

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 tests messages is now serialized. Note that if a process
crashes while holding the mutex, that mutex will be abandonned and not
cause a deadlock.

-- 
https://gitlab.winehq.org/wine/wine/-/merge_requests/734

[PATCH 1/1] tests: Make sure only one thread prints traces at a time.

[Francois Gouget]

From: Francois Gouget <fgouget(a)free.fr>

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 tests messages is now serialized. Note that if a process
crashes while holding the mutex, that mutex will be abandonned and not
cause a deadlock.
---
 include/wine/test.h | 42 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 42 insertions(+)

diff --git a/include/wine/test.h b/include/wine/test.h
index 1690c5613d8..57bee9d467e 100644
--- a/include/wine/test.h
+++ b/include/wine/test.h
@@ -203,6 +203,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;
@@ -309,14 +311,30 @@ static void winetest_print_context( const char *msgtype )
         printf( "%s: ", data->context[i] );
 }
 
+static void winetest_print_lock(void)
+{
+    DWORD ret = WaitForSingleObject(winetest_mutex, INFINITE);
+    if (ret != WAIT_OBJECT_0 && ret != WAIT_ABANDONED)
+        winetest_printf("could not get the print lock: %ld\n", ret);
+}
+
+static void winetest_print_unlock(void)
+{
+    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 )
@@ -336,7 +354,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;
 }
@@ -359,10 +381,12 @@ int winetest_vok( int condition, const char *msg, va_list args )
     {
         if (condition)
         {
+            winetest_print_lock();
             if (winetest_color) printf( color_dark_red );
             winetest_print_context( "Test succeeded inside todo block: " );
             vprintf(msg, args);
             if (winetest_color) printf( color_reset );
+            winetest_print_unlock();
             InterlockedIncrement(&todo_failures);
             return 0;
         }
@@ -373,10 +397,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);
             }
@@ -389,10 +415,12 @@ int winetest_vok( int condition, const char *msg, va_list args )
     {
         if (!condition)
         {
+            winetest_print_lock();
             if (winetest_color) printf( color_bright_red );
             winetest_print_context( "Test failed: " );
             vprintf(msg, args);
             if (winetest_color) printf( color_reset );
+            winetest_print_unlock();
             InterlockedIncrement(&failures);
             return 0;
         }
@@ -401,9 +429,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;
@@ -428,10 +458,13 @@ void winetest_trace( const char *msg, ... )
         return;
     if (winetest_add_line() < winetest_mute_threshold)
     {
+        char* foo = NULL;
+        winetest_print_lock();
         winetest_print_context( "" );
         va_start(valist, msg);
         vprintf( msg, valist );
         va_end(valist);
+        winetest_print_unlock();
     }
     else
         InterlockedIncrement(&muted_traces);
@@ -441,10 +474,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
@@ -551,12 +586,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);
         }
@@ -640,6 +679,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 );
@@ -647,6 +687,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;
 }
 
@@ -668,6 +709,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;
-- 
GitLab

https://gitlab.winehq.org/wine/wine/-/merge_requests/734