[LU-3410] mgc_copy_llog()) Failed to copy remote log routed1-OST00b3 (-2) ecountered during bring up of a 2.4 file system

• Status: Closed
• Project: Lustre
• Affects Version/s: Lustre 2.4.0
• Type: Bug
• Priority: Major
• Reporter: James A Simmons
• Assignee: Mikhail Pershin
• Resolution: Duplicate

Environment

RHEL6.4 running 2.4.0-RC2

• Severity: 3

Description

At our first attempt to mount the file system we experienced the following assertion on about 40 OSS. Th eassertion we hit is as follows:

May 28 10:36:43 widow-oss11c4 kernel: [ 2743.137026] LDISKFS-fs (dm-12): mounted filesystem with ordered data mode. quota=on. Opts:
May 28 10:37:07 widow-oss11c4 kernel: [ 2767.330069] LustreError: 24348:0:(ofd_obd.c:1535:ofd_iocontrol()) routed1-OST0113: aborting recovery
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.099708] LustreError: 24283:0:(ofd_obd.c:1535:ofd_iocontrol()) routed1-OST00b3: aborting recovery
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.145570] LustreError: 24562:0:(mgc_request.c:1693:mgc_copy_llog()) Failed to copy remote log routed1-OST00b3 (-2)
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.166762] LustreError: 13a-8: Failed to get MGS log routed1-OST00b3 and no local copy.
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.183045] LustreError: 24562:0:(lvfs_linux.c:175:pop_ctxt()) ASSERTION( cfs_fs_pwd(current->fs) == new_ctx->pwd ) failed: ffff8803bcea02c0 != ffff8803bcefcf00
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.211874] LustreError: 24562:0:(lvfs_linux.c:175:pop_ctxt()) LBUG
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.224479] Pid: 24562, comm: ll_cfg_requeue
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.233060]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.233061] Call Trace:
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.240987] [<ffffffffa045e895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.254989] [<ffffffffa045ee97>] lbug_with_loc+0x47/0xb0 [libcfs]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.267434] [<ffffffffa03cecb5>] pop_ctxt+0x295/0x2e0 [lvfs]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.278976] [<ffffffffa06d6225>] mgc_process_cfg_log+0x6a5/0x15c0 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.292448] [<ffffffffa06d9133>] mgc_process_log+0x463/0x1390 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.305221] [<ffffffff8150ed8a>] ? schedule_timeout+0x19a/0x2e0
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.317303] [<ffffffffa06d3a60>] ? mgc_blocking_ast+0x0/0x7e0 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.330171] [<ffffffffa071cb90>] ? ldlm_completion_ast+0x0/0x960 [ptlrpc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.343991] [<ffffffff8109705c>] ? remove_wait_queue+0x3c/0x50
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.355882] [<ffffffffa06daa13>] mgc_requeue_thread+0x1a3/0x750 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.368999] [<ffffffff81063310>] ? default_wake_function+0x0/0x20
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.381448] [<ffffffffa06da870>] ? mgc_requeue_thread+0x0/0x750 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.394565] [<ffffffff8100c0ca>] child_rip+0xa/0x20
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.404563] [<ffffffffa06da870>] ? mgc_requeue_thread+0x0/0x750 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.423777] [<ffffffffa06da870>] ? mgc_requeue_thread+0x0/0x750 [mgc]
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.442884] [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
May 28 10:37:28 widow-oss11c4 kernel: [ 2788.459196]

Issue Links

• is related to: LU-4783 start params llog automatically durin...

Comments

[Andreas Dilger]

James, did the same problem happen on a second restart, or did it work on the next try?

[Andreas Dilger]

James, what is the origin of this filesystem? Is this a newly formatted filesystem with 2.4.0 or is it upgraded from some previous version of Lustre?

[Andreas Dilger]

Mike rewrote the MGC llog backup code to use the OSD API recently in http://review.whamcloud.com/5049 (patch is ready to land, but missed "feature freeze" window), so any work in this area should take that into account. I'm not sure it will solve this problem, but it doesn't make sense to work on the old code when it is being replaced.

[Oleg Drokin]

This only happened once, second restart worked.
The filesystem was freshly formatted 2.4 system.

[Mikhail Pershin]

the mgs_fs_setup() may rewrite the obd_lvfs_ctxt with new values and there is no any protection that could prevent that between push/pop pair. That can be the reasonfor this bug. Note, that mgs_fs_setup() is called from obd_mount.c code to set new bottom fs and can be called multiple times with several OSTs on one node. Meanwhile this is old code and I am not sure why it happens now.

[Alexey Lyashkov]

Mike,

looks you are wrong (or it's second bug with same assert).
mgc_requeue_thread - don't have an cfs_daemonize_ctxt() at top of function so share a current->fs between several threads, as ldlm_elt, zombid, ldlm_poold (with vitaly patch with stale lock cancel) and some other.
in that case different thread may change a own current->fs but it's affected to whole threads with same fs.
Xyratex hit that bug in ldlm_elt thread (don't have an cfs_daemonize_ctxt() call also.

..
00002000:00040000:9.0:1375891841.290003:0:1448:0:(lvfs_linux.c:175:pop_ctxt()) ASSERTION( cfs_fs_pwd(current->fs) == new_ctx->pwd ) failed: ffff88076b4d68c0 != ffff88069df8fd80
..

crash> bt
PID: 1448   TASK: ffff880817656040  CPU: 9   COMMAND: "ldlm_elt"
 #0 [ffff880774e7dba8] machine_kexec at ffffffff810310db
 #1 [ffff880774e7dc08] crash_kexec at ffffffff810b6332
 #2 [ffff880774e7dcd8] panic at ffffffff814d684f
 #3 [ffff880774e7dd58] lbug_with_loc at ffffffffa0380ecb [libcfs]
 #4 [ffff880774e7dd78] pop_ctxt at ffffffffa0427b77 [lvfs]
 #5 [ffff880774e7ddc8] filter_client_del at ffffffffa0ed5637 [obdfilter]
 #6 [ffff880774e7de78] filter_disconnect at ffffffffa0ed7820 [obdfilter]
 #7 [ffff880774e7dea8] class_fail_export at ffffffffa0648365 [obdclass]
 #8 [ffff880774e7dec8] expired_lock_main at ffffffffa07b81b1 [ptlrpc]
 #9 [ffff880774e7df48] kernel_thread at ffffffff8100c1ca

but in task fs is correct value

crash> p *((struct task_struct *)0xffff880817656040)->fs
$119 = {
  users = 481, 
  lock = {
    raw_lock = {
      lock = 16777216
    }
  }, 
  umask = 0, 
  in_exec = 0, 
  root = {
    mnt = 0xffff880817b090c0, 
    dentry = 0xffff880818e4fa40
  }, 
  pwd = {
    mnt = 0xffff8808174b6180, 
    dentry = 0xffff88069df8fd80
  }
}

as you see - fs have a correct value and assert should be don't hit.
BUT users is large number which should be impossible for a thread with disk IO.
so it's race between modification for same fs struct.

additional bugs in that area
1) current->fs.pwd accessed without lock, but readlock should be held. need look carefully about bug impact.
2) cfs_daemonize_ctxt have lost a return code from unshare_fs_struct() call so we have failed with ENOMEM and none will know about it
3) none error code checks for cfs_daemonize_ctxt() calls, so function may failed with ENOMEM but none know about it and uses a shared FS after fail.

[Andreas Dilger]

Mike, I also see "13a-8: Failed to get MGS log routed1-OST00b3 and no local copy." in many test logs. This is a misleading error message and should probably be removed, or at least quieted in the common case when a new filesystem is first mounted.

[Emoly Liu]

I filed a new ticket LU-4783 to fix the misleading error message "LustreError: 13a-8: Failed to get MGS log params and no local copy.".

So, can we close this one ?

[Mikhail Pershin]

closing in favor of LU-4783