i/o error if next unused loop device is queried

[Eric Desrochers]

[Impact]

* There's an I/O error on fsync() in a detached loop device if it has
been previously attached. The issue is that write cache is enabled in
the attach path in loop_configure() but it isn't disabled in the detach
path; thus it remains enabled in the block device regardless of whether
it is attached or not.

* fsync() on detached loop devices can be called by partition tools and
commands run by sosreport, so the unexpected kernel error message might
surprise users or even distract from the actual issue being
investigatedr. It might also trigger alerts in
logging/monitoring/alerting stacks

[Fix]

* Disable write cache in the detach path

[Test Plan]

* Attach and detach an image to a loop device and test fsync return
value aterwards

# DEV=/dev/loop7

# IMG=/tmp/image
# truncate --size 1M $IMG

# losetup $DEV $IMG
# losetup -d $DEV

Before:
    # strace -e fsync parted -s $DEV print 2>&1 | grep fsync
    fsync(3) = -1 EIO (Input/output error)
    Warning: Error fsyncing/closing /dev/loop7: Input/output error
    [ 982.529929] blk_update_request: I/O error, dev loop7, sector 0 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 0

After:
    # strace -e fsync parted -s $DEV print 2>&1 | grep fsync
    fsync(3) = 0

[Where problems could occur]

* The detach path for block devices is modified. Worst case scenario
would be an error when detaching loop devices.

[Eric Desrochers (slashd)]

Booting with "systemd.log_level=debug" revealed:

Dec 18 17:26:22 ubuntu systemd-udevd[1326]: value '[dmi/id]sys_vendor' is 'QEMU'
Dec 18 17:26:22 ubuntu systemd-udevd[1326]: created db file '/run/udev/data/b7:2' for '/devices/virtual/block/loop2'
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Changed dead -> tentative
Dec 18 17:26:22 ubuntu systemd-udevd[1326]: created db file '/run/udev/data/b7:2' for '/devices/virtual/block/loop2'
Dec 18 17:26:22 ubuntu systemd-udevd[1326]: passed 293 byte device to netlink monitor 0x557a8c0f8680
Dec 18 17:26:22 ubuntu systemd[1120]: dev-loop2.device: Changed dead -> tentative
...
Dec 18 17:26:22 ubuntu systemd[1120]: sys-devices-virtual-block-loop2.device: Changed dead -> plugged
Dec 18 17:26:22 ubuntu systemd[1120]: dev-loop2.device: Changed tentative -> plugged
Dec 18 17:26:22 ubuntu systemd-udevd[529]: passed 179 byte device to netlink monitor 0x557a8c0c7bc0
Dec 18 17:26:22 ubuntu systemd[1]: sys-devices-virtual-block-loop2.device: Changed dead -> plugged
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Changed tentative -> plugged
...
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/dev_2dloop2_2edevice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1009 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/dev_2dloop2_2edevice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1010 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
...
Dec 18 17:26:22 ubuntu systemd-udevd[1328]: created db file '/run/udev/data/b7:2' for '/devices/virtual/block/loop2'
Dec 18 17:26:22 ubuntu systemd-udevd[1328]: created db file '/run/udev/data/b7:2' for '/devices/virtual/block/loop2'
Dec 18 17:26:22 ubuntu systemd-udevd[1328]: passed 252 byte device to netlink monitor 0x557a8c0f8680
Dec 18 17:26:22 ubuntu systemd[1]: sys-devices-virtual-block-loop2.device: Installed new job sys-devices-virtual-block-loop2.device/nop as 412
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Installed new job dev-loop2.device/nop as 413
Dec 18 17:26:22 ubuntu systemd[1]: sys-devices-virtual-block-loop2.device: Changed plugged -> dead
Dec 18 17:26:22 ubuntu systemd[1120]: sys-devices-virtual-block-loop2.device: Installed new job sys-devices-virtual-block-loop2.device/nop as 14
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Changed plugged -> dead
Dec 18 17:26:22 ubuntu systemd[1120]: dev-loop2.device: Installed new job dev-loop2.device/nop as 15
Dec 18 17:26:22 ubuntu systemd[1120]: sys-devices-virtual-block-loop2.device: Changed plugged -> dead
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/dev_2dloop2_2edevice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1028 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1120]: dev-loop2.device: Changed plugged -> dead
Dec 18 17:26:22 ubuntu systemd[1]: Sent me...

