[PATCH v5 0/1] MR734: 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 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. -- v5: tests: Make sure only one thread prints traces at a time. https://gitlab.winehq.org/wine/wine/-/merge_requests/734
From: Francois Gouget <fgouget(a)codeweavers.com> 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 | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/include/wine/test.h b/include/wine/test.h index 1690c5613d8..a8d4c0e3262 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) +{ + UINT ret = WaitForSingleObject(winetest_mutex, INFINITE); + if (ret != WAIT_OBJECT_0 && ret != WAIT_ABANDONED) + winetest_printf("could not get the print lock: %u\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,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); @@ -441,10 +473,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 +585,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 +678,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 +686,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 +708,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
This is particularly useful for the Direct 3D tests because they are multi-threaded. In particular d3d11:d3d11 has a lot of failures and generates at least one garbled failure message per day in the WineTest results: 2022-08-31: https://test.winehq.org/data/3fdc28c7f866c060cb716f9f81a1dd5c466e0cac/linux_... `d3d11.c:2942: d3d11.c:6403: Test marked todo: Got unexpected hr 0x1.` 2022-08-30: https://test.winehq.org/data/c0ad6d745e511da6e1459fb6a5b51ac307205c24/linux_... `d3d11.c:1576: Test marked todo: d3d11.c:16617: Test marked todo: Feature level 0xb100: d3d11.c:1576: Test succeeded inside todo block: Format 0x5b - ...` `d3d11.c:1571: Test succeeded inside todo block: Feature level 0xa000: d3d11.c:21131: Test marked todo: Feature level 0xa100: d3d11.c:16610: Test marked todo: SHADER_SAMPLE is supported for R32G32B32A32_UINT.` 2022-08-29: https://test.winehq.org/data/f143af50a35f77880babf817899a33e4579b1dd3/linux_... `d3d11.c:1571: Test succeeded inside todo block: d3d11.c:1576: Test succeeded inside todo block: Feature level 0xb000: Got unexpected hr 0.` 2022-08-29: https://test.winehq.org/data/f143af50a35f77880babf817899a33e4579b1dd3/linux_... `d3d11.c:1576: Test succeeded inside todo block: d3d11.c:1576: Test succeeded inside todo block: Feature level 0x9100: Got unexpected hr 0.` 2022-08-28: https://test.winehq.org/data/a4930f003f45ab82c4c05746cbd29cbd4af09735/linux_... `d3d11.c:1576: Test succeeded inside todo block: Feature level 0xa100: d3d11.c:1571: Test succeeded inside todo block: Feature level 0xb000: Got unexpected hr 0.` 2022-08-28: https://test.winehq.org/data/a4930f003f45ab82c4c05746cbd29cbd4af09735/linux_... `d3d11.c:5791: Test marked todo: d3d11.c:6403: Test marked todo: Got unexpected hr 0x1.` -- https://gitlab.winehq.org/wine/wine/-/merge_requests/734#note_7443
participants (2)
-
Francois Gouget -
Francois Gouget (＠fgouget)