Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

udisks 2.9.1 and Kernel 5.10.x on Mageia 8/Cauldron: spurious Kernel output when unmounting on behalf of user #827

Closed
aureoud-fr85 opened this issue Dec 20, 2020 · 17 comments
Closed

udisks 2.9.1 and Kernel 5.10.x on Mageia 8/Cauldron: spurious Kernel output when unmounting on behalf of user #827

aureoud-fr85 opened this issue Dec 20, 2020 · 17 comments

Comments

@aureoud-fr85
Copy link

Under the following configuration:
Operating System: Mageia 8/Cauldron
KDE Plasma Version: 5.20.4
KDE Frameworks Version: 5.76.0
Qt Version: 5.15.2
Kernel Version: 5.10.1-desktop-2.mga8
OS Type: 64-bit
Processors: 4 × Intel® Core™ i5-6600K CPU @ 3.50GHz
Memory: 15.6 Gio of RAM
Graphics Processor: GeForce GTX 1660 Ti/PCIe/SSE2,

with udisks-2.9.1:
There are the following errors from kernel and udisks when unmouting a USB-device:
usb-key-sequence-strange-unmount.txt

KDE devs think it is somewhere between there code and Kernel
See: https://bugs.kde.org/show_bug.cgi?id=430584

Attached here is same sequence on 5.9.12 kernel:
usb-key-sequence-kernel-5.9.12-unmount.txt

Here is our bug report in our Bugzilla database at Mageia: https://bugs.mageia.org/show_bug.cgi?id=27877

Mitigation:
Later mounting the device, run a fsck on this, it seems there is no error.
@tbzatek
Copy link
Member

tbzatek commented Dec 30, 2020

Haven't switched to kernel 5.10 yet here, will try that soon...

Can you try calling eject /dev/sdb and check if you can reproduce the error. That's the command UDisks calls on org.freedesktop.UDisks2.Drive.Eject().

You can also try experimenting with udisksctl power-off which sends more magic commands to the drive. Also for USB devices UDisks tries to "remove" the device from kernel - see https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=253e05724f9230910344357b1142ad8642ff9f5a.

Something may have changed recently that tries to access a "removed" device. Any removed device should stay dead until an unplug event and should not re-announce itself nor should be listed as present in the system.

@aureoud-fr85
Copy link
Author

aureoud-fr85 commented Dec 30, 2020 •
edited

Here are some tests:

Plugging USB Key with ISO 9660 dumped on it.
Plasma pop-up a notification.
Choose to mount drive.
Output in journal:
kernel: usb 2-2: new SuperSpeed Gen 1 USB device number 4 using xhci_hcd
kernel: usb 2-2: New USB device found, idVendor=05dc, idProduct=0700, bcdDevice=10.75
kernel: usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
kernel: usb 2-2: Product: JumpDrive
kernel: usb 2-2: Manufacturer: Lexar
kernel: usb 2-2: SerialNumber: 4137252770
kernel: usb-storage 2-2:1.0: USB Mass Storage device detected
kernel: scsi host4: usb-storage 2-2:1.0
mtp-probe[47508]: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[47508]: bus: 2, device: 4 was not an MTP device
mtp-probe[47524]: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[47524]: bus: 2, device: 4 was not an MTP device
kernel: scsi 4:0:0:0: Direct-Access Lexar JumpDrive 1.00 PQ: 0 ANSI: 6
kernel: sd 4:0:0:0: [sdb] 31260672 512-byte logical blocks: (16.0 GB/14.9 GiB)
kernel: sd 4:0:0:0: [sdb] Write Protect is off
kernel: sd 4:0:0:0: [sdb] Mode Sense: 23 00 00 00
kernel: sd 4:0:0:0: [sdb] Write cache: disabled, read cache: disabled, doesn't support DPO or FUA
kernel: sdb: sdb1 sdb2
kernel: sd 4:0:0:0: [sdb] Attached SCSI removable disk
dbus-daemon[1039]: [system] Activating service name='org.kde.kded.smart' requested by ':1.69' (uid=1000 pid=2433 comm="/usr/bin/kded5") (using servicehelper)
dbus-daemon[1039]: [system] Successfully activated service 'org.kde.kded.smart
kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
kernel: ISO 9660 Extensions: RRIP_1991A
udisksd[1066]: Mounted /dev/sdb1 at /run/media/aurelien/Mageia-8-beta2-x86_64 on behalf of uid 1000
udisksd[1066]: udisks_state_check_mounted_fs_entry: block device /dev/sdb1 is busy, skipping cleanup

