From 4ad39b0531f550cde6e01df0801f177c08514c8b Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= <zbyszek@in.waw.pl>
Date: Mon, 14 Sep 2020 17:58:03 +0200
Subject: [PATCH] test-mountpointutil-util: do not assert in test_mnt_id()

https://bugzilla.redhat.com/show_bug.cgi?id=1803070

I *think* this a kernel bug: the mnt_id as listed in /proc/self/mountinfo is different
than the one we get from /proc/self/fdinfo/. This only matters when both statx and
name_to_handle_at are unavailable and we hit the fallback path that goes through fdinfo:

(gdb) !uname -r
5.6.19-200.fc31.ppc64le

(gdb) !cat /proc/self/mountinfo
697 664 253:0 /var/lib/mock/fedora-31-ppc64le/root / rw,relatime shared:298 master:1 - xfs /dev/mapper/fedora_rh--power--vm14-root rw,seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota
698 697 253:0 /var/cache/mock/fedora-31-ppc64le/yum_cache /var/cache/yum rw,relatime shared:299 master:1 - xfs /dev/mapper/fedora_rh--power--vm14-root rw,seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota
699 697 253:0 /var/cache/mock/fedora-31-ppc64le/dnf_cache /var/cache/dnf rw,relatime shared:300 master:1 - xfs /dev/mapper/fedora_rh--power--vm14-root rw,seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota
700 697 0:32 /mock-selinux-plugin.7me9bfpi /proc/filesystems rw,nosuid,nodev shared:301 master:18 - tmpfs tmpfs rw,seclabel <==========================================================
701 697 0:41 / /sys ro,nosuid,nodev,noexec,relatime shared:302 - sysfs sysfs ro,seclabel
702 701 0:21 / /sys/fs/selinux ro,nosuid,nodev,noexec,relatime shared:306 master:8 - selinuxfs selinuxfs rw
703 697 0:42 / /dev rw,nosuid shared:303 - tmpfs tmpfs rw,seclabel,mode=755
704 703 0:43 / /dev/shm rw,nosuid,nodev shared:304 - tmpfs tmpfs rw,seclabel
705 703 0:45 / /dev/pts rw,nosuid,noexec,relatime shared:307 - devpts devpts rw,seclabel,gid=5,mode=620,ptmxmode=666
706 703 0:6 /btrfs-control /dev/btrfs-control rw,nosuid shared:308 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
707 703 0:6 /loop-control /dev/loop-control rw,nosuid shared:309 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
708 703 0:6 /loop0 /dev/loop0 rw,nosuid shared:310 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
709 703 0:6 /loop1 /dev/loop1 rw,nosuid shared:311 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
710 703 0:6 /loop10 /dev/loop10 rw,nosuid shared:312 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
711 703 0:6 /loop11 /dev/loop11 rw,nosuid shared:313 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
712 703 0:6 /loop2 /dev/loop2 rw,nosuid shared:314 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
713 703 0:6 /loop3 /dev/loop3 rw,nosuid shared:315 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
714 703 0:6 /loop4 /dev/loop4 rw,nosuid shared:316 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
715 703 0:6 /loop5 /dev/loop5 rw,nosuid shared:317 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
716 703 0:6 /loop6 /dev/loop6 rw,nosuid shared:318 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
717 703 0:6 /loop7 /dev/loop7 rw,nosuid shared:319 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
718 703 0:6 /loop8 /dev/loop8 rw,nosuid shared:320 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
719 703 0:6 /loop9 /dev/loop9 rw,nosuid shared:321 master:9 - devtmpfs devtmpfs rw,seclabel,size=4107840k,nr_inodes=64185,mode=755
720 697 0:44 / /run rw,nosuid,nodev shared:305 - tmpfs tmpfs rw,seclabel,mode=755
721 720 0:25 /systemd/nspawn/propagate/9cc8a155d0244558b273f773d2b92142 /run/systemd/nspawn/incoming ro master:12 - tmpfs tmpfs rw,seclabel,mode=755
722 697 0:32 /mock-resolv.dvml91hp /etc/resolv.conf rw,nosuid,nodev shared:322 master:18 - tmpfs tmpfs rw,seclabel
725 697 0:47 / /proc rw,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
603 725 0:47 /sys /proc/sys ro,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
604 725 0:44 /systemd/inaccessible/reg /proc/kallsyms ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
605 725 0:44 /systemd/inaccessible/reg /proc/kcore ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
606 725 0:44 /systemd/inaccessible/reg /proc/keys ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
607 725 0:44 /systemd/inaccessible/reg /proc/sysrq-trigger ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
608 725 0:44 /systemd/inaccessible/reg /proc/timer_list ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
609 725 0:47 /bus /proc/bus ro,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
610 725 0:47 /fs /proc/fs ro,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
611 725 0:47 /irq /proc/irq ro,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
612 725 0:47 /scsi /proc/scsi ro,nosuid,nodev,noexec,relatime shared:323 - proc proc rw
613 703 0:46 / /dev/mqueue rw,nosuid,nodev,noexec,relatime shared:324 - mqueue mqueue rw,seclabel
614 701 0:26 / /sys/fs/cgroup rw,nosuid,nodev,noexec,relatime shared:325 - cgroup2 cgroup rw,seclabel,nsdelegate
615 603 0:44 /.#proc-sys-kernel-random-boot-id4fbdce67af46d1c2//deleted /proc/sys/kernel/random/boot_id ro,nosuid,nodev,noexec shared:305 - tmpfs tmpfs rw,seclabel,mode=755
616 725 0:44 /.#proc-sys-kernel-random-boot-id4fbdce67af46d1c2//deleted /proc/sys/kernel/random/boot_id rw,nosuid,nodev shared:305 - tmpfs tmpfs rw,seclabel,mode=755
617 725 0:44 /.#proc-kmsg5b7a8bcfe6717139//deleted /proc/kmsg rw,nosuid,nodev shared:305 - tmpfs tmpfs rw,seclabel,mode=755

