| Summary: | Strange kernel outputs when ejecting a usb key | ||
|---|---|---|---|
| Product: | Mageia | Reporter: | Aurelien Oudelet <ouaurelien> |
| Component: | RPM Packages | Assignee: | Kernel and Drivers maintainers <kernel> |
| Status: | RESOLVED FIXED | QA Contact: | |
| Severity: | major | ||
| Priority: | High | CC: | geiger.david68210, jan-bugs, kernel, mageia, pterjan |
| Version: | Cauldron | ||
| Target Milestone: | Mageia 8 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Source RPM: | udisks2-2.9.1-1.mga8.src.rpm | CVE: | |
| Status comment: | util-linux-2.36.1-4.mga8.src.rpm ? Kernel itself? | ||
| Attachments: |
Strange sequence in ejecting USB drive device using Device Notifier Applet
Sequence in ejecting USB drive device using Device Notifier Applet with Kernel 5.9.12 |
||
|
Aurelien Oudelet
2020-12-19 16:04:24 CET
CC:
(none) =>
geiger.david68210 These errors does not appear in 5.9.12 kernel (Beta 2) but since 5.10.1 Kernel. Adding Kernel and Drivers Maintainers here for advice. Something missing? Reported meanwhile to KDE devs. CC:
(none) =>
kernel KDE.org devs dismissed this bug. Seems rather a 5.10 kernel one. Need more testing. Assignee:
kde =>
bugsquad
David Walser
2020-12-19 16:59:50 CET
CC:
(none) =>
jan-bugs Created attachment 12126 [details]
Sequence in ejecting USB drive device using Device Notifier Applet with Kernel 5.9.12
Attached system journal output when unmounting a USB key with 5.9.12 kernel running.
No spurious errors!
Assigning to Kernel and Drivers maintainers.
Also, it seems to be a middleware problem.
Aurelien Oudelet
2020-12-20 10:59:36 CET
Assignee:
bugsquad =>
kernel Do mount/unmount commands as root: nothing wrong in system journal. I do think there is something in trouble using Kernel 5.10.1 with udisks tools. Drives and Devices Notification Applet in Plasma relies on udisks tools. So, this is reported here: https://github.com/storaged-project/udisks/issues/827 In facts, after many tests, it appears that the command /usr/bin/eject is culprit here. Assuming your USB device is /dev/sdb Doing as root: # mount /dev/sdb1 /media # eject /media See errors in system journal 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 This is present from Kernel 5.10.0 to latest 5.10.4-2.mga8 BUT 5.9.12-1.mga8 is unaffected! udisks2 has not been updated, not the real culprit, eject command is part of util-linux (util-linux-2.36), not updated upstream. I do think there is issue with the kernel: the wolume seems well unmounted but the strange errors printed by Kernel with lots of warnings and errors-level ones are really spurious.
Aurelien Oudelet
2021-01-02 20:51:30 CET
Status comment:
(none) =>
util-linux-2.36.1-4.mga8.src.rpm ? Kernel itself?
Aurelien Oudelet
2021-01-02 20:51:36 CET
Priority:
Normal =>
High It seems the kernel is trying to read the partition table of the device after it got removed, not sure how to find out if it does that by itself or that is requested by something (udev?). CC:
(none) =>
pterjan Note that it can be even reproduced without a graphical session, even with udisks2 stopped. The errors are displayed right after pressing the Enter key. And again no error with 5.9.12-1. Really strange. strace tells me that after ejecting, the eject command asks the kernel to reread the partition table:
openat(AT_FDCWD, "/dev/sda", O_RDWR|O_EXCL|O_NONBLOCK) = 3
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=0, 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
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=1, info=0}) = 0
ioctl(3, BLKRRPART) = -1 EIO (Input/output error)
However running it again, it does so again but and causes no errors to be logged by the kernel:
openat(AT_FDCWD, "/dev/sda", O_RDWR|O_EXCL|O_NONBLOCK) = 3
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=0, 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
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) = 0
I could confirm that removing the "ioctl(ctl->fd, BLKRRPART);" line from eject.c made the problem go away but even if I don't see the point of that call, this seems to be a problem in the kernel accepting the command while it is removing the device.
Also for the record, this can be reproduced with kernel-linus. does it change anything with util-linux-2.36.1-5.mga8 ? It's basically only a rebuild for glibc 2.32 and kernel 5.10 series headers... Technically it should not matter, but sometimes there have been some subtle changes in glibc and/or kernel that could cause issues... (In reply to Thomas Backlund from comment #10) > does it change anything with util-linux-2.36.1-5.mga8 ? > > It's basically only a rebuild for glibc 2.32 and kernel 5.10 series > headers... > > > Technically it should not matter, but sometimes there have been some subtle > changes in glibc and/or kernel that could cause issues... $ uname -r 5.10.4-desktop-3.mga8 $ rpm -qa | grep util-linux util-linux-2.36.1-5.mga8 This is the same. Kernel logs errors like @Pascal can confirm. I really think there is something in Kernel. I report upstream to bugzilla.kernel.org: https://bugzilla.kernel.org/show_bug.cgi?id=211023 Don't know if this helps but here is the dmesg output after ejecting a USB drive. First with kernel 5.7.19-desktop-3.mga7 and second with kernel 5.10.3-desktop-1.mga7. ============================ $ uname -a Linux marte 5.7.19-desktop-3.mga7 #1 SMP Sun Oct 18 15:46:00 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux $ rpm -q util-linux util-linux-2.33.2-1.mga7 $ eject /dev/sda $ dmesg <SNIP> [22391.943859] sd 5:0:0:0: [sdg] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [22391.943864] sd 5:0:0:0: [sdg] tag#0 Sense Key : Not Ready [current] [22391.943867] sd 5:0:0:0: [sdg] tag#0 Add. Sense: Medium not present [22391.943871] sd 5:0:0:0: [sdg] tag#0 CDB: Read(10) 28 00 00 00 08 08 00 00 08 00 [22391.943874] blk_update_request: I/O error, dev sdg, sector 2056 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0 [22391.944490] sd 5:0:0:0: [sdg] tag#0 access beyond end of device [22391.944493] blk_update_request: I/O error, dev sdg, sector 2056 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0 [22391.944496] Buffer I/O error on dev sdg1, logical block 1, async page read [22391.947358] sdg: detected capacity change from 32019316736 to 0 ============================ $ uname -a Linux marte-vm-mageia-7 5.10.3-desktop-1.mga7 #1 SMP Sat Dec 26 18:15:40 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux $ rpm -q util-linux util-linux-2.33.2-1.mga7 $ lsusb | grep lexar Bus 001 Device 003: ID 05dc:a81d Lexar Media, Inc. LJDTT16G [JumpDrive 16GB] $ eject /dev/sda $ dmesg <SNIP> [ 58.992896] sd 8:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 58.992904] sd 8:0:0:0: [sda] tag#0 Sense Key : Not Ready [current] [ 58.992908] sd 8:0:0:0: [sda] tag#0 Add. Sense: Medium not present [ 58.992912] sd 8:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 03 40 10 b0 00 00 08 00 [ 58.992917] blk_update_request: I/O error, dev sda, sector 54530224 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0 [ 59.001952] sd 8:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 59.001958] sd 8:0:0:0: [sda] tag#0 Sense Key : Not Ready [current] [ 59.001961] sd 8:0:0:0: [sda] tag#0 Add. Sense: Medium not present [ 59.001965] sd 8:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 03 40 10 b0 00 00 08 00 [ 59.001969] blk_update_request: I/O error, dev sda, sector 54530224 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0 [ 59.001973] Buffer I/O error on dev sda2, logical block 2224, async page read [ 59.001977] Buffer I/O error on dev sda2, logical block 2225, async page read [ 59.001979] Buffer I/O error on dev sda2, logical block 2226, async page read [ 59.001981] Buffer I/O error on dev sda2, logical block 2227, async page read [ 59.001982] Buffer I/O error on dev sda2, logical block 2228, async page read [ 59.001984] Buffer I/O error on dev sda2, logical block 2229, async page read [ 59.001986] Buffer I/O error on dev sda2, logical block 2230, async page read [ 59.001988] Buffer I/O error on dev sda2, logical block 2231, async page read [ 59.020965] sd 8:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 59.021000] sd 8:0:0:0: [sda] tag#0 Sense Key : Not Ready [current] [ 59.021011] sd 8:0:0:0: [sda] tag#0 Add. Sense: Medium not present [ 59.021032] sd 8:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 03 40 10 b0 00 00 08 00 [ 59.021045] blk_update_request: I/O error, dev sda, sector 54530224 op 0x0:(READ) flags 0x0 phys_seg 8 prio class 0 [ 59.021056] Buffer I/O error on dev sda2, logical block 2224, async page read [ 59.021069] Buffer I/O error on dev sda2, logical block 2225, async page read CC:
(none) =>
mageia I managed to bisect the changes to https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=471bd0af544bcd80450d61659a1ffabdd1820d7d thanks for tracking it down. I will revert it for now in Mageia until upstream have time to sort it out revert is in kernel-5.10.5-1.mga8 currently mirroring out Yeah. This is fixed. Thanks Thomas. Closing. Resolution:
(none) =>
FIXED |
Created attachment 12118 [details] Strange sequence in ejecting USB drive device using Device Notifier Applet SUMMARY Since Plasma 5.20.4, we remark a strange behavior when ejecting a USB disk-based device. Kernel seems complain about missing device while udisks has been ejected it. See attached log. STEPS TO REPRODUCE 1. Plug a USB-based disk (USB key, USB Harddrive,...) 2. Mount partition while proposed by Disks and Device Notification applet. 3. Open Dolphin. 4. Close Dolphin window. 5. In Disks and Devices Notification applet, click on Remove securely. 6. See system logs. OBSERVED RESULT 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 Reproduced by several users on IRC and forums. Reported upstream.