Bug 103601 - better progress reporting for "embedded tests" (more TAP)
Summary: better progress reporting for "embedded tests" (more TAP)
Status: RESOLVED FIXED
Alias: None
Product: dbus
Classification: Unclassified
Component: core (show other bugs)
Version: git master
Hardware: Other All
: medium enhancement
Assignee: Simon McVittie
QA Contact: D-Bus Maintainers
URL:
Whiteboard: review+
Keywords: patch
Depends on:
Blocks:
 
Reported: 2017-11-06 20:29 UTC by Simon McVittie
Modified: 2017-11-15 14:03 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments
[01/13] Remove commented-out printf debugging (2.79 KB, patch)
2017-11-14 19:08 UTC, Simon McVittie
Details | Splinter Review
[02/13] Windows autolaunch: Turn stdout spam into stderr spam (1.41 KB, patch)
2017-11-14 19:08 UTC, Simon McVittie
Details | Splinter Review
[03/13] Do not export dbus_internal_do_not_use_run_tests if unused (1.33 KB, patch)
2017-11-14 19:09 UTC, Simon McVittie
Details | Splinter Review
[04/13] Add utility functions to emit TAP diagnostics and fatal errors (5.41 KB, patch)
2017-11-14 19:09 UTC, Simon McVittie
Details | Splinter Review
[05/13] Embedded tests: Emit TAP diagnostics instead of printf (36.95 KB, patch)
2017-11-14 19:09 UTC, Simon McVittie
Details | Splinter Review
[06/13] Use _dbus_test_fatal to include more detail in test failure diagnostics (17.82 KB, patch)
2017-11-14 19:10 UTC, Simon McVittie
Details | Splinter Review
[07/13] Prefer to use _dbus_test_fatal() for assertion failures in tests (139.78 KB, patch)
2017-11-14 19:10 UTC, Simon McVittie
Details | Splinter Review
[08/13] Unix: Flush stdout and stderr streams before forking (5.60 KB, patch)
2017-11-14 19:10 UTC, Simon McVittie
Details | Splinter Review
[09/13] bus: Silence most log messages when testing OOM handling (12.24 KB, patch)
2017-11-14 19:11 UTC, Simon McVittie
Details | Splinter Review
[10/13] bus: Silence the output of the test services when doing OOM testing (5.63 KB, patch)
2017-11-14 19:11 UTC, Simon McVittie
Details | Splinter Review
[11/13] test-dbus: Produce machine-readable TAP output (10.44 KB, patch)
2017-11-14 19:11 UTC, Simon McVittie
Details | Splinter Review
[12/13] test-bus*: Output TAP directly (8.23 KB, patch)
2017-11-14 19:12 UTC, Simon McVittie
Details | Splinter Review
[13/13] dispatch test: Output finer-grained TAP (5.86 KB, patch)
2017-11-14 19:12 UTC, Simon McVittie
Details | Splinter Review
[14] _dbus_test_diag: Flush stdout after each diagnostic (762 bytes, patch)
2017-11-15 12:15 UTC, Simon McVittie
Details | Splinter Review

Description Simon McVittie 2017-11-06 20:29:56 UTC
test-dbus, test-bus, test-bus-system and test-launch-helper are all legacy Automake tests (output non-machine-readable noise to stdout/stderr, exit 0 for success, 77 for skip or anything else for failure) which we wrap in small shell scripts to get some very simplistic TAP.

Unfortunately, test-dbus and (especially) test-bus are really slow. If we gave them machine-readable TAP logging to stdout and sent all the random noise to stderr, we'd be able to report intermediate results, so that a user running these tests wouldn't think they'd got stuck.

Talking of random noise, this is ridiculous:

% ls -sh
...
16M test-bus.log

Nobody is going to read 16M of output to find out what has failed!

The majority of that is the dbus-daemon reporting that it has run out of memory while trying to activate a service, in the tests that make malloc() fail to check how well we cope with that. Perhaps we could selectively silence those log messages if (defined(DBUS_ENABLE_EMBEDDED_TESTS) && some flag is set)?

