Re: BUG in: Driver core: convert block from raw kobjects to core devices

[Alan Stern <stern@rowland.harvard.edu>]

On Fri, 19 Oct 2007, Kay Sievers wrote:

> > Don't you have a USB storage device?  It should be easy for you to test 
> > this on your own system.
> 
> Sure, I have, and tried a lot of times, and all seemed correct here with
> the final put. I don't say that it's the right fix, but without it, the
> disk device object is never released here, it only gets removed from
> sysfs.

Well, attached is a testing patch.  It should apply to 2.6.23 together 
with gregkh-all-2.6.23.  Here's the output on my system using your 
original code:

Plug in USB drive:

[   75.555077] usb-storage: device found at 3
[   75.558052] scsi 0:0:0:0: Direct-Access     UDISK    PDU01_1G 65G2.0  0.00 PQ: 0 ANSI: 2
[   75.568248] usb-storage: device scan complete
[   75.917139] sd 0:0:0:0: [sda] 1967616 512-byte hardware sectors (1007 MB)
[   75.918463] sd 0:0:0:0: [sda] Write Protect is off
[   75.919011] sd 0:0:0:0: [sda] Mode Sense: 00 00 00 00
[   75.919263] sd 0:0:0:0: [sda] Assuming drive cache: write through
[   75.919397] sd_probe: call add_disk
[   75.919615] start of register_disk: 1
[   75.920402] after device_add: 3
[   75.920692] after disk_sysfs_add_subdirs: 5
[   75.921173] after get_capacity: 5
[   75.921461] after bdget_disk: 5
[   75.927996] sd 0:0:0:0: [sda] 1967616 512-byte hardware sectors (1007 MB)
[   75.929405] sd 0:0:0:0: [sda] Write Protect is off
[   75.929801] sd 0:0:0:0: [sda] Mode Sense: 00 00 00 00
[   75.929960] sd 0:0:0:0: [sda] Assuming drive cache: write through
[   75.930202]  sda: sda1
[   75.966112] after blkdev_get: 8
[   75.966648] after blkdev_put: 7
[   75.968997] end of register_disk: 7
[   75.969327] after blk_register_queue: 9
[   75.969823] sd 0:0:0:0: [sda] Attached SCSI removable disk
[   76.448192] sd 0:0:0:0: Attached scsi generic sg0 type 0

Unplug USB drive:

[   92.852078] usb 6-4: USB disconnect, address 3
[   92.853389] usb 6-4: unregistering device
[   92.853507] usb 6-4: usb_disable_device nuking all URBs
[   92.853783] usb 6-4: unregistering interface 6-4:1.0
[   92.863556] sd_remove: call del_gendisk
[   92.864043] start of del_gendisk: 9
[   92.866551] after deleting subpartitions: 7
[   92.866880] after invalidate_partition(0): 7
[   92.867469] after unlink_gendisk: 5
[   92.867738] after kobject_unregister subdirs: 3
[   92.869450] after device_del: 1
[   92.869741] after put_device: 1802201963
[   92.870267] BUG: unable to handle kernel paging request at virtual address 6b6b6b6f
[   92.870494]  printing eip:
[   92.870547] d09639d2
[   92.870597] *pde = 00000000
[   92.870747] Oops: 0000 [#1]
[   92.870797] PREEMPT SMP 
[   92.870915] last sysfs file: /block/sda/sda1/dev
[   92.870968] Modules linked in: sg sd_mod usb_storage scsi_mod fan container battery ac evdev thermal button processor ohci_hcd e100 mii ehci_hcd uhci_hcd pcspkr usbcore
[   92.871749] CPU:    0
[   92.871751] EIP:    0060:[<d09639d2>]    Not tainted VLI
[   92.871753] EFLAGS: 00010202   (2.6.23 #7)
[   92.871905] EIP is at __scsi_disk_get+0xd/0x2a [sd_mod]
[   92.871958] eax: 6b6b6b6b   ebx: 6b6b6b6b   ecx: 00000000   edx: 00000008
[   92.872014] esi: cd7359a0   edi: cd7359a8   ebp: cf6edd6c   esp: cf6edd68
[   92.872069] ds: 007b   es: 007b   fs: 00d8  gs: 0000  ss: 0068
[   92.872124] Process khubd (pid: 970, ti=cf6ec000 task=cf6f0a90 task.ti=cf6ec000)
[   92.872179] Stack: 00000000 cf6edd78 d0963a13 cfb32910 cf6edd9c d0963bfd cf6edd9c c0194e69 
[   92.872555]        c032351e 6b6b6b6b cfb32910 cd7359a0 cd7359a8 cf6eddb4 d0964096 d09659fa 
[   92.872932]        cfb32910 d09670a4 00000292 cf6eddc4 c022303e cfb32910 cfb32910 cf6eddd0 
[   92.873310] Call Trace:
[   92.873400]  [<c01050fd>] show_trace_log_lvl+0x1a/0x2f
[   92.873496]  [<c01051af>] show_stack_log_lvl+0x9d/0xa5
[   92.873584]  [<c01053a4>] show_registers+0x1ed/0x32c
[   92.873672]  [<c01055fa>] die+0x117/0x236
[   92.873758]  [<c02ac046>] do_page_fault+0x4c0/0x591
[   92.873849]  [<c02aa69a>] error_code+0x72/0x78
[   92.873936]  [<d0963a13>] scsi_disk_get_from_dev+0x24/0x35 [sd_mod]
[   92.874029]  [<d0963bfd>] sd_shutdown+0xe/0xfd [sd_mod]
[   92.874122]  [<d0964096>] sd_remove+0x40/0x77 [sd_mod]
[   92.874213]  [<c022303e>] __device_release_driver+0x74/0x90
[   92.874306]  [<c022342c>] device_release_driver+0x30/0x47
[   92.874394]  [<c02229c3>] bus_remove_device+0x73/0x82
[   92.874482]  [<c02211ac>] device_del+0x206/0x27c
[   92.874569]  [<d0988b4e>] __scsi_remove_device+0x3c/0x6d [scsi_mod]
[   92.874678]  [<d0986509>] scsi_forget_host+0x30/0x4f [scsi_mod]
[   92.874781]  [<d0981543>] scsi_remove_host+0x6a/0xdf [scsi_mod]
[   92.874882]  [<d099f7b1>] quiesce_and_remove_host+0xa5/0xb5 [usb_storage]
[   92.874983]  [<d099f893>] storage_disconnect+0x11/0x1b [usb_storage]
[   92.875079]  [<d0847a52>] usb_unbind_interface+0x47/0x99 [usbcore]
[   92.875191]  [<c022303e>] __device_release_driver+0x74/0x90
[   92.875280]  [<c022342c>] device_release_driver+0x30/0x47
[   92.875369]  [<c02229c3>] bus_remove_device+0x73/0x82
[   92.875456]  [<c02211ac>] device_del+0x206/0x27c
[   92.875543]  [<d0844fee>] usb_disable_device+0xe2/0x145 [usbcore]
[   92.875648]  [<d08407e6>] usb_disconnect+0xce/0x167 [usbcore]
[   92.875751]  [<d0841b97>] hub_thread+0x646/0xea7 [usbcore]
[   92.875852]  [<c0131c9e>] kthread+0x3b/0x61
[   92.875940]  [<c0104d53>] kernel_thread_helper+0x7/0x10
[   92.876028]  =======================
[   92.876077] Code: e8 e1 6a 86 ef 8b 43 04 05 b0 00 00 00 e8 e6 d1 8b ef 89 d8 e8 45 e6 7f ef 58 5b 5e 5d c3 55 89 e5 53 8b 40 38 85 c0 74 18 89 c3 <8b> 40 04 e8 fb c6 01 00 85 c0 75 0a 8d 43 08 e8 79 fd 8b ef eb 
[   92.878418] EIP: [<d09639d2>] __scsi_disk_get+0xd/0x2a [sd_mod] SS:ESP 0068:cf6edd68


And here is the output with the put_device() call removed (the 
plug-in part is the same as before):

Plug in USB drive:

[   74.683198] usb-storage: device found at 3
[   74.685229] scsi 0:0:0:0: Direct-Access     UDISK    PDU01_1G 65G2.0  0.00 PQ: 0 ANSI: 2
[   74.692196] usb-storage: device scan complete
[   75.018341] sd 0:0:0:0: [sda] 1967616 512-byte hardware sectors (1007 MB)
[   75.019465] sd 0:0:0:0: [sda] Write Protect is off
[   75.019624] sd 0:0:0:0: [sda] Mode Sense: 00 00 00 00
[   75.019745] sd 0:0:0:0: [sda] Assuming drive cache: write through
[   75.019872] sd_probe: call add_disk
[   75.019986] start of register_disk: 1
[   75.020234] after device_add: 3
[   75.020387] after disk_sysfs_add_subdirs: 5
[   75.020519] after get_capacity: 5
[   75.020672] after bdget_disk: 5
[   75.023582] sd 0:0:0:0: [sda] 1967616 512-byte hardware sectors (1007 MB)
[   75.024637] sd 0:0:0:0: [sda] Write Protect is off
[   75.024905] sd 0:0:0:0: [sda] Mode Sense: 00 00 00 00
[   75.025115] sd 0:0:0:0: [sda] Assuming drive cache: write through
[   75.025264]  sda: sda1
[   75.054655] after blkdev_get: 8
[   75.054924] after blkdev_put: 7
[   75.057048] end of register_disk: 7
[   75.057628] after blk_register_queue: 9
[   75.057871] sd 0:0:0:0: [sda] Attached SCSI removable disk
[   75.464875] sd 0:0:0:0: Attached scsi generic sg0 type 0

Unplug USB drive:

[   85.266412] usb 4-4: USB disconnect, address 3
[   85.266719] usb 4-4: unregistering device
[   85.266831] usb 4-4: usb_disable_device nuking all URBs
[   85.266961] usb 4-4: unregistering interface 4-4:1.0
[   85.271229] sd_remove: call del_gendisk
[   85.275622] start of del_gendisk: 9
[   85.276204] after deleting subpartitions: 7
[   85.276336] after invalidate_partition(0): 7
[   85.276512] after unlink_gendisk: 5
[   85.276644] after kobject_unregister subdirs: 3
[   85.276966] after device_del: 1
[   85.277095] scsi_disk_release: call put_disk
[   85.292153] usb 4-4:1.0: uevent
[   85.292468] usb 4-4:1.0: uevent
[   85.293458] usb 4-4: uevent

As you can see, this definitely proves that the final put is done at 
the right time.

See what the patch shows on your system.  One extra thing to check for: 
When you plug in a USB drive, the SCSI core starts up an error-handler 
process for it.  When you unplug the drive, the error-handler task 
should exit.  If it doesn't then there's an extra reference somewhere 
that never got released.

Alan Stern

Index: usb-2.6/block/genhd.c
===================================================================
--- usb-2.6.orig/block/genhd.c
+++ usb-2.6/block/genhd.c
@@ -17,6 +17,10 @@
 #include <linux/buffer_head.h>
 #include <linux/mutex.h>
 
+extern int alantest;
+#define alanp(msg, disk)   if (alantest) printk(KERN_INFO msg ": %d\n", \
+			atomic_read(&disk->dev.kobj.kref.refcount))
+
 extern struct class block_class;
 extern struct device_type disk_type;
 extern struct device_type part_type;
@@ -185,6 +189,7 @@ void add_disk(struct gendisk *disk)
 			    disk->minors, NULL, exact_match, exact_lock, disk);
 	register_disk(disk);
 	blk_register_queue(disk);
