Project

General

Profile

Bug #3862

stmf + kstat = kernel panic

Added by Christopher Siden over 7 years ago. Updated over 7 years ago.

Status:
Closed
Priority:
Normal
Category:
comstar - iSCSI/FC/SAS target
Start date:
2013-07-02
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:
needs-triage
Gerrit CR:

Description

We were hitting this repeatably on a customer system. After extensive investigation by Jeremy Jones and Jeff Biseda, Jeremy wrote up this root cause:

I think I found the root cause of the issue.  If we start from a state where we
have 2 iSCSI luns and no views we have no global kstats as expected:
...
delphix@jjones-trunk-1.dcenter:~$ stmfadm list-lu
LU Name: 600144F00000000000005170B7010006
LU Name: 600144F00000000000005170B7030007
...
> stmf_state::print stmf_state_t stmf_itl_kstat_list | ::walk avl | ::print stmf
_i_itl_kstat_t
...

Now we add a view to the first lun.  This lun gets assigned to slot 0 of the
session's lun map since it's the first lun to be visible by this session:
...
  1  64855        stmf_add_view_entry:entry 0 0 255

  1  64595    stmf_get_next_free_lun:return 0
...

We have have one global stats entry for itl_0.0.0 and guid
600144f00000000000005170b7010006 as expected:
...
> stmf_state::print stmf_state_t stmf_itl_kstat_list | ::walk avl | ::print stmf
_i_itl_kstat_t iitl_kstat_nm iitl_kstat_guid
iitl_kstat_nm = [ "itl_0.0.0" ]
iitl_kstat_guid = [ "600144f00000000000005170b7010006" ]
...

And the session lun map entry for lun 0 maps to the expected lun guid and
stmf_itl_data_t kstats:
...
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[].lm_
plus | ::print uint64_t | ::print stmf_lun_map_ent_t  ent_lu[].lu_stmf_private
|
 ::print stmf_i_lu_t ilu_ascii_hex_guid
ilu_ascii_hex_guid = [ "600144f00000000000005170b7010006" ]
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[].lm_
plus | ::print uint64_t | ::print stmf_lun_map_ent_t ent_itl_datap | ::print
stm
f_itl_data_t
{
    itl_counter = 0x1
    itl_flags = 0
    itl_hdlrm_reason = 0
    itl_lun = 0
    itl_kstat_strbuf = 0xffffff01da27b780 " 
iqn.1991-05.com.microsoft:10-43-1-222.ad.delphix.com" 
    itl_kstat_strbuflen = 0xd4
    itl_kstat_info = 0xffffff01d2b7f220
    itl_kstat_taskq = 0xffffff01d2b7f330
    itl_kstat_lu_xfer = 0xffffff01d7537e70
    itl_kstat_lport_xfer = 0xffffff01d222c770
    itl_handle = 0xffffff01e01ec950
    itl_ilu = 0xffffff01d712d400
    itl_session = 0xffffff01d49f32b8
    itl_next = 0
}
...

Now remove the view for the lun.  This removes the entry from the session lun
mapping table but leaves the global stats entry since the lun hasn't been
deleted:
...
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[]
stmf_ilportlist[].ilport_ss_list[].iss_sm = {
    stmf_ilportlist[].ilport_ss_list[].iss_sm->lm_nluns = 0
    stmf_ilportlist[].ilport_ss_list[].iss_sm->lm_nentries = 0x8
    stmf_ilportlist[].ilport_ss_list[].iss_sm->lm_plus = 0xffffff01d6fc8c00
}
> stmf_state::print stmf_state_t stmf_itl_kstat_list | ::walk avl | ::print stmf
_i_itl_kstat_t iitl_kstat_nm iitl_kstat_guid
iitl_kstat_nm = [ "itl_0.0.0" ]
iitl_kstat_guid = [ "600144f00000000000005170b7010006" ]
...

We now add a view for the 2nd lun.  This lun also gets slot 0 in the session
lun map since the lun map is empty:
...
  0  64855        stmf_add_view_entry:entry 0 0 255

  0  64595    stmf_get_next_free_lun:return 0
...

The problem now is that the lun map entry points to the lun guid
600144F00000000000005170B7030007 but the stmf_itl_data_t is pointing to stats
for lun guid 600144F00000000000005170B7010006:
...
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[].lm_
plus | ::print uint64_t | ::print stmf_lun_map_ent_t  ent_lu[].lu_stmf_private
|
 ::print stmf_i_lu_t ilu_ascii_hex_guid
