Discussion:
[PATCH SCSI] sr: check_events() ignore GET_EVENT when TUR says otherwise
Tejun Heo
2011-06-30 13:03:48 UTC
Permalink
From: 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 ***@googlemail.com
Signed-off-by: Kay Sievers <***@vrfy.org>
Signed-off-by: Tejun Heo <***@kernel.org>
Cc: ***@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 */
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Tejun Heo
2011-07-20 16:33:08 UTC
Permalink
Post by Tejun Heo
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.
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.
James, ping.
--
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Kay Sievers
2011-07-20 16:42:06 UTC
Permalink
Post by Tejun Heo
Post by Tejun Heo
Some broken devices indicates that media has changed on every
GET_EVENT_STATUS_NOTIFICATION. =C2=A0This translates into MEDIA_CHAN=
GE
Post by Tejun Heo
Post by Tejun Heo
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
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug=
" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
James Bottomley
2011-07-20 16:45:16 UTC
Permalink
Post by Kay Sievers
Post by Tejun Heo
Post by Tejun Heo
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


--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Markus Rathgeb
2012-07-30 19:06:48 UTC
Permalink
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
Kay Sievers
2012-07-30 19:41:29 UTC
Permalink
On Mon, Jul 30, 2012 at 9:06 PM, Markus Rathgeb
Post by Markus Rathgeb
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
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Markus Rathgeb
2012-07-30 20:28:50 UTC
Permalink
Post by Kay Sievers
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!!

Loading...