[PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says

[PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says

[Tejun Heo]

From: Kay Sievers <kay.sievers@vrfy.org>

Some broken devices indicates that media has changed on every
GET_EVENT_STATUS_NOTIFICATION.  This translates into MEDIA_CHANGE
uevent on every open() which lets udev run into a loop.

Verify GET_EVENT result against TUR and if it generates spurious
events for several times in a row, ignore the GET_EVENT events, and
trust only the TUR status.

This is the log of a USB stick with a (broken) fake CDROM drive:

 scsi 5:0:0:0: Direct-Access     SanDisk  U3 Cruzer Micro  8.02 PQ: 0 ANSI: 0 CCS
 sd 5:0:0:0: Attached scsi generic sg3 type 0
 scsi 5:0:0:1: CD-ROM            SanDisk  U3 Cruzer Micro  8.02 PQ: 0 ANSI: 0
 sd 5:0:0:0: [sdb] Attached SCSI removable disk
 sr2: scsi3-mmc drive: 48x/48x tray
 sr 5:0:0:1: Attached scsi CD-ROM sr2
 sr 5:0:0:1: Attached scsi generic sg4 type 5
 sr2: GET_EVENT and TUR disagree continuously, suppress GET_EVENT events
 sd 5:0:0:0: [sdb] 31777279 512-byte logical blocks: (16.2 GB/15.1 GiB)
 sd 5:0:0:0: [sdb] No Caching mode page present
 sd 5:0:0:0: [sdb] Assuming drive cache: write through
 sd 5:0:0:0: [sdb] No Caching mode page present
 sd 5:0:0:0: [sdb] Assuming drive cache: write through
 sdb: sdb1

-tj: Updated to consider only spurious GET_EVENT events among
     different types of disagreement and allow using TUR for kernel
     event polling after GET_EVENT is ignored.

Reported-By: Markus Rathgeb maggu2810@googlemail.com
Signed-off-by: Kay Sievers <kay.sievers@vrfy.org>
Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: stable@kernel.org	# >= v2.6.38, fixes udev busy looping w/ certain devices
---
 drivers/scsi/sr.c |   46 ++++++++++++++++++++++++++++++++++++++++++----
 drivers/scsi/sr.h |    7 +++++++
 2 files changed, 49 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/sr.c b/drivers/scsi/sr.c
index 4778e27..5fc97d2 100644
--- a/drivers/scsi/sr.c
+++ b/drivers/scsi/sr.c
@@ -221,14 +221,33 @@ static unsigned int sr_check_events(struct cdrom_device_info *cdi,
 		return 0;
 
 	events = sr_get_events(cd->device);
+	cd->get_event_changed |= events & DISK_EVENT_MEDIA_CHANGE;
+
+	/*
+	 * If earlier GET_EVENT_STATUS_NOTIFICATION and TUR did not agree
+	 * for several times in a row.  We rely on TUR only for this likely
+	 * broken device, to prevent generating incorrect media changed
+	 * events for every open().
+	 */
+	if (cd->ignore_get_event) {
+		events &= ~DISK_EVENT_MEDIA_CHANGE;
+		goto do_tur;
+	}
+
 	/*
 	 * GET_EVENT_STATUS_NOTIFICATION is enough unless MEDIA_CHANGE
 	 * is being cleared.  Note that there are devices which hang
 	 * if asked to execute TUR repeatedly.
 	 */
-	if (!(clearing & DISK_EVENT_MEDIA_CHANGE))
-		goto skip_tur;
+	if (cd->device->changed) {
+		events |= DISK_EVENT_MEDIA_CHANGE;
+		cd->device->changed = 0;
+		cd->tur_changed = true;
+	}
 
+	if (!(clearing & DISK_EVENT_MEDIA_CHANGE))
+		return events;
+do_tur:
 	/* let's see whether the media is there with TUR */
 	last_present = cd->media_present;
 	ret = scsi_test_unit_ready(cd->device, SR_TIMEOUT, MAX_RETRIES, &sshdr);
@@ -242,12 +261,31 @@ static unsigned int sr_check_events(struct cdrom_device_info *cdi,
 		(scsi_sense_valid(&sshdr) && sshdr.asc != 0x3a);
 
 	if (last_present != cd->media_present)
-		events |= DISK_EVENT_MEDIA_CHANGE;
-skip_tur:
+		cd->device->changed = 1;
+
 	if (cd->device->changed) {
 		events |= DISK_EVENT_MEDIA_CHANGE;
 		cd->device->changed = 0;
+		cd->tur_changed = true;
+	}
+
+	if (cd->ignore_get_event)
+		return events;
+
+	/* check whether GET_EVENT is reporting spurious MEDIA_CHANGE */
+	if (!cd->tur_changed) {
+		if (cd->get_event_changed) {
+			if (cd->tur_mismatch++ > 8) {
+				sdev_printk(KERN_WARNING, cd->device,
+					    "GET_EVENT and TUR disagree continuously, suppress GET_EVENT events\n");
+				cd->ignore_get_event = true;
+			}
+		} else {
+			cd->tur_mismatch = 0;
+		}
 	}
+	cd->tur_changed = false;
+	cd->get_event_changed = false;
 
 	return events;
 }
diff --git a/drivers/scsi/sr.h b/drivers/scsi/sr.h
index e036f1d..37c8f6b 100644
--- a/drivers/scsi/sr.h
+++ b/drivers/scsi/sr.h
@@ -41,6 +41,13 @@ typedef struct scsi_cd {
 	unsigned readcd_known:1;	/* drive supports READ_CD (0xbe) */
 	unsigned readcd_cdda:1;	/* reading audio data using READ_CD */
 	unsigned media_present:1;	/* media is present */
+
+	/* GET_EVENT spurious event handling, blk layer guarantees exclusion */
+	int tur_mismatch;		/* nr of get_event TUR mismatches */
+	bool tur_changed:1;		/* changed according to TUR */
+	bool get_event_changed:1;	/* changed according to GET_EVENT */
+	bool ignore_get_event:1;	/* GET_EVENT is unreliable, use TUR */
+
 	struct cdrom_device_info cdi;
 	/* We hold gendisk and scsi_device references on probe and use
 	 * the refs on this kref to decide when to release them */

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says

[Tejun Heo]

On Thu, Jun 30, 2011 at 03:03:48PM +0200, Tejun Heo wrote:
> From: Kay Sievers <kay.sievers@vrfy.org>
> 
> Some broken devices indicates that media has changed on every
> GET_EVENT_STATUS_NOTIFICATION.  This translates into MEDIA_CHANGE
> uevent on every open() which lets udev run into a loop.
> 
> Verify GET_EVENT result against TUR and if it generates spurious
> events for several times in a row, ignore the GET_EVENT events, and
> trust only the TUR status.
> 
> This is the log of a USB stick with a (broken) fake CDROM drive:
> 
>  scsi 5:0:0:0: Direct-Access     SanDisk  U3 Cruzer Micro  8.02 PQ: 0 ANSI: 0 CCS
>  sd 5:0:0:0: Attached scsi generic sg3 type 0
>  scsi 5:0:0:1: CD-ROM            SanDisk  U3 Cruzer Micro  8.02 PQ: 0 ANSI: 0
>  sd 5:0:0:0: [sdb] Attached SCSI removable disk
>  sr2: scsi3-mmc drive: 48x/48x tray
>  sr 5:0:0:1: Attached scsi CD-ROM sr2
>  sr 5:0:0:1: Attached scsi generic sg4 type 5
>  sr2: GET_EVENT and TUR disagree continuously, suppress GET_EVENT events
>  sd 5:0:0:0: [sdb] 31777279 512-byte logical blocks: (16.2 GB/15.1 GiB)
>  sd 5:0:0:0: [sdb] No Caching mode page present
>  sd 5:0:0:0: [sdb] Assuming drive cache: write through
>  sd 5:0:0:0: [sdb] No Caching mode page present
>  sd 5:0:0:0: [sdb] Assuming drive cache: write through
>  sdb: sdb1
> 
> -tj: Updated to consider only spurious GET_EVENT events among
>      different types of disagreement and allow using TUR for kernel
>      event polling after GET_EVENT is ignored.
> 
> Reported-By: Markus Rathgeb maggu2810@googlemail.com
> Signed-off-by: Kay Sievers <kay.sievers@vrfy.org>
> Signed-off-by: Tejun Heo <tj@kernel.org>
> Cc: stable@kernel.org	# >= v2.6.38, fixes udev busy looping w/ certain devices

James, ping.

-- 
tejun

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says otherwise

[Kay Sievers]

On Wed, Jul 20, 2011 at 18:33, Tejun Heo <tj@kernel.org> wrote:
> On Thu, Jun 30, 2011 at 03:03:48PM +0200, Tejun Heo wrote:
>> From: Kay Sievers <kay.sievers@vrfy.org>
>>
>> Some broken devices indicates that media has changed on every
>> GET_EVENT_STATUS_NOTIFICATION.  This translates into MEDIA_CHANGE
>> uevent on every open() which lets udev run into a loop.
>>
>> Verify GET_EVENT result against TUR and if it generates spurious
>> events for several times in a row, ignore the GET_EVENT events, and
>> trust only the TUR status.

> James, ping.

This is a rather urgent fix, that needs to go in, and also to -stable.

Systems run into endless loops with ever-growing event queues. Nothing
really works any more if we hit that condition, unless the (broken)
device is disconnected.

Thanks,
Kay

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says

[James Bottomley]

On Wed, 2011-07-20 at 18:42 +0200, Kay Sievers wrote:
> On Wed, Jul 20, 2011 at 18:33, Tejun Heo <tj@kernel.org> wrote:
> > On Thu, Jun 30, 2011 at 03:03:48PM +0200, Tejun Heo wrote:
> >> From: Kay Sievers <kay.sievers@vrfy.org>
> >>
> >> Some broken devices indicates that media has changed on every
> >> GET_EVENT_STATUS_NOTIFICATION.  This translates into MEDIA_CHANGE
> >> uevent on every open() which lets udev run into a loop.
> >>
> >> Verify GET_EVENT result against TUR and if it generates spurious
> >> events for several times in a row, ignore the GET_EVENT events, and
> >> trust only the TUR status.
> 
> > James, ping.
> 
> This is a rather urgent fix, that needs to go in, and also to -stable.
> 
> Systems run into endless loops with ever-growing event queues. Nothing
> really works any more if we hit that condition, unless the (broken)
> device is disconnected.

Sorry ... I have it marked for inclusion in my internal queue, I'm just
having difficulty finding time to do a dump from queue and test.  I
should be able to get all the fixes sorted on the 'plane home tomorrow.

James

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says otherwise

[Markus Rathgeb]

[-- Attachment #1: Type: text/plain, Size: 3109 bytes --]

Hello!

Do you remember?
I get it again, is there something I could do?

I attached a file that contains the "udevadm monitor" log.

I am using a v3.5.0 linux kernel (containing some gentoo patches).
Should I test it with a vanilla one?

Here the versions of some packages (kernel, udev, systemd):
sys-kernel/gentoo-sources-3.5.0
sys-fs/udev-186
sys-apps/systemd-44-r1


Here (again) the information about the two sticks I run in trouble
after plug them in:

# udevadm info --path=/block/sdb
P: /devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host22/target22:0:0/22:0:0:0/block/sdb
N: sdb
S: disk/by-id/usb-SanDisk_Cruzer_07745302FB131CFA-0:0
S: disk/by-path/pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: DEVLINKS=/dev/disk/by-id/usb-SanDisk_Cruzer_07745302FB131CFA-0:0
/dev/disk/by-path/pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: DEVNAME=/dev/sdb
E: DEVPATH=/devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host22/target22:0:0/22:0:0:0/block/sdb
E: DEVTYPE=disk
E: ID_BUS=usb
E: ID_DRIVE_THUMB=1
E: ID_INSTANCE=0:0
E: ID_MODEL=Cruzer
E: ID_MODEL_ENC=Cruzer\x20\x20\x20\x20\x20\x20\x20\x20\x20\x20
E: ID_MODEL_ID=5406
E: ID_PART_TABLE_TYPE=dos
E: ID_PATH=pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: ID_PATH_TAG=pci-0000_00_04_1-usb-0_4_1_0-scsi-0_0_0_0
E: ID_REVISION=8.02
E: ID_SERIAL=SanDisk_Cruzer_07745302FB131CFA-0:0
E: ID_SERIAL_SHORT=07745302FB131CFA
E: ID_TYPE=disk
E: ID_USB_DRIVER=usb-storage
E: ID_USB_INTERFACES=:080650:
E: ID_USB_INTERFACE_NUM=00
E: ID_VENDOR=SanDisk
E: ID_VENDOR_ENC=SanDisk\x20
E: ID_VENDOR_ID=0781
E: LVM_SBIN_PATH=/sbin
E: MAJOR=8
E: MINOR=16
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_PARTITION_TABLE=1
E: UDISKS_PARTITION_TABLE_COUNT=1
E: UDISKS_PARTITION_TABLE_SCHEME=mbr
E: UDISKS_PRESENTATION_NOPOLICY=0
E: USEC_INITIALIZED=79287950141


# udevadm info --path=/block/sdb
P: /devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host23/target23:0:0/23:0:0:0/block/sdb
N: sdb
S: disk/by-id/usb-SanDisk_Cruzer_22427202FB10CD97-0:0
S: disk/by-path/pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: DEVLINKS=/dev/disk/by-id/usb-SanDisk_Cruzer_22427202FB10CD97-0:0
/dev/disk/by-path/pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: DEVNAME=/dev/sdb
E: DEVPATH=/devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host23/target23:0:0/23:0:0:0/block/sdb
E: DEVTYPE=disk
E: ID_BUS=usb
E: ID_DRIVE_THUMB=1
E: ID_INSTANCE=0:0
E: ID_MODEL=Cruzer
E: ID_MODEL_ENC=Cruzer\x20\x20\x20\x20\x20\x20\x20\x20\x20\x20
E: ID_MODEL_ID=5406
E: ID_PART_TABLE_TYPE=dos
E: ID_PATH=pci-0000:00:04.1-usb-0:4:1.0-scsi-0:0:0:0
E: ID_PATH_TAG=pci-0000_00_04_1-usb-0_4_1_0-scsi-0_0_0_0
E: ID_REVISION=8.02
E: ID_SERIAL=SanDisk_Cruzer_22427202FB10CD97-0:0
E: ID_SERIAL_SHORT=22427202FB10CD97
E: ID_TYPE=disk
E: ID_USB_DRIVER=usb-storage
E: ID_USB_INTERFACES=:080650:
E: ID_USB_INTERFACE_NUM=00
E: ID_VENDOR=SanDisk
E: ID_VENDOR_ENC=SanDisk\x20
E: ID_VENDOR_ID=0781
E: LVM_SBIN_PATH=/sbin
E: MAJOR=8
E: MINOR=16
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_PARTITION_TABLE=1
E: UDISKS_PARTITION_TABLE_COUNT=1
E: UDISKS_PARTITION_TABLE_SCHEME=mbr
E: UDISKS_PRESENTATION_NOPOLICY=0
E: USEC_INITIALIZED=342063581

[-- Attachment #2: insert-stick.log.gz --]
[-- Type: application/x-gzip, Size: 4558 bytes --]

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says otherwise

[Kay Sievers]

On Mon, Jul 30, 2012 at 9:06 PM, Markus Rathgeb
<maggu2810@googlemail.com> wrote:
> Hello!
>
> Do you remember?
> I get it again, is there something I could do?
>
> I attached a file that contains the "udevadm monitor" log.
>
> I am using a v3.5.0 linux kernel (containing some gentoo patches).
> Should I test it with a vanilla one?

I have 3.5 here and see the loop too, but it stops after a couple of seconds:

first: KERNEL[15636.368034]
last: KERNEL[15638.879796]

The kernel log says:
[15634.066481] sr 13:0:0:1: GET_EVENT and TUR disagree continuously,
suppress GET_EVENT events

Kay

Re: [PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says otherwise

[Markus Rathgeb]

[-- Attachment #1: Type: text/plain, Size: 1020 bytes --]

> I have 3.5 here and see the loop too, but it stops after a couple of seconds:
>
> first: KERNEL[15636.368034]
> last: KERNEL[15638.879796]

Ah, sorry then.
The udev messages reported by the udev monitor reported up to 20
seconds of udev (userspace) events. I did not filter kernel reported
messages.

# for SRC in KERNEL UDEV; do for CMD in head tail; do less udev.log |
grep ${SRC} | ${CMD} -n1; done; done

KERNEL[83579.700428] add      /devices/pci0000:00/0000:00:04.1/usb5/5-4 (usb)
KERNEL[83582.989470] change
/devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host31/target31:0:0/31:0:0:1/block/sr1
(block)
UDEV  [83579.747646] add      /devices/pci0000:00/0000:00:04.1/usb5/5-4 (usb)
UDEV  [83601.504952] add
/devices/pci0000:00/0000:00:04.1/usb5/5-4/5-4:1.0/host31/target31:0:0/31:0:0:0/block/sdb/sdb1
(block)


I should also disable the dbus logging verbosity:
journald reported 494 complete dbus messages and 846 (475 + 371)
suppressed dbus messages.
That is really too much (but not your problem).

Thanks!!

[-- Attachment #2: journald.log.gz --]
[-- Type: application/x-gzip, Size: 2081 bytes --]

[-- Attachment #3: udev.log.gz --]
[-- Type: application/x-gzip, Size: 4540 bytes --]