[LU-8990] Failback LBUG lod_device_free()) ASSERTION( atomic_read(&lu->ld_ref)

• Type: Bug
• Resolution: Fixed
• Priority: Critical
• Fix Version/s: Lustre 2.11.0, Lustre 2.10.4
• Affects Version/s: Lustre 2.10.0, Lustre 2.11.0, Lustre 2.10.2, Lustre 2.10.3
• Labels: soak
• Environment: Soak cluster lustre: 2.9.51_4_g39af202 - tip of master on 12/30
• Severity: 3
• Assignee: Lai Siyao
• Reporter: Cliff White (Inactive)

Description

System completed failover of lola-8 to lola-9 (MDS failover)
Attempting to tailback, trigger assertion.

<4>Lustre: Failing over soaked-MDT0000
<3>LustreError: 34433:0:(osp_precreate.c:912:osp_precreate_cleanup_orphans()) soaked-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -5
<3>LustreError: 34433:0:(osp_precreate.c:912:osp_precreate_cleanup_orphans()) Skipped 10 previous similar messages
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.126@o2ib100 (stopping)
<6>Lustre: Skipped 3 previous similar messages
<3>LustreError: 34664:0:(lod_qos.c:208:lod_statfs_and_check()) soaked-MDT0000-mdtlov: statfs: rc = -108
<3>LustreError: 34664:0:(lod_qos.c:208:lod_statfs_and_check()) Skipped 43 previous similar messages
<3>LustreError: 34700:0:(ldlm_resource.c:882:ldlm_resource_complain()) mdt-soaked-MDT0000_UUID: namespace resource [0x20002ac2a:0x1fbe:0x0].0xe8519c29 (ffff8803f859fec0) refcount nonzero (1) after lock cleanup; forcing cleanup.
<3>LustreError: 34700:0:(ldlm_resource.c:882:ldlm_resource_complain()) Skipped 5 previous similar messages
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac2a:0x1fbe:0x0].0xe8519c29 (ffff8803f859fec0) refcount = 2
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1469:ldlm_resource_dump()) ### ### ns: mdt-soaked-MDT0000_UUID lock: ffff8804001e4b40/0xda913c453295768d lrc: 2/0,1 mode: PW/PW res: [0x20002ac2a:0x1fbe:0x0].0xe8519c29 bits 0x2 rrc: 2 type: IBT flags: 0x40316400000000 nid: local remote: 0x0 expref: -99 pid: 34549 timeout: 0 lvb_type: 0
<3>LustreError: 34700:0:(ldlm_resource.c:1469:ldlm_resource_dump()) Skipped 4 previous similar messages
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac14:0xd2e4:0x0].0x786cbc9c (ffff8807f5e87b00) refcount = 5
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1484:ldlm_resource_dump()) Waiting locks:
<3>LustreError: 34700:0:(ldlm_resource.c:1486:ldlm_resource_dump()) ### ### ns: mdt-soaked-MDT0000_UUID lock: ffff880836be2b80/0xda913c4532957639 lrc: 2/0,1 mode: --/PW res: [0x20002ac14:0xd2e4:0x0].0x786cbc9c bits 0x2 rrc: 5 type: IBT flags: 0x40316400000020 nid: local remote: 0x0 expref: -99 pid: 34463 timeout: 0 lvb_type: 0
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac2a:0x1fbe:0x0].0xc7d60cfe (ffff8807f5e87a40) refcount = 2
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac2a:0x1fbe:0x0].0x0 (ffff88041165ac00) refcount = 9
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac2a:0x1fbe:0x0].0x78a9f709 (ffff880401cd9b40) refcount = 2
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac2a:0x1fbe:0x0].0xd5a94b89 (ffff8803f859fbc0) refcount = 2
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 34700:0:(ldlm_resource.c:1463:ldlm_resource_dump()) --- Resource: [0x20002ac14:0xd2e4:0x0].0x0 (ffff8807fbdccf00) refcount = 9
<3>LustreError: 34700:0:(ldlm_resource.c:1466:ldlm_resource_dump()) Granted locks (in reverse order):
<3>LustreError: 9135:0:(client.c:1166:ptlrpc_import_delay_req()) @@@ IMP_CLOSED   req@ffff8803f0bb0c80 x1555552176176736/t0(0) o13->soaked-OST000f-osc-MDT0000@192.168.1.105@o2ib10:7/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:/0/ffffffff rc 0/-1
<3>LustreError: 9135:0:(client.c:1166:ptlrpc_import_delay_req()) Skipped 6 previous similar messages
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.107@o2ib10 (stopping)
<6>Lustre: Skipped 7 previous similar messages
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.117@o2ib100 (stopping)
<6>Lustre: Skipped 15 previous similar messages
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.130@o2ib100 (stopping)
<6>Lustre: Skipped 6 previous similar messages
<3>LustreError: 0-0: Forced cleanup waiting for mdt-soaked-MDT0000_UUID namespace with 6 resources in use, (rc=-110)
<3>LustreError: 0-0: Forced cleanup waiting for mdt-soaked-MDT0000_UUID namespace with 6 resources in use, (rc=-110)
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.133@o2ib100 (stopping)
<6>Lustre: Skipped 9 previous similar messages
<6>Lustre: soaked-MDT0000: Not available for connect from 192.168.1.106@o2ib10 (stopping)
<6>Lustre: Skipped 23 previous similar messages
<3>LustreError: 0-0: Forced cleanup waiting for mdt-soaked-MDT0000_UUID namespace with 6 resources in use, (rc=-110)
<3>LustreError: 34661:0:(lod_qos.c:208:lod_statfs_and_check()) soaked-MDT0000-mdtlov: statfs: rc = -108
<3>LustreError: 34661:0:(lod_qos.c:208:lod_statfs_and_check()) Skipped 201 previous similar messages
<0>LustreError: 34700:0:(mdt_handler.c:4565:mdt_fini()) ASSERTION( atomic_read(&d->ld_ref) == 0 ) failed:
<0>LustreError: 9095:0:(lod_dev.c:1654:lod_device_free()) ASSERTION( atomic_read(&lu->ld_ref) == 0 ) failed: lu is ffff8803ffd54000
<0>LustreError: 9095:0:(lod_dev.c:1654:lod_device_free()) LBUG
<4>Pid: 9095, comm: obd_zombid