The test process does
name_to_handle_at("/proc/filesystems") which returns -EOPNOTSUPP, and then
openat(AT_FDCWD, "/proc/filesystems") which returns 4, and then
read(open("/proc/self/fdinfo/4", ...)) which gives
"pos:\t0\nflags:\t012100000\nmnt_id:\t725\n"

and the "725" is clearly inconsistent with "700" in /proc/self/mountinfo.

We could either drop the fallback path (and fail name_to_handle_at() is not
avaliable) or ignore the error in the test. Not sure what is better. I think
this issue only occurs sometimes and with older kernels, so probably continuing
with the current flaky implementation is better than ripping out the fallback.

Another strace:
writev(2</dev/pts/0>, [{iov_base="mnt ids of /proc/sys is 603", iov_len=27}, {iov_base="\n", iov_len=1}], 2mnt ids of /proc/sys is 603
) = 28
name_to_handle_at(AT_FDCWD, "/", {handle_bytes=128 => 12, handle_type=129, f_handle=0x52748401000000008b93e20d}, [697], 0) = 0
writev(2</dev/pts/0>, [{iov_base="mnt ids of / is 697", iov_len=19}, {iov_base="\n", iov_len=1}], 2mnt ids of / is 697
) = 20
name_to_handle_at(AT_FDCWD, "/proc/kcore", {handle_bytes=128 => 12, handle_type=1, f_handle=0x92ddcfcd2e802d0100000000}, [605], 0) = 0
writev(2</dev/pts/0>, [{iov_base="mnt ids of /proc/kcore is 605", iov_len=29}, {iov_base="\n", iov_len=1}], 2mnt ids of /proc/kcore is 605
) = 30
name_to_handle_at(AT_FDCWD, "/dev", {handle_bytes=128 => 12, handle_type=1, f_handle=0x8ae269160c802d0100000000}, [703], 0) = 0
writev(2</dev/pts/0>, [{iov_base="mnt ids of /dev is 703", iov_len=22}, {iov_base="\n", iov_len=1}], 2mnt ids of /dev is 703
) = 23
name_to_handle_at(AT_FDCWD, "/proc/filesystems", {handle_bytes=128}, 0x7fffe36ddb84, 0) = -1 EOPNOTSUPP (Operation not supported)
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4</proc/filesystems>
openat(AT_FDCWD, "/proc/self/fdinfo/4", O_RDONLY|O_CLOEXEC) = 5</proc/20/fdinfo/4>
fstat(5</proc/20/fdinfo/4>, {st_mode=S_IFREG|0400, st_size=0, ...}) = 0
fstat(5</proc/20/fdinfo/4>, {st_mode=S_IFREG|0400, st_size=0, ...}) = 0
read(5</proc/20/fdinfo/4>, "pos:\t0\nflags:\t012100000\nmnt_id:\t725\n", 2048) = 36
read(5</proc/20/fdinfo/4>, "", 1024)    = 0
close(5</proc/20/fdinfo/4>)             = 0
close(4</proc/filesystems>)             = 0
writev(2</dev/pts/0>, [{iov_base="mnt ids of /proc/filesystems are 700, 725", iov_len=41}, {iov_base="\n", iov_len=1}], 2mnt ids of /proc/filesystems are 700, 725
) = 42
writev(2</dev/pts/0>, [{iov_base="the other path for mnt id 725 is /proc", iov_len=38}, {iov_base="\n", iov_len=1}], 2the other path for mnt id 725 is /proc
) = 39
writev(2</dev/pts/0>, [{iov_base="Assertion 'path_equal(p, t)' failed at src/test/test-mountpoint-util.c:94, function test_mnt_id(). Aborting.", iov_len=108}, {iov_base="\n", iov_len=1}], 2Assertion 'path_equal(p, t)' failed at src/test/test-mountpoint-util.c:94, function test_mnt_id(). Aborting.
) = 109
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
getpid()                                = 20
gettid()                                = 20
tgkill(20, 20, SIGABRT)                 = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0

Resolves: #1910425
---
 src/test/test-mount-util.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/src/test/test-mount-util.c b/src/test/test-mount-util.c
index c10e1681fb..991d165fc3 100644
--- a/src/test/test-mount-util.c
+++ b/src/test/test-mount-util.c
@@ -74,7 +74,13 @@ static void test_mnt_id(void) {
 
                 /* The ids don't match? If so, then there are two mounts on the same path, let's check if that's really
                  * the case */
-                assert_se(path_equal_ptr(hashmap_get(h, INT_TO_PTR(mnt_id2)), p));
+                char *t = hashmap_get(h, INT_TO_PTR(mnt_id2));
+                log_debug("Path for mnt id %i from /proc/self/mountinfo is %s\n", mnt_id2, t);
+
+                if (!path_equal(p, t))
+                        /* Apparent kernel bug in /proc/self/fdinfo */
+                        log_warning("Bad mount id given for %s: %d, should be %d",
+                                    p, mnt_id2, mnt_id);
         }
 
         hashmap_free_free(h);