+	alanp("after blk_register_queue", disk);
 }
 
 EXPORT_SYMBOL(add_disk);
Index: usb-2.6/drivers/scsi/sd.c
===================================================================
--- usb-2.6.orig/drivers/scsi/sd.c
+++ usb-2.6/drivers/scsi/sd.c
@@ -62,6 +62,8 @@
 
 #include "scsi_logging.h"
 
+extern int alantest;
+
 MODULE_AUTHOR("Eric Youngdale");
 MODULE_DESCRIPTION("SCSI disk (sd) driver");
 MODULE_LICENSE("GPL");
@@ -1677,7 +1679,10 @@ static int sd_probe(struct device *dev)
 		gd->flags |= GENHD_FL_REMOVABLE;
 
 	dev_set_drvdata(dev, sdkp);
+	printk(KERN_INFO "sd_probe: call add_disk\n");
+	alantest = 1;
 	add_disk(gd);
+	alantest = 0;
 
 	sd_printk(KERN_NOTICE, sdkp, "Attached SCSI %sdisk\n",
 		  sdp->removable ? "removable " : "");
@@ -1708,6 +1713,8 @@ static int sd_remove(struct device *dev)
 	struct scsi_disk *sdkp = dev_get_drvdata(dev);
 
 	class_device_del(&sdkp->cdev);
+	printk(KERN_INFO "sd_remove: call del_gendisk\n");
+	alantest = 1;
 	del_gendisk(sdkp->disk);
 	sd_shutdown(dev);
 
@@ -1716,6 +1723,7 @@ static int sd_remove(struct device *dev)
 	class_device_put(&sdkp->cdev);
 	mutex_unlock(&sd_ref_mutex);
 
