Bug 828853 - null pointer dereferencing in scsi_mod:scsi_end_async [NEEDINFO]
null pointer dereferencing in scsi_mod:scsi_end_async
Status: CLOSED WONTFIX
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: kernel (Show other bugs)
5.5
x86_64 Linux
medium Severity high
: rc
: ---
Assigned To: Red Hat Kernel Manager
Red Hat Kernel QE team
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-06-05 09:21 EDT by Maruthi Seshidhar Inukonda
Modified: 2014-12-16 22:00 EST (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-06-02 09:09:16 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
pm-rhel: needinfo? (imaruthi)
knoha: needinfo? (kernel-mgr)


Attachments (Terms of Use)

  None (edit)
Description Maruthi Seshidhar Inukonda 2012-06-05 09:21:48 EDT
Description of problem:

PMC-Sierra SAS HBA, and libsas and pm8001 kernel modules are installed in
RHEL 5.5 x86_64 box.  On the HBA, Netapp DS4243 SAS disk shelf is connected.
The shelf has 24 SAS drives (3Gbps drives).

While I/Os (via read/write via ioctl(fd, SG_IO, cdb)) to the disks 
are in progress, plugged-out the SAS cable to disk shelf.
After this the 2.6.18-194 kernel hits into null pointer de-referencing issue in
scsi_mod:scsi_end_async.

Version-Release number of selected component (if applicable):

RHEL 5.5 x86_64 (kernel 2.6.18-194)

How reproducible:
Very easily reproducible. Just takes few minutes to start I/O.

Steps to Reproduce:
1. Start read/write to all 24 disks in a SAS disk shelf
2. Remove the SAS cable to disk shelf (or power off all the drives, using Shelf CLI command)
3. The kernel panics in scsi_mod

Actual results:
Kernel panics in scsi_mod.

Expected results:
The scsi_mod can gracefully fail the pending SCSI commands.

Additional info:

[root@lnx154-37 ~]# sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: Expander phy change count has changed
sas: ex 500a09800042463f phy8 originated BROADCAST(CHANGE)
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
sas: broadcast received: 11
sas: broadcast received: 11
sas: broadcast received: 11
sas: broadcast received: 11
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: Expander phy change count has changed
sas: ex 500a09800042463f phy9 originated BROADCAST(CHANGE)
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: Expander phy change count has changed
sas: ex 500a09800042463f phy10 originated BROADCAST(CHANGE)
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
sas: broadcast received: 11
sas: broadcast received: 11
sas: broadcast received: 11
sas: broadcast received: 11
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: broadcast received: 9
sas: REVALIDATING DOMAIN on port 0, pid:5281
sas: Expander phy change count has changed
sas: ex 500a09800042463f phy11 originated BROADCAST(CHANGE)
sas: done REVALIDATING DOMAIN on port 0, pid:5281, res 0x0
general protection fault: 0000 [1] SMP
last sysfs file: /devices/pci0000:00/0000:00:1c.0/0000:06:00.0/host4/port-4:1/expander-4:1/port-4:1:9/end_device-4:1:9/target4:0:34/4:0:34:0/type
CPU 0
Modules linked in: ipv6 xfrm_nalgo crypto_api autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc cpufreq_ondemand acpi_cpufreq freq_table loop dm_mirror dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec dell_wmi wmi button battery asus_acpi acpi_memhotplug ac parport_pc lp parport sr_mod cdrom pm8001(U) libsas(U) joydev serio_raw sg i2c_i801 e1000e i2c_core shpchp pcspkr dm_raid45 dm_message dm_region_hash dm_log dm_mod dm_mem_cache usb_storage mpt2sas(U) scsi_transport_sas ata_piix libata sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 0, comm: swapper Tainted: G      2.6.18-194.el5 #1
RIP: 0010:[<ffffffff8822420d>]  [<ffffffff8822420d>] :sg:sg_cmd_done+0x2e/0x253
RSP: 0018:ffffffff80448e20  EFLAGS: 00010006
RAX: ffffffff882241df RBX: 0000000000050000 RCX: 0000000000000000
RDX: 0000000000050000 RSI: ffff810117f29de8 RDI: ffffffff8822792b
RBP: ffff81011831d070 R08: ffff81013c6f8000 R09: ffff81011758c9c0
R10: 0000000000000000 R11: ffffffff8807aa9d R12: ffff810134c70c98
R13: 2030207772207366 R14: ffff810117f29de8 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffffffff803cb000(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 00007fff4d710b48 CR3: 0000000118718000 CR4: 00000000000006e0
Process swapper (pid: 0, threadinfo ffffffff803fc000, task ffffffff80309b60)
Stack:  ffff81011758c9c0 ffffffff8002cfe9 ffff81013c05d400 ffff810117f29dd8
 ffff810116458b08 ffff810134c70c98 0000000000000001 0000000000000246
 0000000000000000 ffffffff8807aac8 0000000000000001 ffff810116458b08
Call Trace:
 <IRQ>  [<ffffffff8002cfe9>] __end_that_request_first+0x23c/0x5bf
 [<ffffffff8807aac8>] :scsi_mod:scsi_end_async+0x2b/0x4d
 [<ffffffff8807a065>] :scsi_mod:scsi_end_request+0xa7/0xcd
 [<ffffffff8807a1d9>] :scsi_mod:scsi_io_completion+0x14e/0x324
 [<ffffffff8807a46e>] :scsi_mod:scsi_device_unbusy+0x67/0x81
 [<ffffffff80037fd5>] blk_done_softirq+0x5f/0x6d
 [<ffffffff80012409>] __do_softirq+0x89/0x133
 [<ffffffff8005f2fc>] call_softirq+0x1c/0x28
 [<ffffffff8006dba8>] do_softirq+0x2c/0x85
 [<ffffffff8006da30>] do_IRQ+0xec/0xf5
 [<ffffffff8005e615>] ret_from_intr+0x0/0xa
 <EOI>  [<ffffffff8019d779>] acpi_safe_halt+0x25/0x36
 [<ffffffff8019dfa3>] acpi_processor_idle_simple+0xe0/0x30e
 [<ffffffff8019dec3>] acpi_processor_idle_simple+0x0/0x30e
 [<ffffffff8019dec3>] acpi_processor_idle_simple+0x0/0x30e
 [<ffffffff800497be>] cpu_idle+0x95/0xb8
 [<ffffffff80407807>] start_kernel+0x220/0x225
 [<ffffffff8040722f>] _sinittext+0x22f/0x236


Code: 4d 8b 65 08 4d 85 e4 74 09 41 8a 44 24 30 84 c0 74 13 48 c7
RIP  [<ffffffff8822420d>] :sg:sg_cmd_done+0x2e/0x253
 RSP <ffffffff80448e20>
 <0>Kernel panic - not syncing: Fatal exception
Comment 2 David Jeffery 2012-08-14 11:13:10 EDT
There is a race condition in the sg driver with outstanding commands and the driver's device removal callback, sg_remove().  When the main scsi device is deleted, sg_remove() will be called and free the memory used by the attached sg device, including the command buffers.  But sg_removal() fails to wait for any running commands to complete, resulting in the driver freeing memory which will be used by the completion handling of the running commands.  This leaves a race condition where the commands take long enough to complete that the removal callback will have freed everything first, resulting in a crash from using freed and reused memory.

This can be recreated with the scsi_debug driver.
1) set the delay option on scsi_debug to 10000 (10 seconds).
2) send a command to the device, e.g. sg_readcap /dev/sg2
3) delete the scsi_debug scsi device. e.g. echo "1" >/sys/block/sdc/device/delete

