Re: wine/test.h: Identify test result lines printed by child processes.

[Alexandre Julliard]

Francois Gouget  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
>
> 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...

wine/test.h: Identify test result lines printed by child processes.

[Francois Gouget]

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.

wine/test.h: Identify test result lines printed by child processes.

[Alexandre Julliard]

Francois Gouget  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?

wine/test.h: Identify test result lines printed by child processes.

[Francois Gouget]

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).

wine/test.h: Identify test result lines printed by child processes.

[Alexandre Julliard]

Francois Gouget  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.

wine/test.h: Identify the process responsible for test summary lines. [RFC]

[Francois Gouget]

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 
---

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);