umockdev 0.16.3-1 breaks autopkgtest of bolt

[Christian Ehrhardt ]

The test of bolt fails with the new version due to a crash:
https://autopkgtest.ubuntu.com/results/autopkgtest-impish/impish/amd64/b/bolt/20210917_063952_c9336@/log.gz

...
  Trace/breakpoint trap (core dumped)

The bolt test really uses umockdev, d/t/control has gir1.2-umockdev-1.0 and
python3-dbusmock and the new version causes this.

Retrying autopkgtest locally with no, all and just umockdev from proposed
and it seems reproducible.
 - impish-release - works
 - impish-all-proposed - crashes
 - impish-release + umockdev+libc6 from proposed - crashes

Repro:
$ umockdev-wrapper /usr/libexec/installed-tests/bolt/test-power

FYI:
Downgrading to umockdev 0.16.2-1 in the same environment does not
eliminate the issue. So it might happen at the bolt test-build time.

Debian has the same issue in:
https://ci.debian.net/data/autopkgtest/testing/amd64/b/bolt/15587717/log.gz

The new mockdev fails to create /sys/bus which is requested by the test.
From there the error path is what crashes, but the root cause is why we enter
the error-path in the first place.

One should be aware, this fail is "normal" if the environment is not mocked.
Even in the good case the different calls with/without umockdev lead to
exactly the same crash.
# good
$ umockdev-wrapper /usr/libexec/installed-tests/bolt/test-power
# same crash as the new version has with umockdev-wrapper
$ gdb /usr/libexec/installed-tests/bolt/test-power

This is based on ldpreload.
$ cat /usr/bin/umockdev-wrapper
#!/bin/sh
# Wrapper program to preload the libumockdev library, so that test programs can
# set $UMOCKDEV_DIR for redirecting sysfs and other queries to a test bed.
exec env LD_PRELOAD=libumockdev-preload.so.0:$LD_PRELOAD "$@"

Gut feeling: it seems the mocking no more happens, and due to that
it runs into the non-mocked crash

Debugging with that:
$ pull-lp-source bolt
$ cd bolt-0.9.1/tests
$ gdb /usr/libexec/installed-tests/bolt/test-power
(gdb) set environment LD_PRELOAD libumockdev-preload.so.0
(gdb) b mock_sysfs_init
(gdb) run

With that we can see that while the crash is somewhere inside g_warning the
reason is in the g_mkdir failing with the new umockdev.

Good-case