ilu_ascii_hex_guid = [ "600144f00000000000005170b7030007" ]
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[].lm_
plus | ::print uint64_t | ::print stmf_lun_map_ent_t ent_itl_datap | ::print
stm
f_itl_data_t
{
    itl_counter = 0x1
    itl_flags = 0
    itl_hdlrm_reason = 0
    itl_lun = 0
    itl_kstat_strbuf = 0xffffff01da27b780 " 
iqn.1991-05.com.microsoft:10-43-1-222.ad.delphix.com" 
    itl_kstat_strbuflen = 0xd4
    itl_kstat_info = 0xffffff01d2b7f220
    itl_kstat_taskq = 0xffffff01d2b7f330
    itl_kstat_lu_xfer = 0xffffff01d7537e70
    itl_kstat_lport_xfer = 0xffffff01d222c770
    itl_handle = 0xffffff01d23aabe8
    itl_ilu = 0xffffff01d72902c0
    itl_session = 0xffffff01d49f32b8
    itl_next = 0
}
...

When we delete a lun we delete by guid, so if we delete lun
600144F00000000000005170B7010006 that will end up freeing the global stats for
"itl_0.0.0" but we will not clean up the session's lun map since it doesn't
have a view for the lun we deleted.  This menas that after we delete lun
600144F00000000000005170B7010006 the remaining lun map entry stmf_itl_data_t
will be pointing to stale kstat buffers:

...
> stmf_state::print stmf_state_t stmf_ilportlist[].ilport_ss_list[].iss_sm[].lm_
plus | ::print uint64_t | ::print stmf_lun_map_ent_t ent_itl_datap | ::print
stm
f_itl_data_t
{
    itl_counter = 0x1
    itl_flags = 0
    itl_hdlrm_reason = 0
    itl_lun = 0
    itl_kstat_strbuf = 0xffffff01da27b780 "" 
    itl_kstat_strbuflen = 0xd4
    itl_kstat_info = 0xffffff01d2b7f220
    itl_kstat_taskq = 0xffffff01d2b7f330
    itl_kstat_lu_xfer = 0xffffff01d7537e70
    itl_kstat_lport_xfer = 0xffffff01d222c770
    itl_handle = 0xffffff01d23aabe8
    itl_ilu = 0xffffff01d72902c0
    itl_session = 0xffffff01d49f32b8
    itl_next = 0
}
> 0xffffff01da27b780::whatis
ffffff01da27b780 is freed from kmem_alloc_224
> 0xffffff01d2b7f220::whatis
ffffff01d2b7f220 is freed from the kstat vmem arena:
            ADDR TYPE            START              END             SIZE
                                THREAD        TIMESTAMP
ffffff01d70853f0 FREE ffffff01d2b7f220 ffffff01d2b7f550              816
> 0xffffff01d2b7f330::whatis
ffffff01d2b7f330 is ffffff01d2b7f220+110, freed from the kstat vmem arena:
            ADDR TYPE            START              END             SIZE
                                THREAD        TIMESTAMP
ffffff01d70853f0 FREE ffffff01d2b7f220 ffffff01d2b7f550              816
> 0xffffff01d7537e70::whatis
ffffff01d7537e70 is freed from the kstat vmem arena:
            ADDR TYPE            START              END             SIZE
                                THREAD        TIMESTAMP
ffffff01e4423578 FREE ffffff01d7537e70 ffffff01d7538000              400
> 0xffffff01d222c770::whatis
ffffff01d222c770 is freed from the kstat vmem arena:
            ADDR TYPE            START              END             SIZE
                                THREAD        TIMESTAMP
ffffff01d88f40e0 FREE ffffff01d222c770 ffffff01d222c8d0              352
...

The original bug report from Sebastien Roy was based on a panic resulting from a NULL pointer dereference:

> ::status
debugging crash dump vmcore.0 (64-bit) from delphix-sql
operating system: 5.11 dlpx-3.1.0.1_2013-01-12-00-25 (i86pc)
image uuid: 19813ef6-13c4-c63c-9585-f6d3f90b5041
panic message: 
BAD TRAP: type=e (#pf Page fault) rp=ffffff00f4f1b8f0 addr=40 occurred in
module "unix" due to a NULL pointer dereference
dump content: kernel pages only
> $C
ffffff00f4f1b9f0 kstat_runq_exit+0x19(0)
ffffff00f4f1ba40 stmf_lu_xfer_done+0xbf(ffffff250713f800, 1, 10000, 12cc289)
ffffff00f4f1bac0 sbd_data_read+0x137(ffffff2211fdf2d8, ffffff250713f800,
17d2b0000, 10000, ffffff272e9b1000)
ffffff00f4f1bb30 sbd_handle_read+0x460(ffffff250713f800, 0)
ffffff00f4f1bb90 sbd_new_task+0x92f(ffffff250713f800, 0)
ffffff00f4f1bc20 stmf_worker_task+0x3c8(ffffff21ee8000a0)
ffffff00f4f1bc30 thread_start+8()

We pass NULL to kstat_runq_exit() in stmf_lu_xfer_done():

void
stmf_lu_xfer_done(scsi_task_t *task, boolean_t read, uint64_t xfer_bytes,
    hrtime_t elapsed_time)
{
        stmf_i_scsi_task_t      *itask = task->task_stmf_private;
        stmf_itl_data_t         *itl = itask->itask_itl_datap;
        stmf_i_lu_t     *ilu = (stmf_i_lu_t *)task->task_lu->lu_stmf_private;
        kstat_io_t              *kip;

...
        kip = KSTAT_IO_PTR(itl->itl_kstat_lu_xfer);
        mutex_enter(ilu->ilu_kstat_io->ks_lock);
        kstat_runq_exit(kip);     <---- BOOM

Sure enough, itl->itl_kstat_lu_xfer points at garbage:

> ffffff250713f800::print scsi_task_t task_stmf_private | ::print stmf_i_scsi_task_t itask_itl_datap
itask_itl_datap = 0xffffff230c3b24c0
> 0xffffff230c3b24c0::print stmf_itl_data_t itl_kstat_lu_xfer
itl_kstat_lu_xfer = 0xffffff21fae61270
> 0xffffff21fae61270::print kstat_t
{
    ks_crtime = 0x300000000383065
    ks_next = 0x6f69
    ks_kid = 0
    ks_module = [ '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0',
'\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\
0', '\\0', '\\0', '0', '\\023', '\\346', '\\372', '!', '\\377', '\\377', '\\377',
'\\001', '\\0', '\\0' ]
    ks_resv = 0
    ks_instance = 0
    ks_name = [ "P" ]
    ks_type = 0
    ks_class = [ '@', 'F', '\\210', '\\373', '\\377', '\\377', '\\377', '\\377',
'\\310', '\\376', '\\375', '\\021', '\\"', '\\377', '
\\377', '\\377', '`', '\\001', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0', '\\0',
'\\0', '\\0', '\\0', '\\0', '\\0' ]
    ks_flags = 0
    ks_data = 0
    ks_ndata = 0
    ks_data_size = 0
    ks_snaptime = 0xffffff21fae611e5
    ks_update = 0
    ks_private = 0
    ks_snapshot = 0xffffff21fa8c10e9
    ks_lock = 0xffffffff
}

We need to find out what itl_kstat_lu_xfer points to (has it been freed and
reallocated, or is something scribbling over this memory?).

#1

Updated by Christopher Siden over 7 years ago

  • Status changed from In Progress to Closed
commit 09409df
Author: Jeff Biseda <jeff.biseda@delphix.com>
Date:   Sun Jul 7 19:18:37 2013

    3862 stmf + kstat = kernel panic
    3863 stmf_itl_task_start() must check for ilu->ilu_kstat_io is non-null
    3864 memory leak in the iSCSI code
    Reviewed by: Adam Leventhal <ahl@delphix.com>
    Reviewed by: Jeremy Jones <jeremy@delphix.com>
    Reviewed by: Sebastien Roy <sebastien.roy@delphix.com>
    Reviewed by: Dan McDonald <danmcd@nexenta.com>
    Reviewed by: Garrett D'Amore <garrett@damore.org>
    Reviewed by: Richard Elling <richard.elling@gmail.com>
    Approved by: Gordon Ross <gwr@nexenta.com>

Also available in: Atom PDF