[Eric Desrochers (slashd)]

I also filed a sosreport upstream issue, because I believe sosreport shouldn't try to query "unused" block device such as loop device.

https://github.com/sosreport/sos/issues/1897

but situation remain that there is something going wrong with loop device and systemd/systemd-udevd at boot as explained above.

[Eric Desrochers (slashd)]

Interesting fact,

If I modified "snapd.service" to prevent snapd to run and reboot. I don't get the problem with the first unused loop device which is /dev/loop0 since nothing is using a loop device.

[Eric Desrochers (slashd)]

Talking with mvo (snap team) on the subject trying to eliminate some components:

[09:48:27] <mvo> so snapd does not do anything "special" with block devices beside using them
[09:48:39] <mvo> it uses the standard system mount units to do that
[09:49:01] <mvo> so if you see strange things with extra block devices, I'm inclined to point my finger at systemd :/

[Eric Desrochers (slashd)]

losetup -l
NAME SIZELIMIT OFFSET AUTOCLEAR RO BACK-FILE DIO LOG-SEC
/dev/loop1 0 0 1 1 /var/lib/snapd/snaps/core_7270.snap 0 512
/dev/loop2 0 0 1 1 /var/lib/snapd/snaps/core_8268.snap 0 512
/dev/loop0 0 0 1 1 /var/lib/snapd/snaps/firefox_287.snap 0 512

# losetup -f
/dev/loop3

# strace parted -s $(losetup -f) unit s print
ioctl(3, BLKSSZGET, [512]) = 0
fadvise64(3, 0, 0, POSIX_FADV_RANDOM) = 0
fstat(3, {st_mode=S_IFBLK|0660, st_rdev=makedev(7, 3), ...}) = 0
ioctl(3, BLKGETSIZE64, [0]) = 0
openat(AT_FDCWD, "/sys/dev/block/7:3", O_RDONLY|O_CLOEXEC) = 4
openat(4, "dm/uuid", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
close(4) = 0
ioctl(3, BLKALIGNOFF, [0]) = 0
ioctl(3, BLKIOMIN, [512]) = 0
ioctl(3, BLKIOOPT, [0]) = 0
ioctl(3, BLKPBSZGET, [512]) = 0
ioctl(3, BLKSSZGET, [512]) = 0
ioctl(3, BLKGETSIZE64, [0]) = 0
ioctl(3, BLKGETSIZE64, [0]) = 0
fsync(3) = -1 EIO (Input/output error)
openat(AT_FDCWD, "/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale-langpack/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
write(2, "Warning", 7Warning) = 7
write(2, ": ", 2: ) = 2
write(2, "Error fsyncing/closing /dev/loop"..., 53Error fsyncing/closing /dev/loop3: Input/output error) = 53
write(2, "\n", 1
) = 1
close(1) = 0
close(2) = 0
exit_group(1) = ?
+++ exited with 1 +++

# strace parted -s /dev/loop5 unit s print

ioctl(3, BLKSSZGET, [512]) = 0
fadvise64(3, 0, 0, POSIX_FADV_RANDOM) = 0
...

[Eric Desrochers (slashd)]

# parted code (3.3-1) from focal

---------
libparted/arch/linux.c:
.....
=> if (fsync (fd) < 0 || close (fd) < 0)
                                        if (ped_exception_throw (
                                                PED_EXCEPTION_WARNING,
                                                PED_EXCEPTION_RETRY +
                                                        PED_EXCEPTION_IGNORE,
=> _("Error fsyncing/closing %s: %s"),
                                                name, strerror (errno))
                                                        == PED_EXCEPTION_RETRY)
                                                goto retry;
                        }
                }
                free (name);

# FSYNC(2)
RETURN VALUE
       On success, these system calls return zero. On error, -1 is returned, and errno is set appropriately.
---------

so definitely fsync() fails returning "-1" on the next unused loop device as oppose to any other unused loop device.

The question is why unused loop device fails on fsync() ONLY when it is the next unused loop device after a system boot (losetup -f) ?

[John Lenton (chipaca)]

FWIW snapd mounts and unmounts a squashfs on startup to determine whether the system can mount squashfs's. It does this using mount, and cleans up with umount -l. That is, it's not via systemd in this instance in particular.

