[LU-1165] ASSERTION(cfs_atomic_read(&key->lct_used) > 1)

• Status: Resolved
• Project: Lustre
• Type: Bug
• Priority: Minor
• Reporter: Christopher Morrone
• Assignee: Hongchao Zhang
• Resolution: Fixed

Environment

Lustre 2.1.0-23chaos

• Severity: 3

Description

When a sysadmin attempted to unmount an OST which was hosted by the failover OSS (intending to restart is on the primary OSS), he hit the following assertion:

2012-02-29 12:02:09 Lustre: lsc-OST00b7: shutting down for failover; client state will be preserved.
2012-02-29 12:02:09 LustreError: 20218:0:(lu_object.c:1251:key_fini()) ASSERTION(cfs_atomic_read(&key->lct_used) > 1) failed
2012-02-29 12:02:09 LustreError: 20218:0:(lu_object.c:1251:key_fini()) LBUG
2012-02-29 12:02:09 Pid: 20218, comm: umount
2012-02-29 12:02:09 
2012-02-29 12:02:09 Call Trace:
2012-02-29 12:02:09  [<ffffffffa039b895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
2012-02-29 12:02:09  [<ffffffffa039bdc7>] lbug_with_loc+0x47/0xb0 [libcfs]
2012-02-29 12:02:09  [<ffffffffa03a542d>] libcfs_assertion_failed+0x2d/0x30 [libcfs]
2012-02-29 12:02:09  [<ffffffffa04f6ee8>] key_fini+0xf8/0x170 [obdclass]
2012-02-29 12:02:09  [<ffffffffa04f714b>] lu_context_key_quiesce+0x5b/0x90 [obdclass]
2012-02-29 12:02:09  [<ffffffffa04f71d9>] lu_context_key_quiesce_many+0x59/0x80 [obdclass]
2012-02-29 12:02:09  [<ffffffffa09e8d3f>] vvp_type_stop+0x2f/0x40 [lustre]
2012-02-29 12:02:09  [<ffffffffa04f5ef9>] lu_types_stop+0x49/0x60 [obdclass]
2012-02-29 12:02:09  [<ffffffffa04ef8bd>] lustre_common_put_super+0x49d/0x960 [obdclass]
2012-02-29 12:02:09  [<ffffffffa04cdbc6>] ? class_name2dev+0x56/0xd0 [obdclass]
2012-02-29 12:02:09  [<ffffffffa04eff4f>] server_put_super+0x1cf/0xc20 [obdclass]
2012-02-29 12:02:09  [<ffffffff811928f6>] ? invalidate_inodes+0xf6/0x190
2012-02-29 12:02:09  [<ffffffff81179c2b>] generic_shutdown_super+0x5b/0xe0
2012-02-29 12:02:09  [<ffffffff81179d16>] kill_anon_super+0x16/0x60
2012-02-29 12:02:09  [<ffffffffa04ea146>] lustre_kill_super+0x36/0x60 [obdclass]
2012-02-29 12:02:09  [<ffffffff8117aca0>] deactivate_super+0x70/0x90
2012-02-29 12:02:09  [<ffffffff81196c4f>] mntput_no_expire+0xbf/0x110
2012-02-29 12:02:09  [<ffffffff811976eb>] sys_umount+0x7b/0x3a0
2012-02-29 12:02:09  [<ffffffff810818d1>] ? sigprocmask+0x71/0x110
2012-02-29 12:02:09  [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b
2012-02-29 12:02:09

Comments

[Peter Jones]

Hongchao

Can you please look into this one?

Thanks

Peter

[Hongchao Zhang]

Did the node ever mount Lustre client? the module related to this assertion is llite.
normally the lu_context_key.lct_used is set with 1 when its module is loaded and the key is registered. it's suspected that
the value allocated in lu_context is not from the lu_context_key! I'll create a debug patch to track it.

[Hongchao Zhang]

the debug patch is tracked at http://review.whamcloud.com/#change,2264

Hi Chris,
Can this issue be reproduced? if so, it's recommended to use "--enable-lu-ref=yes" to track the values related to
the lu_context_key, which will be much help for fixing this issue. thanks!

[Christopher Morrone]

I am not aware of a reproducer.

[Jay Lan (Inactive)]

NASA Ames hit this on 'umount' command when we tried to take down all servers for an upgrade. One OSS crashed. Not critical though since we are taking them down anyway.

[Gregoire Pichon]

I have reproduced the issue described in this ticket.
Lustre version is 2.4.2 with kernel 2.6.32-431.1.2.

Reproducer is quite simple: unload "lustre" kernel module on the OSS while IOs are in progress on files striped on its OSTs.

I first hit the same assertion ats in ticket's title: ASSERTION(cfs_atomic_read(&key->lct_used) > 1).

Then, to help debuging, I have rebuilt lustre with the --enable-lu_ref configure option. Performing the same reproducer test I hit an assertion in the same routine key_fini().

Here are some information extracted from the crash dump.

crash> dmesg
...
LustreError: 32024:0:(lu_ref.c:112:lu_ref_print()) lu_ref: ffffffffa1873770 1 0 lu_context_key_register:1329
LustreError: 31963:0:(lu_object.c:1346:key_fini()) ASSERTION( key != ((void *)0) ) failed: 
LustreError: 31963:0:(lu_object.c:1346:key_fini()) LBUG
Pid: 31963, comm: ll_ost_io00_003

Call Trace:
 [<ffffffffa0e1a895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
 [<ffffffffa0e1ae97>] lbug_with_loc+0x47/0xb0 [libcfs]
 [<ffffffffa0f3f21d>] key_fini+0x17d/0x180 [obdclass]
 [<ffffffffa0f3f24f>] keys_fini+0x2f/0x130 [obdclass]
 [<ffffffffa0f3f380>] lu_context_fini+0x30/0xc0 [obdclass]
 [<ffffffffa10dfa66>] ptlrpc_server_handle_request+0x426/0xc60 [ptlrpc]
 [<ffffffffa0e1b5de>] ? cfs_timer_arm+0xe/0x10 [libcfs]
 [<ffffffffa0e2cd9f>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
 [<ffffffffa10d6d39>] ? ptlrpc_wait_event+0xa9/0x290 [ptlrpc]
 [<ffffffff81058bd3>] ? __wake_up+0x53/0x70
 [<ffffffffa10e0d6e>] ptlrpc_main+0xace/0x1700 [ptlrpc]
 [<ffffffffa10e02a0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
 [<ffffffff8100c20a>] child_rip+0xa/0x20
 [<ffffffffa10e02a0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
 [<ffffffffa10e02a0>] ? ptlrpc_main+0x0/0x1700 [ptlrpc]
 [<ffffffff8100c200>] ? child_rip+0x0/0x20
...

crash> rd -64 lu_keys 40
ffffffffa0fd0c60:  ffffffffa0fa68e0 ffffffffa0fa9020   .h...... .......
ffffffffa0fd0c70:  ffffffffa0fa77c0 ffffffffa0faf1c0   .w..............
ffffffffa0fd0c80:  ffffffffa0f93f20 ffffffffa1185600    ?.......V......
ffffffffa0fd0c90:  ffffffffa06b4760 ffffffffa06c8140   `Gk.....@.l.....
ffffffffa0fd0ca0:  ffffffffa12d1e40 ffffffffa12d9220   @.-..... .-.....
ffffffffa0fd0cb0:  ffffffffa12d4340 ffffffffa17075c0   @C-......up.....
ffffffffa0fd0cc0:  ffffffffa1707640 ffffffffa17919c0   @vp.......y.....
ffffffffa0fd0cd0:  ffffffffa1791a40 0000000000000000   @.y.............
ffffffffa0fd0ce0:  0000000000000000 ffffffffa1874a40   ........@J......
ffffffffa0fd0cf0:  ffffffffa1874ac0 ffffffffa1522d80   .J.......-R.....
ffffffffa0fd0d00:  ffffffffa1522d00 ffffffffa15802a0   .-R.......X.....
ffffffffa0fd0d10:  ffffffffa1611720 ffffffffa1666d80    .a......mf.....
ffffffffa0fd0d20:  ffffffffa1666e00 0000000000000000   .nf.............
ffffffffa0fd0d30:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d40:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d50:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d60:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d70:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d80:  0000000000000000 0000000000000000   ................
ffffffffa0fd0d90:  0000000000000000 0000000000000000   ................

crash> struct lu_context_key.lct_reference -x
struct lu_context_key {
  [0x30] struct lu_ref lct_reference;
}

crash> print &ccc_session_key
$5 = (struct lu_context_key *) 0xffffffffa1873740

crash> struct lu_context_key -x ccc_session_key
struct lu_context_key {
  lct_tags = 0x40000010, 
  lct_init = 0xffffffffa1840dd0 <ccc_session_key_init>, 
  lct_fini = 0xffffffffa183def0 <ccc_session_key_fini>, 
  lct_exit = 0, 
  lct_index = 0x10, 
  lct_used = {
    counter = 0x2
  }, 
  lct_owner = 0xffffffffa18763a0, 
  lct_reference = {
    lf_guard = {
      raw_lock = {
        slock = 0x51d051d
      }
    }, 
    lf_list = {
      next = 0xffff880848ad56a8, 
      prev = 0xffff880848ad56a8
    }, 
    lf_refs = 0x1, 
    lf_failed = 0x0, 
    lf_flags = 0x0, 
    lf_line = 0x531, 
    lf_func = 0xffffffffa0f73570 "lu_context_key_register", 
    lf_linkage = {
      next = 0xffffffffa1791a98, 
      prev = 0xffffffffa1874a98
    }
  }
}

crash> struct lu_ref 0xffff880848ad56a0 -x
struct lu_ref {
  lf_guard = {
    raw_lock = {
      slock = 0xa1873770
    }
  }, 
  lf_list = {
    next = 0xffffffffa1873778, 
    prev = 0xffffffffa1873778
  }, 
  lf_refs = 0x4e51, 
  lf_failed = 0xa0f8, 
  lf_flags = 0xffff, 
  lf_line = 0xffff, 
  lf_func = 0xffff8808347fcf40 "\020", 
  lf_linkage = {
    next = 0xffffffffa1185630, 
    prev = 0xffff880848ad51a8
  }
}

It seems to me deregistration of ccc_session_key is done while values are still in use (lct_used=2).
Will upload the crash dump.

Note that the issue is also present in 2.5.0, but does not seem to be present in 2.5.51.

[Gregoire Pichon]

I have uploaded the following file on the ftp server in directory /uploads/LU-1165

$ md5sum *
80be0049ba939cb87313ad58469bea16  crash
f164ef5ee4af3a8c3fe4f021ae07f721  lustre-debuginfo-2.4.2-2.6.32_431.1.2.el6.Bull.44.x86_64_gb6158f6.x86_64.rpm
ef54859f62da72a46b9a485fa7284fae  vmcore
45df48f0533bdd53bf1665bf00a8dccf  vmlinux

[Gregoire Pichon]

The crash shows that the ccc_session_key deregister is in progress.

crash> ps | grep modprobe
> 32024   3771   9  ffff880f6ae39500  RU   0.0    4156    612  modprobe
crash> bt 32024
PID: 32024  TASK: ffff880f6ae39500  CPU: 9   COMMAND: "modprobe"
 #0 [ffff88089c447e90] crash_nmi_callback at ffffffff81030096
 #1 [ffff88089c447ea0] notifier_call_chain at ffffffff8152e3b5
 #2 [ffff88089c447ee0] atomic_notifier_call_chain at ffffffff8152e41a
 #3 [ffff88089c447ef0] notify_die at ffffffff810a052e
 #4 [ffff88089c447f20] do_nmi at ffffffff8152c07b
 #5 [ffff88089c447f50] nmi at ffffffff8152b940
    [exception RIP: io_serial_in+22]
    RIP: ffffffff81364566  RSP: ffff880f6b4df938  RFLAGS: 00000002
    RAX: 0000000050176000  RBX: ffffffff820073f8  RCX: 0000000000000000
    RDX: 00000000000002fd  RSI: 0000000000000005  RDI: ffffffff820073f8
    RBP: ffff880f6b4df938   R8: 0000000000012d1f   R9: 00000000fffffffc
    R10: 0000000000000002  R11: 0000000000000000  R12: 0000000000002708
    R13: 0000000000000020  R14: 0000000000000000  R15: ffffffff81364c10
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
 #6 [ffff880f6b4df938] io_serial_in at ffffffff81364566
 #7 [ffff880f6b4df940] wait_for_xmitr at ffffffff81364b73
 #8 [ffff880f6b4df970] serial8250_console_putchar at ffffffff81364c36
 #9 [ffff880f6b4df990] uart_console_write at ffffffff813605ce
#10 [ffff880f6b4df9d0] serial8250_console_write at ffffffff81364f9d
#11 [ffff880f6b4dfa20] __call_console_drivers at ffffffff81070f55
#12 [ffff880f6b4dfa50] _call_console_drivers at ffffffff81070fba
#13 [ffff880f6b4dfa70] release_console_sem at ffffffff81071608
#14 [ffff880f6b4dfab0] vprintk at ffffffff81071d08
#15 [ffff880f6b4dfb50] printk at ffffffff815281ac
#16 [ffff880f6b4dfbb0] cfs_print_to_console at ffffffffa0e1a114 [libcfs]
#17 [ffff880f6b4dfbe0] libcfs_debug_vmsg2 at ffffffffa0e2ace6 [libcfs]
#18 [ffff880f6b4dfd50] libcfs_debug_msg at ffffffffa0e2b2d1 [libcfs]
#19 [ffff880f6b4dfdb0] lu_ref_print at ffffffffa0f5d0ee [obdclass]
#20 [ffff880f6b4dfde0] lu_ref_fini at ffffffffa0f5d4f2 [obdclass]
#21 [ffff880f6b4dfe00] lu_context_key_degister at ffffffffa0f3f5b3 [obdclass]
#22 [ffff880f6b4dfe20] lu_context_key_degister_many at ffffffffa0f3f719 [obdclass]
#23 [ffff880f6b4dfe80] vvp_type_fini at ffffffffa184266f [lustre]
#24 [ffff880f6b4dfe90] lu_device_type_fini at ffffffffa0f3dfc3 [obdclass]
#25 [ffff880f6b4dfea0] ccc_global_fini at ffffffffa183e82c [lustre]
#26 [ffff880f6b4dfec0] vvp_global_fini at ffffffffa18434e5 [lustre]
#27 [ffff880f6b4dfed0] exit_lustre_lite at ffffffffa1848cc9 [lustre]
#28 [ffff880f6b4dfee0] sys_delete_module at ffffffff810b9524
#29 [ffff880f6b4dff80] system_call_fastpath at ffffffff8100b072
    RIP: 000000310fee8e17  RSP: 00007fff73195230  RFLAGS: 00010206
    RAX: 00000000000000b0  RBX: ffffffff8100b072  RCX: 0000000000000008
    RDX: 00007fff7319538f  RSI: 0000000000000080  RDI: 00000000022cb2b0
    RBP: 00000000022cb2b0   R8: 000000311018d580   R9: 000000310ff41740
    R10: 0000000000000000  R11: 0000000000000246  R12: 0000000000000000
    R13: 00000000022cade0  R14: 00007fff73195610  R15: 00000000022cade0
    ORIG_RAX: 00000000000000b0  CS: 0033  SS: 002b

As far as I understand, the ll_ost_io threads have a value in their lu_context for the ccc_session_key lu_key because of the tag LCT_SESSION. Unfortunately nothing prevents deregistering ccc_session_key while ll_ost_io threads are processing requests. So the system asserts either because ccc_session_key is still in use (key->lct_used > 1) when deregistering, or because ll_ost_io thread's lu_context is calling key_fini() on the just'removed ccc_session_key.

It seems to me there is a synchronisation mechanism missing between ll_ost_io threads and ccc_session_key destruction. But there is no reason to correlate these two lustre component, isn't it ? Maybe having two distinct LCT_SESSION tags one for server side, one for client side would be better.

[Hongchao Zhang]

the patch in LU-3806 adds LCT_SERVER_SESSION to separate from LCT_SESSION to fix the conflict if the server and client are at the same node.

[Gregoire Pichon]

Thanks for pointing the patch. I will give it a try.

Note that during my tests, the failing node was only running OSTs (no client).

[Gregoire Pichon]

I backported the patch into b2_4: http://review.whamcloud.com/9010
Running the same tests than above with the patch installed prevented the OSS node to crash.

[Peter Jones]

duplicate of LU-3806