Re: wine/test.h: Identify test result lines printed by child processes.
Francois Gouget <fgouget(a)codeweavers.com> writes:
Currently the child process result lines are indistinguishable from the main process one. This makes it impossible to automatically detect when a process exits abruptly, i.e. without printing a result line, if it has run a subprocess. By making the subprocess result lines different analysis tools will detect that the main result line is missing and automatically consider that the main process crashed, thus marking the test as failed.
Signed-off-by: Francois Gouget <fgouget(a)codeweavers.com> ---
This should fix bug 32354: https://bugs.winehq.org/show_bug.cgi?id=32354
I don't think the test framework should be modifying the environment in all the tests. It already breaks some things: ../../../tools/runtest -q -P wine -T ../../.. -M msvcrt.dll -p msvcrt_test.exe.so environ && touch environ.ok environ.c:198: Test failed: Expected environment block pointer element to be non-NULL wine: Unhandled page fault on read access to 0x00000000 at address 0x7ed2a986 (thread 0074), starting debugger... -- Alexandre Julliard julliard(a)winehq.org
On Mon, 30 Jan 2017, Alexandre Julliard wrote: [...]
I don't think the test framework should be modifying the environment in all the tests. It already breaks some things:
../../../tools/runtest -q -P wine -T ../../.. -M msvcrt.dll -p msvcrt_test.exe.so environ && touch environ.ok environ.c:198: Test failed: Expected environment block pointer element to be non-NULL wine: Unhandled page fault on read access to 0x00000000 at address 0x7ed2a986 (thread 0074), starting debugger...
Damn. I still think making the child process result lines different from their parent's is necessary to fix bug 32354 but I'm open to alternatives if someone has any idea. https://bugs.winehq.org/show_bug.cgi?id=32354 Maybe creating a named object would be less likely to break the tests and be acceptable? For instance this could be a mutex called something like "winetest${bitness}_${dll}_${test}" to avoid problems in case different tests are run in parallel, and the idea would be to check for GetLastError() == ERROR_ALREADY_EXISTS. The nice thing about named objects is they should just go away when the last process referencing them goes away. Creating a file instead would certainly avoid nasty side-effects but to avoid trouble with left-over files after crashes one would have to check for locks on it which seems much more complex. -- Francois Gouget <fgouget(a)codeweavers.com>
Francois Gouget <fgouget(a)codeweavers.com> writes:
On Mon, 30 Jan 2017, Alexandre Julliard wrote: [...]
I don't think the test framework should be modifying the environment in all the tests. It already breaks some things:
../../../tools/runtest -q -P wine -T ../../.. -M msvcrt.dll -p msvcrt_test.exe.so environ && touch environ.ok environ.c:198: Test failed: Expected environment block pointer element to be non-NULL wine: Unhandled page fault on read access to 0x00000000 at address 0x7ed2a986 (thread 0074), starting debugger...
Damn.
I still think making the child process result lines different from their parent's is necessary to fix bug 32354 but I'm open to alternatives if someone has any idea. https://bugs.winehq.org/show_bug.cgi?id=32354
Couldn't you simply print the pid, have winetest print it too on the 'done' line, and check that they match? -- Alexandre Julliard julliard(a)winehq.org
On Tue, 31 Jan 2017, Alexandre Julliard wrote: [...]
Couldn't you simply print the pid, have winetest print it too on the 'done' line, and check that they match?
That's going to be more work but it's an excellent idea. Would something like this do? diff --git a/include/wine/test.h b/include/wine/test.h index f33ab9ab560..cd07772e366 100644 --- a/include/wine/test.h +++ b/include/wine/test.h @@ -590,8 +590,9 @@ static int run_test( const char *name ) if (winetest_debug) { - printf( "%s: %d tests executed (%d marked as todo, %d %s), %d skipped.\n", - test->name, successes + failures + todo_successes + todo_failures, + printf( "%s:%u %d tests executed (%d marked as todo, %d %s), %d skipped.\n", + test->name, GetCurrentProcessId(), + successes + failures + todo_successes + todo_failures, todo_successes, failures + todo_failures, (failures + todo_failures != 1) ? "failures" : "failure", skipped ); diff --git a/programs/winetest/main.c b/programs/winetest/main.c index 1eb49b6a699..388e351c5b3 100644 --- a/programs/winetest/main.c +++ b/programs/winetest/main.c @@ -620,7 +620,7 @@ static void append_path( const char *path) value of WaitForSingleObject. */ static int -run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms) +run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms, DWORD* pid) { STARTUPINFOA si; PROCESS_INFORMATION pi; @@ -634,9 +634,13 @@ run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms) if (!CreateProcessA (NULL, cmd, NULL, NULL, TRUE, CREATE_DEFAULT_ERROR_MODE, NULL, tempdir, &si, &pi)) + { + if (pid) *pid = 0; return -2; + } CloseHandle (pi.hThread); + if (pid) *pid = pi.dwProcessId; status = wait_process( pi.hProcess, ms ); switch (status) { @@ -720,7 +724,7 @@ get_subtests (const char *tempdir, struct wine_test *test, LPSTR res_name) /* We need to add the path (to the main dll) to PATH */ append_path(test->maindllpath); } - status = run_ex (cmd, subfile, tempdir, 5000); + status = run_ex (cmd, subfile, tempdir, 5000, NULL); err = GetLastError(); if (test->maindllpath) { /* Restore PATH again */ @@ -791,13 +795,13 @@ run_test (struct wine_test* test, const char* subtest, HANDLE out_file, const ch else { int status; - DWORD start = GetTickCount(); + DWORD pid, start = GetTickCount(); char *cmd = strmake (NULL, "%s %s", test->exename, subtest); report (R_STEP, "Running: %s:%s", test->name, subtest); xprintf ("%s:%s start %s -\n", test->name, subtest, file); - status = run_ex (cmd, out_file, tempdir, 120000); + status = run_ex (cmd, out_file, tempdir, 120000, &pid); heap_free (cmd); - xprintf ("%s:%s done (%d) in %ds\n", test->name, subtest, status, (GetTickCount()-start)/1000); + xprintf ("%s:%s:%u done (%d) in %ds\n", test->name, subtest, pid, status, (GetTickCount()-start)/1000); if (status) failures++; } if (failures) report (R_STATUS, "Running tests - %u failures", failures); If yes I'll also update the code parsing the test results for the winetest and testbot websites so they recognize both the old and new styles. Then this patch can be committed and I'll adapt it to TestLauncher which will mean committing the new binaries to Git (yuck) unless the TestBot is further modified, or we revive the idea of using WineTest for everything (but it cannot be built for just one test anymore). -- Francois Gouget <fgouget(a)codeweavers.com>
Francois Gouget <fgouget(a)codeweavers.com> writes:
On Tue, 31 Jan 2017, Alexandre Julliard wrote: [...]
Couldn't you simply print the pid, have winetest print it too on the 'done' line, and check that they match?
That's going to be more work but it's an excellent idea.
Would something like this do?
I would print the pid in hex to match other Wine traces, but otherwise it looks fine.
If yes I'll also update the code parsing the test results for the winetest and testbot websites so they recognize both the old and new styles. Then this patch can be committed and I'll adapt it to TestLauncher which will mean committing the new binaries to Git (yuck) unless the TestBot is further modified, or we revive the idea of using WineTest for everything (but it cannot be built for just one test anymore).
Using winetest would definitely be better. -- Alexandre Julliard julliard(a)winehq.org
Currently the child process summary lines are indistinguishable from the main process one. This makes it impossible to automatically detect when a process exits abruptly, i.e. without printing a summary line, if it has run a subprocess. This patch will let analysis tools identify which summary lines correspond to processes they started and thus when some are missing. Note also that in case of a crash the 'unhandled exception' play the same role as the test summary lines. Thus it is important to also tag them with the pid of the source process. Signed-off-by: Francois Gouget <fgouget(a)codeweavers.com> --- Preview of the patch that's meant to go along with this WineRunTask patch: https://www.winehq.org/pipermail/wine-patches/2017-February/158323.html include/wine/test.h | 8 +++++--- programs/winetest/main.c | 14 +++++++++----- 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/include/wine/test.h b/include/wine/test.h index f33ab9ab560..bf353a5076f 100644 --- a/include/wine/test.h +++ b/include/wine/test.h @@ -590,8 +590,9 @@ static int run_test( const char *name ) if (winetest_debug) { - printf( "%s: %d tests executed (%d marked as todo, %d %s), %d skipped.\n", - test->name, successes + failures + todo_successes + todo_failures, + printf( "%04x:%s: %d tests executed (%d marked as todo, %d %s), %d skipped.\n", + GetCurrentProcessId(), test->name, + successes + failures + todo_successes + todo_failures, todo_successes, failures + todo_failures, (failures + todo_failures != 1) ? "failures" : "failure", skipped ); @@ -617,7 +618,8 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs ) if (data->current_file) printf( "%s:%d: this is the last test seen before the exception\n", data->current_file, data->current_line ); - printf( "%s: unhandled exception %08x at %p\n", current_test->name, + printf( "%04x:%s: unhandled exception %08x at %p\n", + GetCurrentProcessId(), current_test->name, ptrs->ExceptionRecord->ExceptionCode, ptrs->ExceptionRecord->ExceptionAddress ); fflush( stdout ); return EXCEPTION_EXECUTE_HANDLER; diff --git a/programs/winetest/main.c b/programs/winetest/main.c index 9c32573a3da..c8ff1026638 100644 --- a/programs/winetest/main.c +++ b/programs/winetest/main.c @@ -609,7 +609,7 @@ static void append_path( const char *path) value of WaitForSingleObject. */ static int -run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms) +run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms, DWORD* pid) { STARTUPINFOA si; PROCESS_INFORMATION pi; @@ -627,9 +627,13 @@ run_ex (char *cmd, HANDLE out_file, const char *tempdir, DWORD ms) if (!CreateProcessA (NULL, cmd, NULL, NULL, TRUE, CREATE_DEFAULT_ERROR_MODE, NULL, tempdir, &si, &pi)) + { + if (pid) *pid = 0; return -2; + } CloseHandle (pi.hThread); + if (pid) *pid = pi.dwProcessId; status = wait_process( pi.hProcess, ms ); switch (status) { @@ -713,7 +717,7 @@ get_subtests (const char *tempdir, struct wine_test *test, LPSTR res_name) /* We need to add the path (to the main dll) to PATH */ append_path(test->maindllpath); } - status = run_ex (cmd, subfile, tempdir, 5000); + status = run_ex (cmd, subfile, tempdir, 5000, NULL); err = GetLastError(); if (test->maindllpath) { /* Restore PATH again */ @@ -785,13 +789,13 @@ run_test (struct wine_test* test, const char* subtest, HANDLE out_file, const ch else { int status; - DWORD start = GetTickCount(); + DWORD pid, start = GetTickCount(); char *cmd = strmake (NULL, "%s %s", test->exename, subtest); report (R_STEP, "Running: %s:%s", test->name, subtest); xprintf ("%s:%s start %s -\n", test->name, subtest, file); - status = run_ex (cmd, out_file, tempdir, 120000); + status = run_ex (cmd, out_file, tempdir, 120000, &pid); heap_free (cmd); - xprintf ("%s:%s done (%d) in %ds\n", test->name, subtest, status, (GetTickCount()-start)/1000); + xprintf ("%s:%s:%04x done (%d) in %ds\n", test->name, subtest, pid, status, (GetTickCount()-start)/1000); if (status) failures++; } if (failures) report (R_STATUS, "Running tests - %u failures", failures); -- 2.11.0
participants (2)
-
Alexandre Julliard -
Francois Gouget