[#LU-1484] Test failure on test suite recovery-small, subtest test

05:43:48:Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash =================================== 05:43:48 (1338900228) 05:43:53:LustreError: 28843:0:(fail.c:126:__cfs_fail_timeout_set()) cfs_fail_timeout id b00 sleeping for 10000ms 05:44:01:LustreError: 28843:0:(fail.c:130:__cfs_fail_timeout_set()) cfs_fail_timeout id b00 awake 05:46:17:INFO: task lctl:28843 blocked for more than 120 seconds. 05:46:17:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 05:46:18:lctl D 0000000000001000 0 28843 28631 (NOTLB) 05:46:18: ffff8100517dfe38 0000000000000086 ffffffff800cfa4c ffff810037d56d40 05:46:18: 0000000000000282 0000000000000007 ffff810067000080 ffff8100668c47e0 05:46:18: 000005e137f5c0e1 000000000001b643 ffff810067000268 0000000000000001 05:46:18:Call Trace: 05:46:18: [<ffffffff800cfa4c>] zone_statistics+0x3e/0x6d 05:46:18: [<ffffffff8000f40b>] __alloc_pages+0x78/0x308 05:46:19: [<ffffffff8006468c>] __down_read+0x7a/0x92 05:46:19: [<ffffffff888d90e2>] :obdclass:lprocfs_fops_read+0x82/0x1e0 05:46:19: [<ffffffff8010ab77>] proc_reg_read+0x7e/0x99 05:46:19: [<ffffffff8000b721>] vfs_read+0xcb/0x171 05:46:19: [<ffffffff80011d15>] sys_read+0x45/0x6e 05:46:19: [<ffffffff8005d28d>] tracesys+0xd5/0xe0 05:46:19: 05:46:19:INFO: task umount:28863 blocked for more than 120 seconds. 05:46:22:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 05:46:24:umount D ffff810002536420 0 28863 28862 (NOTLB) 05:46:24: ffff810057f81828 0000000000000082 0000000000000000 0000000100000002 05:46:24: 0000000000000000 0000000000000007 ffff8100668c47e0 ffffffff80319b60 05:46:24: 000005e137f5e08c 0000000000001fab ffff8100668c49c8 0000000000000000 05:46:24:Call Trace: 05:46:24: [<ffffffff80064cb5>] __reacquire_kernel_lock+0x2e/0x47 05:46:24: [<ffffffff80063171>] wait_for_completion+0x79/0xa2 05:46:24: [<ffffffff8008ee74>] default_wake_function+0x0/0xe 05:46:24: [<ffffffff8010dcdb>] remove_proc_entry+0xfb/0x1c7 05:46:25: [<ffffffff888d7603>] :obdclass:lprocfs_remove+0x103/0x130 05:46:25: [<ffffffff888d6a46>] :obdclass:lprocfs_free_stats+0x1e6/0x230 05:46:25: [<ffffffff888d7a1f>] :obdclass:lprocfs_obd_cleanup+0x6f/0x80 05:46:28: [<ffffffff88b7ca32>] :osc:osc_precleanup+0x292/0x370 05:46:28: [<ffffffff888ff13c>] :obdclass:lu_context_fini+0x1c/0x50 05:46:28: [<ffffffff888e303f>] :obdclass:class_cleanup+0xc6f/0xe30 05:46:28: [<ffffffff888e6d8c>] :obdclass:class_process_config+0x1e5c/0x3200 05:46:28: [<ffffffff888e97f7>] :obdclass:class_manual_cleanup+0xad7/0xe80 05:46:28: [<ffffffff8002ff6f>] __up_write+0x27/0xf2 05:46:30: [<ffffffff88bba26c>] :lov:lov_putref+0xb0c/0xb90 05:46:30: [<ffffffff88bc2b98>] :lov:lov_disconnect+0x308/0x3e0 05:46:30: [<ffffffff88c66d94>] :lustre:client_common_put_super+0x894/0xed0 05:46:30: [<ffffffff88c676e5>] :lustre:ll_put_super+0x195/0x310 05:46:30: [<ffffffff800f079e>] invalidate_inodes+0xce/0xe0 05:46:30: [<ffffffff800e77ab>] generic_shutdown_super+0x79/0xfb 05:46:30: [<ffffffff800e787b>] kill_anon_super+0x9/0x35 05:46:30: [<ffffffff800e792c>] deactivate_super+0x6a/0x82 05:46:31: [<ffffffff800f1e8b>] sys_umount+0x245/0x27b 05:46:31: [<ffffffff800ba767>] audit_syscall_entry+0x1a8/0x1d3 05:46:31: [<ffffffff8005d28d>] tracesys+0xd5/0xe0

proc reader proc remover proc_reg_read() LPROCFS_WRITE_ENTRY() // down_write _lprocfs_lock semaphore -------> (1) pdeaux->pde_users++ lprocfs_fops_read() LPROCFS_ENTRY_AND_CHECK() // down_read _lprocfs_lock semaphore, wait here ---------------------------> (2) remove_proc_entry() if (pdeaux->pde_users > 0) wait_for_completion() ------------------------------------> (3) ... pde_users_dec() // pdeaux->pde_users--, complete() ---------------------------------------------------------- (4)

== recovery-small test 57: read procfs entries causes kernel crash =================================== 19:13:57 (1354936437) fail_loc=0x80000B00 CMD: fat-intel-3vm6.lab.whamcloud.com grep -c /mnt/lustre' ' /proc/mounts Stopping client fat-intel-3vm6.lab.whamcloud.com /mnt/lustre (opts:) CMD: fat-intel-3vm6.lab.whamcloud.com lsof -t /mnt/lustre CMD: fat-intel-3vm6.lab.whamcloud.com umount /mnt/lustre 2>&1

19:14:02:Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash =================================== 19:13:57 (1354936437)
19:14:02:Lustre: DEBUG MARKER: grep -c /mnt/lustre' ' /proc/mounts
19:14:02:LustreError: 9173:0:(fail.c:133:__cfs_fail_timeout_set()) cfs_fail_timeout id b00 sleeping for 10000ms
19:14:02:Lustre: DEBUG MARKER: lsof -t /mnt/lustre
19:14:02:Lustre: DEBUG MARKER: umount /mnt/lustre 2>&1
19:14:13:LustreError: 9173:0:(fail.c:137:__cfs_fail_timeout_set()) cfs_fail_timeout id b00 awake
19:16:57:INFO: task lctl:9173 blocked for more than 120 seconds.
19:16:57:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
19:16:57:lctl          D 0000000000001000     0  9173   8913                     (NOTLB)
19:16:57: ffff810044841e38 0000000000000086 ffffffff800cfa80 ffff810037d56d40
19:16:57: 0000000000000282 0000000000000007 ffff81004de4f860 ffff81005f2120c0
19:16:57: 00002a16f848196c 0000000000020344 ffff81004de4fa48 0000000000000001
19:16:57:Call Trace:
19:16:57: [<ffffffff800cfa80>] zone_statistics+0x3e/0x6d
19:16:58: [<ffffffff8000f47b>] __alloc_pages+0x78/0x308
19:16:58: [<ffffffff8006468c>] __down_read+0x7a/0x92
19:16:58: [<ffffffff889170c2>] :obdclass:lprocfs_fops_read+0x82/0x200
19:16:58: [<ffffffff8010b73e>] proc_reg_read+0x7e/0x99
19:16:58: [<ffffffff8000b72f>] vfs_read+0xcb/0x171
19:16:58: [<ffffffff80011d85>] sys_read+0x45/0x6e
19:16:58: [<ffffffff8005d28d>] tracesys+0xd5/0xe0
19:16:58:
19:16:58:INFO: task umount:9195 blocked for more than 120 seconds.
19:16:58:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
19:16:58:umount        D ffff810002536420     0  9195   9194                     (NOTLB)
19:16:58: ffff810058613a08 0000000000000086 00000000ffffffff 0000000000000020
19:16:58: 00000000ffffffff 0000000000000007 ffff81005f2120c0 ffffffff8031ab60
19:16:58: 00002a16f8483cb6 000000000000234a ffff81005f2122a8 0000000000000000
19:16:58:Call Trace:
19:16:58: [<ffffffff80064cb5>] __reacquire_kernel_lock+0x2e/0x47
19:16:58: [<ffffffff80063171>] wait_for_completion+0x79/0xa2
19:16:58: [<ffffffff8008ee97>] default_wake_function+0x0/0xe
19:16:58: [<ffffffff8010e8a2>] remove_proc_entry+0xfb/0x1c7
19:16:58: [<ffffffff88915573>] :obdclass:lprocfs_remove+0x103/0x130
19:16:58: [<ffffffff889159d0>] :obdclass:lprocfs_obd_cleanup+0x90/0xa0
19:16:58: [<ffffffff88caf665>] :osc:osc_precleanup+0x2e5/0x3a0
19:16:58: [<ffffffff88920c35>] :obdclass:class_cleanup+0xc55/0xda0
19:16:58: [<ffffffff889241f6>] :obdclass:class_process_config+0x1b46/0x2cc0
19:16:58: [<ffffffff88926a0b>] :obdclass:class_manual_cleanup+0x9bb/0xd70
19:16:58: [<ffffffff88d03c5d>] :lov:lov_putref+0xa7d/0xaf0
19:16:58: [<ffffffff88cfe623>] :lov:lov_del_target+0x6d3/0x720
19:16:58: [<ffffffff88d0b78b>] :lov:lov_disconnect+0x39b/0x440
19:16:58: [<ffffffff88de73ea>] :lustre:client_common_put_super+0x83a/0xe10
19:16:58: [<ffffffff88de7d15>] :lustre:ll_put_super+0x1a5/0x330
19:16:58: [<ffffffff800f120a>] invalidate_inodes+0xce/0xe0
19:16:58: [<ffffffff800e78ae>] generic_shutdown_super+0x79/0xfb
19:16:58: [<ffffffff800e797e>] kill_anon_super+0x9/0x35
19:16:58: [<ffffffff800e7a2f>] deactivate_super+0x6a/0x82
19:16:58: [<ffffffff800f28f7>] sys_umount+0x245/0x27b
19:16:58: [<ffffffff800ba78a>] audit_syscall_entry+0x1a8/0x1d3
19:16:58: [<ffffffff8005d28d>] tracesys+0xd5/0xe0

/* Wait until all existing callers into module are done. */ if (pdeaux->pde_users > 0) { DECLARE_COMPLETION_ONSTACK(c); pdeaux = to_pde_aux(de); if (!pdeaux->pde_unload_completion) pdeaux->pde_unload_completion = &c; spin_unlock(&pdeaux->pde_unload_lock); spin_unlock(&proc_subdir_lock); wait_for_completion(pdeaux->pde_unload_completion); spin_lock(&proc_subdir_lock); goto continue_removing; }

LU-1484 kernel: pass RHEL5 build for 2.6.18-308 For vanilla kernel, proc_dir_entry::deleted and ::pde_users co-exists from 2.6.23 to 2.6.23.17. For some RHEL5 kernels, it defines co-existings proc_dir_entry::deleted and proc_dir_entry_aux::pde_users.

LU-1484 lprocfs: refine LC_PROCFS_USERS check In some RHEL patched 2.6.18 kernels, pde_users member is added in another struct proc_dir_entry_aux instead of in struct proc_dir_entry in later kernel version of 2.6.23.

$ tail -n 15 linux-2.6.18-308.11.1.el5-b18/fs/proc/internal.h /* * RHEL internal wrapper to extend struct proc_dir_entry */ struct proc_dir_entry_aux { struct proc_dir_entry pde; int pde_users; /* number of callers into module in progress */ spinlock_t pde_unload_lock; /* proc_fops checks and pde_users bumps */ struct completion *pde_unload_completion; char name[]; /* PDE name */ }; static inline struct proc_dir_entry_aux *to_pde_aux(struct proc_dir_entry *d) { return container_of(d, struct proc_dir_entry_aux, pde); } $ ./configure --with-linux=/path-to/linux-2.6.18-308.11.1.el5-b18 ... ... checking if kernel has pde_users member in procfs entry struct... yes ... checking if kernel has deleted member in procfs entry struct... yes ... $ grep PROCFS ~/work/lustre-b18/config.h 440:#define HAVE_PROCFS_DELETED 1 443:#define HAVE_PROCFS_USERS 1 $ONLY=57 bash recovery-small.sh ... ... == test 57: read procfs entries causes kernel crash == 20:41:25 fail_loc=0x80000B00 Stopping client test3 /mnt/lustre (opts:) fail_loc=0x80000B00 Stopping /mnt/mds (opts:) Failover mds to test3 20:41:49 (1359549709) waiting for test3 network 900 secs ... 20:41:49 (1359549709) network interface is UP Starting mds: -o loop -o abort_recovery /tmp/lustre-mdt /mnt/mds lnet.debug=0x33f1504 lnet.subsystem_debug=0xffb7e3ff lnet.debug_mb=32 Started lustre-MDT0000 recovery-small.sh: line 992: kill: (1143) - No such process fail_loc=0 Starting client: test3: -o user_xattr,acl,flock test3@tcp:/lustre /mnt/lustre lnet.debug=0x33f1504 lnet.subsystem_debug=0xffb7e3ff lnet.debug_mb=32 Filesystem 1K-blocks Used Available Use% Mounted on test3@tcp:/lustre 562408 53656 478752 11% /mnt/lustre Resetting fail_loc on all nodes...done. PASS 57 (26s) ...===== recovery-small.sh test complete, duration 28 sec ======================

#include <linux/kernel.h> | | #include "/var/lib/jenkins/workspace/lustre-b1_8/arch/x86_64/build_type/client/distro/el5/ib_stack/inkernel/BUILD/reused/usr/src/kernels/2.6.18-348.1.1.el5-x86_64/fs/proc/internal.h" | | int | main (void) | { | | struct proc_dir_entry_aux pde_aux; | | pde_aux.pde_users = 0; | | ; | return 0; | } configure:14056: result: no

if ! kernelrpm=$(find_linux_rpm "-$DEVEL_KERNEL_TYPE"); then fatal 1 "Could not find the kernel-$DEVEL_KERNEL_TYPE RPM in ${KERNELRPMSBASE}/${lnxmaj}/${DISTRO}" fi if ! lnxrel="$lnxrel" unpack_linux_devel_rpm "$kernelrpm" "-"; then fatal 1 "Could not find the Linux tree in $kernelrpm" fi

+ kernelrpm=/var/lib/jenkins/lbuild-data/kernelrpm/2.6.18/rhel5/x86_64/kernel-devel-2.6.18-348.1.1.el5.x86_64.rpm ... + unpack_linux_devel_rpm /var/lib/jenkins/lbuild-data/kernelrpm/2.6.18/rhel5/x86_64/kernel-devel-2.6.18-348.1.1.el5.x86_64.rpm -

++ ./configure --build=x86_64-redhat-linux-gnu --host=x86_64-redhat-linux-gnu --target=x86_64-redhat-linux-gnu --program-prefix= --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/libexec --localstatedir=/var --sharedstatedir=/usr/com --mandir=/usr/share/man --infodir=/usr/share/info --with-linux=/var/lib/jenkins/workspace/lustre-b1_8/arch/x86_64/build_type/client/distro/el5/ib_stack/inkernel/BUILD/reused/usr/src/kernels/2.6.18-348.1.1.el5-x86_64 --with-linux-obj=/var/lib/jenkins/workspace/lustre-b1_8/arch/x86_64/build_type/client/distro/el5/ib_stack/inkernel/BUILD/reused/usr/src/kernels/2.6.18-348.1.1.el5-x86_64 --disable-server --enable-liblustre --enable-liblustre-tests --with-release=wc1_2.6.18_348.1.1.el5_g3480bb0 --enable-tests --enable-liblustre-tests

static inline int LPROCFS_ENTRY_AND_CHECK(struct proc_dir_entry *dp) { int deleted = 0; #ifdef HAVE_PROCFS_USERS spin_lock(&dp->pde_unload_lock); #endif if (unlikely(dp->proc_fops == NULL)) deleted = 1; #ifdef HAVE_PROCFS_USERS spin_unlock(&dp->pde_unload_lock); #endif LPROCFS_ENTRY(); #if defined(HAVE_PROCFS_DELETED) if (unlikely(dp->deleted)) { LPROCFS_EXIT(); deleted = 1; } #endif return deleted ? -ENODEV : 0; }

[LU-1484] Test failure on test suite recovery-small, subtest test_57 Created: 05/Jun/12 Updated: 18/Apr/13 Resolved: 21/Feb/13
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	Lustre 2.3.0, Lustre 2.1.2, Lustre 2.1.3, Lustre 2.1.4, Lustre 1.8.8
Fix Version/s:	Lustre 2.4.0, Lustre 2.1.5, Lustre 1.8.9

[LU-1484] Test failure on test suite recovery-small, subtest test_57 Created: 05/Jun/12 Updated: 18/Apr/13 Resolved: 21/Feb/13