Review of attachment 302460 [details] [review]:

Looks good to me.

Comment on attachment 302460 [details] [review]
gtestutils: better diagnostics if a captured subprocess  fails

Generally, yeah, this totally makes sense.

>+  escaped = g_strescape (test_trap_last_stdout, NULL);
>+  g_test_message ("child process (%s) stdout: %s", process_id, escaped);
>+  g_free (escaped);
>+
>+  escaped = g_strescape (test_trap_last_stderr, NULL);
>+  g_test_message ("child process (%s) stderr: %s", process_id, escaped);
>+  g_free (escaped);

stdout will often be empty, and in the case of a failed g_test_trap_assert_failed(), stderr will probably be empty. Maybe only print them if they're non-empty? Or else indicate explicitly that it was empty rather than just printing "... stdout: " (which looks like it means that the stdout starts on the next line)

(In reply to Dan Winship from comment #2)
> stdout will often be empty, and in the case of a failed
> g_test_trap_assert_failed(), stderr will probably be empty.

Fair point. If I used "... stdout: \"%s\"" and the same for stderr, would that address this concern? g_strescape() does escape double quotes, so it would be unambiguous.

If I did that, my sample output would change to this:

# child process (/gdbus/x11-autolaunch [22203]) stdout: ""
# child process (/gdbus/x11-autolaunch [22203]) stderr: "**\nGLib-GIO:ERROR:/home/user/glib2.0-2.44.0/./gio/tests/gdbus-unix-addresses.c:40:print_address: assertion failed (error == NULL): Cannot autolaunch D-Bus without X11 $DISPLAY (g-io-error-quark, 0)\n"

I think it's worth printing *something* even if there was no output on stdout, and doing an if/else to print '(none)' vs. '"foo"' (as opposed to '""' vs. '"foo"' like I suggest) seems like overkill?

Created attachment 302556 [details] [review]
gtestutils: better diagnostics if a captured subprocess fails

---

now with double quotes as suggested

Created attachment 302557 [details] [review]
g_test_subprocess: record raw wait status and interpret  it later

This avoids losing information that might be useful for later debugging.

Created attachment 302558 [details] [review]
GTest: interpret child processes' wait status if we log  their stdout/stderr

WCOREDUMP is not a separate "mode" as suggested by the previous
code to interpret wait status: instead, it is an extra bit of
information if the "mode" is WIFSIGNALED.

Created attachment 302559 [details]
manual test for Attachment #302558 [details]

This deliberately fails a bunch of unit tests to demonstrate the extra diagnostics added by my patches on this bug.

Sample output:

./a.out --tap --keep-going
# random seed: R02S7418e510c1585ffcc106cb5c165631d7
# child process (/exit0 [3461]) exit status: 0 (success)
# child process (/exit0 [3461]) stdout: "I am going to exit 0\n"
# child process (/exit0 [3461]) stderr: "I am going to exit 0 and this is stderr\n"
**
ERROR:test-subprocess.c:41:test_exit0: child process (/exit0 [3461]) did not fail as expected
# ERROR:test-subprocess.c:41:test_exit0: child process (/exit0 [3461]) did not fail as expected
not ok 1 /exit0
# child process (/exit23 [3463]) exit status: 23 (error)
# child process (/exit23 [3463]) stdout: ""
# child process (/exit23 [3463]) stderr: ""
**
ERROR:test-subprocess.c:52:test_exit23: child process (/exit23 [3463]) failed unexpectedly
# ERROR:test-subprocess.c:52:test_exit23: child process (/exit23 [3463]) failed unexpectedly
not ok 2 /exit23
# child process (/sigbus [3464]) killed by signal 7 (Bus error), core dumped
# child process (/sigbus [3464]) stdout: ""
# child process (/sigbus [3464]) stderr: ""
**
ERROR:test-subprocess.c:15:test_sigbus: child process (/sigbus [3464]) failed unexpectedly
# ERROR:test-subprocess.c:15:test_sigbus: child process (/sigbus [3464]) failed unexpectedly
not ok 3 /sigbus
# child process (/sigalrm [3480]) timed out
# child process (/sigalrm [3480]) stdout: ""
# child process (/sigalrm [3480]) stderr: ""
**
ERROR:test-subprocess.c:26:test_sigalrm: child process (/sigalrm [3480]) failed unexpectedly
# ERROR:test-subprocess.c:26:test_sigalrm: child process (/sigalrm [3480]) failed unexpectedly
not ok 4 /sigalrm
1..4

Review of attachment 302557 [details] [review]:

This looks good to me. Might want to add a comment to the declarations of WaitForChildData.child_status and test_trap_last_status to note that they store unmodified platform-specific exit status codes.

Review of attachment 302558 [details] [review]:

::: glib/gtestutils.c
@@ +2971,3 @@
 
+#ifdef G_OS_UNIX
+  if (WIFEXITED (test_trap_last_status)) /* normal exit */

Would it not be simpler to call g_test_trap_has_passed() here?

@@ +2976,3 @@
+        g_test_message ("child process (%s) exit status: 0 (success)",
+            process_id);
+      else

If you go with my suggestion, I guess a new g_test_trap_has_failed() should be added which checks this condition. Could be static for now, unless there’s a compelling reason to make it public.

@@ +2981,3 @@
+    }
+  else if (WIFSIGNALED (test_trap_last_status) &&
+      WTERMSIG (test_trap_last_status) == SIGALRM)

