[LU-13500] Client gets evicted - nfsd non-standard errorno -108

• Type: Bug
• Resolution: Unresolved
• Priority: Minor
• Severity: 3
• Assignee: Oleg Drokin
• Reporter: Campbell Mcleay (Inactive)

Description

Client is getting evicted by MDT as soon as nfsd service started on the client.

client (golf1) kernel version : 3.10.0-1062.1.1.el7_lustre.x86_64
client (golf1) lustre version : lustre-2.12.3-1.el7.x86_64

mds (gmds1) kernel version : 3.10.0-1062.1.1.el7_lustre.x86_64
mds (gmds1) lustre version : lustre-2.12.3-1.el7.x86_64

oss (goss1-goss6) kernel version : 3.10.0-1062.1.1.el7_lustre.x86_64
oss (goss1-goss6) lustre version : lustre-2.12.3-1.el7.x86_64

/etc/exports on golf1 :

/user_data       10.25.0.0/16(fsid=123456789,rw,anonuid=0,insecure,no_subtree_check,insecure_locks,async)

Apr 30 14:03:07 golf1 kernel: LustreError: 11-0: golf-MDT0000-mdc-ffff973bf6409800: operation ldlm_enqueue to node 10.25.22.90@tcp failed: rc = -107
Apr 30 14:03:07 golf1 kernel: Lustre: golf-MDT0000-mdc-ffff973bf6409800: Connection to golf-MDT0000 (at 10.25.22.90@tcp) was lost; in progress operations using this service will wait for recovery to complete
Apr 30 14:03:07 golf1 kernel: LustreError: Skipped 8 previous similar messages
Apr 30 14:03:07 golf1 kernel: LustreError: 167-0: golf-MDT0000-mdc-ffff973bf6409800: This client was evicted by golf-MDT0000; in progress operations using this service will fail.
Apr 30 14:03:07 golf1 kernel: LustreError: 25491:0:(file.c:4339:ll_inode_revalidate_fini()) golf: revalidate FID [0x20004884e:0x16:0x0] error: rc = -5
Apr 30 14:03:07 golf1 kernel: ------------[ cut here ]------------
Apr 30 14:03:07 golf1 kernel: WARNING: CPU: 26 PID: 25600 at fs/nfsd/nfsproc.c:805 nfserrno+0x58/0x70 [nfsd]
Apr 30 14:03:07 golf1 kernel: LustreError: 25579:0:(file.c:216:ll_close_inode_openhandle()) golf-clilmv-ffff973bf6409800: inode [0x20004884e:0x15:0x0] mdc close failed: rc = -108
Apr 30 14:03:07 golf1 kernel: ------------[ cut here ]------------
Apr 30 14:03:07 golf1 kernel: ------------[ cut here ]------------
Apr 30 14:03:07 golf1 kernel: nfsd: non-standard errno: -108
Apr 30 14:03:07 golf1 kernel: ------------[ cut here ]------------
Apr 30 14:03:07 golf1 kernel: WARNING: CPU: 54 PID: 25602 at fs/nfsd/nfsproc.c:805 nfserrno+0x58/0x70 [nfsd]
Apr 30 14:03:07 golf1 kernel: LustreError: 25579:0:(file.c:216:ll_close_inode_openhandle()) Skipped 2 previous similar messages
Apr 30 14:03:07 golf1 kernel: WARNING: CPU: 24 PID: 25601 at fs/nfsd/nfsproc.c:805 nfserrno+0x58/0x70 [nfsd]
Apr 30 14:03:07 golf1 kernel: WARNING: CPU: 9 PID: 25505 at fs/nfsd/nfsproc.c:805 nfserrno+0x58/0x70 [nfsd]

Issue Links

• is related to: LU-13692 MDS slow/hung threads at mdt_object_local_lock
• is related to: LU-13054 MDS kernel BUG at ldiskfs/htree_lock.c:429!

Comments

[Peter Jones]

The timeline will be affected by third party software releases so is a little unclear but seems very likely to be before the year is out.

[Dneg (Inactive)]

Hi Peter,

