Skip to contentSkip to conversation

kernel crash when unloading host with offline device

PATCH Saeed Bishara 2 participants 2 messages Sep 1, 2004 – Sep 2, 2004

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

Hi,
I got this crash when trying to unload my scsi driver that has been
experienced errors that made the scsi error handler to put the device in offline mode.
The problem occurred when reading from the device with sg_dd , but
didn't happen with dd.
I succeeded to generate the crash using the scsi_debug with a little
change that makes it behave like my device, the change it simply to timeout all the commands after
processing 30 commands, this will cause the device to set in offline
mode.
here are the system information, my patch to the scsi_debug, the
system log on crash, and the commands I run.

system info:

kernel 2.6.9-rc1
sg_utils_1.08
scsi_debug 1.73 (comes with the mentioned kernel) + my patch

scsi_debug.c patch:

scsi_debug.c 2004-09-01 21:20:39.000000000 +0300 renamed from usr/src/linux-2.6.9-rc1/drivers/scsi/scsi_debug.c 2004-08-14 08:37:15.000000000 +0300 +0 -0
@@ -79,9 +79,9 @@
 */

#define DEF_DELAY 1
#define DEF_DEV_SIZE_MB 8
-#define DEF_EVERY_NTH 0
+#define DEF_EVERY_NTH 30
#define DEF_NUM_PARTS 0
-#define DEF_OPTS 0
+#define DEF_OPTS 7
#define DEF_SCSI_LEVEL 3
#define DEF_PTYPE 0