The latter line is spurious...

Later, do:
$ udisksctl unmount -b /dev/sdb1
Unmounted /dev/sdb1.
In log:
udisksd[1066]: Cleaning up mount point /run/media/aurelien/Mageia-8-beta2-x86_64 (device 8:17 is not mounted)
udisksd[1066]: Unmounted /dev/sdb1 on behalf of uid 1000
systemd[1]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.

I can even do:
$ udisksctl mount -b /dev/sdb1
Mounted /dev/sdb1 at /run/media/aurelien/Mageia-8-beta2-x86_64
(Same logical output in journal)
Only this suprious line:
udisksd[1066]: udisks_state_check_mounted_fs_entry: block device /dev/sdb1 is busy, skipping cleanup

If I do
$ eject /dev/sdb
eject: impossible d'ouvrir /dev/sdb: Permission non accordée
Log:
udisksd[1066]: udisks_state_check_mounted_fs_entry: block device /dev/sdb1 is busy, skipping cleanup
systemd[2277]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
systemd[1]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
udisksd[1066]: Cleaning up mount point /run/media/aurelien/Mageia-8-beta2-x86_64 (device 8:17 is not mounted)
udisksd[1066]: Unmounted /dev/sdb1 on behalf of uid 1000

But the key is no longer mounted in UI.

If I mount the key and I do:
$ udisksctl power-off -b /dev/sdb1
Error powering off drive: The drive in use: Device /dev/sdb1 is mounted (udisks-error-quark, 14)

I must unmount and do power-off:
$ udisksctl unmount -b /dev/sdb && udisksctl power-off -b /dev/sdb
Unmounted /dev/sdb1.
Log:
udisksd[1066]: Cleaning up mount point /run/media/aurelien/Mageia-8-beta2-x86_64 (device 8:17 is not mounted)
udisksd[1066]: Unmounted /dev/sdb1 on behalf of uid 1000
systemd[1]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
systemd[2277]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
udisksd[1066]: Successfully sent SCSI command SYNCHRONIZE CACHE to /dev/sdb
udisksd[1066]: Successfully sent SCSI command START STOP UNIT to /dev/sdb
udisksd[1066]: Powered off /dev/sdb - successfully wrote to sysfs path /sys/devices/pci0000:00/0000:00:14.0/usb2/2-2/remove
kernel: usb 2-2: USB disconnect, device number 5

So, after I can unplug physically the key and no spurious lines in system log.
The bug is really in Plasma somewhere.

Thanks,
Closing.

@tbzatek
Copy link
Member

tbzatek commented Dec 30, 2020

I still don't think this is a Plasma bug. You can ignore that spurious line, I'll probably just remove the warning, it's harmless and confusing to users. Also the eject command needs to be run as root.

Anyway, I was expecting writing to /sys/devices/pci0000:00/0000:00:14.0/usb2/2-2/remove would case the error, weird.

@tbzatek
Copy link
Member

tbzatek commented Dec 30, 2020

Perhaps related:

plasmashell[2315]: file:///usr/share/plasma/plasmoids/org.kde.plasma.devicenotifier/contents/ui/DeviceItem.qml:160:5: Unable to assign [undefined] to QString
kernel: scsi_io_completion_action: 6 callbacks suppressed
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current] 
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00

@aureoud-fr85
Copy link
Author

I still don't think this is a Plasma bug. You can ignore that spurious line, I'll probably just remove the warning, it's harmless and confusing to users. Also the eject command needs to be run as root.