Thanks for the update,  We have applied above patch on hotel and monitoring it further. 

When are we planning to release the version 2.12.8 ? 

[Peter Jones]

The fix is queued up for the upcoming 2.12.8 release but, in the meantime, you could apply the patch - see https://review.whamcloud.com/#/c/44121/

[Dneg (Inactive)]

Hi Oleg,

Whether this patch(for the reboot issue) included in 2.12.6 version or do we need to apply this manually in 2.12.6 ? 

[Oleg Drokin]

The last one looks like LU-13054 to me and this patch seems to be missing from the tree you are running (git hash ac40c31)

 

 

[Campbell Mcleay (Inactive)]

I have uploaded the crash logs for couple of reboot instances to check this further.

Uploaded file name: vmcore-dmesg-2021-06-17.txt - Restarted on 17th June
vmcore-dmesg-2021-05-11.txt - Restarted on 11th May

Last restart instance

reboot   system boot  3.10.0-1062.18.1 Thu Jun 17 16:34 - 14:58 (7+22:23)

Load usage seems to be normal during that time

03:50:01 PM         2      1990      8.66      8.37      9.16         2
04:00:01 PM        11      1981      6.24      8.02      8.75         1
04:10:01 PM        15      1981      9.57     10.08      9.54         3
04:20:01 PM         2      1982     11.88     13.18     11.28         1
Average:           10      1983     10.40     10.50     10.42         2

04:35:02 PM       LINUX RESTART

04:40:01 PM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15   blocked
04:50:01 PM         2      1917     14.27     12.43      7.79         2
05:00:01 PM         5      1939     13.30     13.36     10.71         3
05:10:01 PM        11      1931     11.81     12.92     11.84         3
05:20:01 PM        20      1924     17.28     14.74     13.02         2

Most of the restart, could see the message "blk_update_request: critical medium error" always.