Breakpoint 1, mock_sysfs_init (ms=0x5555555b6400) at ../tests/mock-sysfs.c:165
165 {
(gdb) n
171 ms->bed = umockdev_testbed_new ();
(gdb)
[New Thread 0x7ffff6e65640 (LWP 11444)]
# GLib-DEBUG: setenv()/putenv() are not thread-safe and should not be used after threads are created
# DEBUG: umockdev.vala:104: Created udev test bed /tmp/umockdev.RQBNA1
172 ms->domains = g_hash_table_new_full (g_str_hash, g_str_equal,
(gdb)
[New Thread 0x7ffff6664640 (LWP 11445)]
175 ms->devices = g_hash_table_new (g_str_hash, g_str_equal);
(gdb)
180 sys = umockdev_testbed_get_sys_dir (ms->bed);
(gdb)
182 bus = g_build_filename (sys, "bus", NULL);
(gdb) p sys
$1 = 0x5555555b99a0 "/tmp/umockdev.RQBNA1/sys"
(gdb) n
183 r = g_mkdir (bus, 0744);
(gdb) p bus
$2 = 0x5555555be330 "/tmp/umockdev.RQBNA1/sys/bus"
(gdb) n
185 if (r < 0)
(gdb) p r
$3 = 0
(gdb) n
188 cls = g_build_filename (sys, "class", NULL);

Bad-Case

Breakpoint 1, mock_sysfs_init (ms=0x5555555b6400) at ../tests/mock-sysfs.c:165
165 {
(gdb) n
171 ms->bed = umockdev_testbed_new ();
(gdb)
[New Thread 0x7ffff6e65640 (LWP 17082)]
# GLib-DEBUG: setenv()/putenv() are not thread-safe and should not be used after threads are created
# DEBUG: umockdev.vala:110: Created udev test bed /tmp/umockdev.TK2VA1
172 ms->domains = g_hash_table_new_full (g_str_hash, g_str_equal,
(gdb)
[New Thread 0x7ffff6664640 (LWP 17083)]
175 ms->devices = g_hash_table_new (g_str_hash, g_str_equal);
(gdb)
180 sys = umockdev_testbed_get_sys_dir (ms->bed);
(gdb)
182 bus = g_build_filename (sys, "bus", NULL);
(gdb) p sys
$1 = 0x5555555a98b0 "/tmp/umockdev.TK2VA1/sys"
(gdb) n
183 r = g_mkdir (bus, 0744);
(gdb) p bus
$2 = 0x5555555be560 "/tmp/umockdev.TK2VA1/sys/bus"
(gdb) n
185 if (r < 0)
(gdb) p r
$3 = -1
(gdb) n
186 g_warning ("could not create %s", bus);
(gdb) n

** (/usr/libexec/installed-tests/bolt/test-power:17078): WARNING **: 15:11:06.614: could not create /tmp/umockdev.TK2VA1/sys/bus

Thread 1 "test-power" received signal SIGTRAP, Trace/breakpoint trap.

I'll tag this update-excuse and FYI-subscribe Martin who has done the Debian upload and the Ubuntu sync of this on 16th Sept (post FF).

[Martin Pitt (pitti)]

Thanks Christian -- Indeed I noticed that, and set https://gitlab.freedesktop.org/bolt/bolt/-/merge_requests/246 the day after to fix this. Unfortunately I didn't get a reaction yet, and Christian also didn't respond on IRC yet. I'll do some more prodding.

[Christian Ehrhardt  (paelzer)]

Looking at the changelog this looks suspicious:
  - Immediately create "bus" and "class" directories in /sys to fix udev
    enumerator (thanks David Lechner)

That change is at
  https://github.com/martinpitt/umockdev/commit/5e829601434610ef510bda12571291509a3a51d2

And that explains it, the bolt test code wants to create /tmp/umockdev.RQBNA1/sys/bus and it already exists.

Offending code in bolt tests is at:
https://gitlab.freedesktop.org/bolt/bolt/-/blob/master/tests/mock-sysfs.c#L183

Checking that theory in the debugger confirms that - breaking just prior to the failing mkdir.

Good-case
183 r = g_mkdir (bus, 0744);
(gdb) p bus
$4 = 0x5555555be330 "/tmp/umockdev.P7PGA1/sys/bus"
(gdb) shell find /tmp/umockdev.P7PGA1/
/tmp/umockdev.P7PGA1/
/tmp/umockdev.P7PGA1/sys
/tmp/umockdev.P7PGA1/ioctl
/tmp/umockdev.P7PGA1/ioctl/_default

Bad-case
183 r = g_mkdir (bus, 0744);
(gdb) p bus
$4 = 0x5555555be560 "/tmp/umockdev.7MRGA1/sys/bus"
gdb) shell find /tmp/umockdev.7MRGA1/
/tmp/umockdev.7MRGA1/
/tmp/umockdev.7MRGA1/sys
/tmp/umockdev.7MRGA1/sys/bus
/tmp/umockdev.7MRGA1/sys/class
/tmp/umockdev.7MRGA1/ioctl
/tmp/umockdev.7MRGA1/ioctl/_default

So we either need to stop umockdev from doing that (but that will break whatever it fixed to introduce this) OR we need to teach bolt tests to be ok, if the directory already exists.

[Christian Ehrhardt  (paelzer)]

Since Debian is also affected I filed it there as well:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=995248

[Martin Pitt (pitti)]

Christian, as I write above I believe this really needs to be fixed in bolt's tests. The umockdev change was a bug fix which bolt's tests (incorrectly) worked around. So I hope you don't mind that I flipped the affected package around? I am in contact with Christian now, and hope to sort this out soon.

[Martin Pitt (pitti)]

> I am in contact with Christian now, and hope to sort this out soon.

Sorry -- I meant Christian Kellner, bolt's upstream, not you :-)

[Christian Ehrhardt  (paelzer)]

Martin, I almost expected that would be the call but wanted to leave it to you to decide.
Thank you as always!
o/