************************ crashinfo ************************* /exports/testreports/47845/testresults/sanityn-special1-ldiskfs-centos7_x86_64-centos7_x86_64/oleg101-client-timeout-core (3.10.0-7.9-debug) +==========================+ | *** Crashinfo v1.3.7 *** | +==========================+ +++WARNING+++ PARTIAL DUMP with size(vmcore) < 25% size(RAM) KERNEL: /tmp/crash-anaysis.mDj6D/vmlinux [TAINTED] DUMPFILE: /exports/testreports/47845/testresults/sanityn-special1-ldiskfs-centos7_x86_64-centos7_x86_64/oleg101-client-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Thu Dec 12 11:09:12 EST 2024 UPTIME: 01:07:00 LOAD AVERAGE: 0.00, 0.01, 0.05 TASKS: 152 NODENAME: oleg101-client.virtnet RELEASE: 3.10.0-7.9-debug VERSION: #1 SMP Sat Mar 26 23:28:42 EDT 2022 MACHINE: x86_64 (2399 Mhz) MEMORY: 4 GB PANIC: "" +--------------------------+ >------------------------| Per-cpu Stacks ('bt -a') |------------------------< +--------------------------+ -- CPU#0 -- PID=0 CPU=0 CMD=swapper/0 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 rest_init+0x8e #7 start_kernel+0x456 #8 x86_64_start_reservations+0x2a #9 x86_64_start_kernel+0x152 #10 start_cpu+0x5 -- CPU#1 -- PID=0 CPU=1 CMD=swapper/1 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 -- CPU#2 -- PID=0 CPU=2 CMD=swapper/2 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 -- CPU#3 -- PID=0 CPU=3 CMD=swapper/3 #-1 native_safe_halt+0xb, 449 bytes of data #0 default_idle+0x1e #1 default_enter_idle+0x45 #2 cpuidle_enter_state+0x40 #3 cpuidle_idle_call+0xd8 #4 arch_cpu_idle+0xe #5 cpu_startup_entry+0x14a #6 start_secondary+0x1eb #7 start_cpu+0x5 +--------------------------------+ >---------------------| How This Dump Has Been Created |---------------------< +--------------------------------+ Cannot identify the specific condition that triggered vmcore +---------------+ >------------------------------| Tasks Summary |------------------------------< +---------------+ Number of Threads That Ran Recently ----------------------------------- last second 20 last 5s 24 last 60s 31 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 148 TASK_RUNNING 1 +++WARNING+++ There are 3 threads running in their own namespaces Use 'taskinfo --ns' to get more details +-----------------------+ >--------------------------| 5 Most Recent Threads |--------------------------< +-----------------------+ PID CMD Age ARGS ----- -------------- ------ ---------------------------- 1 systemd 0 ms /usr/lib/systemd/systemd --switched-root --system --deserialize 21 4745 ldlm_bl_01 0 ms (no user stack) 11 rcuos/0 0 ms (no user stack) 9 rcu_sched 0 ms (no user stack) 46 kworker/0:1 76 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955079 3.6 GB ---- FREE 854059 3.3 GB 89% of TOTAL MEM USED 101020 394.6 MB 10% of TOTAL MEM SHARED 10865 42.4 MB 1% of TOTAL MEM BUFFERS 5179 20.2 MB 0% of TOTAL MEM CACHED 47542 185.7 MB 4% of TOTAL MEM SLAB 11331 44.3 MB 1% of TOTAL MEM TOTAL HUGE 0 0 ---- HUGE FREE 0 0 0% of TOTAL HUGE TOTAL SWAP 262143 1024 MB ---- SWAP USED 0 0 0% of TOTAL SWAP SWAP FREE 262143 1024 MB 100% of TOTAL SWAP COMMIT LIMIT 739682 2.8 GB ---- COMMITTED 63016 246.2 MB 8% of TOTAL LIMIT +-------------------------------+ >----------------------| Scheduler Runqueues (per CPU) |----------------------< +-------------------------------+ ---+ CPU=0 ---- | CURRENT TASK , CMD=swapper/0 ---+ CPU=1 ---- | CURRENT TASK , CMD=swapper/1 ---+ CPU=2 ---- | CURRENT TASK , CMD=swapper/2 ---+ CPU=3 ---- | CURRENT TASK , CMD=swapper/3 +------------------------+ >-------------------------| Network Status Summary |-------------------------< +------------------------+ TCP Connection Info ------------------- ESTABLISHED 3 LISTEN 3 NAGLE disabled (TCP_NODELAY): 3 user_data set (NFS etc.): 1 UDP Connection Info ------------------- 2 UDP sockets, 0 in ESTABLISHED Unix Connection Info ------------------------ ESTABLISHED 26 CLOSE 18 LISTEN 8 Raw sockets info -------------------- CLOSE 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 4017.4 eth0 n/a 0.3 RSS_TOTAL=81920 pages, %mem= 1.4 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012b270700 ffff88012ab08000 sysfs sysfs /sys ffff88012b2708c0 ffff880139944000 proc proc /proc ffff88012b270a80 ffff880137678000 devtmpfs devtmpfs /dev ffff88012b270c40 ffff8800b6cff000 securityfs securityfs /sys/kernel/security ffff88012b270e00 ffff88012ab08800 tmpfs tmpfs /dev/shm ffff88012b270fc0 ffff88012b298000 devpts devpts /dev/pts ffff88012b271180 ffff88012ab09000 tmpfs tmpfs /run ffff88012b271340 ffff88012ab09800 tmpfs tmpfs /sys/fs/cgroup ffff88012b271500 ffff88012ab0a000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012b2716c0 ffff88012ab0a800 pstore pstore /sys/fs/pstore ffff88012b271880 ffff88012ab0c800 cgroup cgroup /sys/fs/cgroup/memory ffff88012b271a40 ffff88012b29d800 cgroup cgroup /sys/fs/cgroup/perf_event ffff88012b2921c0 ffff88012b29e000 cgroup cgroup /sys/fs/cgroup/devices ffff88012b292380 ffff88012b29e800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012b292540 ffff88012b29f000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012b292700 ffff88012b29f800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012b2928c0 ffff88012b29a800 cgroup cgroup /sys/fs/cgroup/blkio ffff88012b292a80 ffff88012b299800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012b292c40 ffff88012ab20000 cgroup cgroup /sys/fs/cgroup/pids ffff88012b292e00 ffff88012ab20800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012b292fc0 ffff88012ab21000 configfs configfs /sys/kernel/config ffff880137669500 ffff8800b6d41800 ext4 /dev/nbd0 / ffff88012b271c00 ffff88012b3de800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880138ccb6c0 ffff88012a6aa800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880137669880 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880137669a40 ffff88012a6a6000 hugetlbfs hugetlbfs /dev/hugepages ffff880137669c00 ffff880137679000 mqueue mqueue /dev/mqueue ffff88012b2936c0 ffff8801369b4000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012b271dc0 ffff8800b6242800 ramfs none /mnt ffff88012c0ec000 ffff8800b6245000 tmpfs none /var/lib/stateless/writable ffff88012c0ec1c0 ffff8800b6240000 squashfs /dev/vda /home/green/git/lustre-release ffff88012c0ec380 ffff8800b6245000 tmpfs none /var/cache/man ffff880130964000 ffff8800b6245000 tmpfs none /var/log ffff8801309641c0 ffff8800b6245000 tmpfs none /var/lib/dbus ffff880138ccba40 ffff8800b6245000 tmpfs none /tmp ffff880130964380 ffff8800b6245000 tmpfs none /var/lib/dhclient ffff880130964540 ffff8800b6245000 tmpfs none /var/tmp ffff880138ccbc00 ffff8800b6245000 tmpfs none /var/lib/NetworkManager ffff880138ccbdc0 ffff8800b6245000 tmpfs none /var/lib/systemd/random-seed ffff880130964700 ffff8800b6245000 tmpfs none /var/spool ffff88012b293500 ffff8800b6245000 tmpfs none /var/lib/nfs ffff8801309648c0 ffff8800b6245000 tmpfs none /var/lib/gssproxy ffff88012c0ec540 ffff8800b6245000 tmpfs none /var/lib/logrotate ffff88012b293340 ffff8800b6245000 tmpfs none /etc ffff88012c0ec700 ffff8800b6245000 tmpfs none /var/lib/rsyslog ffff88012b293880 ffff8800b6245000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012c0ec8c0 ffff8801369b2000 nfs4 192.168.200.253:/exports/state/oleg101-client.virtnet /var/lib/stateless/state ffff88012c0ece00 ffff8801369b2000 nfs4 192.168.200.253:/exports/state/oleg101-client.virtnet /boot ffff88012c0ecfc0 ffff8801369b2000 nfs4 192.168.200.253:/exports/state/oleg101-client.virtnet /etc/etc/kdump.conf ffff880130964a80 ffff88012b3de800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b0131340 ffff88012ab0e800 nfs4 192.168.200.253://exports/testreports/47845/testresults/sanityn-special1-ldiskfs-centos7_x86_64-centos7_x86_64 /tmp/tmp/testlogs ffff88012cc181c0 ffff8800b63d4000 tmpfs tmpfs /run/user/0 ffff8800b4265340 ffff8800b6240000 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b0134000 ffff8800b60f2800 lustre 192.168.201.101@tcp:/lustre /mnt/lustre ffff88012c0eda40 ffff8800aae6f000 lustre 192.168.201.101@tcp:/lustre /mnt/lustre2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 55.151299] Key type lgssc registered [ 55.522092] Lustre: Echo OBD driver; http://www.lustre.org/ [ 104.462360] Lustre: Mounted lustre-client [ 106.450554] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 118.153425] Lustre: DEBUG MARKER: oleg101-client.virtnet: executing check_logdir /tmp/testlogs/ [ 119.384531] Lustre: DEBUG MARKER: oleg101-client.virtnet: executing yml_node [ 120.947363] Lustre: DEBUG MARKER: Client: 2.16.0.RC5 [ 121.817693] Lustre: DEBUG MARKER: MDS: 2.16.0.RC5 [ 122.736228] Lustre: DEBUG MARKER: OSS: 2.16.0.RC5 [ 123.210652] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Thu Dec 12 10:04:13 EST 2024 [ 129.121537] Lustre: DEBUG MARKER: excepting tests: 28 [ 129.491224] Lustre: lustre-OST0000-osc-ffff8800b60f2800: disconnect after 23s idle [ 129.830673] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 130.630012] Lustre: DEBUG MARKER: === sanityn: start setup 10:04:20 (1734015860) === [ 130.955660] Lustre: Mounted lustre-client [ 132.716906] Lustre: DEBUG MARKER: oleg101-client.virtnet: executing check_config_client /mnt/lustre [ 141.295350] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 147.656984] Lustre: DEBUG MARKER: === sanityn: finish setup 10:04:37 (1734015877) === [ 149.213655] Lustre: DEBUG MARKER: == sanityn test 16a: 2500 iterations of dual-mount fsx === 10:04:38 (1734015878) [ 155.151776] random: crng init done [ 305.127270] hrtimer: interrupt took 3105414 ns [ 314.273420] Lustre: lustre-OST0000-osc-ffff8800aae6f000: disconnect after 21s idle [ 314.276085] Lustre: Skipped 1 previous similar message [ 419.227026] Lustre: DEBUG MARKER: == sanityn test 16b: 2500 iterations of dual-mount fsx at small size ========================================================== 10:09:08 (1734016148) [ 435.938402] Lustre: 1982:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1734016150/real 1734016150] req@ffff8800aa163480 x1818247339346432/t0(0) o4->lustre-OST0001-osc-ffff8800b60f2800@192.168.201.101@tcp:6/4 lens 488/448 e 0 to 1 dl 1734016166 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 [ 435.954141] Lustre: lustre-OST0001-osc-ffff8800b60f2800: Connection to lustre-OST0001 (at 192.168.201.101@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 440.513313] Lustre: 1981:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1734016154/real 1734016154] req@ffff8800a8a45c00 x1818247339346688/t0(0) o400->lustre-MDT0000-mdc-ffff8800b60f2800@192.168.201.101@tcp:12/10 lens 224/224 e 0 to 1 dl 1734016170 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 440.513353] LustreError: MGC192.168.201.101@tcp: Connection to MGS (at 192.168.201.101@tcp) was lost; in progress operations using this service will fail [ 440.513472] Lustre: lustre-OST0000-osc-ffff8800b60f2800: Connection to lustre-OST0000 (at 192.168.201.101@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 440.544013] Lustre: 1981:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 445.513263] Lustre: 1980:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1734016159/real 1734016159] req@ffff8800a8a47480 x1818247339347584/t0(0) o400->lustre-OST0000-osc-ffff8800b60f2800@192.168.201.101@tcp:28/4 lens 224/224 e 0 to 1 dl 1734016175 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 445.520774] Lustre: 1980:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 450.522307] Lustre: 1980:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1734016164/real 1734016164] req@ffff88012c3a0000 x1818247339348352/t0(0) o400->lustre-OST0000-osc-ffff8800b60f2800@192.168.201.101@tcp:28/4 lens 224/224 e 0 to 1 dl 1734016180 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 450.537498] Lustre: 1980:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 456.281290] Lustre: 1983:0:(client.c:2363:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1734016170/real 1734016170] req@ffff8800aa162d80 x1818247339349760/t0(0) o400->lustre-MDT0000-mdc-ffff8800b60f2800@192.168.201.101@tcp:12/10 lens 224/224 e 0 to 1 dl 1734016186 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 456.296091] Lustre: 1983:0:(client.c:2363:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 1019.935328] LustreError: 10408:0:(osc_cache.c:908:osc_extent_wait()) extent ffff8800a7ab1840@{[0 -> 1023/1023], [3|0|+|rpc|wiY|ffff8800b02021a0], [4218880|1024|+|-|ffff88012e3e98c0|1024|ffff8800ab7cb330]} lustre-OST0001-osc-ffff8800b60f2800: wait ext to 0 timedout, recovery in progress? [ 1019.946966] LustreError: 10408:0:(osc_cache.c:908:osc_extent_wait()) ### extent: ffff8800a7ab1840 ns: lustre-OST0001-osc-ffff8800b60f2800 lock: ffff88012e3e98c0/0x99188b78c51a2ace lrc: 4/0,1 mode: PW/PW res: [0x280000400:0x7:0x0].0x0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x800020080000000 nid: local remote: 0x903ef4aec732260b expref: -99 pid: 10408 timeout: 0 lvb_type: 1 [ 1620.577296] LustreError: 4746:0:(osc_cache.c:908:osc_extent_wait()) extent ffff8800a9ae6a80@{[0 -> 0/1023], [3|0|+|rpc|wiuY|ffff8800a8fa8820], [28672|1|+|-|ffff88012e3e9d40|1024|ffff88012d46e660]} lustre-OST0000-osc-ffff8800b60f2800: wait ext to 0 timedout, recovery in progress? [ 1620.588429] LustreError: 4746:0:(osc_cache.c:908:osc_extent_wait()) ### extent: ffff8800a9ae6a80 ns: lustre-OST0000-osc-ffff8800b60f2800 lock: ffff88012e3e9d40/0x99188b78c519b923 lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x4:0x0].0x0 rrc: 2 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x800029400020000 nid: local remote: 0x903ef4aec7319971 expref: -99 pid: 9547 timeout: 0 lvb_type: 1 ****************************************************************************** ************************ A Summary Of Problems Found ************************* ****************************************************************************** -------------------- A list of all +++WARNING+++ messages -------------------- PARTIAL DUMP with size(vmcore) < 25% size(RAM) There are 3 threads running in their own namespaces Use 'taskinfo --ns' to get more details ------------------------------------------------------------------------------ ** Execution took 11.29s (real) 5.81s (CPU), Child processes: 5.44s