I suspect that there is also some badness going on with the fact that the activation code paths in the dbus-daemon call fork() without flushing stdout/stderr, so messages that came out of stdout/stderr before we fork are duplicated, many times. The activation tests are basically a fork-bomb, which exacerbates that.

I have a work-in-progress branch with the early stages of this.
Comment 1 Simon McVittie 2017-11-14 19:08:40 UTC
Created attachment 135460 [details] [review]
[01/13] Remove commented-out printf debugging

Printing to stdout would interfere with generating TAP syntax.
Comment 2 Simon McVittie 2017-11-14 19:08:59 UTC
Created attachment 135462 [details] [review]
[02/13] Windows autolaunch: Turn stdout spam into stderr spam

This is still not how warnings and diagnostics should be done
(the advice should probably be included in the DBusError) but at least
this way it won't interfere with machine-readable output on stdout.
Comment 3 Simon McVittie 2017-11-14 19:09:13 UTC
Created attachment 135463 [details] [review]
[03/13] Do not export dbus_internal_do_not_use_run_tests if  unused
Comment 4 Simon McVittie 2017-11-14 19:09:27 UTC
Created attachment 135464 [details] [review]
[04/13] Add utility functions to emit TAP diagnostics and fatal  errors
Comment 5 Simon McVittie 2017-11-14 19:09:49 UTC
Created attachment 135465 [details] [review]
[05/13] Embedded tests: Emit TAP diagnostics instead of printf
Comment 6 Simon McVittie 2017-11-14 19:10:07 UTC
Created attachment 135466 [details] [review]
[06/13] Use _dbus_test_fatal to include more detail in test  failure diagnostics
Comment 7 Simon McVittie 2017-11-14 19:10:27 UTC
Created attachment 135467 [details] [review]
[07/13] Prefer to use _dbus_test_fatal() for assertion failures  in tests

This is a little more self-documenting - it justifies why it's
acceptable to fail hard on out-of-memory conditions. _dbus_test_fatal()
isn't compiled unless we are compiling embedded tests, so compiling
with embedded tests disabled provides reasonable confidence that we
aren't using _dbus_test_fatal() inappropriately.
Comment 8 Simon McVittie 2017-11-14 19:10:48 UTC
Created attachment 135468 [details] [review]
[08/13] Unix: Flush stdout and stderr streams before forking

stdout and stderr are close-on-exec and buffered, so we can't rely on
their buffers being empty. If we continue to execute application code
after forking (as opposed to immediately exec()ing), then the child
process might later flush the libc stdio buffers, resulting in
output that is printed by the parent also being printed by the child.

In particular, test-bus.log sometimes grows extremely large for
this reason, because this test repeatedly attempts to carry out
legacy activation.
Comment 9 Simon McVittie 2017-11-14 19:11:04 UTC
Created attachment 135469 [details] [review]
[09/13] bus: Silence most log messages when testing OOM  handling

In parts of the OOM testing, our logging produces multiple megabytes
of output. Let's not do that.
Comment 10 Simon McVittie 2017-11-14 19:11:39 UTC
Created attachment 135470 [details] [review]
[10/13] bus: Silence the output of the test services when doing  OOM testing

The echo service frequently fails to connect to the bus when we are
testing OOM code paths, again causing a lot of noise in the log.
Comment 11 Simon McVittie 2017-11-14 19:11:59 UTC
Created attachment 135471 [details] [review]
[11/13] test-dbus: Produce machine-readable TAP output

See http://testanything.org/ for more information on TAP.
Comment 12 Simon McVittie 2017-11-14 19:12:40 UTC
Created attachment 135472 [details] [review]
[12/13] test-bus*: Output TAP directly
Comment 13 Simon McVittie 2017-11-14 19:12:56 UTC
Created attachment 135473 [details] [review]
[13/13] dispatch test: Output finer-grained TAP