+	alantest = 0;
 	return 0;
 }
 
@@ -1738,6 +1746,7 @@ static void scsi_disk_release(struct cla
 	spin_unlock(&sd_index_lock);
 
 	disk->private_data = NULL;
+	printk(KERN_INFO "scsi_disk_release: call put_disk\n");
 	put_disk(disk);
 	put_device(&sdkp->device->sdev_gendev);
 
Index: usb-2.6/fs/partitions/check.c
===================================================================
--- usb-2.6.orig/fs/partitions/check.c
+++ usb-2.6/fs/partitions/check.c
@@ -36,6 +36,11 @@
 #include "karma.h"
 #include "sysv68.h"
 
+int alantest;
+EXPORT_SYMBOL(alantest);
+#define alanp(msg, disk)   if (alantest) printk(KERN_INFO msg ": %d\n", \
+			atomic_read(&disk->dev.kobj.kref.refcount))
+
 extern struct kobject block_depr;
 extern struct class block_class;
 
@@ -378,6 +383,7 @@ void register_disk(struct gendisk *disk)
 	struct hd_struct *p;
 	int err;
 
+	alanp("start of register_disk", disk);
 	disk->dev.parent = disk->driverfs_dev;
 	disk->dev.devt = MKDEV(disk->major, disk->first_minor);
 
@@ -392,6 +398,7 @@ void register_disk(struct gendisk *disk)
 
 	if (device_add(&disk->dev))
 		return;
+	alanp("after device_add", disk);
 #ifndef CONFIG_SYSFS_DEPRECATED
 	err = sysfs_create_link(&block_depr, &disk->dev.kobj,
 				kobject_name(&disk->dev.kobj));
@@ -399,8 +406,10 @@ void register_disk(struct gendisk *disk)
 		device_del(&disk->dev);
 		return;
 	}
+	alanp("after sysfs_create_link", disk);
 #endif
  	disk_sysfs_add_subdirs(disk);
+	alanp("after disk_sysfs_add_subdirs", disk);
 
 	/* No minors to use for partitions */
 	if (disk->minors == 1)
@@ -409,16 +418,20 @@ void register_disk(struct gendisk *disk)
 	/* No such device (e.g., media were just removed) */
 	if (!get_capacity(disk))
 		goto exit;
+	alanp("after get_capacity", disk);
 
 	bdev = bdget_disk(disk, 0);
 	if (!bdev)
 		goto exit;
+	alanp("after bdget_disk", disk);
 
 	bdev->bd_invalidated = 1;
 	err = blkdev_get(bdev, FMODE_READ, 0);
 	if (err < 0)
 		goto exit;
+	alanp("after blkdev_get", disk);
 	blkdev_put(bdev);
+	alanp("after blkdev_put", disk);
 
 exit:
 	/* announce disk after possible partitions are created */
@@ -432,6 +445,7 @@ exit:
 			continue;
 		kobject_uevent(&p->dev.kobj, KOBJ_ADD);
 	}
+	alanp("end of register_disk", disk);
 }
 
 int rescan_partitions(struct gendisk *disk, struct block_device *bdev)
@@ -497,24 +511,34 @@ void del_gendisk(struct gendisk *disk)
 {
 	int p;
 
+	alanp("start of del_gendisk", disk);
+
 	/* invalidate stuff */
 	for (p = disk->minors - 1; p > 0; p--) {
 		invalidate_partition(disk, p);
 		delete_partition(disk, p);
 	}
+	alanp("after deleting subpartitions", disk);
 	invalidate_partition(disk, 0);
+	alanp("after invalidate_partition(0)", disk);
+
 	disk->capacity = 0;
 	disk->flags &= ~GENHD_FL_UP;
 	unlink_gendisk(disk);
+	alanp("after unlink_gendisk", disk);
 	disk_stat_set_all(disk, 0);
 	disk->stamp = 0;
 
 	kobject_unregister(disk->holder_dir);
 	kobject_unregister(disk->slave_dir);
+	alanp("after kobject_unregister subdirs", disk);
 	disk->driverfs_dev = NULL;
 #ifndef CONFIG_SYSFS_DEPRECATED
 	sysfs_remove_link(&block_depr, disk->dev.bus_id);
+	alanp("after sysfs_remove_link", disk);
 #endif
 	device_del(&disk->dev);
+	alanp("after device_del", disk);
 	put_device(&disk->dev);
+	alanp("after put_device", disk);
 }