g_test_trap_reached_timeout()?

@@ +2985,3 @@
+      g_test_message ("child process (%s) timed out", process_id);
+    }
+  else if (WIFSIGNALED (test_trap_last_status))

Similarly, a g_test_trap_has_signalled() would be needed.

@@ +2997,3 @@
+          process_id, WTERMSIG (test_trap_last_status),
+          g_strsignal (WTERMSIG (test_trap_last_status)),
+          maybe_dumped_core);

Random idea: if we could call getrlimit(RLIMIT_CORE) and check /proc/sys/kernel/core_pattern, and work out if/where a core dump file has been written, it would be quite useful to print that out, for example as ‘run `gdb $argv[0] $core_dump_file`’ command the user could copy and paste for instant debugging gratification.

@@ +3005,3 @@
+    }
+#else
+  if (test_trap_last_status== 0)

Missing space before the ‘==’.

(In reply to Philip Withnall from comment #9)
> +#ifdef G_OS_UNIX
> +  if (WIFEXITED (test_trap_last_status)) /* normal exit */
> 
> Would it not be simpler to call g_test_trap_has_passed() here?

Maaaaaybe... but it seems easier to confirm by inspection that every (realistic) possibility is covered if it's consistently in terms of "parse a native wait-status from first principles". Could go either way.

> +  else if (WIFSIGNALED (test_trap_last_status) &&
> +      WTERMSIG (test_trap_last_status) == SIGALRM)
> 
> g_test_trap_reached_timeout()?

This one does seem possibly worth it, but it's such a matter of opinion that I'd prefer not to change it without a maintainer's review.

> +          maybe_dumped_core);
> 
> Random idea: if we could call getrlimit(RLIMIT_CORE) and check
> /proc/sys/kernel/core_pattern, and work out if/where a core dump file has
> been written, it would be quite useful to print that out, for example as
> ‘run `gdb $argv[0] $core_dump_file`’ command the user could copy and paste
> for instant debugging gratification.

In practice, on systems with Apport (Ubuntu) or abrt (Fedora) or corekeeper (e.g. my laptop), the core_pattern is going to be "|/some/helper" which doesn't really help you. Meanwhile, constructing a core filename from a core pattern is context-dependent: for instance, the default, "core", is only actually valid for the first core dumped to a particular directory. If "core" exists, subsequent cores are silently disambiguated by adding a number (process ID, I think).

