Race in sysfs while fast unloading/loading drivers is causing system to crash

Diagnostic Steps

• Vmocre analysis is as follows :

 #4 [ffff886fd1f359f0] __bad_area_nosemaphore at ffffffff81046ea5
 #5 [ffff886fd1f35a40] bad_area_nosemaphore at ffffffff81046f73
 #6 [ffff886fd1f35a50] __do_page_fault at ffffffff810476d1
 #7 [ffff886fd1f35b70] do_page_fault at ffffffff815144be
 #8 [ffff886fd1f35ba0] page_fault at ffffffff81511875
    [exception RIP: strcmp+11]
    RIP: ffffffff8127eb2b  RSP: ffff886fd1f35c58  RFLAGS: 00010286
    RAX: 0000000000000064  RBX: ffff881062880490  RCX: ffff888fe99dab50
    RDX: 0000000000000065  RSI: ffffffffa034b17a  RDI: ffff88afe9e8c740
    RBP: ffff886fd1f35c58   R8: 0000000000000001   R9: 0000000000000240
    R10: 000000000000003b  R11: 0000000000002000  R12: ffff88afe9e8c740
    R13: ffff88afe885f490  R14: ffff886fd1f35cf8  R15: 00000000fffffffe
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #9 [ffff886fd1f35c60] sysfs_find_dirent at ffffffff811fa818
#10 [ffff886fd1f35c80] __sysfs_add_one at ffffffff811fba3b
#11 [ffff886fd1f35cb0] sysfs_add_one at ffffffff811fbafc
#12 [ffff886fd1f35cf0] sysfs_do_create_link at ffffffff811fc01b
#13 [ffff886fd1f35d50] sysfs_create_link at ffffffff811fc093
#14 [ffff886fd1f35d60] driver_sysfs_add at ffffffff8135f312
#15 [ffff886fd1f35d90] driver_probe_device at ffffffff8135f492
#16 [ffff886fd1f35dc0] __driver_attach at ffffffff8135f75b
#17 [ffff886fd1f35df0] bus_for_each_dev at ffffffff8135ea64
#18 [ffff886fd1f35e30] driver_attach at ffffffff8135f24e
#19 [ffff886fd1f35e40] bus_add_driver at ffffffff8135e298
#20 [ffff886fd1f35e80] driver_register at ffffffff8135faa6
#21 [ffff886fd1f35ec0] __pci_register_driver at ffffffff8129aa16
#22 [ffff886fd1f35ef0] init_module at ffffffffa01c80c6 [nx_xport]
#23 [ffff886fd1f35f20] do_one_initcall at ffffffff8100204c
#24 [ffff886fd1f35f50] sys_init_module at ffffffff810b7611


crash> struct sysfs_addrm_cxt ffff886fd1f35cf8
struct sysfs_addrm_cxt {
  parent_sd = 0xffff888fe99dab50,  <<------- (1)
  parent_inode = 0xffff88106990f048, 
  removed = 0x0, 
  cnt = 0
}