[463108.636890] blk_update_request: critical medium error, dev nvme3n1, sector 5325696536
[622470.873927] md: md0: data-check done.
[955488.123023] md: data-check of RAID array md0
[1028448.215074] ------------[ cut here ]------------
[1028448.215083] WARNING: CPU: 7 PID: 0 at lib/percpu-refcount.c:155 percpu_ref_switch_to_atomic_rcu+0x136/0x150
[1028448.215088] percpu ref (no_op) <= 0 (0) after switching to atomic
[1028448.215089] Modules linked in:
[1028448.215091]  vfat fat osp(OE) mdd(OE) lod(OE) mdt(OE) lfsck(OE) mgs(OE) mgc(OE) mpt3sas mpt2sas raid_class scsi_transport_sas mptctl mptbase osd_ldiskfs(OE) ldiskfs(OE) lquota(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) mbcache jbd2 obdclass(OE) lnet(OE) libcfs(OE) dell_rbu nfsv3 nfs fscache binfmt_misc bonding iTCO_wdt iTCO_vendor_support mxm_wmi dcdbas sb_edac intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel kvm irqbypass raid10 sg lpc_ich mei_me mei ipmi_si ipmi_devintf ipmi_msghandler wmi acpi_power_meter pcc_cpufreq nfsd auth_rpcgss nfs_acl lockd grace ip_tables xfs sd_mod crc_t10dif crct10dif_generic 8021q garp mrp stp llc mgag200 i2c_algo_bit drm_kms_helper bnx2x syscopyarea sysfillrect sysimgblt fb_sys_fops ttm crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel ghash_clmulni_intel
[1028448.215136]  ahci drm aesni_intel lrw gf128mul libahci glue_helper ablk_helper cryptd scsi_transport_iscsi libata megaraid_sas nvme ptp nvme_core pps_core drm_panel_orientation_quirks mdio libcrc32c dm_multipath sunrpc dm_mirror dm_region_hash dm_log dm_mod [last unloaded: usb_storage]
[1028448.215163] CPU: 7 PID: 0 Comm: swapper/7 Kdump: loaded Tainted: G           OE  ------------   3.10.0-1062.18.1.el7_lustre.x86_64 #1
[1028448.215164] Hardware name: Dell Inc. PowerEdge R730/072T6D, BIOS 2.11.0 11/02/2019
[1028448.215165] Call Trace:
[1028448.215167]  <IRQ>  [<ffffffff8cf7b416>] dump_stack+0x19/0x1b
[1028448.215178]  [<ffffffff8c89bab8>] __warn+0xd8/0x100
[1028448.215180]  [<ffffffff8c89bb3f>] warn_slowpath_fmt+0x5f/0x80
[1028448.215185]  [<ffffffff8c958b6d>] ? rcu_advance_cbs+0xcd/0xe0
[1028448.215187]  [<ffffffff8cd9b740>] ? null_show+0x20/0x20
[1028448.215189]  [<ffffffff8cb86cd6>] percpu_ref_switch_to_atomic_rcu+0x136/0x150
[1028448.215192]  [<ffffffff8c95a4f8>] rcu_process_callbacks+0x1d8/0x570
[1028448.215195]  [<ffffffff8c8a5435>] __do_softirq+0xf5/0x280
[1028448.215200]  [<ffffffff8cf9242c>] call_softirq+0x1c/0x30
[1028448.215204]  [<ffffffff8c82f715>] do_softirq+0x65/0xa0
[1028448.215206]  [<ffffffff8c8a57b5>] irq_exit+0x105/0x110
[1028448.215209]  [<ffffffff8cf939d8>] smp_apic_timer_interrupt+0x48/0x60
[1028448.215211]  [<ffffffff8cf8fefa>] apic_timer_interrupt+0x16a/0x170
[1028448.215213]  <EOI>  [<ffffffff8cdc2027>] ? cpuidle_enter_state+0x57/0xd0
[1028448.215218]  [<ffffffff8cdc217e>] cpuidle_idle_call+0xde/0x230
[1028448.215221]  [<ffffffff8c837c6e>] arch_cpu_idle+0xe/0xc0
[1028448.215226]  [<ffffffff8c9017da>] cpu_startup_entry+0x14a/0x1e0
[1028448.215231]  [<ffffffff8c85a0c7>] start_secondary+0x1f7/0x270
[1028448.215234]  [<ffffffff8c8000d5>] start_cpu+0x5/0x14
[1028448.215236] ---[ end trace 4441139b69972efc ]---
[1136636.662352] blk_update_request: critical medium error, dev nvme3n1, sector 10406963584
[1136636.710304] blk_update_request: critical medium error, dev nvme3n1, sector 10406967424
[1165058.648561] md: md0: data-check done.
[1560227.473353] md: data-check of RAID array md0
[1745005.678257] blk_update_request: critical medium error, dev nvme3n1, sector 9927251728
[1779948.753709] md: md0: data-check done.
[1852184.120501] blk_update_request: critical medium error, dev nvme3n1, sector 9334756896
[1852184.120532] md/raid10:md0: nvme3n1: rescheduling sector 18668989512
[1852184.120644] blk_update_request: critical medium error, dev nvme3n1, sector 9334757280
[1852184.120673] md/raid10:md0: nvme3n1: rescheduling sector 18668990280
[1852184.120952] blk_update_request: critical medium error, dev nvme3n1, sector 9334756896
[1852184.121138] md/raid10:md0: read error corrected (8 sectors at 262144 on nvme3n1)
[1852184.121148] md/raid10:md0: nvme2n1: redirecting sector 18668989512 to another mirror
[1852184.121526] blk_update_request: critical medium error, dev nvme3n1, sector 9334757280
[1852184.121709] md/raid10:md0: read error corrected (8 sectors at 262144 on nvme3n1)
[1852184.121720] md/raid10:md0: nvme2n1: redirecting sector 18668990280 to another mirror
[2164966.710539] md: data-check of RAID array md0
[2183165.845838] blk_update_request: critical medium error, dev nvme3n1, sector 917466240
[2183165.846403] blk_update_request: critical medium error, dev nvme3n1, sector 917466280
[2431150.697903] md: md0: data-check done.
[2769705.550545] md: data-check of RAID array md0
[2969839.376579] 

