[Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Tom Seewald]

Hi,

Since v5.10 ejecting removable USB devices on my desktop has resulted
in the kernel throwing errors and not cleanly unmounting the drives
(dirty bit is set upon remounting).

I have bisected this issue to commit 471bd0af544b ("sd: use
bdev_check_media_change"), and have confirmed the problem is still
present as of v5.11-rc7. It appears that several others have run into
this issue, as I see that there was a bugzilla report filed a month
ago [1]. There was also a bug report filed against udisks [2], and it
looks like they believe it is also a kernel issue.

Steps to reproduce the problem:
1. Insert removable USB storage device.
2. Use eject(1) to attempt to eject the USB device. (e.g. # eject /dev/sdd)

Example result:
[42006.656393] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.656402] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.656406] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.656411] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.656413] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.656420] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.657520] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.657528] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.657531] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.657535] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.657537] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.657544] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.658490] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.658492] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.658494] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.658496] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.658497] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.658499] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.658505] ldm_validate_partition_table(): Disk read failed.
[42006.659490] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.659492] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.659494] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.659496] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.659497] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.659499] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.661000] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.661003] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.661005] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.661006] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.661007] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.661010] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.662002] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.662006] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.662007] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.662009] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.662010] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.662013] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.663050] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.663053] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.663054] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.663055] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.663056] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.663059] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.663068] Dev sdd: unable to read RDB block 0
[42006.663993] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.663995] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.663997] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.663998] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.663999] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.664001] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.665000] sd 8:0:0:1: [sdd] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[42006.665003] sd 8:0:0:1: [sdd] tag#0 Sense Key : Not Ready [current]
[42006.665004] sd 8:0:0:1: [sdd] tag#0 Add. Sense: Medium not present
[42006.665006] sd 8:0:0:1: [sdd] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[42006.665007] blk_update_request: I/O error, dev sdd, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[42006.665009] Buffer I/O error on dev sdd, logical block 0, async page read
[42006.665019]  sdd: unable to read partition table
[42006.668496] sdd: detected capacity change from 0 to 62333952

Please cc me on replies as I am not subscribed to the block mailing list.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=211023
[2] https://github.com/storaged-project/udisks/issues/827

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Christoph Hellwig]

I can't reproduce this with an AHCI attached CDROM.

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Christoph Hellwig]

... but you were using sd, not sr.

Can you give this patch a spin?

diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index a3d2d4bc4a3dcd..6671b4e1909777 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -2116,6 +2116,14 @@ static int sd_done(struct scsi_cmnd *SCpnt)
 			}
 		}
 		break;
+	case NOT_READY:
+		/* Medium not present */
+		if (SCpnt->device->removable && sshdr.asc == 0x3a00) {
+			req->rq_flags |= RQF_QUIET;
+			set_media_not_present(sdkp);
+			sdkp->capacity = 0;
+		}
+		break;
 	default:
 		break;
 	}

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Tom Seewald]

Hi Christoph,

Thank you for looking into this. I applied your patch to v5.11 but
unfortunately I am encountering the same errors when ejecting USB
drives.

e.g.
[   45.188575] sd 8:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE cmd_age=0s
[   45.188584] sd 8:0:0:0: [sdc] tag#0 Sense Key : Not Ready [current]
[   45.188588] sd 8:0:0:0: [sdc] tag#0 Add. Sense: Medium not present
[   45.188592] sd 8:0:0:0: [sdc] tag#0 CDB: Read(10) 28 00 00 00 00 00
00 00 08 00
[   45.188594] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.188601] Buffer I/O error on dev sdc, logical block 0, async page read

I am happy to test any patches you send my way.

Tom

On Tue, Feb 16, 2021 at 6:37 AM Christoph Hellwig <hch@lst.de> wrote:
>
> ... but you were using sd, not sr.
>
> Can you give this patch a spin?
>
> diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
> index a3d2d4bc4a3dcd..6671b4e1909777 100644
> --- a/drivers/scsi/sd.c
> +++ b/drivers/scsi/sd.c
> @@ -2116,6 +2116,14 @@ static int sd_done(struct scsi_cmnd *SCpnt)
>                         }
>                 }
>                 break;
> +       case NOT_READY:
> +               /* Medium not present */
> +               if (SCpnt->device->removable && sshdr.asc == 0x3a00) {
> +                       req->rq_flags |= RQF_QUIET;
> +                       set_media_not_present(sdkp);
> +                       sdkp->capacity = 0;
> +               }
> +               break;
>         default:
>                 break;
>         }

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Tom Seewald]

On Tue, Feb 16, 2021 at 6:37 AM Christoph Hellwig <hch@lst.de> wrote:
>
> ... but you were using sd, not sr.
>
> Can you give this patch a spin?
>
> diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
> index a3d2d4bc4a3dcd..6671b4e1909777 100644
> --- a/drivers/scsi/sd.c
> +++ b/drivers/scsi/sd.c
> @@ -2116,6 +2116,14 @@ static int sd_done(struct scsi_cmnd *SCpnt)
>                         }
>                 }
>                 break;
> +       case NOT_READY:
> +               /* Medium not present */
> +               if (SCpnt->device->removable && sshdr.asc == 0x3a00) {
> +                       req->rq_flags |= RQF_QUIET;
> +                       set_media_not_present(sdkp);
> +                       sdkp->capacity = 0;
> +               }
> +               break;
>         default:
>                 break;
>         }

After reading the asc/ascq assignments from t10.org, I think it should
be "sshdr.asc == 0x3a" rather than "sshdr.asc == 0x3a00". With that
change to your above patch, I am seeing different output after
ejecting USB drives.