Anyway, I was expecting writing to /sys/devices/pci0000:00/0000:00:14.0/usb2/2-2/remove would case the error, weird.

In facts, you're right, executing as superuser (on a USB-key mounted before).
$ sudo eject /dev/sdb1
Log:
sudo[3804]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/eject /dev/sdb1
kernel: scsi_io_completion_action: 6 callbacks suppressed
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: print_req_error: 6 callbacks suppressed
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: buffer_io_error: 54 callbacks suppressed
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 1, async page read
kernel: Buffer I/O error on dev sdb, logical block 2, async page read
kernel: Buffer I/O error on dev sdb, logical block 3, async page read
kernel: Buffer I/O error on dev sdb, logical block 4, async page read
kernel: Buffer I/O error on dev sdb, logical block 5, async page read
kernel: Buffer I/O error on dev sdb, logical block 6, async page read
kernel: Buffer I/O error on dev sdb, logical block 7, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 1, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: ldm_validate_partition_table(): Disk read failed.
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 08 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0
kernel: sdb: unable to read partition table
udisksd[1100]: Cleaning up mount point /run/media/aurelien/Mageia-8-beta2-x86_64 (device 8:17 is not mounted)
systemd[2288]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
systemd[1]: run-media-aurelien-Mageia\x2d8\x2dbeta2\x2dx86_64.mount: Succeeded.
plasmashell[2485]: file:///usr/share/plasma/plasmoids/org.kde.plasma.devicenotifier/contents/ui/DeviceItem.qml:195: TypeError: Value is undefined and could not be converted to an object
plasmashell[2485]: file:///usr/share/plasma/plasmoids/org.kde.plasma.devicenotifier/contents/ui/DeviceItem.qml:202: TypeError: Value is undefined and could not be converted to an object

The bug reoccurs. You're right after all.

@aureoud-fr85 aureoud-fr85 reopened this Dec 30, 2020
@aureoud-fr85
Copy link
Author

$ uname -a
Linux mageia.local 5.10.4-desktop-1.mga8 #1 SMP Wed Dec 30 11:49:25 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
and
$ rpm -qa | grep udisks
udisks2-2.9.1-1.mga8

@aureoud-fr85 aureoud-fr85 changed the title udisks 2.9.1 and Kernel 5.10.1 on Mageia 8/Cauldron: spurious Kernel output when unmounting on behalf of user udisks 2.9.1 and Kernel 5.10.x on Mageia 8/Cauldron: spurious Kernel output when unmounting on behalf of user Dec 30, 2020
@tbzatek
Copy link
Member

tbzatek commented Dec 30, 2020

Okay, couple more questions:

  • does it happen with any contents on the USB stick? I.e. not just the Mageia (installation?) media? Just trying to figure out whether this is related to a hybrid medium or not.
  • can you try mounting /dev/sdb1 manually somewhere in /run/media/aurelien/ (create a new directory first) and then ejecting it?
  • can you try that with udisksd turned off? (may need to be masked and stopped through systemctl first)

@aureoud-fr85
Copy link
Author

Yes,

  1. and 2) All USB drives have this bug.
    Mount an ext4 USB key with:
    $ sudo mount /dev/sdb1 /mnt
    sudo[3527]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/mount /dev/sdb1 /mnt
    kernel: EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)

Do later:
$ sudo eject /dev/sdb1
sudo[3559]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/eject /dev/sdb1
systemd[1]: mnt.mount: Succeeded.
systemd[2291]: mnt.mount: Succeeded.
kernel: scsi_io_completion_action: 6 callbacks suppressed
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: print_req_error: 6 callbacks suppressed
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: buffer_io_error: 54 callbacks suppressed
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 1, async page read
kernel: Buffer I/O error on dev sdb, logical block 2, async page read
kernel: Buffer I/O error on dev sdb, logical block 3, async page read
kernel: Buffer I/O error on dev sdb, logical block 4, async page read
kernel: Buffer I/O error on dev sdb, logical block 5, async page read
kernel: Buffer I/O error on dev sdb, logical block 6, async page read
kernel: Buffer I/O error on dev sdb, logical block 7, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00

  1. udisks2 service stopped:
    sudo[4358]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/systemctl stop udisks2
    systemd[1]: Stopping Disk Manager...
    unknown[1103]: udisks daemon version 2.9.1 exiting
    systemd[1]: udisks2.service: Succeeded.
    systemd[1]: Stopped Disk Manager.