I'm setting it as invalid for snapd, but if this behaviour is somehow tickling a bug and there's a workaround that could avoid it, let us know and we'd be happy to accommodate (set the bug task back to New so our triage picks it up).

[Thadeu Lima de Souza Cascardo (cascardo)]

I did some quick testing and it seems this happens on whatever loop device that had a file attached and then detached. No matter if it's the next available or not. So, if you create a new loop device without ever attaching a file to it, it seems the block layer is not setup sufficiently so any requests will really go through it. But when it is attached, then detached, the block layer still sends requests to the loop driver, which will result in the EIO as it is detached.

Cascardo.

[Thadeu Lima de Souza Cascardo (cascardo)]

<slashd> so the problem is inside the block layer ?

More likely the loop driver not undoing something it does when a file is attached to it. But could as well be something related to the multiqueue support, so could still be something in the block layer. Still needs investigation.

Anyway, as this is not exactly a difference in behavior between the next available loop device and other detached loop devices, what is the exact problem this is causing? I don't see why getting EIO for a detached loop device is the wrong behavior here. I agree there is an inconsistency, but I would accept EIO when trying to fsync a detached device.

[Eric Desrochers (slashd)]

@thadeu,

To respond your question "What is the exact problem this is causing?"

So far it's not causing much problem, it's pretty harmless, but while running sosreport block plugin (which most Canonical customer uses) it may lead to output "blk" error to the stderr and save syslog || kern.log.

As an fyi, we are re-working the sosreport block plugin upstream to prevent to query unused disk, but still, while I agree with your EIO statement, I don't think a detached loop device should behave differently from a "never" detached loop device, if there current state is "unused" unless I missed something. IMHO they should produce consistent behaviour if 'unused' no ?

- Eric

[Thadeu Lima de Souza Cascardo (cascardo)]

Exactly my point about consistency. They should either return EIO in both cases or succeed in both cases. Which behavior will depend on: 1) which is the easier solution; 2) what upstream thinks is okay.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1856871

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Eric Desrochers (slashd)]

It then might be a problem with "/dev/loop-control" device node. Which dynamically find or allocate a free device, but also add and remove loop devices from the running system.

# drivers/block/loop.c

   2090 static void loop_remove(struct loop_device *lo)
   2091 {
   2092 del_gendisk(lo->lo_disk);
   2093 blk_cleanup_queue(lo->lo_queue);
   2094 blk_mq_free_tag_set(&lo->tag_set);
   2095 put_disk(lo->lo_disk);
   2096 kfree(lo);
   2097 }

   2177 case LOOP_CTL_REMOVE:
   2178 ret = loop_lookup(&lo, parm);
   2179 if (ret < 0)
   2180 break;
   2181 if (lo->lo_state != Lo_unbound) {
   2182 ret = -EBUSY;
   2183 break;
   2184 }
   2185 if (atomic_read(&lo->lo_refcnt) > 0) {
   2186 ret = -EBUSY;
   2187 break;
   2188 }
   2189 lo->lo_disk->private_data = NULL;
   2190 idr_remove(&loop_index_idr, lo->lo_number);
   2191 loop_remove(lo);
   2192 break;

[Eric Desrochers (slashd)]

Agreed with your comment #11

will start a discussion with the linux-block maintainer.

[Eric Desrochers (slashd)]

I reproduced the behaviour using 5.5 upstream kernel by:

1) Mounting a loop device
2) Setup frace for all loop function for capture purposes
3) Then umount the loop device

trace_pipe reveal the following:
"umount-1850 [000] .... 471.727511: loop_release_xfer <-__loop_clr_fd"

As cascardo mentioned earlier it might be in the way that loop device are detached, now that I know what function to look at, I'll investigate further.

[Dan Streetman (ddstreet)]

marking invalid for systemd, as i think we all agree it's not an issue caused by systemd, but please feel free to re-mark it for systemd if i'm incorrect

[Eric Desrochers (slashd)]

The upstream proposal fix that mfo and I worked on has been applied:

https://patchwork<email address hidden>/

- Eric

[Mauricio Faria de Oliveira (mfo)]

The fix/commit is applied in v5.12, thus available on Jammy (v5.15-based).

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=4ceddce55eb35d15b0f87f5dcf6f0058fd15d3a4