@@ -323,7 +323,7 @@

        if ((scsi_debug_every_nth > 0) &&
            (++scsi_debug_cmnd_count >= scsi_debug_every_nth)) {

- scsi_debug_cmnd_count =0;
+ // scsi_debug_cmnd_count =0; /*timeout forever!!!*/
if (SCSI_DEBUG_OPT_TIMEOUT & scsi_debug_opts)
return 0; /* ignore command causing timeout */
else if (SCSI_DEBUG_OPT_RECOVERED_ERR & scsi_debug_opts)

crash log:

Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 07 00 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 07 80 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 08 00 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 08 80 00 00 80 00
Sep  1 21:58:34 localhost kernel: scsi_debug: abort
Sep  1 21:59:04 localhost last message repeated 5 times
Sep  1 21:59:04 localhost kernel: scsi_debug: device_reset
Sep  1 21:59:14 localhost kernel: scsi_debug: abort
Sep  1 21:59:14 localhost kernel: scsi_debug: bus_reset
Sep  1 21:59:34 localhost kernel: scsi_debug: abort
Sep  1 21:59:54 localhost last message repeated 2 times
Sep  1 21:59:54 localhost kernel: scsi_debug: host_reset
Sep  1 22:00:14 localhost kernel: scsi_debug: abort
Sep  1 22:00:34 localhost last message repeated 2 times
Sep  1 22:00:34 localhost kernel: scsi: Device offlined - not ready after error recovery: host 0 channel 0 id 0 lun 0
Sep  1 22:00:34 localhost last message repeated 2 times
Sep  1 22:00:34 localhost kernel: scsi0 (0:0): rejecting I/O to offline device
Sep  1 22:00:34 localhost last message repeated 4 times
Sep  1 22:02:11 localhost kernel: Synchronizing SCSI cache for disk sda:
Sep  1 22:02:11 localhost kernel: FAILED
Sep  1 22:02:11 localhost kernel:   status = 0, message = 00, host = 1, driver = 00
Sep  1 22:02:11 localhost kernel:   <6>scsi_debug: slave_destroy <0 0 0 0>
Sep  1 22:02:11 localhost kernel: slab error in kmem_cache_destroy(): cache `scsi_cmd_cache': Can't free all objects
Sep  1 22:02:11 localhost kernel:  [<c0106ccf>] dump_stack+0x1e/0x22
Sep  1 22:02:11 localhost kernel:  [<c0154b30>] kmem_cache_destroy+0xa4/0x12a
Sep  1 22:02:11 localhost kernel:  [<e0a1e9f3>] scsi_destroy_command_freelist+0x70/0xa1 [scsi_mod]
Sep  1 22:02:11 localhost kernel:  [<e0a2003b>] scsi_host_dev_release+0x38/0xec [scsi_mod]
Sep  1 22:02:11 localhost kernel:  [<c0253bb1>] device_release+0x5a/0x5e
Sep  1 22:02:11 localhost kernel:  [<c01f3bcf>] kobject_cleanup+0x8d/0x8f
Sep  1 22:02:11 localhost kernel:  [<e08b22db>] sdebug_driver_remove+0x66/0x8b [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<c0254de2>] device_release_driver+0x62/0x64
Sep  1 22:02:11 localhost kernel:  [<c0255038>] bus_remove_device+0x7e/0xbf
Sep  1 22:02:11 localhost kernel:  [<c0253f1f>] device_del+0x6e/0xa3 Sep  1 22:02:11 localhost kernel:  [<c0253f68>] device_unregister+0x14/0x22
Sep  1 22:02:11 localhost kernel:  [<e08b2114>] sdebug_remove_adapter+0xf1/0x18b [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<e08b2520>] scsi_debug_exit+0x5a/0x61 [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<c0140a59>] sys_delete_module+0x138/0x187
Sep  1 22:02:11 localhost kernel:  [<c0106749>] sysenter_past_esp+0x52/0x71
Sep  1 22:02:11 localhost kernel: scsi_debug: pseudo_0_release() called

my commands history

1022 sg_dd if=/dev/sg0 of=/dev/null bs=512 &

1023  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1024  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1025  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1026  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1027  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1028  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1029  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1030  jobs

insmod ./scsi_debug.ko
..

1057  cat /sys/bus/scsi/devices/0\:0\:0\:0/state            /*at this point the device was offline*/
1058  lsmod                                                              1059  rmmod sg            /*failed, sg used by zombie sg_dd*/
1060  jobs
1061  killall sg_dd           1062  jobs
1063  rmmod sg
1064  lsmod
1065  rmmod scsi_debug         /*bummmmm*/

saeed

#1 lore raw
Quoted 5 lines · Saeed Bishara

Hi,
I got this crash when trying to unload my scsi driver that has been
experienced errors that made the scsi error handler to put the device in offline mode.
The problem occurred when reading from the device with sg_dd , but
didn't happen with dd.

Saeed,
You might also try:
sg_dd if=/dev/sda blk_sgio=1 ....
to inject the commands through the block SG_IO ioctl rather than the sg driver.

Quoted 4 lines

I succeeded to generate the crash using the scsi_debug with a little
change that makes it behave like my device, the change it simply to timeout all the commands after
processing 30 commands, this will cause the device to set in offline
mode.

I have a patch so that a negative number can be given to 'every_nth'. When the command count in scsi_debug reaches |every_nth_value| then the error condition persists. BTW You can go into sysfs and clear the error condition for subsequent commands by writing 0 (for example) to every_nth.

Quoted 17 lines

here are the system information, my patch to the scsi_debug, the
system log on crash, and the commands I run.

system info:

kernel 2.6.9-rc1
sg_utils_1.08
scsi_debug 1.73 (comes with the mentioned kernel) + my patch

scsi_debug.c patch:

--- /usr/src/linux-2.6.9-rc1/drivers/scsi/scsi_debug.c 2004-08-14
08:37:15.000000000 +0300
+++ ./scsi_debug.c 2004-09-01 21:20:39.000000000 +0300

Review line 84

Quoted 8 lines
(quoted diff) +2 -2
@@ -79,9 +79,9 @@
 */
 #define DEF_DELAY   1
 #define DEF_DEV_SIZE_MB   8
-#define DEF_EVERY_NTH   0
+#define DEF_EVERY_NTH   30
 #define DEF_NUM_PARTS   0
-#define DEF_OPTS   0
+#define DEF_OPTS   7

Maybe 5 would be a better value since a MEDIUM ERROR as well at lba 0x1234 is only going to potentially complicate things.

Also there is no need to change the defaults:

  $ modprobe scsi_debug opts=5 every_nth=30
would have the same effect.
Quoted 16 lines
(quoted diff) +1 -1
 #define DEF_SCSI_LEVEL   3
 #define DEF_PTYPE   0
 
@@ -323,7 +323,7 @@
 
        if ((scsi_debug_every_nth > 0) &&
            (++scsi_debug_cmnd_count >= scsi_debug_every_nth)) {
-                scsi_debug_cmnd_count =0;
+              //  scsi_debug_cmnd_count =0; /*timeout forever!!!*/
        if (SCSI_DEBUG_OPT_TIMEOUT & scsi_debug_opts)
            return 0; /* ignore command causing timeout */
        else if (SCSI_DEBUG_OPT_RECOVERED_ERR & scsi_debug_opts)

crash log:

Quoted 16 lines
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 07 00 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 07 80 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 08 00 00 00 80 00
Sep  1 21:57:34 localhost kernel: scsi_debug: cmd 28 00 00 00 08 80 00 00 80 00
Sep  1 21:58:34 localhost kernel: scsi_debug: abort
Sep  1 21:59:04 localhost last message repeated 5 times
Sep  1 21:59:04 localhost kernel: scsi_debug: device_reset
Sep  1 21:59:14 localhost kernel: scsi_debug: abort
Sep  1 21:59:14 localhost kernel: scsi_debug: bus_reset
Sep  1 21:59:34 localhost kernel: scsi_debug: abort
Sep  1 21:59:54 localhost last message repeated 2 times
Sep  1 21:59:54 localhost kernel: scsi_debug: host_reset
Sep  1 22:00:14 localhost kernel: scsi_debug: abort
Sep  1 22:00:34 localhost last message repeated 2 times
Sep  1 22:00:34 localhost kernel: scsi: Device offlined - not ready after error recovery: host 0 channel 0 id 0 lun 0
Sep  1 22:00:34 localhost last message repeated 2 times

Strange, the device being taken offline multiple times.

Quoted 4 lines
Sep  1 22:00:34 localhost kernel: scsi0 (0:0): rejecting I/O to offline device
Sep  1 22:00:34 localhost last message repeated 4 times
Sep  1 22:02:11 localhost kernel: Synchronizing SCSI cache for disk sda:
Sep  1 22:02:11 localhost kernel: FAILED

This looks wrong. The midlevel should not be issuing a SYNCHRONIZE CACHE command to an offline device.

Quoted 23 lines
Sep  1 22:02:11 localhost kernel:   status = 0, message = 00, host = 1, driver = 00
Sep  1 22:02:11 localhost kernel:   <6>scsi_debug: slave_destroy <0 0 0 0>
Sep  1 22:02:11 localhost kernel: slab error in kmem_cache_destroy(): cache `scsi_cmd_cache': Can't free all objects
Sep  1 22:02:11 localhost kernel:  [<c0106ccf>] dump_stack+0x1e/0x22
Sep  1 22:02:11 localhost kernel:  [<c0154b30>] kmem_cache_destroy+0xa4/0x12a
Sep  1 22:02:11 localhost kernel:  [<e0a1e9f3>] scsi_destroy_command_freelist+0x70/0xa1 [scsi_mod]
Sep  1 22:02:11 localhost kernel:  [<e0a2003b>] scsi_host_dev_release+0x38/0xec [scsi_mod]
Sep  1 22:02:11 localhost kernel:  [<c0253bb1>] device_release+0x5a/0x5e
Sep  1 22:02:11 localhost kernel:  [<c01f3bcf>] kobject_cleanup+0x8d/0x8f
Sep  1 22:02:11 localhost kernel:  [<e08b22db>] sdebug_driver_remove+0x66/0x8b [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<c0254de2>] device_release_driver+0x62/0x64
Sep  1 22:02:11 localhost kernel:  [<c0255038>] bus_remove_device+0x7e/0xbf
Sep  1 22:02:11 localhost kernel:  [<c0253f1f>] device_del+0x6e/0xa3 Sep  1 22:02:11 localhost kernel:  [<c0253f68>] device_unregister+0x14/0x22
Sep  1 22:02:11 localhost kernel:  [<e08b2114>] sdebug_remove_adapter+0xf1/0x18b [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<e08b2520>] scsi_debug_exit+0x5a/0x61 [scsi_debug]
Sep  1 22:02:11 localhost kernel:  [<c0140a59>] sys_delete_module+0x138/0x187
Sep  1 22:02:11 localhost kernel:  [<c0106749>] sysenter_past_esp+0x52/0x71
Sep  1 22:02:11 localhost kernel: scsi_debug: pseudo_0_release() called

my commands history

Quoted 9 lines
   1022  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1023  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1024  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1025  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1026  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1027  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1028  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1029  sg_dd if=/dev/sg0 of=/dev/null bs=512 &
1030  jobs

sgp_dd should have a similar effect using POSIX threads (default 4 threads).

Quoted 4 lines

insmod ./scsi_debug.ko
..
1057 cat /sys/bus/scsi/devices/0\:0\:0\:0/state /*at this point the device was offline*/
1058 lsmod 1059 rmmod sg /*failed, sg used by zombie sg_dd*/

At this point 'cat /proc/scsi/sg/debug' would be interesting.

When I tried to replicate this failure, one thread of sgp_dd had a stuck command with 10 minutes and climbing elapsed for a command that claimed to time out in 60 seconds??

Quoted 5 lines
1060  jobs
1061  killall sg_dd           1062  jobs
1063  rmmod sg
1064  lsmod
1065  rmmod scsi_debug         /*bummmmm*/

My test blew up about 30 seconds after issuing the SYNCHRONIZE CACHE, nothing went to the log, alt-sysrq was the only thing that worked.

Doug Gilbert