Redo test:
sudo[4372]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/systemctl status udisks2
sudo[4389]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/mount /dev/sdb1 /mnt
kernel: usb 2-2: USB disconnect, device number 5
kernel: usb 2-2: new SuperSpeed Gen 1 USB device number 6 using xhci_hcd
kernel: usb 2-2: New USB device found, idVendor=05dc, idProduct=0700, bcdDevice=10.75
kernel: usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
kernel: usb 2-2: Product: JumpDrive
kernel: usb 2-2: Manufacturer: Lexar
kernel: usb 2-2: SerialNumber: 4137252770
kernel: usb-storage 2-2:1.0: USB Mass Storage device detected
kernel: scsi host4: usb-storage 2-2:1.0
mtp-probe[4424]: checking bus 2, device 6: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[4424]: bus: 2, device: 6 was not an MTP device
mtp-probe[4441]: checking bus 2, device 6: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[4441]: bus: 2, device: 6 was not an MTP device
kernel: scsi 4:0:0:0: Direct-Access Lexar JumpDrive 1.00 PQ: 0 ANSI: 6
kernel: sd 4:0:0:0: [sdb] 31260672 512-byte logical blocks: (16.0 GB/14.9 GiB)
kernel: sd 4:0:0:0: [sdb] Write Protect is off
kernel: sd 4:0:0:0: [sdb] Mode Sense: 23 00 00 00
kernel: sd 4:0:0:0: [sdb] Write cache: disabled, read cache: disabled, doesn't support DPO or FUA
kernel: sdb: sdb1
kernel: sd 4:0:0:0: [sdb] Attached SCSI removable disk
sudo[4469]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/mount /dev/sdb1 /mnt
kernel: EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)

Do eject:
sudo[4485]: aurelien : HOST=mageia.local ; TTY=pts/1 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/eject /dev/sdb1
systemd[2291]: mnt.mount: Succeeded.
systemd[1]: mnt.mount: Succeeded.
kernel: scsi_io_completion_action: 6 callbacks suppressed
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: print_req_error: 6 callbacks suppressed
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: buffer_io_error: 54 callbacks suppressed
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 1, async page read
kernel: Buffer I/O error on dev sdb, logical block 2, async page read
kernel: Buffer I/O error on dev sdb, logical block 3, async page read
kernel: Buffer I/O error on dev sdb, logical block 4, async page read
kernel: Buffer I/O error on dev sdb, logical block 5, async page read
kernel: Buffer I/O error on dev sdb, logical block 6, async page read
kernel: Buffer I/O error on dev sdb, logical block 7, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 0, async page read

It seems the eject command which does the tricks.
So, do $ urpmf -f /usr/bin/eject
util-linux-2.36.1-4.mga8.x86_64:/usr/bin/eject
So, it is not udisks2 the culprit. Rather a bug in utils-linux package which contains the eject command.
WDYT?

@tbzatek
Copy link
Member

tbzatek commented Dec 31, 2020

Interesting, thanks for testing. As a last test you can try using plain console with no running desktop session to rule Plasma out. Make sure udisksd is not running, it may get autostarted via any D-Bus call.

Haven't found any suspicious change in https://github.com/karelzak/util-linux/commits/master/sys-utils/eject.c so I guess kernel is to blame here. Or it could be some change in udev, etc... Better to check with @karelzak first though.

@aureoud-fr85
Copy link
Author

In a plain console, at init 3 (without a DM), udisksd stopped, on Kernel 5.10.4,

$ sudo mount /dev/sdb1 /mnt