[   45.027823] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.027832] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.027871] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.027875] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.027885] ldm_validate_partition_table(): Disk read failed.
[   45.027902] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.027905] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.027928] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.027931] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.027953] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.027956] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.028103] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.028106] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.028113] Dev sdc: unable to read RDB block 0
[   45.028124] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.028126] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.028140] sd 8:0:0:0: [sdc] tag#0 device offline or changed
[   45.028142] blk_update_request: I/O error, dev sdc, sector 0 op
0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[   45.028148]  sdc: unable to read partition table
[   45.029893] sdc: detected capacity change from 0 to 30595072

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Christoph Hellwig]

Ok, let's try something else entirely, which restores the full revalidation
that BLKRRPART previously caused by accident:

diff --git a/block/ioctl.c b/block/ioctl.c
index d61d652078f41c..06b2ecdce593c6 100644
--- a/block/ioctl.c
+++ b/block/ioctl.c
@@ -81,20 +81,25 @@ static int compat_blkpg_ioctl(struct block_device *bdev,
 }
 #endif
 
-static int blkdev_reread_part(struct block_device *bdev)
+static int blkdev_reread_part(struct block_device *bdev, fmode_t mode)
 {
-	int ret;
+	struct block_device *tmp;
 
 	if (!disk_part_scan_enabled(bdev->bd_disk) || bdev_is_partition(bdev))
 		return -EINVAL;
 	if (!capable(CAP_SYS_ADMIN))
 		return -EACCES;
 
-	mutex_lock(&bdev->bd_mutex);
-	ret = bdev_disk_changed(bdev, false);
-	mutex_unlock(&bdev->bd_mutex);
-
-	return ret;
+	/*
+	 * Reopen the device to revalidate the driver state and force a
+	 * partition rescan.
+	 */
+	set_bit(GD_NEED_PART_SCAN, &bdev->bd_disk->state);
+	tmp = blkdev_get_by_dev(bdev->bd_dev, mode, NULL);
+	if (IS_ERR(tmp))
+		return PTR_ERR(tmp);
+	blkdev_put(tmp, mode);
+	return 0;
 }
 
 static int blk_ioctl_discard(struct block_device *bdev, fmode_t mode,
@@ -498,7 +503,7 @@ static int blkdev_common_ioctl(struct block_device *bdev, fmode_t mode,
 		bdev->bd_bdi->ra_pages = (arg * 512) / PAGE_SIZE;
 		return 0;
 	case BLKRRPART:
-		return blkdev_reread_part(bdev);
+		return blkdev_reread_part(bdev, mode & ~FMODE_EXCL);
 	case BLKTRACESTART:
 	case BLKTRACESTOP:
 	case BLKTRACETEARDOWN:

Re: [Regression] [Bisected] Errors when ejecting USB storage drives since v5.10

[Tom Seewald]

On 2/22/21 5:44 AM, Christoph Hellwig wrote:

> Ok, let's try something else entirely, which restores the full revalidation
> that BLKRRPART previously caused by accident:
>
> diff --git a/block/ioctl.c b/block/ioctl.c
> index d61d652078f41c..06b2ecdce593c6 100644
> --- a/block/ioctl.c
> +++ b/block/ioctl.c
> @@ -81,20 +81,25 @@ static int compat_blkpg_ioctl(struct block_device *bdev,
>  }
>  #endif
>  
> -static int blkdev_reread_part(struct block_device *bdev)
> +static int blkdev_reread_part(struct block_device *bdev, fmode_t mode)
>  {
> -	int ret;
> +	struct block_device *tmp;
>  
>  	if (!disk_part_scan_enabled(bdev->bd_disk) || bdev_is_partition(bdev))
>  		return -EINVAL;
>  	if (!capable(CAP_SYS_ADMIN))
>  		return -EACCES;
>  
> -	mutex_lock(&bdev->bd_mutex);
> -	ret = bdev_disk_changed(bdev, false);
> -	mutex_unlock(&bdev->bd_mutex);
> -
> -	return ret;
> +	/*
> +	 * Reopen the device to revalidate the driver state and force a
> +	 * partition rescan.
> +	 */
> +	set_bit(GD_NEED_PART_SCAN, &bdev->bd_disk->state);
> +	tmp = blkdev_get_by_dev(bdev->bd_dev, mode, NULL);
> +	if (IS_ERR(tmp))
> +		return PTR_ERR(tmp);
> +	blkdev_put(tmp, mode);
> +	return 0;
>  }
>  
>  static int blk_ioctl_discard(struct block_device *bdev, fmode_t mode,
> @@ -498,7 +503,7 @@ static int blkdev_common_ioctl(struct block_device *bdev, fmode_t mode,
>  		bdev->bd_bdi->ra_pages = (arg * 512) / PAGE_SIZE;
>  		return 0;
>  	case BLKRRPART:
> -		return blkdev_reread_part(bdev);
> +		return blkdev_reread_part(bdev, mode & ~FMODE_EXCL);
>  	case BLKTRACESTART:
>  	case BLKTRACESTOP:
>  	case BLKTRACETEARDOWN:
I can confirm the above patch results in my USB drives being unmounted cleanly
and there are no errors in dmesg afterwards. One minor nit I have noticed is
that after ejecting the device, the kernel still reports:

"sde: detected capacity change from 0 to 62333952"

This appears to be reversed from what was previously reported by the kernel in
v5.9 and earlier. I would expect that after ejection it would report:

"sde: detected capacity change from 62333952 to 0"

This appears to be purely cosmetic and it is not something your above patch
introduced so you can add Tested-by: Tom Seewald <tseewald@gmail.com> if you
wish. Thank you again for your help.