This lets us see which bits are painfully slow. (Spoilers:
check_existent_service_no_auto_start.)
Comment 14 Philip Withnall 2017-11-15 08:28:50 UTC
Comment on attachment 135460 [details] [review]
[01/13] Remove commented-out printf debugging

Review of attachment 135460 [details] [review]:
-----------------------------------------------------------------

r+
Comment 15 Philip Withnall 2017-11-15 08:29:52 UTC
Comment on attachment 135462 [details] [review]
[02/13] Windows autolaunch: Turn stdout spam into stderr spam

Review of attachment 135462 [details] [review]:
-----------------------------------------------------------------

It would be good to eliminate these fprintf()s entirely, as a follow-up patch. (You may have done that already; I’m reviewing the patches in sequence.)

r+
Comment 16 Philip Withnall 2017-11-15 08:30:38 UTC
Comment on attachment 135463 [details] [review]
[03/13] Do not export dbus_internal_do_not_use_run_tests if  unused

Review of attachment 135463 [details] [review]:
-----------------------------------------------------------------

r+
Comment 17 Philip Withnall 2017-11-15 08:32:30 UTC
Comment on attachment 135464 [details] [review]
[04/13] Add utility functions to emit TAP diagnostics and fatal  errors

Review of attachment 135464 [details] [review]:
-----------------------------------------------------------------

r+, good tapping.
Comment 18 Philip Withnall 2017-11-15 08:41:28 UTC
Comment on attachment 135465 [details] [review]
[05/13] Embedded tests: Emit TAP diagnostics instead of printf

Review of attachment 135465 [details] [review]:
-----------------------------------------------------------------

r+, with a couple of questions. Well tapped.

