[LU-11038] replay-dual test_26: MDS crash with BUG: unable to handle kernel NULL pointer dereference

• Type: Bug
• Resolution: Cannot Reproduce
• Priority: Minor
• Affects Version/s: Lustre 2.10.4
• Severity: 3
• Assignee: WC Triage
• Reporter: Maloo

Description

This issue was created by maloo for sarah_lw <[e-mail]>

This issue relates to the following test suite run: https://testing.hpdd.intel.com/test_sets/b045d08a-5b46-11e8-93e6-52540065bddc

test_26 failed with the following error:

Test crashed during replay-dual test_26

Env: 2.10.4-RC2 SLES12SP3 server/client.

 

The same test passed on 2.10.4-RC1

[40924.262982] Lustre: DEBUG MARKER: dmesg
[40924.661415] Lustre: DEBUG MARKER: /usr/sbin/lctl mark == replay-dual test 26: dbench and tar with mds failover ============================================= 02:22:47 \(1526721767\)
[40924.703962] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ============================================= 02:22:47 (1526721767)
[40924.817912] Lustre: MGS: Received new LWP connection from 10.9.6.10@tcp, removing former export from same NID
[40925.069705] LustreError: 166-1: MGC10.9.6.12@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail
[40925.070624] LustreError: 1454:0:(ldlm_resource.c:1100:ldlm_resource_complain()) MGC10.9.6.12@tcp: namespace resource [0x65727473756c:0x2:0x0].0x0 (ffff8800400104c0) refcount nonzero (1) after lock cleanup; forcing cleanup.
[40925.070626] LustreError: 1454:0:(ldlm_resource.c:1100:ldlm_resource_complain()) Skipped 1 previous similar message
[40925.070628] LustreError: 1454:0:(ldlm_resource.c:1682:ldlm_resource_dump()) --- Resource: [0x65727473756c:0x2:0x0].0x0 (ffff8800400104c0) refcount = 2
[40925.070631] LustreError: 1454:0:(ldlm_resource.c:1703:ldlm_resource_dump()) Waiting locks:
[40925.070636] LustreError: 1454:0:(ldlm_resource.c:1705:ldlm_resource_dump()) ### ### ns: MGC10.9.6.12@tcp lock: ffff88003f3f7000/0xbe3e0ba9bf8042d4 lrc: 4/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 3 type: PLN flags: 0x1106400000000 nid: local remote: 0xbe3e0ba9bf8042db expref: -99 pid: 32450 timeout: 0 lvb_type: 0
[40925.129264] Lustre: DEBUG MARKER: /usr/sbin/lctl mark trevis-6vm10: executing set_default_debug -1 all 4
[40925.165673] Lustre: DEBUG MARKER: trevis-6vm10: executing set_default_debug -1 all 4
[40927.211147] Lustre: DEBUG MARKER: sync; sync; sync
[40927.709545] Lustre: DEBUG MARKER: /usr/sbin/lctl --device lustre-MDT0000 notransno
[40927.758867] Lustre: DEBUG MARKER: /usr/sbin/lctl --device lustre-MDT0000 readonly
[40928.000551] Turning device dm-0 (0xfe00000) read-only
[40928.020838] Lustre: DEBUG MARKER: /usr/sbin/lctl mark mds1 REPLAY BARRIER on lustre-MDT0000
[40928.039076] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000
[40930.184043] Lustre: DEBUG MARKER: /usr/sbin/lctl mark test_26 fail mds1 1 times
[40930.255200] Lustre: DEBUG MARKER: test_26 fail mds1 1 times
[40930.323562] Lustre: DEBUG MARKER: grep -c /mnt/lustre-mds1' ' /proc/mounts || true
[40930.404857] Lustre: DEBUG MARKER: umount /mnt/lustre-mds1
[40930.435375] Lustre: lustre-MDT0000: Not available for connect from 10.9.6.9@tcp (stopping)
[40930.713797] LustreError: 685:0:(client.c:1166:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff880068bd96c0 x1600869444311072/t0(0) o13->lustre-OST0002-osc-MDT0000@10.9.6.11@tcp:7/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:/0/ffffffff rc 0/-1
[40930.713805] LustreError: 685:0:(client.c:1166:ptlrpc_import_delay_req()) Skipped 6 previous similar messages
[40931.602998] Lustre: MGS: Received new LWP connection from 10.9.6.9@tcp, removing former export from same NID
[40931.603006] Lustre: Skipped 1 previous similar message
[40932.089774] LustreError: 687:0:(client.c:1166:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff88006e88e040 x1600869444311152/t0(0) o13->lustre-OST0000-osc-MDT0000@10.9.6.11@tcp:7/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:/0/ffffffff rc 0/-1
[40932.089784] LustreError: 687:0:(client.c:1166:ptlrpc_import_delay_req()) Skipped 5 previous similar messages
[40932.763746] Lustre: lustre-MDT0000: Not available for connect from 10.9.6.11@tcp (stopping)
[40932.763750] Lustre: Skipped 1 previous similar message
[40934.819065] Lustre: lustre-MDT0000: Not available for connect from 10.9.6.10@tcp (stopping)
[40934.819068] Lustre: Skipped 6 previous similar messages
[40937.761756] Lustre: lustre-MDT0000: Not available for connect from 10.9.6.11@tcp (stopping)
[40937.761761] Lustre: Skipped 3 previous similar messages
[40937.963592] BUG: unable to handle kernel NULL pointer dereference at (null)
[40937.964686] IP: [<ffffffffa07e33bf>] _ldlm_lock_debug+0x11f/0x710 [ptlrpc]
[40937.966338] PGD 0 
[40937.966648] Oops: 0000 [#1] SMP 
[40937.967150] Modules linked in: osp(OEN) mdd(OEN) lod(OEN) mdt(OEN) lfsck(OEN) mgs(OEN) mgc(OEN) osd_ldiskfs(OEN) ldiskfs(OEN) lquota(OEN) fid(OEN) fld(OEN) ksocklnd(OEN) ptlrpc(OEN) obdclass(OEN) lnet(OEN) libcfs(OEN) loop(E) rpcsec_gss_krb5(E) auth_rpcgss(E) nfsv4(E) dns_resolver(E) nfs(E) lockd(E) grace(E) fscache(E) af_packet(E) iscsi_ibft(E) iscsi_boot_sysfs(E) rpcrdma(E) sunrpc(E) ib_isert(E) iscsi_target_mod(E) ib_iser(E) libiscsi(E) scsi_transport_iscsi(E) ib_srpt(E) target_core_mod(E) ib_srp(E) scsi_transport_srp(E) ib_ipoib(E) rdma_ucm(E) ib_ucm(E) ib_uverbs(E) ib_umad(E) rdma_cm(E) configfs(E) ib_cm(E) iw_cm(E) ib_core(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) ghash_clmulni_intel(E) jitterentropy_rng(E) drbg(E) ansi_cprng(E) aesni_intel(E) 8139too(E) aes_x86_64(E) lrw(E) gf128mul(E)
[40937.977623] glue_helper(E) 8139cp(E) ablk_helper(E) cryptd(E) joydev(E) mii(E) pcspkr(E) virtio_balloon(E) i2c_piix4(E) button(E) processor(E) ata_generic(E) ext4(E) crc16(E) jbd2(E) mbcache(E) ata_piix(E) virtio_blk(E) ahci(E) libahci(E) serio_raw(E) virtio_pci(E) virtio_ring(E) virtio(E) uhci_hcd(E) ehci_hcd(E) usbcore(E) libata(E) usb_common(E) floppy(E) sg(E) dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) autofs4(E) [last unloaded: libcfs]
[40937.983840] Supported: No, Unsupported modules are loaded
[40937.984556] CPU: 0 PID: 1607 Comm: ldlm_bl_03 Tainted: G OE N 4.4.126-94.22_lustre-default #1
[40937.985795] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[40937.986538] task: ffff88003f5c5380 ti: ffff880066d80000 task.ti: ffff880066d80000
[40937.987515] RIP: 0010:[<ffffffffa07e33bf>] [<ffffffffa07e33bf>] _ldlm_lock_debug+0x11f/0x710 [ptlrpc]
[40937.988776] RSP: 0018:ffff880066d83ac0 EFLAGS: 00010286
[40937.989461] RAX: ffffffffa0744620 RBX: ffff88007ac21200 RCX: 0000000000000000
[40937.990376] RDX: 000000000000000a RSI: 000000000000000a RDI: 0000000000000000
[40937.991287] RBP: ffff880066d83bf0 R08: 0000000000000004 R09: 0000000000007ebf
[40937.992207] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88003d10ad00
[40937.993124] R13: ffff8800666d8400 R14: ffffffffa08de134 R15: 0009000000000000
[40937.994038] FS: 0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
[40937.995082] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[40937.995830] CR2: 0000000000000000 CR3: 000000006d4dc000 CR4: 0000000000060670
[40937.996760] Stack:
[40937.997046] 0000000000000000 ffffffffa08dda07 ffff88006ee4b622 0000000000000000
[40937.998116] ffffffffa08e78d6 ffff88006ee4b63c 0000000000000000 ffffffffa0788ab8
[40937.999172] ffff88006ee4b5af ffff880000000010 ffff880066d83c18 ffff880066d83bd8
[40938.000227] Call Trace:
[40938.000678] [<ffffffffa07f0bfe>] ldlm_resource_add_lock+0xee/0x1b0 [ptlrpc]
[40938.001670] [<ffffffffa07ea8e0>] ldlm_handle_conflict_lock+0x230/0x2e0 [ptlrpc]
[40938.002694] [<ffffffffa07fdd56>] ldlm_process_plain_lock+0x406/0xaf0 [ptlrpc]
[40938.003668] [<ffffffffa07e9fba>] ldlm_reprocess_queue+0x11a/0x260 [ptlrpc]
[40938.004600] [<ffffffffa07eaaa3>] __ldlm_reprocess_all+0x113/0x350 [ptlrpc]
[40938.005531] [<ffffffffa07eb002>] ldlm_reprocess_res+0x22/0x30 [ptlrpc]
[40938.006502] [<ffffffffa07799a4>] cfs_hash_for_each_relax+0x244/0x430 [libcfs]
[40938.007484] [<ffffffffa077c952>] cfs_hash_for_each_nolock+0x72/0x1b0 [libcfs]
[40938.008462] [<ffffffffa07eb048>] ldlm_reprocess_recovery_done+0x38/0x100 [ptlrpc]
[40938.009478] [<ffffffffa07ebbe4>] ldlm_export_cancel_locks+0xe4/0xf0 [ptlrpc]
[40938.010436] [<ffffffffa0812dff>] ldlm_bl_thread_main+0x48f/0x690 [ptlrpc]
[40938.011411] [<ffffffff8109ea99>] kthread+0xc9/0xe0
[40938.012176] [<ffffffff81618505>] ret_from_fork+0x55/0x80
[40938.017587] DWARF2 unwinder stuck at ret_from_fork+0x55/0x80
[40938.018338] 
[40938.018556] Leftover inexact backtrace:
 
[40938.019262] [<ffffffff8109e9d0>] ? kthread_park+0x50/0x50
[40938.019974] Code: 8b 9b 50 01 00 00 4c 8b 93 80 01 00 00 44 8b 8b 88 01 00 00 be 9d ff ff ff 74 04 41 8b 75 40 48 8b 4b 48 45 8b 44 24 18 8b 7b 40 <48> 8b 09 48 8b 09 48 8b 49 10 44 89 8c 24 80 00 00 00 49 89 d9 
[40938.023999] RIP [<ffffffffa07e33bf>] _ldlm_lock_debug+0x11f/0x710 [ptlrpc]
[40938.024962] RSP <ffff880066d83ac0>
[40938.025423] CR2: 0000000000000000

VVVVVVV DO NOT REMOVE LINES BELOW, Added by Maloo for auto-association VVVVVVV
replay-dual test_26 - Test crashed during replay-dual test_26

Issue Links

• duplicates: LU-7372 replay-dual test_26: test failed to respond and timed out
• is related to: LU-18001 replay-dual test_26: Timeout occurred after 136 minutes - hang during unmount MDS

Comments

[Li Xi (Inactive)]

Got this issue on my site too on Lustre-2.10.4.

4853.863850] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ============================================= 19:10:39 (1527073839)
[ 4857.258739] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 509 < left 638, rollback = 2
[ 4857.265541] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/0, destroy: 0/0/0
[ 4857.270705] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4857.276600] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4857.285310] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/3, delete: 0/0/0
[ 4857.290653] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4858.049927] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 509 < left 638, rollback = 2
[ 4858.056424] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 7 previous similar messages
[ 4858.061225] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/0, destroy: 0/0/0
[ 4858.066306] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 7 previous similar messages
[ 4858.071319] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4858.077706] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 7 previous similar messages
[ 4858.083901] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4858.090166] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 7 previous similar messages
[ 4858.096507] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/3, delete: 0/0/0
[ 4858.108592] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 7 previous similar messages
[ 4858.114122] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4858.120097] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 7 previous similar messages
[ 4859.276388] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 504 < left 638, rollback = 2
[ 4859.282904] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 87 previous similar messages
[ 4859.297126] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/4, destroy: 0/0/0
[ 4859.303500] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 87 previous similar messages
[ 4859.308834] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4859.314310] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 87 previous similar messages
[ 4859.319758] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4859.322635] Lustre: DEBUG MARKER: sync; sync; sync
[ 4859.332972] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 87 previous similar messages
[ 4859.338367] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/4, delete: 0/0/0
[ 4859.343583] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 87 previous similar messages
[ 4859.349626] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4859.357229] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 87 previous similar messages
[ 4861.591545] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 502 < left 638, rollback = 2
[ 4861.598048] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 55 previous similar messages
[ 4861.603329] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/5, destroy: 0/0/0
[ 4861.608250] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 55 previous similar messages
[ 4861.613206] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4861.618462] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 55 previous similar messages
[ 4861.623794] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4861.629265] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 55 previous similar messages
[ 4861.634206] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/5, delete: 0/0/0
[ 4861.638943] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 55 previous similar messages
[ 4861.643917] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4861.648812] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 55 previous similar messages
[ 4862.383599] Lustre: DEBUG MARKER: /usr/sbin/lctl --device lustre-MDT0000 notransno
[ 4863.153800] Lustre: DEBUG MARKER: /usr/sbin/lctl --device lustre-MDT0000 readonly
[ 4864.185346] Turning device vdb (0xfd00010) read-only
[ 4864.654871] Lustre: DEBUG MARKER: /usr/sbin/lctl mark mds1 REPLAY BARRIER on lustre-MDT0000
[ 4865.082331] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000
[ 4865.611961] Lustre: 6652:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 505 < left 638, rollback = 2
[ 4865.618851] Lustre: 6652:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 31 previous similar messages
[ 4865.624480] Lustre: 6652:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/3, destroy: 0/0/0
[ 4865.629503] Lustre: 6652:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 31 previous similar messages
[ 4865.634719] Lustre: 6652:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4865.639975] Lustre: 6652:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 31 previous similar messages
[ 4865.644902] Lustre: 6652:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4865.650149] Lustre: 6652:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 31 previous similar messages
[ 4865.655072] Lustre: 6652:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/4, delete: 0/0/0
[ 4865.660397] Lustre: 6652:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 31 previous similar messages
[ 4865.665815] Lustre: 6652:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4865.671025] Lustre: 6652:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 31 previous similar messages
[ 4867.620546] Lustre: DEBUG MARKER: /usr/sbin/lctl mark test_26 fail mds1 1 times
[ 4868.162595] Lustre: DEBUG MARKER: test_26 fail mds1 1 times
[ 4868.587024] Lustre: DEBUG MARKER: grep -c /mnt/lustre-mds1' ' /proc/mounts || true
[ 4869.337772] Lustre: DEBUG MARKER: umount -d /mnt/lustre-mds1
[ 4873.832032] Lustre: 3863:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 508 < left 638, rollback = 2
[ 4873.839128] Lustre: 3863:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 151 previous similar messages
[ 4873.844748] Lustre: 3863:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/1, destroy: 0/0/0
[ 4873.852092] Lustre: 3863:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 151 previous similar messages
[ 4873.857492] Lustre: 3863:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4873.880971] Lustre: 3863:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 151 previous similar messages
[ 4873.888084] Lustre: 3863:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4873.893552] Lustre: 3863:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 151 previous similar messages
[ 4873.898667] Lustre: 3863:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/3, delete: 0/0/0
[ 4873.903637] Lustre: 3863:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 151 previous similar messages
[ 4873.908995] Lustre: 3863:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4873.914058] Lustre: 3863:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 151 previous similar messages
[ 4900.065841] Lustre: 4511:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 504 < left 638, rollback = 2
[ 4900.072969] Lustre: 4511:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 279 previous similar messages
[ 4900.088107] Lustre: 4511:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/4, destroy: 0/0/0
[ 4900.094712] Lustre: 4511:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 279 previous similar messages
[ 4900.104952] Lustre: 4511:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4900.124421] Lustre: 4511:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 279 previous similar messages
[ 4900.138081] Lustre: 4511:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4900.145762] Lustre: 4511:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 279 previous similar messages
[ 4900.151332] Lustre: 4511:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/4, delete: 0/0/0
[ 4900.156757] Lustre: 4511:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 279 previous similar messages
[ 4900.163104] Lustre: 4511:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4900.168387] Lustre: 4511:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 279 previous similar messages
[ 4935.827897] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 501 < left 638, rollback = 2
[ 4935.837586] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 239 previous similar messages
[ 4935.845497] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/6, destroy: 0/0/0
[ 4935.852328] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 239 previous similar messages
[ 4935.859506] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 4935.866531] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 239 previous similar messages
[ 4935.872820] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 4935.879939] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 239 previous similar messages
[ 4935.886349] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/5, delete: 0/0/0
[ 4935.892222] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 239 previous similar messages
[ 4935.898171] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 4935.903051] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 239 previous similar messages
[ 5001.767877] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 508 < left 638, rollback = 2
[ 5001.774742] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 695 previous similar messages
[ 5001.780504] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/2, destroy: 0/0/0
[ 5001.785460] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 695 previous similar messages
[ 5001.790992] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 5001.796465] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 695 previous similar messages
[ 5001.802010] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 5001.808416] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 695 previous similar messages
[ 5001.814112] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/2, delete: 0/0/0
[ 5001.819500] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 695 previous similar messages
[ 5001.825194] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 5001.830458] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 695 previous similar messages
[ 5043.531844] INFO: task umount:7051 blocked for more than 120 seconds.
[ 5043.559145] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 5043.571856] umount D ffff965a5b45eeb0 0 7051 7050 0x00000000
[ 5043.588676] Call Trace:
[ 5043.590253] [<ffffffff82f13e99>] schedule_preempt_disabled+0x29/0x70
[ 5043.594280] [<ffffffff82f11c57>] __mutex_lock_slowpath+0xc7/0x1d0
[ 5043.598409] [<ffffffff82f1103f>] mutex_lock+0x1f/0x2f
[ 5043.601442] [<ffffffffc07b93a7>] mgc_process_config+0x207/0x13f0 [mgc]
[ 5043.605151] [<ffffffffc0829d78>] obd_process_config.constprop.13+0x88/0x2e0 [obdclass]
[ 5043.612032] [<ffffffffc04bdcc7>] ? libcfs_debug_msg+0x57/0x80 [libcfs]
[ 5043.621123] [<ffffffffc0816cf9>] ? lprocfs_counter_add+0xf9/0x160 [obdclass]
[ 5043.627421] [<ffffffffc082b0af>] lustre_end_log+0x1ff/0x550 [obdclass]
[ 5043.630929] [<ffffffffc0853d1e>] server_put_super+0x7de/0xcd0 [obdclass]
[ 5043.634737] [<ffffffff82a1d69d>] generic_shutdown_super+0x6d/0x100
[ 5043.638215] [<ffffffff82a1da82>] kill_anon_super+0x12/0x20
[ 5043.653558] [<ffffffffc0829402>] lustre_kill_super+0x32/0x50 [obdclass]
[ 5043.657368] [<ffffffff82a1de3e>] deactivate_locked_super+0x4e/0x70
[ 5043.660755] [<ffffffff82a1e5c6>] deactivate_super+0x46/0x60
[ 5043.663775] [<ffffffff82a3c57f>] cleanup_mnt+0x3f/0x80
[ 5043.666571] [<ffffffff82a3c612>] __cleanup_mnt+0x12/0x20
[ 5043.679438] [<ffffffff828b784b>] task_work_run+0xbb/0xe0
[ 5043.682215] [<ffffffff8282ac55>] do_notify_resume+0xa5/0xc0
[ 5043.685702] [<ffffffff82f1fada>] int_signal+0x12/0x17
[ 5130.557643] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 502 < left 638, rollback = 2
[ 5130.566402] Lustre: 3864:0:(osd_internal.h:1139:osd_trans_exec_op()) Skipped 1463 previous similar messages
[ 5130.572039] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) create: 3/24/5, destroy: 0/0/0
[ 5130.577152] Lustre: 3864:0:(osd_handler.c:1673:osd_trans_dump_creds()) Skipped 1463 previous similar messages
[ 5130.582341] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 9/638/0
[ 5130.587512] Lustre: 3864:0:(osd_handler.c:1680:osd_trans_dump_creds()) Skipped 1463 previous similar messages
[ 5130.592725] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 3/3/0
[ 5130.600231] Lustre: 3864:0:(osd_handler.c:1690:osd_trans_dump_creds()) Skipped 1463 previous similar messages
[ 5130.605633] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) insert: 11/199/5, delete: 0/0/0
[ 5130.610566] Lustre: 3864:0:(osd_handler.c:1697:osd_trans_dump_creds()) Skipped 1463 previous similar messages
[ 5130.615660] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) ref_add: 5/5/0, ref_del: 0/0/0
[ 5130.620572] Lustre: 3864:0:(osd_handler.c:1704:osd_trans_dump_creds()) Skipped 1463 previous similar messages
[ 5136.751418] LustreError: 3878:0:(ldlm_request.c:130:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1527073823, 300s ago); not entering recovery in server code, just going back to sleep ns: MGS lock: ffff965a5c79c200/0xc539b8615eb9c76 lrc: 3/0,1 mode: --/EX res: [0x65727473756c:0x2:0x0].0x0 rrc: 14 type: PLN flags: 0x40210400000020 nid: local remote: 0x0 expref: -99 pid: 3878 timeout: 0 lvb_type: 0
[ 5136.786410] LustreError: dumping log to /tmp/lustre-log.1527074123.3878
[ 5143.791753] Lustre: MGS: Received new LWP connection from 10.0.2.38@tcp, removing former export from same NID
[ 5143.797868] Lustre: MGS: Connection restored to bc8f32af-75b1-d99f-ee7c-157fd1d1987f (at 10.0.2.38@tcp)
[ 5143.803193] Lustre: Skipped 113 previous similar messages
[ 5151.286402] LustreError: 166-1: MGC10.0.2.48@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail
[ 5151.293159] LustreError: 3862:0:(ldlm_request.c:148:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1527073837, 300s ago), entering recovery for MGS@10.0.2.48@tcp ns: MGC10.0.2.48@tcp lock: ffff965a5d519a00/0xc539b8615eb9d25 lrc: 4/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 2 type: PLN flags: 0x1000000000000 nid: local remote: 0xc539b8615eb9d2c expref: -99 pid: 3862 timeout: 0 lvb_type: 0
[ 5151.293512] Lustre: MGS: Received new LWP connection from 0@lo, removing former export from same NID
[ 5151.293514] Lustre: Skipped 2 previous similar messages
[ 5151.294777] LustreError: 9613:0:(ldlm_resource.c:1100:ldlm_resource_complain()) MGC10.0.2.48@tcp: namespace resource [0x65727473756c:0x2:0x0].0x0 (ffff965a7ac16840) refcount nonzero (2) after lock cleanup; forcing cleanup.
[ 5151.294782] LustreError: 9613:0:(ldlm_resource.c:1682:ldlm_resource_dump()) — Resource: [0x65727473756c:0x2:0x0].0x0 (ffff965a7ac16840) refcount = 3
[ 5151.294785] LustreError: 9613:0:(ldlm_resource.c:1703:ldlm_resource_dump()) Waiting locks:
[ 5151.294793] LustreError: 9613:0:(ldlm_resource.c:1705:ldlm_resource_dump()) ### ### ns: MGC10.0.2.48@tcp lock: ffff965a5d519a00/0xc539b8615eb9d25 lrc: 4/1,0 mode: --/CR res: [0x65727473756c:0x2:0x0].0x0 rrc: 4 type: PLN flags: 0x1106400000000 nid: local remote: 0xc539b8615eb9d2c expref: -99 pid: 3862 timeout: 0 lvb_type: 0
[ 5151.358516] Lustre: Failing over lustre-MDT0000
[ 5151.360959] Lustre: Skipped 8 previous similar messages
[ 5151.410257] Lustre: lustre-MDT0000: Not available for connect from 10.0.2.51@tcp (stopping)
[ 5151.416502] Lustre: Skipped 1 previous similar message
[ 5153.740590] LustreError: 726:0:(client.c:1166:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff965a5ffdc000 x1601249971853200/t0(0) o13->lustre-OST0001-osc-MDT0000@10.0.2.32@tcp:7/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:/0/ffffffff rc 0/-1
[ 5153.759784] LustreError: 726:0:(client.c:1166:ptlrpc_import_delay_req()) Skipped 1 previous similar message
[ 5154.332546] LustreError: 727:0:(client.c:1166:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff965a5ffdc4c0 x1601249971853216/t0(0) o13->lustre-OST0000-osc-MDT0000@10.0.2.39@tcp:7/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:/0/ffffffff rc 0/-1
[ 5157.129226] BUG: unable to handle kernel NULL pointer dereference at 000000000000001c
[ 5157.134863] IP: [<ffffffffc11676ce>] ldlm_process_plain_lock+0x6e/0xb30 [ptlrpc]
[ 5157.139884] PGD 0
[ 5157.141267] Oops: 0000 1 SMP
[ 5157.143341] Modules linked in: osp(OE) mdd(OE) lod(OE) mdt(OE) lfsck(OE) mgs(OE) mgc(OE) osd_ldiskfs(OE) lquota(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE) ldiskfs(OE) libcfs(OE) mbcache jbd2 zfs(POE) zunicode(POE) zavl(POE) icp(POE) zcommon(POE) znvpair(POE) spl(OE) rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ppdev pcspkr sg joydev i2c_piix4 virtio_balloon parport_pc i2c_core parport nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sr_mod cdrom ata_generic pata_acpi virtio_scsi virtio_blk virtio_net ata_piix serio_raw virtio_pci libata virtio_ring virtio floppy [last unloaded: libcfs]
[ 5157.212014] CPU: 0 PID: 9614 Comm: ldlm_bl_03 Kdump: loaded Tainted: P OE ------------ 3.10.0-862.2.3.el7_lustre.2.10.4_33_gd942416.ddn0.x86_64 #1
[ 5157.226568] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[ 5157.244021] task: ffff965a79d25ee0 ti: ffff965a5d4f4000 task.ti: ffff965a5d4f4000
[ 5157.248225] RIP: 0010:[<ffffffffc11676ce>] [<ffffffffc11676ce>] ldlm_process_plain_lock+0x6e/0xb30 [ptlrpc]
[ 5157.253914] RSP: 0018:ffff965a5d4f7be0 EFLAGS: 00010287
[ 5157.256926] RAX: 0000000000000000 RBX: ffff965a5c79d000 RCX: 0000000000000000
[ 5157.260710] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff965a7a78e200
[ 5157.264452] RBP: ffff965a5d4f7c58 R08: 0000000000000001 R09: 0000000000000000
[ 5157.268412] R10: ffff965a7cc5a628 R11: 000000000000000f R12: ffff965a5888de80
[ 5157.272403] R13: 0000000000000002 R14: ffff965a5d4f7cd0 R15: ffff965a5c79d060
[ 5157.286857] FS: 0000000000000000(0000) GS:ffff965a7fc00000(0000) knlGS:0000000000000000
[ 5157.291044] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 5157.294048] CR2: 000000000000001c CR3: 000000000a20e000 CR4: 00000000000006f0
[ 5157.299570] Call Trace:
[ 5157.301199] [<ffffffffc04bdcc7>] ? libcfs_debug_msg+0x57/0x80 [libcfs]
[ 5157.305503] [<ffffffffc1167660>] ? ldlm_errno2error+0x60/0x60 [ptlrpc]
[ 5157.309668] [<ffffffffc11529ed>] ldlm_reprocess_queue+0x13d/0x2a0 [ptlrpc]
[ 5157.313748] [<ffffffffc115358d>] __ldlm_reprocess_all+0x14d/0x3a0 [ptlrpc]
[ 5157.336428] [<ffffffffc1153b46>] ldlm_reprocess_res+0x26/0x30 [ptlrpc]
[ 5157.339825] [<ffffffffc04c3d70>] cfs_hash_for_each_relax+0x250/0x450 [libcfs]
[ 5157.343689] [<ffffffffc1153b20>] ? ldlm_lock_downgrade+0x320/0x320 [ptlrpc]
[ 5157.347679] [<ffffffffc1153b20>] ? ldlm_lock_downgrade+0x320/0x320 [ptlrpc]
[ 5157.351716] [<ffffffffc04c7105>] cfs_hash_for_each_nolock+0x75/0x1c0 [libcfs]
[ 5157.355477] [<ffffffffc1153b8c>] ldlm_reprocess_recovery_done+0x3c/0x110 [ptlrpc]
[ 5157.359889] [<ffffffffc115483c>] ldlm_export_cancel_locks+0x11c/0x130 [ptlrpc]
[ 5157.363807] [<ffffffffc117dda8>] ldlm_bl_thread_main+0x4c8/0x700 [ptlrpc]
[ 5157.367533] [<ffffffff828cee80>] ? wake_up_state+0x20/0x20
[ 5157.370635] [<ffffffffc117d8e0>] ? ldlm_handle_bl_callback+0x410/0x410 [ptlrpc]
[ 5157.375198] [<ffffffff828bae31>] kthread+0xd1/0xe0
[ 5157.378054] [<ffffffff828bad60>] ? insert_kthread_work+0x40/0x40
[ 5157.381485] [<ffffffff82f1f5f7>] ret_from_fork_nospec_begin+0x21/0x21
[ 5157.385004] [<ffffffff828bad60>] ? insert_kthread_work+0x40/0x40
[ 5157.388502] Code: 89 45 a0 74 0d f6 05 33 5f 37 ff 01 0f 85 34 06 00 00 8b 83 98 00 00 00 39 83 9c 00 00 00 89 45 b8 0f 84 57 09 00 00 48 8b 45 a0 <8b> 40 1c 85 c0 0f 84 7a 09 00 00 48 8b 4d a0 48 89 c8 48 83 c0
[ 5157.400499] RIP [<ffffffffc11676ce>] ldlm_process_plain_lock+0x6e/0xb30 [ptlrpc]
[ 5157.404838] RSP <ffff965a5d4f7be0>
[ 5157.410691] CR2: 000000000000001c