kernel: usb 2-2: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
kernel: usb 2-2: New USB device found, idVendor=05dc, idProduct=0700, bcdDevice=10.75
kernel: usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
kernel: usb 2-2: Product: JumpDrive
kernel: usb 2-2: Manufacturer: Lexar
kernel: usb 2-2: SerialNumber: 4137252770
mtp-probe[16038]: checking bus 2, device 2: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[16038]: bus: 2, device: 2 was not an MTP device
kernel: usb-storage 2-2:1.0: USB Mass Storage device detected
kernel: scsi host4: usb-storage 2-2:1.0
kernel: usbcore: registered new interface driver usb-storage
kernel: usbcore: registered new interface driver uas
mtp-probe[16057]: checking bus 2, device 2: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-2"
mtp-probe[16057]: bus: 2, device: 2 was not an MTP device
kernel: scsi 4:0:0:0: Direct-Access Lexar JumpDrive 1.00 PQ: 0 ANSI: 6
kernel: sd 4:0:0:0: [sdb] 31260672 512-byte logical blocks: (16.0 GB/14.9 GiB)
kernel: sd 4:0:0:0: [sdb] Write Protect is off
kernel: sd 4:0:0:0: [sdb] Mode Sense: 23 00 00 00
kernel: sd 4:0:0:0: [sdb] Write cache: disabled, read cache: disabled, doesn't support DPO or FUA
kernel: sdb: sdb1
kernel: sd 4:0:0:0: [sdb] Attached SCSI removable disk
systemd[1]: systemd-hostnamed.service: Succeeded.

sudo[16060]: aurelien : HOST=mageia.local ; TTY=tty2 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/mount /dev/sdb1 /mnt
kernel: EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)

do $ sudo eject /dev/sdb1
sudo[16073]: aurelien : HOST=mageia.local ; TTY=tty2 ; PWD=/home/aurelien ; USER=root ; COMMAND=/bin/eject /dev/sdb1
systemd[15922]: mnt.mount: Succeeded.
systemd[1]: mnt.mount: Succeeded.
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00
kernel: blk_update_request: I/O error, dev sdb, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 0, async page read
kernel: sd 4:0:0:0: [sdb] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
kernel: sd 4:0:0:0: [sdb] tag#0 Sense Key : Not Ready [current]
kernel: sd 4:0:0:0: [sdb] tag#0 Add. Sense: Medium not present
kernel: sd 4:0:0:0: [sdb] tag#0 CDB: Read(10) 28 00 00 00 00 01 00 00 07 00
kernel: blk_update_request: I/O error, dev sdb, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
kernel: Buffer I/O error on dev sdb, logical block 1, async page read
kernel: Buffer I/O error on dev sdb, logical block 2, async page read
kernel: Buffer I/O error on dev sdb, logical block 3, async page read
kernel: Buffer I/O error on dev sdb, logical block 4, async page read
kernel: Buffer I/O error on dev sdb, logical block 5, async page read
kernel: Buffer I/O error on dev sdb, logical block 6, async page read
kernel: Buffer I/O error on dev sdb, logical block 7, async page read

last repeated 7 times.

@karelzak
Copy link

karelzak commented Jan 4, 2021

For testing purposes it's probably a good idea to use the command "udevadm settle" between mount, eject, and other block device related commands (just to be sure that udev does not work with the device).

Please, try the strace eject /dev/sdb1 (as root user), it will provide more information about a way how eject(8) uses the device. Unfortunately, eject tries multiple ways until it's successful -- not sure why you see I/O errors in this case.

@tbzatek
Copy link
Member

tbzatek commented Jan 4, 2021

Compiled custom 5.10.4 kernel, confirming the issue with eject from util-linux 2.36.1 (Gentoo build).

@karelzak would you like a separate ticket for util-linux?

@tbzatek
Copy link
Member

tbzatek commented Jan 4, 2021 