The memory for the sg device will be freed before the command completes.  If it has been reused, it will cause a crash when the command is finally completed.
Comment 4 shiva krishna merla 2012-09-18 01:41:09 EDT
Hi, 

Our Netapp testers have observed the same issue while testing with RHEL 5.8 with SAS connected array and LSI MPT Fusion SAS 2.0 Device Driver with MPP multipath driver.

Kernel : 
2.6.18-308.el5xen #1 SMP Fri Jan 27 17:26:57 EST 2012 x86_64 x86_64 x86_64 GNU/Linux

Exception Trace :

PID: 63     TASK: ffff8803bddab0c0  CPU: 20  COMMAND: "ksoftirqd/20"
 #0 [ffff8803bde0bc30] crash_kexec at ffffffff802a7dca
 #1 [ffff8803bde0bcf0] __die at ffffffff8026427d
 #2 [ffff8803bde0bd30] die at ffffffff8026cca4
 #3 [ffff8803bde0bd60] do_general_protection at ffffffff80264594
 #4 [ffff8803bde0bda0] error_exit at ffffffff8025f82b
    [exception RIP: sg_cmd_done+46]
    RIP: ffffffff880b70ad  RSP: ffff8803bde0be58  RFLAGS: 00010006
    RAX: ffffffff880b707f  RBX: 0000000000010000  RCX: 0000000000000000
    RDX: 0000000000010000  RSI: ffff88037134fe58  RDI: ffffffff880ba88a
    RBP: ffff88037134e070   R8: 00000014be097e58   R9: 00000000fffffffb
    R10: ffff88038493f398  R11: ffffffff8807af9f  R12: ffff880380a806f0
    R13: 3d48544150564544  R14: ffff88037134fe58  R15: 0000000000000000
    ORIG_RAX: ffffffffffffffff  CS: 10000e030  SS: e02b
 #5 [ffff8803bde0bea0] scsi_end_async at ffffffff8807afca [scsi_mod]
 #6 [ffff8803bde0bec0] scsi_end_request at ffffffff8807a51e [scsi_mod]
 #7 [ffff8803bde0bef0] scsi_io_completion at ffffffff8807a6b4 [scsi_mod]
 #8 [ffff8803bde0bf60] blk_done_softirq at ffffffff80238f50
 #9 [ffff8803bde0bf80] __do_softirq at ffffffff80212ebc
