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

[Petr Vorel]

Hi Li,


> 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.

Good catch!

>   # 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"
When 2 lines are needed, could it be without trailing space?
			"Background probing (e.g., udisks2) can cause this.\n"

nit: I don't like LTP messages are split on more lines, but this is indeed too
long.

> +			"Consider temporarily stopping udisks2 during the test.");

We already have suggestion about some process running in tst_umount()
in lib/tst_device.c:

			tst_resm(TINFO, "Likely gvfsd-trash is probing newly "
				 "mounted fs, kill it to speed up tests.");

Would you agree to have a library function which would parse
/proc/*/comm to check if particular process is running?
(I would do it as a separate effort).

Reviewed-by: Petr Vorel <pvorel@suse.cz>

Kind regards,
Petr

>  		tst_brkm_(file, lineno, TBROK, cleanup_fn,
>  			"%s failed with exit code %i", mkfs, ret);
>  	}