I don't think we can *reliably* tell the user where the core is, and if it's unreliable, then it does more harm than good.

(Also, the effort:result ratio seems unfavourable :-)

(In reply to Simon McVittie from comment #10)
> (In reply to Philip Withnall from comment #9)
> > +#ifdef G_OS_UNIX
> > +  if (WIFEXITED (test_trap_last_status)) /* normal exit */
> > 
> > Would it not be simpler to call g_test_trap_has_passed() here?
> 
> Maaaaaybe... but it seems easier to confirm by inspection that every
> (realistic) possibility is covered if it's consistently in terms of "parse a
> native wait-status from first principles". Could go either way.

Yeah, it could easily go either way. Thought I’d mention it in case.

> > +          maybe_dumped_core);
> > 
> I don't think we can *reliably* tell the user where the core is, and if it's
> unreliable, then it does more harm than good.
> 
> (Also, the effort:result ratio seems unfavourable :-)

Yup. Also thought I’d mention it in case. :-)

> Fair point. If I used "... stdout: \"%s\"" and the same for stderr, would
> that address this concern? g_strescape() does escape double quotes, so it
> would be unambiguous.

Sounds good

(In reply to Simon McVittie from comment #7)
> Created attachment 302559 [details]
> manual test for Attachment #302558 [details]
> 
> This deliberately fails a bunch of unit tests to demonstrate the extra
> diagnostics added by my patches on this bug.

I think you could incorporate this into glib/tests/testing.c by using two levels of g_test_trap_subprocess(). (The inner level does printf/exit/raise, the middle level calls g_test_trap_assert_passed()/g_test_trap_assert_failed() on the inner level, and the outer level calls g_test_trap_assert_stdout() on the middle level.)

(In reply to Dan Winship from comment #12)
> > Fair point. If I used "... stdout: \"%s\"" and the same for stderr, would
> > that address this concern? g_strescape() does escape double quotes, so it
> > would be unambiguous.
> 
> Sounds good

OK, may I merge Attachment #302556 [details], which does that?

> > This deliberately fails a bunch of unit tests to demonstrate the extra
> > diagnostics added by my patches on this bug.
> 
> I think you could incorporate this into glib/tests/testing.c by using two
> levels of g_test_trap_subprocess().

That was more testing complexity than I really had in mind for a change that is only meant to improve diagnostics... but OK, I'll try to turn this into an automated test at some point.

Comment on attachment 302556 [details] [review]
gtestutils: better diagnostics if a captured subprocess fails

yes

Comment on attachment 302556 [details] [review]
gtestutils: better diagnostics if a captured subprocess fails

Committed as d92a67afcb4349bd3e9f6d02b0fd1acf4526d5be for 2.45.2, thanks. Leaving this bug open for the other enhancements.

(In reply to Dan Winship from comment #12)
> I think you could incorporate this into glib/tests/testing.c by using two
> levels of g_test_trap_subprocess(). (The inner level does printf/exit/raise,
> the middle level calls
> g_test_trap_assert_passed()/g_test_trap_assert_failed() on the inner level,
> and the outer level calls g_test_trap_assert_stdout() on the middle level.)

It isn't actually that easy, because these diagnostics are only produced if --tap or -v, and GTest explicitly runs subprocesses with -q. The outer level would have to run the middle level with g_spawn_*() and pipes, wait for it, and assert about its stdout without using g_test_trap_assert_stdout().

This seems like more open-coded test stuff than the feature really justifies.

Review of attachment 302557 [details] [review]:

I’ll push this with minor changes to add the comments I requested.

Review of attachment 302558 [details] [review]:

I’ll push a version of this with the missing space fixed (final review comment) and no other changes.

All pushed.

I don’t understand why git-bz is not posting the checksums of the commits any more.

9c8c6094f (HEAD -> master, origin/master, origin/HEAD) GTest: interpret child processes' wait status if we log their stdout/stderr
fa8b76ab9 g_test_subprocess: record raw wait status and interpret it later