* [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy
@ 2025-08-12 14:17 Li Wang via ltp
2025-08-14 13:06 ` Petr Vorel
0 siblings, 1 reply; 5+ messages in thread
From: Li Wang via ltp @ 2025-08-12 14:17 UTC (permalink / raw)
To: ltp; +Cc: rafael.tinoco
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
--
Mailing list info: https://lists.linux.it/listinfo/ltp
^ permalink raw reply related [flat|nested] 5+ messages in thread* Re: [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy
2025-08-12 14:17 [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy Li Wang via ltp
@ 2025-08-14 13:06 ` Petr Vorel
2025-08-15 0:44 ` Li Wang via ltp
0 siblings, 1 reply; 5+ messages in thread
From: Petr Vorel @ 2025-08-14 13:06 UTC (permalink / raw)
To: Li Wang; +Cc: rafael.tinoco, ltp
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);
> }
--
Mailing list info: https://lists.linux.it/listinfo/ltp
^ permalink raw reply [flat|nested] 5+ messages in thread* Re: [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy
2025-08-14 13:06 ` Petr Vorel
@ 2025-08-15 0:44 ` Li Wang via ltp
2025-08-15 5:22 ` Petr Vorel
0 siblings, 1 reply; 5+ messages in thread
From: Li Wang via ltp @ 2025-08-15 0:44 UTC (permalink / raw)
To: Petr Vorel; +Cc: rafael.tinoco, ltp
Petr Vorel <pvorel@suse.cz> wrote:
> > 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.
+1
> > + "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.");
This is a good example, thanks!!
(The debugging work exhausted my energy this week, and I felt like my
brain was stuck there, unable to write a simple printed message.)
So what about:
tst_resm_(file, lineno, TWARN,
"mkfs may have failed because the device is busy (e.g., udisks2 probing). "
"Consider disabling background probing services.");
> 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).
Yes, that would be helpful to confirm some special damon is running,
if something you were mean:
if (tst_proc_comm_running("udisksd", NULL) ||
tst_proc_comm_running("gvfsd-trash", NULL)) {
tst_resm_(file, lineno, TINFO,
"Likely udisksd/gvfsd-trash is probing newly mounted fs
in backgroud... ");
}
--
Regards,
Li Wang
--
Mailing list info: https://lists.linux.it/listinfo/ltp
^ permalink raw reply [flat|nested] 5+ messages in thread* Re: [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy
2025-08-15 0:44 ` Li Wang via ltp
@ 2025-08-15 5:22 ` Petr Vorel
2025-08-16 1:38 ` Li Wang via ltp
0 siblings, 1 reply; 5+ messages in thread
From: Petr Vorel @ 2025-08-15 5:22 UTC (permalink / raw)
To: Li Wang; +Cc: rafael.tinoco, ltp
> Petr Vorel <pvorel@suse.cz> wrote:
> > > 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.
> +1
> > > + "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.");
> This is a good example, thanks!!
> (The debugging work exhausted my energy this week, and I felt like my
> brain was stuck there, unable to write a simple printed message.)
Understand :).
> So what about:
> tst_resm_(file, lineno, TWARN,
> "mkfs may have failed because the device is busy (e.g., udisks2 probing). "
> "Consider disabling background probing services.");
+1
> > 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).
> Yes, that would be helpful to confirm some special damon is running,
> if something you were mean:
> if (tst_proc_comm_running("udisksd", NULL) ||
> tst_proc_comm_running("gvfsd-trash", NULL)) {
> tst_resm_(file, lineno, TINFO,
> "Likely udisksd/gvfsd-trash is probing newly mounted fs
> in backgroud... ");
> }
Yes, something like this. It can be done as a separate effort to not block this
simple patch.
Kind regards,
Petr
--
Mailing list info: https://lists.linux.it/listinfo/ltp
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2025-08-16 1:39 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2025-08-12 14:17 [LTP] [PATCH v2] tst_mkfs: print short hint when mkfs fails in device busy Li Wang via ltp
2025-08-14 13:06 ` Petr Vorel
2025-08-15 0:44 ` Li Wang via ltp
2025-08-15 5:22 ` Petr Vorel
2025-08-16 1:38 ` Li Wang via ltp
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.