#10 [ffff8803bde0bfb0] call_softirq at ffffffff8025fda4
--- <IRQ stack> ---
#11 [ffff8803bddffec8] do_softirq at ffffffff8026db89
#12 [ffff8803bddffed8] ksoftirqd at ffffffff8029137e
#13 [ffff8803bddffee8] kthread at ffffffff802338cf
#14 [ffff8803bddfff48] kernel_thread at ffffffff8025fb2c

The command completion occured on device which is already removed.

Device removed from SG table ( 9:0:1:2 )

Sep 11 10:05:36 ictm-soyuzhost-Cfg05-4 kernel: sd 9:0:1:2: Attached scsi disk sdeb
Sep 11 10:05:36 ictm-soyuzhost-Cfg05-4 kernel:   Vendor: <5>sd 9:0:1:2: Attached scsi generic sg135 type 0
Sep 11 10:05:36 ictm-soyuzhost-Cfg05-4 kernel: NETAPP    Model: IN<5>  Vendor: NETAPP    Model: VirtualDisk       Rev: 8786
Sep 11 10:05:36 ictm-soyuzhost-Cfg05-4 kernel:   Type:   Direct-Access                      ANSI SCSI revision: 05

crash> sg_dev_arr
sg_dev_arr = $35 = (Sg_device **) 0xffff88038067b000
crash>

crash> p *((Sg_device*)0xffff88038067b000+135)
$34 = {
  device = 0x0,
  o_excl_wait = {
    lock = {
      raw_lock = {
        slock = 0
      }
    },
    task_list = {
      next = 0xffffffff88079161,
      prev = 0x5500000000
    }
  },
  sg_tablesize = 1,
  headfp = 0x500000000,
  detached = 0 '\000',
  exclude = 0 '\000',
  sgdebug = 0 '\000',
  disk = 0xffffffff880756b7,
  cdev = 0x200000000
}

crash> struct scsi_device 0xffff88037faa2800 | grep sdev_state
  sdev_state = SDEV_DEL,

kobj = {
      k_name = 0xffff88037faa29e0 "9:0:1:2",
      name = "9:0:1:2\000\000\000\000\000\000\000\000\000\000\000\000",
      kref = {
        refcount = {
          counter = 1
        }
      },

crash> struct scsi_io_context 0xffff88037134fe48
struct scsi_io_context {
  data = 0xffff88037134e070,
  done = 0xffffffff880b707f <sg_cmd_done>,
  sense = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
}

In sg_cmd_done() Sg_request is corrupt. Looks like its freed.

crash> struct Sg_request 0xffff88037134e070 ( Corrupt )
struct Sg_request {
  nextrp = 0x737973207379732f,
  parentfp = 0x2030207772207366,
  data = {
    k_use_sg = 2608,
    sglist_len = 28719,
    bufflen = 795045746,
    b_malloc_len = 796095842,
    buffer = 0x75622f636f72702f,
    dio_in_use = 115 's',
    cmd_opcode = 47 '/'
  },
  header = {
    interface_id = 544433762,
    dxfer_direction = 807434098,
    cmd_len = 32 ' ',
    mx_sb_len = 48 '0',
    iovec_count = 25610,
    dxfer_len = 1953527397,
    dxferp = 0x702f7665642f2073,
    cmdp = 0x7470766564207374 <Address 0x7470766564207374 out of bounds>,
    sbp = 0x3020302077722073,
    timeout = 1701064458,
    flags = 1685270390,
    pack_id = 790638945,
    usr_ptr = 0x7772203374786520,
    status = 44 ',',
    masked_status = 100 'd',
    msg_status = 97 'a',
    sb_len_wr = 116 't',
    host_status = 15713,
    driver_status = 29295,
    resid = 1701995876,
    duration = 540024932,
    info = 1836321328
  },
  sense_b = "/dev/shm tmpfs rw 0 0\nnone /proc/sys/fs/binfmt_misc binfmt_misc rw 0 0\nsunrpc /var/lib/nfs/rpc_p",
  res_used = 105 'i',
  orphan = 112 'p',
  sg_io_owned = 101 'e',
  done = 102 'f'
}

I see major changes in RHEL 6.3 while handling device removal's and how command completions are handled in sg driver. So is there any plan to merge those changes with RHEL 5.9?.

Thanks
Shiva
Comment 6 RHEL Product and Program Management 2012-10-30 01:54:47 EDT
This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.
Comment 9 RHEL Product and Program Management 2014-03-07 07:19:05 EST
Thank you for submitting this request for inclusion in Red Hat Enterprise Linux 5. We've carefully evaluated the request, but are unable to include it in the  last planned RHEL5 minor release. This Bugzilla will soon be CLOSED as WONTFIX. To request that Red Hat re-consider this request, please re-open the bugzilla via  appropriate support channels and provide additional business and/or technical details about its importance to you.
Comment 10 RHEL Product and Program Management 2014-06-02 09:09:16 EDT
Thank you for submitting this request for inclusion in Red Hat Enterprise Linux 5. We've carefully evaluated the request, but are unable to include it in RHEL5 stream. If the issue is critical for your business, please provide additional business justification through the appropriate support channels (https://access.redhat.com/site/support).

Note You need to log in before you can comment on or make changes to this bug.