[Bug 1856871] Re: i/o error if next unused loop device is queried

Wed Dec 18 17:32:12 UTC 2019

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 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=1029 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: Job dev-loop2.device/nop finished, result=done
Dec 18 17:26:22 ubuntu systemd[1120]: sys-devices-virtual-block-loop2.device: Job sys-devices-virtual-block-loop2.device/nop finished, result=done
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/sys_2ddevices_2dvirtual_2dblock_2dloop2_2edevice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1030 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1120]: sys-devices-virtual-block-loop2.device: Collecting.
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/sys_2ddevices_2dvirtual_2dblock_2dloop2_2edevice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=1031 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: Collecting.
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=1032 reply_cookie=0 signature=uos 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 interface=org.freedesktop.systemd1.Manager member=JobNew cookie=1033 reply_cookie=0 signature=uos error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Job dev-loop2.device/nop finished, result=done
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=1034 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1]: sys-devices-virtual-block-loop2.device: Job sys-devices-virtual-block-loop2.device/nop finished, result=done
Dec 18 17:26:22 ubuntu systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=1035 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Dec 18 17:26:22 ubuntu systemd[1]: sys-devices-virtual-block-loop2.device: Collecting.
Dec 18 17:26:22 ubuntu systemd[1]: dev-loop2.device: Collecting.

** Description changed:

  This is reproducible in Bionic and late.

  Here's an example running 'focal':

  $ lsb_release -cs
  focal

  $ uname -r
  5.3.0-24-generic

  The error is:
  blk_update_request: I/O error, dev loop2, sector 0

  How to trigger it:
  $ sosreport -o block

  or more precisely the cmd causing the situation inside the block plugin:
- $ parted -s /dev/$(losetup -f) unit s print
+ $ parted -s $(losetup -f) unit s print

  https://github.com/sosreport/sos/blob/master/sos/plugins/block.py#L52

  but if I run it on the next next unused loop device, in this case
  /dev/loop3 (which is also unused), no errors.

  While I agree that sosreport shouldn't query unused loop devices, there
  is definitely something going on with the next unused loop device.

  What is differentiate loop2 and loop3 and any other unused ones ?

  3 things so far I have noticed:
  * loop2 is the next unused loop device (losetup -f)
  * A reboot is needed (if some loop modification (snap install, mount loop, ...) has been made at runtime
  * I have also noticed that loop2 (or whatever the next unused one is) have some stat as oppose to other unused loop devices. The stat exist already right after the system boot for the next unused loop device.

  /sys/block/loop2/stat
  ::::::::::::::
  2 0 10 0 1 0 0 0 0 0 0

  2  = number of read I/Os processed
  10 = number of sectors read
  1  = number of write I/Os processed

  Explanation of each column:
  https://www.kernel.org/doc/html/latest/block/stat.html

  while /dev/loop3 doesn't

  /sys/block/loop3/stat
  ::::::::::::::
  0 0 0 0 0 0 0 0 0 0 0

  Which tells me that something during the boot process most likely
  acquired (on purpose or not) the next unused loop and possibly didn't
  released it well enough.

  If loop2 is generating errors, and I install a snap, the snap squashfs
  will take loop2, making loop3 the next unused loop device.

  If I query loop3 with 'parted' right after, no errors.

  If I reboot, and query loop3 again, then no I'll have an error.

  To triggers the errors it need to be after a reboot and it only impact
  the first unused loop device available (losetup -f).

  This was tested with focal/systemd whic his very close to latest
  upstream code.

  This has been test with latest v5.5 mainline kernel as well.

  For now, I don't think it's a kernel problem, I'm more thinking of a
  userspace misbehaviour dealing with loop device (or block device) at
  boot.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1856871

Title:
  i/o error if next unused loop device is queried

Status in systemd package in Ubuntu:
  New
Status in udev package in Ubuntu:
  New

Bug description:
  This is reproducible in Bionic and late.

  Here's an example running 'focal':

  $ lsb_release -cs
  focal

  $ uname -r
  5.3.0-24-generic

  The error is:
  blk_update_request: I/O error, dev loop2, sector 0

  How to trigger it:
  $ sosreport -o block

  or more precisely the cmd causing the situation inside the block plugin:
  $ parted -s $(losetup -f) unit s print

  https://github.com/sosreport/sos/blob/master/sos/plugins/block.py#L52