A crash dump is available on lola-9 -/var/crash/127.0.0.1-2017-01-05-05:48:01

Issue Links

• is related to: LU-10677 can't delete directory
• is related to: LU-10887 2 MDTs stuck in WAITING

Comments

[Lai Siyao]

Hi Cliff, I just updated the patch, could you do soak test again?

[Lai Siyao]

The crash dump shows lod->lod_md_root is not NULL at lod_device_free(), which means lod_md_root is released too early (in precleanup), and some request re-initialized it after that, I'll move it to real cleanup time.

[Lai Siyao]

I still need to access the crash dump to verify some details, but I don't have account on Spirit yet, and I just created a ticket for it: https://jira.hpdd.intel.com/browse/DCO-7884

[Lai Siyao]

Thanks Cliff, it's quite helpful.

[45593.537511] LustreError: 8499:0:(lod_dev.c:1688:lod_device_free()) header@ffff8807dc04ee80[0x0, 1, [0x200000007:0x1:0x0] hash exist]

{ [45593.591495] LustreError: 8499:0:(lod_dev.c:1688:lod_device_free()) ....mdt@ffff8807dc04eed0mdt-object@ffff8807dc04ee80( , writecount=0) [45593.645796] LustreError: 8499:0:(lod_dev.c:1688:lod_device_free()) ....mdd@ffff8803cadf5820mdd-object@ffff8803cadf5820(open_count=0, valid=0, cltime=0ns, flags=0) {no format}

The message shows 'root' is not released at lod_device_free(), I'll look into related code.

[Cliff White (Inactive)]

Hit the problem with your patch, relevent syslog attached, core dumped, vmcore-dmesg.txt attached, full data is available on Spirit: crash dump is at: /scratch/dumps/soak-9.spirit.hpdd.intel018-02-08-08\:03\:14/

[Lai Siyao]

Yes, it is.

[Cliff White (Inactive)]

Ask Minh to trigger an MNLX build and I can test that. Is you patch based on latest master?

[Lai Siyao]

Hi Cliff, I uploaded a debug patch, will you test soak/failover with it?

[Gerrit Updater]

Lai Siyao ([e-mail]) uploaded a new patch: https://review.whamcloud.com/31143
Subject: LU-8990 debug: dump objects in lod_device_free
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: cd8a85a3100c1b3aaea6e61a86b7057dade33341

[Cliff White (Inactive)]

Hit this again on version=2.10.57_57_g98ddc99, basically blocks most soak/failover tests

[Cliff White (Inactive)]

Hit this again on 2.10.57 -

Jan 25 00:15:03 soak-9 kernel: LustreError: 3830:0:(lod_qos.c:208:lod_statfs_and_check()) Skipped 46 previous similar messages
Jan 25 00:15:04 soak-9 kernel: Lustre: 3753:0:(service.c:2124:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (42:64s); client may timeout.  req@ffff8803d2008c00 x1590514452745184/t0(0) o101->7f42689f-29c1-6234-8d58-8721a9f86699@192.168.1.125@o2ib:449/0 lens 1728/544 e 0 to 0 dl 1516839239 ref 1 fl Complete:/0/0 rc -19/-19
Jan 25 00:15:04 soak-9 kernel: LustreError: 3830:0:(ldlm_lockd.c:1362:ldlm_handle_enqueue0()) ### lock on destroyed export ffff8808177d1c00 ns: mdt-soaked-MDT0000_UUID lock: ffff880816f58b40/0xb5b8772267a2d8f2 lrc: 3/0,0 mode: CR/CR res: [0x20006e1f6:0x16d28:0x0].0x0 bits 0x8/0x0 rrc: 2 type: IBT flags: 0x50200000000000 nid: 192.168.1.117@o2ib remote: 0xb6333a2c30ac9e3b expref: 3 pid: 3830 timeout: 0 lvb_type: 0
Jan 25 00:15:04 soak-9 kernel: Lustre: 3753:0:(service.c:2124:ptlrpc_server_handle_request()) Skipped 1 previous similar message
Jan 25 00:15:07 soak-9 kernel: Lustre: soaked-MDT0000: Not available for connect from 192.168.1.134@o2ib (stopping)
Jan 25 00:15:07 soak-9 kernel: Lustre: Skipped 10 previous similar messages
Jan 25 00:15:09 soak-9 kernel: LustreError: 3915:0:(lod_dev.c:1687:lod_device_free()) ASSERTION( atomic_read(&lu->ld_ref) == 0 ) failed: lu is ffff88082668e000
Jan 25 00:15:09 soak-9 kernel: LustreError: 3915:0:(lod_dev.c:1687:lod_device_free()) LBUG
Jan 25 00:15:09 soak-9 kernel: Pid: 3915, comm: umount
Jan 25 00:15:09 soak-9 kernel: #012Call Trace:
Jan 25 00:15:09 soak-9 kernel: [<ffffffffc096f7ae>] libcfs_call_trace+0x4e/0x60 [libcfs]
Jan 25 00:15:09 soak-9 kernel: [<ffffffffc096f83c>] lbug_with_loc+0x4c/0xb0 [libcfs]
Jan 25 00:15:09 soak-9 kernel: [<ffffffffc1865f76>] lod_device_free+0x296/0x2a0 [lod] 
Jan 25 00:15:09 soak-9 kernel: [<ffffffffc0a7ec4c>] class_free_dev+0x4dc/0x730 [obdclass]
Jan 25 00:15:09 soak-9 kernel: [<ffffffffc0a7f0c0>] class_export_put+0x220/0x2f0 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a80bd5>] class_unlink_export+0x135/0x170 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a96570>] class_decref+0x80/0x160 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a969d3>] class_detach+0x1b3/0x2e0 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a9d5e9>] class_process_config+0x19d9/0x28a0 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc097ad47>] ? libcfs_debug_msg+0x57/0x80 [libcfs]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a9e690>] class_manual_cleanup+0x1e0/0x710 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc18659c3>] lod_obd_disconnect+0x93/0x1c0 [lod]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc18e3d1e>] mdd_process_config+0x3de/0x630 [mdd]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc177827c>] mdt_stack_fini+0x2bc/0xd40 [mdt]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc1779083>] mdt_device_fini+0x383/0x970 [mdt] 
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a9b21c>] class_cleanup+0x8cc/0xc40 [obdclass]
Jan 25 00:15:10 soak-9 kernel: [<ffffffffc0a9c23c>] class_process_config+0x62c/0x28a0 [obdclass]
Jan 25 00:15:11 soak-9 kernel: [<ffffffffc097ad47>] ? libcfs_debug_msg+0x57/0x80 [libcfs]
Jan 25 00:15:11 soak-9 kernel: [<ffffffffc0a9e676>] class_manual_cleanup+0x1c6/0x710 [obdclass]
Jan 25 00:15:11 soak-9 kernel: [<ffffffffc0ace25e>] server_put_super+0x8de/0xcd0 [obdclass]
Jan 25 00:15:11 soak-9 kernel: [<ffffffff812054d2>] generic_shutdown_super+0x72/0x100
Jan 25 00:15:11 soak-9 kernel: [<ffffffff812058a2>] kill_anon_super+0x12/0x20
Jan 25 00:15:11 soak-9 kernel: [<ffffffffc0aa10c2>] lustre_kill_super+0x32/0x50 [obdclass]
Jan 25 00:15:11 soak-9 kernel: [<ffffffff81205c59>] deactivate_locked_super+0x49/0x60 
Jan 25 00:15:11 soak-9 kernel: [<ffffffff812063c6>] deactivate_super+0x46/0x60
Jan 25 00:15:11 soak-9 kernel: [<ffffffff8122376f>] cleanup_mnt+0x3f/0x80 
Jan 25 00:15:11 soak-9 kernel: [<ffffffff81223802>] __cleanup_mnt+0x12/0x20
Jan 25 00:15:11 soak-9 kernel: [<ffffffff810aee05>] task_work_run+0xc5/0xf0
Jan 25 00:15:11 soak-9 kernel: [<ffffffff8102ab52>] do_notify_resume+0x92/0xb0
Jan 25 00:15:11 soak-9 kernel: [<ffffffff816b8d37>] int_signal+0x12/0x17
Jan 25 00:15:12 soak-9 kernel:
Jan 25 00:15:12 soak-9 kernel: Kernel panic - not syncing: LBUG
Jan 25 00:19:04 soak-9 systemd: Starting Stop Read-Ahead Data Collection...

Crash dumps are available on spirit