[LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy

[Li Wang]

During daily CI testing of LTP, we were intermittently getting EBUSY (in many
testcases) when mkfs the /dev/loop0 device. It seemed that userspace was
reopening the block device immediately after unmounting it. Debugging with
bpftrace revealed that the udisks2 daemon was the culprit (probing the block
device on every change). As this was outside the scope of the LTP code, we
added a printout suggesting that testers stop the udisk2 service when
encountering this failure during testing.

  ==== setxattr01 ====
  tst_test.c:1888: TINFO: === Testing on ext2 ===
  tst_test.c:1217: TINFO: Formatting /dev/loop0 with ext2 opts='' extra opts='' mke2fs 1.47.1 (20-May-2024)
  tst_test.c:1229: TINFO: Mounting /dev/loop0 to /tmp/LTP_setd24dAf/mntpoint fstyp=ext2 flags=0
  ...
  setxattr01.c:174: TPASS: setxattr(2) failed: EFAULT (14)
  tst_test.c:1888: TINFO: === Testing on ext3 ===
  tst_test.c:1217: TINFO: Formatting /dev/loop0 with ext3 opts='' extra opts='' mke2fs 1.47.1 (20-May-2024)
  /dev/loop0 is apparently in use by the system; will not make a filesystem here!
  tst_test.c:1217: TBROK: mkfs.ext3 failed with exit code 1

  ==== close_range01 ====
  tst_test.c:1888: TINFO: === Testing on ext2 ===
  tst_test.c:1217: TINFO: Formatting /dev/loop0 with ext2 opts='' extra opts='' mke2fs 1.47.1 (20-May-2024)
  tst_test.c:1229: TINFO: Mounting /dev/loop0 to /tmp/LTP_cloXeXI39/mnt fstyp=ext2 flags=0
  ...
  close_range01.c:188: TPASS: No kernel taints
  tst_test.c:1888: TINFO: === Testing on ext3 ===
  tst_test.c:1217: TINFO: Formatting /dev/loop0 with ext3 opts='' extra opts='' mke2fs 1.47.1 (20-May-2024)
  /dev/loop0 is apparently in use by the system; will not make a filesystem here!
  tst_test.c:1217: TBROK: mkfs.ext3 failed with exit code 1

Running bpftrace in a separate terminal and also with ./close_range01
simultaneously to get the output shows that another daemon (udisksd) is
probing the block device on every change.

  # bpftrace -e 'tracepoint:syscalls:sys_enter_openat /str(args->filename)=="/dev/loop0"/ \
      { printf("%s pid=%d flags=0x%x %s\n", comm, pid, args->flags, str(args->filename)); }'
  Attaching 1 probe...
  close_range01 pid=298948 flags=0x2 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  close_range01 pid=298948 flags=0x0 /dev/loop0
  systemd-udevd pid=702 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x280000 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x280000 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0
  close_range01 pid=298948 flags=0x241 /dev/loop0
  systemd-udevd pid=702 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x80 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x0 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x0 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x0 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x80800 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x0 /dev/loop0
  mkfs.ext2 pid=298969 flags=0x82 /dev/loop0
  (udev-worker) pid=298949 flags=0x280000 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0
  systemd-udevd pid=702 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0
  (udev-worker) pid=298949 flags=0x280000 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0
  udisksd pid=87323 flags=0x0 /dev/loop0        <--------
  close_range01 pid=298948 flags=0x241 /dev/loop0
  systemd-udevd pid=702 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  (udev-worker) pid=298949 flags=0x288000 /dev/loop0
  mkfs.ext3 pid=298977 flags=0x80 /dev/loop0
  mkfs.ext3 pid=298977 flags=0x0 /dev/loop0
  mkfs.ext3 pid=298977 flags=0x0 /dev/loop0
  ...

Signed-off-by: Li Wang <liwang@redhat.com>
---
 lib/tst_mkfs.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/lib/tst_mkfs.c b/lib/tst_mkfs.c
index 736324f04..dfec06a21 100644
--- a/lib/tst_mkfs.c
+++ b/lib/tst_mkfs.c
@@ -107,6 +107,10 @@ void tst_mkfs_(const char *file, const int lineno, void (cleanup_fn)(void),
 			"%s not found in $PATH", mkfs);
 	break;
 	default:
+		tst_resm_(file, lineno, TWARN,
+			"Check if mkfs failed with the (loop) device busy. "
+			"Background probing (e.g., udisks2) can cause this. \n"
+			"Consider temporarily stopping udisks2 during the test.");
 		tst_brkm_(file, lineno, TBROK, cleanup_fn,
 			"%s failed with exit code %i", mkfs, ret);
 	}
-- 
2.50.1