/dev/sdc1: BLOCK_SIZE="2048" UUID="2019-10-23-23-21-29-00" LABEL="Fedora-WS-Live-31-1-9" TYPE="iso9660" PTUUID="6f869649" PTTYPE="dos" PARTUUID="6f869649-01"
/dev/sdc2: SEC_TYPE="msdos" LABEL_FATBOOT="ANACONDA" LABEL="ANACONDA" UUID="072A-AB27" BLOCK_SIZE="512" TYPE="vfat" PARTUUID="6f869649-02"
/dev/sdc3: UUID="a3bd41de-1a1c-3d80-8fb8-77c151343f52" BLOCK_SIZE="4096" LABEL="ANACONDA" TYPE="hfsplus" PARTUUID="6f869649-03"

strace --follow-forks --output=strace.log -- eject /dev/sdc1: strace.log

/dev/sdc: SEC_TYPE="msdos" LABEL_FATBOOT="memtest86" LABEL="memtest86" UUID="E36A-635A" BLOCK_SIZE="512" TYPE="vfat"

Another one: strace.log

@tbzatek
Copy link
Member

tbzatek commented Jan 4, 2021

The SCSI errors vary a little bit:

2021-01-04T14:33:26,048121+01:00 sd 6:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
2021-01-04T14:33:26,048126+01:00 sd 6:0:0:0: [sdc] tag#0 Sense Key : Unit Attention [current] 
2021-01-04T14:33:26,048130+01:00 sd 6:0:0:0: [sdc] tag#0 Add. Sense: Not ready to ready change, medium may have changed
2021-01-04T14:33:26,048133+01:00 sd 6:0:0:0: [sdc] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 01 00

for the Fedora Live USB

2021-01-04T14:36:17,989958+01:00 sd 6:0:0:0: [sdc] Attached SCSI removable disk
2021-01-04T14:36:50,325494+01:00 sd 6:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s
2021-01-04T14:36:50,325495+01:00 sd 6:0:0:0: [sdc] tag#0 Sense Key : Illegal Request [current] 
2021-01-04T14:36:50,325496+01:00 sd 6:0:0:0: [sdc] tag#0 Add. Sense: Invalid field in cdb
2021-01-04T14:36:50,325498+01:00 sd 6:0:0:0: [sdc] tag#0 CDB: Read(6) 08 00 00 01 07 00

for unpartitioned memtest USB stick

@aureoud-fr85
Copy link
Author

We, at Mageia, do think the issue is in Kernel.
So we have opened a ticket here: https://bugzilla.kernel.org/show_bug.cgi?id=211023

@karelzak
Copy link

karelzak commented Jan 6, 2021

From the eject strace (thanks!):

umount2("/mnt/flash", 0)          = 0

ioctl(3, CDROM_LOCKDOOR, 0)       = -1 EINVAL (Invalid argument)

ioctl(3, SG_GET_VERSION_NUM, [30527]) = 0

ioctl(3, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=6, cmdp="\x1e\x00\x00\x00\x00\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=10000, flags=0, status=0, masked_status=0, msg_status=0, sb_len_wr=0, sbp="", host_status=0, driver_status=0, resid=0, duration=1, info=0}) = 0

ioctl(3, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=6, cmdp="\x1b\x00\x00\x00\x01\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=10000, flags=0, status=0, masked_status=0, msg_status=0, sb_len_wr=0, sbp="", host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0
23805 ioctl(3, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=6, cmdp="\x1b\x00\x00\x00\x02\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=10000, flags=0, status=0, masked_status=0, msg_status=0, sb_len_wr=0, sbp="", host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0

ioctl(3, BLKRRPART)               = -1 EIO (Input/output error)

it means:

  • FS has been mounted
  • classic CDROM_LOCKDOOR failed (probably expected)
  • eject by SG_IO succeeded
  • (BLKRRPART is optional)

.. so from the eject(1) point of view, the device has been ejected.

I don't see what to fix in eject(1); it seems it works as expected.

@tbzatek
Copy link
Member

tbzatek commented Mar 26, 2021

As stated in https://bugzilla.kernel.org/show_bug.cgi?id=211023#c6 this should be fixed on the kernel side.

Closing for UDisks.

@tbzatek tbzatek closed this as completed Mar 26, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@karelzak @tbzatek @aureoud-fr85