sector 10812151448
[2993948.791186] md: md0: data-check done.
[3170956.989559] ------------[ cut here ]------------
[3170956.989584] kernel BUG at /tmp/rpmbuild-lustre-jenkins-KWaNslf3/BUILD/lustre-2.12.5_62_gac40c31/ldiskfs/htree_lock.c:429!
[3170956.989617] invalid opcode: 0000 [#1] SMP 
[3170956.989634] Modules linked in: vfat fat osp(OE) mdd(OE) lod(OE) mdt(OE) lfsck(OE) mgs(OE) mgc(OE) mpt3sas mpt2sas raid_class scsi_transport_sas mptctl mptbase osd_ldiskfs(OE) ldiskfs(OE) lquota(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) mbcache jbd2 obdclass(OE) lnet(OE) libcfs(OE) dell_rbu nfsv3 nfs fscache binfmt_misc bonding iTCO_wdt iTCO_vendor_support mxm_wmi dcdbas sb_edac intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel kvm irqbypass raid10 sg lpc_ich mei_me mei ipmi_si ipmi_devintf ipmi_msghandler wmi acpi_power_meter pcc_cpufreq nfsd auth_rpcgss nfs_acl lockd grace ip_tables xfs sd_mod crc_t10dif crct10dif_generic 8021q garp mrp stp llc mgag200 i2c_algo_bit drm_kms_helper bnx2x syscopyarea sysfillrect sysimgblt fb_sys_fops ttm crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel
[3170956.989935]  ghash_clmulni_intel ahci drm aesni_intel lrw gf128mul libahci glue_helper ablk_helper cryptd scsi_transport_iscsi libata megaraid_sas nvme ptp nvme_core pps_core drm_panel_orientation_quirks mdio libcrc32c dm_multipath sunrpc dm_mirror dm_region_hash dm_log dm_mod [last unloaded: usb_storage]
[3170956.990047] CPU: 28 PID: 17088 Comm: mdt00_017 Kdump: loaded Tainted: G        W  OE  ------------   3.10.0-1062.18.1.el7_lustre.x86_64 #1
[3170956.990085] Hardware name: Dell Inc. PowerEdge R730/072T6D, BIOS 2.11.0 11/02/2019
[3170956.990109] task: ffff9de935f041c0 ti: ffff9de74522c000 task.ti: ffff9de74522c000
[3170956.990132] RIP: 0010:[<ffffffffc0a86284>]  [<ffffffffc0a86284>] htree_node_unlock+0x4b4/0x4c0 [ldiskfs]
[3170956.990179] RSP: 0018:ffff9de74522f8b0  EFLAGS: 00010246
[3170956.990197] RAX: ffff9de933d98600 RBX: 0000000000000001 RCX: ffff9e0936a5b290
[3170956.990219] RDX: 00000000000000c8 RSI: 0000000000000001 RDI: 0000000000000000
[3170956.990241] RBP: ffff9de74522f928 R08: ffff9dcca9a01d00 R09: ffff9dda59559500
[3170956.990263] R10: 0000000000000000 R11: ffff9dcd260b9258 R12: ffff9e0936a5b2d8
[3170956.990285] R13: 0000000000000000 R14: ffff9de7ffea8a00 R15: ffff9dcd260b91e0
[3170956.990308] FS:  0000000000000000(0000) GS:ffff9de93f980000(0000) knlGS:0000000000000000
[3170956.990332] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[3170956.991222] CR2: 00007fdb46c25000 CR3: 0000003ff39b8000 CR4: 00000000003607e0
[3170956.992087] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[3170956.992943] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[3170956.993790] Call Trace:
[3170956.994639]  [<ffffffffc0a8646a>] htree_node_release_all+0x5a/0x80 [ldiskfs]
[3170956.995505]  [<ffffffffc0a864b2>] htree_unlock+0x22/0x70 [ldiskfs]
[3170956.996363]  [<ffffffffc0ad7b1e>] osd_index_ea_delete+0x30e/0xb10 [osd_ldiskfs]
[3170956.997244]  [<ffffffffc138efa8>] lod_sub_delete+0x1c8/0x460 [lod]
[3170956.998285]  [<ffffffffc1369c24>] lod_delete+0x24/0x30 [lod]
[3170956.999350]  [<ffffffffc13de7c4>] __mdd_index_delete_only+0x194/0x250 [mdd]
[3170957.000391]  [<ffffffffc13e1136>] __mdd_index_delete+0x46/0x290 [mdd]
[3170957.001480]  [<ffffffffc13eee78>] mdd_unlink+0x5f8/0xaa0 [mdd]
[3170957.002467]  [<ffffffffc12b0b69>] mdo_unlink+0x46/0x48 [mdt]
[3170957.003319]  [<ffffffffc1274b1d>] mdt_reint_unlink+0xbed/0x14b0 [mdt]
[3170957.004156]  [<ffffffffc12791b3>] mdt_reint_rec+0x83/0x210 [mdt]
[3170957.004990]  [<ffffffffc1255383>] mdt_reint_internal+0x6e3/0xaf0 [mdt]
[3170957.005829]  [<ffffffffc12610f7>] mdt_reint+0x67/0x140 [mdt]
[3170957.006704]  [<ffffffffc0f86e8a>] tgt_request_handle+0xada/0x1570 [ptlrpc]
[3170957.007724]  [<ffffffffc0f605d1>] ? ptlrpc_nrs_req_get_nolock0+0xd1/0x170 [ptlrpc]
[3170957.008755]  [<ffffffffc082cbde>] ? ktime_get_real_seconds+0xe/0x10 [libcfs]
[3170957.009747]  [<ffffffffc0f2b83b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[3170957.010752]  [<ffffffffc0f28655>] ? ptlrpc_wait_event+0xa5/0x360 [ptlrpc]
[3170957.011741]  [<ffffffff8c8d3a33>] ? __wake_up+0x13/0x20
[3170957.012740]  [<ffffffffc0f2f1a4>] ptlrpc_main+0xb34/0x1470 [ptlrpc]
[3170957.013630]  [<ffffffffc0f2e670>] ? ptlrpc_register_service+0xf80/0xf80 [ptlrpc]
[3170957.014404]  [<ffffffff8c8c6321>] kthread+0xd1/0xe0
[3170957.015169]  [<ffffffff8c8c6250>] ? insert_kthread_work+0x40/0x40
[3170957.015910]  [<ffffffff8cf8ed37>] ret_from_fork_nospec_begin+0x21/0x21
[3170957.016633]  [<ffffffff8c8c6250>] ? insert_kthread_work+0x40/0x40
[3170957.017336] Code: 0f 0b 48 8b 45 90 8b 55 8c f3 90 0f a3 10 19 c9 85 c9 75 f5 f0 0f ab 10 19 c9 85 c9 0f 84 a4 fb ff ff eb e5 0f 1f 00 0f 0b 0f 0b <0f> 0b 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 89 f0 48 
[3170957.018817] RIP  [<ffffffffc0a86284>] htree_node_unlock+0x4b4/0x4c0 [ldiskfs]
[3170957.019524]  RSP <ffff9de74522f8b0>

[Oleg Drokin]

is there any more information about the MDS crashes/reboots? Is there an oops/lbug/assert (what's the stacktrace)? a HA-induced reboot due to high load/whatever? something else?

[Campbell Mcleay (Inactive)]

Hi Oleg Drokin,

As we monitored the system with below suggested change , it's noticed that the Metadata server (hmds1) is getting rebooted randomly and the both the clients are evicting from the cluster which is again making issues. Could you please look into that more and suggest ?

lctl set_param ldlm.namespaces.*MDT*mdc*.lru_size=100
lctl set_param -P ldlm.namespaces.*.lru_size=10000
lctl set_param -P ldlm.namespaces.*.lru_max_age=600000

[Oleg Drokin]

these ldlm settings look fine to me if they work for you. You can shorten the max age if you want depending on your workload.

I can't comment on the "svc_rpc_per_connection_limit" parameter as I am not familiar with that part of the NFS stack.

[Campbell Mcleay (Inactive)]

Any updates here ?