struct sysfs_dirent {
  s_count = {
    counter = 0x1f  <<---------- No. of references 
  }, 
  s_active = {
    counter = 0x0 <<-------- Non -ve.
  }, 
  s_parent = 0xffff888fe99cbf40, 
  s_name = 0xffff886fe9566380 "0000:04:00.0", 
  inode_node = {
    rb_parent_color = 0xffff884fe958c539, 
    rb_right = 0x0, 
    rb_left = 0x0
  }, 
  name_node = {
    rb_parent_color = 0xffff884fe958c551, 
    rb_right = 0x0, 
    rb_left = 0x0
  }, 
  u = {
    completion = 0x0, 
    removed_list = 0x0
  }, 
  {

crash> rd ffff88afe9e8c740
ffff88afe9e8c740:  ff00726576697264                    driver

crash> 
crash> px ((struct sysfs_addrm_cxt *)0xffff886fd1f35cf8)->parent_sd->s_dir.name_tree.rb_node
$7 = (struct rb_node *) 0xffff888fe99daca0

• So if reading through the tree one can see

crash>  tree -t rbtree -s sysfs_dirent.s_name -o sysfs_dirent.name_node -N 0xffff888fe99daca0
ffff888fe99dac70
  s_name = 0xffffffff817cbb72 "msi_bus"
ffff88afe958bd00
  s_name = 0xffffffff8180ea45 "irq"
ffff882fe9580490
  s_name = 0xffffffff817e0975 "device"
ffff888fe99dabe0
  s_name = 0xffffffff817dd299 "class"
ffff886fe956a5b0
  s_name = 0xffffffff817cbb5d "broken_parity_status"
ffff886fe959ac70
  s_name = 0xffffffff817d7f02 "config"
ffff884fe958c400
  s_name = 0xffffffff8179f795 "enable"
ffff881062880490
tree: invalid kernel virtual address: ffffffffa034b17a  type: "gdb_readmem_callback" <<------------- (2)

Which probably 

crash> dis -lr strcmp+0xb
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/lib/string.c: 248
0xffffffff8127eb20 <strcmp>:    push   %rbp
0xffffffff8127eb21 <strcmp+0x1>:        mov    %rsp,%rbp
0xffffffff8127eb24 <strcmp+0x4>:        nopl   0x0(%rax)
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/lib/string.c: 252
0xffffffff8127eb28 <strcmp+0x8>:        movzbl (%rdi),%eax
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/lib/string.c: 253
0xffffffff8127eb2b <strcmp+0xb>:        movzbl (%rsi),%edx <<----------

 RSI: ffffffffa034b17a <<--------- (2)

From (2) Looks created the issue.

tree: invalid kernel virtual address: ffffffffa034b17a  type: "gdb_readmem_callback"
  s_name = 0xffffffffa034b17a <Address 0xffffffffa034b17a out of bounds>
ffff886fe956a490
  s_name = 0xffff884fe957b600 "firmware_node"
ffff88cfe99d72e0
  s_name = 0xffffffff817cbb31 "local_cpus"
ffff88efe9a92880
  s_name = 0xffffffff817cbb3c "local_cpulist"
ffff881068af5520
  s_name = 0xffffffff817cbb4a "modalias"
ffff88efe9a927f0
  s_name = 0xffffffff817de801 "resource"
ffff88afe958bd90
  s_name = 0xffffffff817caab9 "remove"
ffff882fe9580520
  s_name = 0xffffffff817cbb53 "numa_node"
ffff888fe99dad00
  s_name = 0xffff886fe9d0db60 "power"
ffff88cfe99d7370
  s_name = 0xffffffff817cbb08 "rescan"
ffff8810672cc520
  s_name = 0xffffffff817da87c "reset"
ffff88cfe99d7250
  s_name = 0xffffffff817caac8 "uevent"
ffff886fe956a520
  s_name = 0xffffffff817cbb20 "subsystem_device"
ffff88efe9ac25b0
  s_name = 0xffff88cfe88e7800 "resource4"
ffff88afe95f12e0
  s_name = 0xffff888fe9a13480 "resource0"
ffff884fe958c490
  s_name = 0xffff882fe957f420 "subsystem"
ffff884fe958c370
  s_name = 0xffffffff817cbb0f "subsystem_vendor"
ffff881068af55b0
  s_name = 0xffffffff817e2938 "vendor"


struct sysfs_dirent {
  s_count = {
    counter = 3
  }, 
  s_active = {
    counter = 0
  }, 
  s_parent = 0xffff888fe99dab50,  <<----------- Parent looks fine to me From (1) and rest seems corrupted to me.

  s_name = 0xffffffffa034b17a tree: invalid kernel virtual address: ffffffffa034b17a  type: "gdb_readmem_callback"
tree: invalid kernel virtual address: ffffffffa034b17a  type: "gdb_readmem_callback"
<Address 0xffffffffa034b17a out of bounds>, 
  inode_node = {
    rb_parent_color = 18446612202764682553, 
    rb_right = 0x0, 
    rb_left = 0x0
  }, 
  name_node = {
    rb_parent_color = 18446612475531543601, 
    rb_right = 0x0, 
    rb_left = 0x0
  }, 
  u = {
    completion = 0x0, 
    removed_list = 0x0
  }, 
  {
    s_dir = {
      kobj = 0xffffffffa034bd20, 
      subdirs = 0, 
      inode_tree = {
        rb_node = 0x0
      }, 
      name_tree = {
        rb_node = 0x0
      }
    }, 
    s_symlink = {
      target_sd = 0xffffffffa034bd20
    }, 
    s_attr = {
      attr = 0xffffffffa034bd20, 
      open = 0x0
    }, 
    s_bin_attr = {
      bin_attr = 0xffffffffa034bd20, 
      buffers = {
        first = 0x0
      }
    }

• Looking at the logs, it seems the problem happened while installing the the driver

NX PCI driver: Major #246
BUG: unable to handle kernel paging request at ffffffffa034b17a
IP: [<ffffffff8127eb2b>] strcmp+0xb/0x30
PGD 1a87067 PUD 1a8b063 PMD afe8736067 PTE 0


struct module {
  state = MODULE_STATE_COMING, 
  list = {
    next = 0xffffffffa05416a8 <__this_module+8>, 
    prev = 0xffffffff81aa6c10 <modules>
  }, 
  name = "nx_xport\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", 
  mkobj = {
    kobj = {
      name = 0xffff88afe8bb2920 "nx_xport", 
      entry = {
        next = 0xffff882fe94b2cc0, 
        prev = 0xffffffffa05416f8 <__this_module+88>
      }, 
      parent = 0xffff882fe94b2cd8, 
      kset = 0xffff882fe94b2cc0, 
      ktype = 0xffffffff81aa3a20 <module_ktype>, 
      sd = 0xffff88afe8ae4f40, 
      kref = {
        refcount = {
          counter = 3
        }
      }, 
      state_initialized = 1, 
      state_in_sysfs = 1, 
      state_add_uevent_sent = 1, 
      state_remove_uevent_sent = 0, 
      uevent_suppress = 0
    }, 
    mod = 0xffffffffa0615d80, 
    drivers_dir = 0x0, 
    mp = 0x0
  }, 
  modinfo_attrs = 0xffff88afe77dec00, 
  version = 0xffff88afe8bb2fa0 "4.0.593", 
  srcversion = 0xffff88afe8bb2780 "38FBBBED8DE4AA5A134AC9F", 
  holders_dir = 0xffff88afe9e038c0, 

• Moving further, last analyze one can see following processes seem to be in D state

crash> ps -l | grep UN
[15560255219756] [UN]  PID: 43813  TASK: ffff888fda0e3540  CPU: 24  COMMAND: "ifdown-eth"
[15560253410836] [UN]  PID: 43791  TASK: ffff886fcaafcaa0  CPU: 48  COMMAND: "ifdown-eth"
[15560253246721] [UN]  PID: 43797  TASK: ffff88afdf708040  CPU: 56  COMMAND: "ifdown-eth"
[15560049632356] [UN]  PID: 43841  TASK: ffff888fda0e2080  CPU: 33  COMMAND: "ifdown-eth" <<----------- Most oldest one 


crash> bt 43841
PID: 43841  TASK: ffff888fda0e2080  CPU: 33  COMMAND: "ifdown-eth"
 #0 [ffff888fe77d3aa8] schedule at ffffffff8150ea32
 #1 [ffff888fe77d3b70] __mutex_lock_slowpath at ffffffff815100de
 #2 [ffff888fe77d3be0] mutex_lock at ffffffff8150ff7b
 #3 [ffff888fe77d3c00] sysfs_lookup at ffffffff811fb96a
 #4 [ffff888fe77d3c40] do_lookup at ffffffff81190915
 #5 [ffff888fe77d3ca0] __link_path_walk at ffffffff81190bad
 #6 [ffff888fe77d3d60] path_walk at ffffffff81191c5a
 #7 [ffff888fe77d3da0] do_path_lookup at ffffffff81191e2b
 #8 [ffff888fe77d3dd0] user_path_at at ffffffff81192ab7
 #9 [ffff888fe77d3ea0] vfs_fstatat at ffffffff81186e6c
#10 [ffff888fe77d3ee0] vfs_stat at ffffffff81186fdb
#11 [ffff888fe77d3ef0] sys_newstat at ffffffff81187004
#12 [ffff888fe77d3f80] system_call_fastpath at ffffffff8100b072
    RIP: 0000003d376daf25  RSP: 00007fff7b0ab4f0  RFLAGS: 00010206
    RAX: 0000000000000004  RBX: ffffffff8100b072  RCX: 0000000000c532b0
    RDX: 00007fff7b0ab1c0  RSI: 00007fff7b0ab1c0  RDI: 0000000000c00730
    RBP: 0000000000c60020   R8: 0000000000000001   R9: 0000000000000001
    R10: 0000000000000008  R11: 0000000000000246  R12: 0000000000000001
    R13: 00007fff7b0ab1c0  R14: 0000000000000001  R15: 00000000006dece0
    ORIG_RAX: 0000000000000004  CS: 0033  SS: 002b


crash> dis -lr ffffffff811fb96a
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 761
0xffffffff811fb930 <sysfs_lookup>:      push   %rbp
0xffffffff811fb931 <sysfs_lookup+1>:    mov    %rsp,%rbp
0xffffffff811fb934 <sysfs_lookup+4>:    sub    $0x30,%rsp
0xffffffff811fb938 <sysfs_lookup+8>:    mov    %rbx,-0x18(%rbp)
0xffffffff811fb93c <sysfs_lookup+12>:   mov    %r12,-0x10(%rbp)
0xffffffff811fb940 <sysfs_lookup+16>:   mov    %r13,-0x8(%rbp)
0xffffffff811fb944 <sysfs_lookup+20>:   nopl   0x0(%rax,%rax,1)
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 763
0xffffffff811fb949 <sysfs_lookup+25>:   mov    0x28(%rsi),%rax
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 767
0xffffffff811fb94d <sysfs_lookup+29>:   mov    $0xffffffff81adc080,%rdi
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 772
0xffffffff811fb954 <sysfs_lookup+36>:   mov    $0xfffffffffffffffe,%r13
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 761
0xffffffff811fb95b <sysfs_lookup+43>:   mov    %rsi,%rbx
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 763
0xffffffff811fb95e <sysfs_lookup+46>:   mov    0x98(%rax),%r12
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 767
0xffffffff811fb965 <sysfs_lookup+53>:   callq  0xffffffff8150ff50 <mutex_lock>
/usr/src/debug/kernel-2.6.32-358.41.1.el6/linux-2.6.32-358.41.1.el6.x86_64/fs/sysfs/dir.c: 769
0xffffffff811fb96a <sysfs_lookup+58>:   mov    0x38(%rbx),%rsi


static struct dentry * sysfs_lookup(struct inode *dir, struct dentry *dentry,
                                struct nameidata *nd)
{
        struct dentry *ret = NULL;
        struct sysfs_dirent *parent_sd = dentry->d_parent->d_fsdata;
        struct sysfs_dirent *sd;
        struct inode *inode;

        mutex_lock(&sysfs_mutex); <<---------------

        sd = sysfs_find_dirent(parent_sd, dentry->d_name.name);


crash> px sysfs_mutex
sysfs_mutex = $14 = {
  count = {
    counter = 0xffffffff
  }, 
  wait_lock = {
    raw_lock = {
      slock = 0x42b142b1
    }
  }, 
  wait_list = {
    next = 0xffff888fe77d3b88, 
    prev = 0xffff888fe77d3b88
  }, 
  owner = 0xffff886fd1f34000 <<------- Looks owner of the lock 
}

crash> kmem 0xffff886fd1f34000
    PID: 43867
COMMAND: "insmod"
   TASK: ffff886fe8d63540  [THREAD_INFO: ffff886fd1f34000]
    CPU: 40
  STATE: TASK_RUNNING (PANIC)

      PAGE         PHYSICAL      MAPPING       INDEX CNT FLAGS
ffffea01875ed360 6fd1f34000                0 ffff882fe784f400  1 1c0000000000000
crash> 

• Looks like this was acquired by insmod process only
• The above process is waiting for 679 mili seconds for the mutex

crash> eval (15560729425844 - 15560049632356)
hexadecimal: 2884d350  
    decimal: 679793488  
      octal: 5041151520
     binary: 0000000000000000000000000000000000101000100001001101001101010000
crash> eval (679793488/1000000)
hexadecimal: 2a7  
    decimal: 679 mili seconds.

• Looks like the insmod process is over CPU-40 for around 15 mili seconds

crash> eval (15560049675247 - 15560034495911)
hexadecimal: e79e48  
    decimal: 15179336  
      octal: 71717110
     binary: 0000000000000000000000000000000000000000111001111001111001001000
crash> eval (15179336 /1000000)
hexadecimal: f  
    decimal: 15 mili seconds. 

• Looks like the mutex was acquired in following function for insmod

void sysfs_addrm_start(struct sysfs_addrm_cxt *acxt,
                       struct sysfs_dirent *parent_sd)
{
        struct inode *inode;

        memset(acxt, 0, sizeof(*acxt));
        acxt->parent_sd = parent_sd;

        /* Lookup parent inode.  inode initialization is protected by
         * sysfs_mutex, so inode existence can be determined by
         * looking up inode while holding sysfs_mutex.
         */
        mutex_lock(&sysfs_mutex); <<--------------

        inode = ilookup5(sysfs_sb, parent_sd->s_ino, sysfs_ilookup_test,