::: dbus/dbus-message-factory.c
@@ -1279,5 @@
>    
>    if (iter_first_in_series (iter))
>      {
> -      printf (" testing message loading: %s ", generators[generator].name);
> -      fflush (stdout);

Do you want to drop this fflush()? _dbus_test_diag() doesn’t fflush() itself (maybe it should?). Only _dbus_test_fatal() fflush()es.

::: dbus/dbus-message-util.c
@@ +663,4 @@
>          {
>            if (_dbus_string_ends_with_c_str (&filename, ".message"))
>              {
> +              _dbus_test_diag ("SKIP: Could not load %s, message builder language no longer supported",

Should this not be a _dbus_test_skip() or similar? (If you’ve done this in a later patch already: great. I’m working through the patches sequentially.)
Comment 19 Philip Withnall 2017-11-15 08:44:16 UTC
Comment on attachment 135466 [details] [review]
[06/13] Use _dbus_test_fatal to include more detail in test  failure diagnostics

Review of attachment 135466 [details] [review]:
-----------------------------------------------------------------

r+. Did you know that ‘tap’ can mean: ‘to add a thickness of leather to the sole or heel of (a boot or shoe), as in repairing’?
Comment 20 Philip Withnall 2017-11-15 08:57:43 UTC
Comment on attachment 135467 [details] [review]
[07/13] Prefer to use _dbus_test_fatal() for assertion failures  in tests

Review of attachment 135467 [details] [review]:
-----------------------------------------------------------------

r+. ‘Tap’ can be reversed to form ‘pat’, both of which are verbs. How ‘apt’.
Comment 21 Philip Withnall 2017-11-15 08:58:55 UTC
Comment on attachment 135468 [details] [review]
[08/13] Unix: Flush stdout and stderr streams before forking

Review of attachment 135468 [details] [review]:
-----------------------------------------------------------------

r+, forking excellence.
Comment 22 Philip Withnall 2017-11-15 09:05:21 UTC
Comment on attachment 135469 [details] [review]
[09/13] bus: Silence most log messages when testing OOM  handling

Review of attachment 135469 [details] [review]:
-----------------------------------------------------------------

r+
Comment 23 Philip Withnall 2017-11-15 09:07:43 UTC
Comment on attachment 135470 [details] [review]
[10/13] bus: Silence the output of the test services when doing  OOM testing

Review of attachment 135470 [details] [review]:
-----------------------------------------------------------------

r+
Comment 24 Philip Withnall 2017-11-15 09:15:09 UTC
Comment on attachment 135471 [details] [review]
[11/13] test-dbus: Produce machine-readable TAP output

Review of attachment 135471 [details] [review]:
-----------------------------------------------------------------

r+ with one nitpick which can be fixed before pushing, if you care about it.

::: dbus/dbus-test-tap.c
@@ +70,5 @@
>  }
>  
> +/*
> + * Output TAP indicating that all tests have been skipped, and exit
> + * successfully.

Might be useful to add a link to http://testanything.org/ in a comment at the top of the file.
Comment 25 Philip Withnall 2017-11-15 09:20:02 UTC
Comment on attachment 135472 [details] [review]
[12/13] test-bus*: Output TAP directly

Review of attachment 135472 [details] [review]:
-----------------------------------------------------------------

r+
Comment 26 Philip Withnall 2017-11-15 09:21:39 UTC
Comment on attachment 135473 [details] [review]
[13/13] dispatch test: Output finer-grained TAP

Review of attachment 135473 [details] [review]:
-----------------------------------------------------------------

r+, tap harder.
Comment 27 Simon McVittie 2017-11-15 11:32:11 UTC
(In reply to Philip Withnall from comment #15)
> It would be good to eliminate these fprintf()s entirely, as a follow-up
> patch. (You may have done that already; I’m reviewing the patches in
> sequence.)

This is far from the worst thing in dbus-sysdeps-win (see Bug #35311) and I don't develop on Windows, so I'm reluctant to make changes I can't test. I opened Bug #103756 instead.
Comment 28 Simon McVittie 2017-11-15 11:45:46 UTC
(In reply to Philip Withnall from comment #18)
> [05/13] Embedded tests: Emit TAP diagnostics instead of printf
...
> > -      printf (" testing message loading: %s ", generators[generator].name);
> > -      fflush (stdout);
> 
> Do you want to drop this fflush()? _dbus_test_diag() doesn’t fflush() itself
> (maybe it should?). Only _dbus_test_fatal() fflush()es.

I don't think it makes sense for just this diagnostic to flush, but none of the others - it should be all or none.

I'm not sure whether the right answer is all or none. You're probably right that it's "all".

> > +              _dbus_test_diag ("SKIP: Could not load %s, message builder language no longer supported",
> 
> Should this not be a _dbus_test_skip() or similar?

In principle yes, but that didn't exist at this point in the patch series.

Looking at this again, I'm really not sure why *.message still exist in the source tree when the "message builder language" is "no longer supported". It was a domain-specific language for building D-Bus message blobs, which was introduced in 2003, and deleted in early 2005 when the type system was rewritten to be fully recursive. I'm not sure that we want to be emitting 30 spurious "SKIP" messages in the machine-readable output for tests that haven't worked since 2005 - a TAP "SKIP" directive creates the expectation that there exists a situation in which the test would not be skipped, and that just isn't true for these...

These tests have been diagnosed as "skipped" since the commit that also deleted dbus-message-builder.[ch]:

commit 9d21554dd3b560952cd5aa607c4ec07898c0b260
Author: Havoc Pennington <hp@redhat.com>
Date:   2005-01-23 06:10:07 +0000

    2005-01-23  Havoc Pennington  <hp@redhat.com>
    
            * dbus/dbus-message-factory.c, dbus/dbus-message-util.c:
            get this all working, not many tests in the framework yet though

but even before that, the message builder language was disabled by:

+      if (FALSE) /* Message builder disabled, probably permanently,
+                  * I want to do it another way

which was part of this mega-commit:

commit 9c3d566e95c9080f6040c64531b0ccae22bd5d74
Author: Havoc Pennington <hp@redhat.com>
Date:   2005-01-15 07:15:38 +0000

    2005-01-15  Havoc Pennington  <hp@redhat.com>
    
            * Land the new message args API and type system.
    
            This patch is huge, but the public API change is not
            really large. The set of D-BUS types has changed somewhat,
            and the arg "getters" are more geared toward language bindings;
            they don't make a copy, etc.
    
            There are also some known issues. See these emails for details
            on this huge patch:
            http://lists.freedesktop.org/archives/dbus/2004-December/001836.html
            http://lists.freedesktop.org/archives/dbus/2005-January/001922.html
    
            * dbus/dbus-marshal-*: all the new stuff
    
            * dbus/dbus-message.c: basically rewritten
    
            * dbus/dbus-memory.c (check_guards): with "guards" enabled, init
            freed blocks to be all non-nul bytes so using freed memory is less
            likely to work right
    
            * dbus/dbus-internals.c (_dbus_test_oom_handling): add
            DBUS_FAIL_MALLOC=N environment variable, so you can do
            DBUS_FAIL_MALLOC=0 to skip the out-of-memory checking, or
            DBUS_FAIL_MALLOC=10 to make it really, really, really slow and
            thorough.
    
            * qt/message.cpp: port to the new message args API
            (operator<<): use str.utf8() rather than str.unicode()
            (pretty sure this is right from the Qt docs?)
    
            * glib/dbus-gvalue.c: port to the new message args API
    
            * bus/dispatch.c, bus/driver.c: port to the new message args API
    
            * dbus/dbus-string.c (_dbus_string_init_const_len): initialize the
            "locked" flag to TRUE and align_offset to 0; I guess we never
            looked at these anyhow, but seems cleaner.
    
            * dbus/dbus-string.h (_DBUS_STRING_ALLOCATION_PADDING):
            move allocation padding macro to this header; use it to implement
            (_DBUS_STRING_STATIC): ability to declare a static string.
    
            * dbus/dbus-message.c (_dbus_message_has_type_interface_member):
            change to return TRUE if the interface is not set.
    
            * dbus/dbus-string.[hc]: move the D-BUS specific validation stuff
            to dbus-marshal-validate.[hc]
    
            * dbus/dbus-marshal-basic.c (_dbus_type_to_string): move here from
            dbus-internals.c
    
            * dbus/Makefile.am: cut over from dbus-marshal.[hc]
            to dbus-marshal-*.[hc]
    
            * dbus/dbus-object-tree.c (_dbus_decompose_path): move this
            function here from dbus-marshal.c
Comment 29 Simon McVittie 2017-11-15 12:06:25 UTC
(In reply to Simon McVittie from comment #28)
> Looking at this again, I'm really not sure why *.message still exist in the
> source tree when the "message builder language" is "no longer supported".

Opened Bug #103758.

> a TAP "SKIP" directive creates the expectation
> that there exists a situation in which the test would not be skipped, and
> that just isn't true for these...

Based on this reasoning I'm going to leave it as a diagnostic for now.
Comment 30 Simon McVittie 2017-11-15 12:07:08 UTC
(In reply to Philip Withnall from comment #24)
> Might be useful to add a link to http://testanything.org/ in a comment at
> the top of the file.

Good idea, but I'll add this to the commit that created the file instead.
Comment 31 Simon McVittie 2017-11-15 12:15:40 UTC
Created attachment 135485 [details] [review]
[14] _dbus_test_diag: Flush stdout after each diagnostic

If we crash, we'll want to know what the most recent diagnostic was.

---

As Philip suggested.

I'm testing patches 1-13 on Travis-CI (slightly adjusted to add a comment referencing http://testanything.org/ as suggested) and will push those if successful.
Comment 32 Philip Withnall 2017-11-15 12:35:15 UTC
Comment on attachment 135485 [details] [review]
[14] _dbus_test_diag: Flush stdout after each diagnostic

Review of attachment 135485 [details] [review]:
-----------------------------------------------------------------

r+
Comment 33 Simon McVittie 2017-11-15 14:03:06 UTC
All applied for 1.13.0. Thanks for reviewing!


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.