~/git/linux$ git describe --contains 4ceddce55eb35d15b0f87f5dcf6f0058fd15d3a4
v5.12-rc1-dontuse~7^2~13

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is awaiting verification that the linux/5.4.0-149.166 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

[Jorge Merlino (jorge-merlino)]

Tested with kernel 5.4.0-149.166 in focal. Test plan works Ok.

[Launchpad Janitor (janitor)]

This bug was fixed in the package linux - 5.4.0-149.166

---------------
linux (5.4.0-149.166) focal; urgency=medium

  * focal/linux: 5.4.0-149.166 -proposed tracker (LP: #2016591)

  * Focal update: v5.4.233 upstream stable release (LP: #2015909)
    - dma-mapping: add generic helpers for mapping sgtable objects
    - scatterlist: add generic wrappers for iterating over sgtable objects
    - drm: etnaviv: fix common struct sg_table related issues
    - drm/etnaviv: don't truncate physical page address
    - wifi: rtl8xxxu: gen2: Turn on the rate control
    - powerpc: dts: t208x: Mark MAC1 and MAC2 as 10G
    - random: always mix cycle counter in add_latent_entropy()
    - KVM: x86: Fail emulation during EMULTYPE_SKIP on any exception
    - can: kvaser_usb: hydra: help gcc-13 to figure out cmd_len
    - powerpc: dts: t208x: Disable 10G on MAC1 and MAC2
    - alarmtimer: Prevent starvation by small intervals and SIG_IGN
    - drm/i915/gvt: fix double free bug in split_2MB_gtt_entry
    - mac80211: mesh: embedd mesh_paths and mpp_paths into ieee80211_if_mesh
    - uaccess: Add speculation barrier to copy_from_user()
    - wifi: mwifiex: Add missing compatible string for SD8787
    - ext4: Fix function prototype mismatch for ext4_feat_ktype
    - Revert "net/sched: taprio: make qdisc_leaf() see the per-netdev-queue pfifo
      child qdiscs"
    - bpf: add missing header file include
    - Linux 5.4.233

  * selftest: fib_tests: Always cleanup before exit (LP: #2015956)
    - selftest: fib_tests: Always cleanup before exit

  * fib_tests.sh in ubuntu_kernel_selftests was skipped silently on Focal
    (LP: #2015440)
    - selftests: Fix the executable permissions for fib_tests.sh

  * Debian autoreconstruct Fix restoration of execute permissions (LP: #2015498)
    - [Debian] autoreconstruct - fix restoration of execute permissions

  * kernel: fix __clear_user() inline assembly constraints (LP: #2013088)
    - s390/uaccess: add missing earlyclobber annotations to __clear_user()

  * i/o error if next unused loop device is queried (LP: #1856871)
    - loop: fix I/O error on fsync() in detached loop devices

  * CVE-2023-1075
    - net/tls: tls_is_tx_ready() checked list_entry

  * Focal update: v5.4.232 upstream stable release (LP: #2011625)
    - firewire: fix memory leak for payload of request subaction to IEC 61883-1
      FCP region
    - bus: sunxi-rsb: Fix error handling in sunxi_rsb_init()
    - ASoC: Intel: bytcr_rt5651: Drop reference count of ACPI device after use
    - ALSA: hda/via: Avoid potential array out-of-bound in add_secret_dac_path()
    - arm64: dts: imx8mm: Fix pad control for UART1_DTE_RX
    - scsi: Revert "scsi: core: map PQ=1, PDT=other values to
      SCSI_SCAN_TARGET_PRESENT"
    - WRITE is "data source", not destination...
    - fix iov_iter_bvec() "direction" argument
    - fix "direction" argument of iov_iter_kvec()
    - netrom: Fix use-after-free caused by accept on already connected socket
    - netfilter: br_netfilter: disable sabotage_in hook after first suppression
    - squashfs: harden sanity check in squashfs_read_xattr_id_table
    - net: phy: meson-gxl: Add generic dummy stubs for MMD register access
  ...

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is awaiting verification that the linux-bluefield/5.4.0-1064.70 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

[Jorge Merlino (jorge-merlino)]

I restored the verification-done-focal tag because I already verified this bug on focal (see comment #24). I think the linux-bluefield kernel patch is not appropriate for this bug.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is awaiting verification that the linux-aws/5.4.0-1104.112 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is awaiting verification that the linux-azure/5.4.0-1110.116 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!