Double ouput when piping

[fwsmit]

I work on dunst and we use greatest for testing. When piping the output of the tests to, for example, cat the output is different than without piping.

make test | cat

Before the dbus suite
* Suite suite_dbus:
After the dbus suite
Total: 0 tests (668 ticks, 0.001 sec), 0 assertions
Pass: 0, fail: 0, skip: 0.
Before the dbus suite
* Suite suite_dbus:

instead of make test

Before the dbus suite
* Suite suite_dbus:
After the dbus suite
Total: 0 tests (748 ticks, 0.001 sec), 0 assertions
Pass: 0, fail: 0, skip: 0.

The only code in the suite that triggers this bug is

        GTestDBus *dbus_bus;
        g_test_dbus_unset();
        dbus_bus = g_test_dbus_new(G_TEST_DBUS_NONE);
        g_test_dbus_up(dbus_bus);

This may be a bug from glib, but I'm posting it here first, since no other printfs seem to be duplicating.

See https://github.com/fwSmit/dunst/blob/test-bug/test/dbus.c and https://github.com/fwSmit/dunst/blob/test-bug/test/test.c for full example code.

[fwsmit]

Link glib issue: https://gitlab.gnome.org/GNOME/glib/-/issues/2322

[silentbicycle]

I will be working on greatest this week (approaching a new release), will look into your issue as well. Thanks for reporting.

[fwsmit]

Great, I'm curious to hear back from you!

[silentbicycle]

It looks like something inside of g_test_dbus_up is forking:

(gdb) b fork
Note: breakpoint 1 also set at pc 0x7ffff71c3690.
Breakpoint 2 at 0x7ffff71c3690: file ../sysdeps/nptl/fork.c, line 56.
(gdb) r
Starting program: /home/scott/tmp/git/dunst/test/test 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Before the dbus suite
* Suite suite_dbus:
[Detaching after vfork from child process 9773]

Breakpoint 1, __libc_fork () at ../sysdeps/nptl/fork.c:56
56  ../sysdeps/nptl/fork.c: No such file or directory.
(gdb) bt
#0  __libc_fork () at ../sysdeps/nptl/fork.c:56
#1  0x00007ffff75a5df3 in ?? () from /usr/lib/libgio-2.0.so.0
#2  0x00007ffff75a68af in g_test_dbus_up () from /usr/lib/libgio-2.0.so.0
#3  0x000055555555fc3d in suite_dbus () at test/dbus.c:14
#4  0x000055555555e753 in greatest_run_suite (suite_cb=<optimized out>, 
    suite_name=0x5555555809f9 "suite_dbus") at test/test.c:8
#5  main (argc=1, argv=0x7fffffffe858) at test/test.c:13

If multiple processes are returning, that's probably a factor in the IO redirection that causes the repeated printout. If I redirect to awk, so it prefixes each line passed through it, it confirms that it's piping all the lines (including the "Before the dbus_suite" part twice).

Without digging into this further, I don't think this is specifically an issue in greatest. I agree it's odd, and I'm curious when you figure the rest out.

greatest isn't trying to do anything particularly clever with process control, it's mostly a pile of macros that factor out boilerplate for counting test results, generating reasonable "Expected: X, Got: Y" messages, and some command line handling to run tests by name. If you fork inside a test body and multiple processes return, confusing stuff could happen. It explicitly doesn't provide forking for test cases (though I've considered providing it as an optional extension) because I don't want to assume any particular OS, or that there's an OS at all.

[fwsmit]

Thanks for looking into it! Glib is indeed forking a few times, but doesn't write anything to stdout in those processes. I'll continue talking to the Glib devs to see what's happening on their end. I'll update when I know more

[silentbicycle]

You could also try to reproduce this without greatest involved -- if something that produces output, then calls the test g_test_dbus_* functions in main, then exits shows the same behavior when piped / not piped through cat, that will reduce the surface area to investigate. If you can't reproduce it without greatest, that will also tell us something.

[fwsmit]

I manged to reproduce this without greatest.h, so I'll go ahead close this issue :).

[fwsmit]

If you're curious there's a detailed update from a dbus developer with the cause

[silentbicycle]

Makes sense -- un-flushed stdio in a fork.