************************ crashinfo ************************* /exports/testreports/51092/testresults/sanityn-zfs-centos7_x86_64-centos7_x86_64/oleg134-server-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.Q4Z6k/vmlinux [TAINTED] DUMPFILE: /exports/testreports/51092/testresults/sanityn-zfs-centos7_x86_64-centos7_x86_64/oleg134-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Fri Apr 25 20:10:02 EDT 2025 UPTIME: 01:49:09 LOAD AVERAGE: 7.46, 2.64, 1.34 TASKS: 380 NODENAME: oleg134-server.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 33 last 5s 85 last 60s 142 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 366 TASK_RUNNING 1 TASK_UNINTERRUPTIBLE 10 +++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 ----- -------------- ------ ---------------------------- 3308 socknal_reaper 0 ms (no user stack) 23584 ll_ost_io00_019 0 ms (no user stack) 27813 ll_ost_io00_010 0 ms (no user stack) 23024 ll_ost_io00_018 0 ms (no user stack) 25039 ll_ost_io00_005 2 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 693661 2.6 GB 72% of TOTAL MEM USED 261406 1021.1 MB 27% of TOTAL MEM SHARED 12116 47.3 MB 1% of TOTAL MEM BUFFERS 5943 23.2 MB 0% of TOTAL MEM CACHED 71726 280.2 MB 7% of TOTAL MEM SLAB 25997 101.6 MB 2% 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 739676 2.8 GB ---- COMMITTED 60320 235.6 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 9 LISTEN 3 NAGLE disabled (TCP_NODELAY): 7 user_data set (NFS etc.): 8 UDP Connection Info ------------------- 2 UDP sockets, 0 in ESTABLISHED Unix Connection Info ------------------------ ESTABLISHED 26 CLOSE 17 LISTEN 8 Raw sockets info -------------------- CLOSE 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 6541.1 eth0 n/a 2.9 RSS_TOTAL=54108 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff880138ccac40 ffff8800b54ef000 sysfs sysfs /sys ffff880138ccae00 ffff880139944000 proc proc /proc ffff880138ccafc0 ffff880137678000 devtmpfs devtmpfs /dev ffff880138ccb180 ffff8800b5280800 securityfs securityfs /sys/kernel/security ffff880137668380 ffff8800b5a74000 tmpfs tmpfs /dev/shm ffff880137668540 ffff88012b2a0000 devpts devpts /dev/pts ffff880137668700 ffff8800b5a74800 tmpfs tmpfs /run ffff880138ccb340 ffff8800b54ef800 tmpfs tmpfs /sys/fs/cgroup ffff880138ccb500 ffff88012a320000 cgroup cgroup /sys/fs/cgroup/systemd ffff880138ccb6c0 ffff88012a320800 pstore pstore /sys/fs/pstore ffff8801376688c0 ffff8800b5a76800 cgroup cgroup /sys/fs/cgroup/devices ffff880137668a80 ffff8800b5a76000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff880137668c40 ffff8800b5a75800 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff880137668e00 ffff8800b5a75000 cgroup cgroup /sys/fs/cgroup/cpuset ffff880138ccb880 ffff88012a321000 cgroup cgroup /sys/fs/cgroup/perf_event ffff880138ccba40 ffff88012a321800 cgroup cgroup /sys/fs/cgroup/pids ffff880138ccbc00 ffff88012a322000 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff880138ccbdc0 ffff88012a322800 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a284000 ffff88012a323000 cgroup cgroup /sys/fs/cgroup/blkio ffff880137668fc0 ffff8800b5a77000 cgroup cgroup /sys/fs/cgroup/memory ffff88012b2dc1c0 ffff8800b5297800 configfs configfs /sys/kernel/config ffff880137669340 ffff8800b53a9800 ext4 /dev/nbd0 / ffff880129dd8380 ffff8800b53a8800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff880129dd88c0 ffff8800b4773800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff88012b2dc000 ffff88012b2a1800 mqueue mqueue /dev/mqueue ffff88012b2dc380 ffff88012fcc0000 hugetlbfs hugetlbfs /dev/hugepages ffff880137669500 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880129dd8700 ffff8800b4770000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012b2dc540 ffff88012fcc6000 ramfs none /mnt ffff88012b2dc700 ffff88012fcc1800 squashfs /dev/vda /home/green/git/lustre-release ffff880137669880 ffff8800b45b9000 tmpfs none /var/lib/stateless/writable ffff88012a284380 ffff8800b45b9000 tmpfs none /var/cache/man ffff880129dd8c40 ffff8800b45b9000 tmpfs none /var/log ffff880129dd8e00 ffff8800b45b9000 tmpfs none /var/lib/dbus ffff880129dd8fc0 ffff8800b45b9000 tmpfs none /tmp ffff880137669a40 ffff8800b45b9000 tmpfs none /var/lib/dhclient ffff880129dd9180 ffff8800b45b9000 tmpfs none /var/tmp ffff88012a284540 ffff8800b45b9000 tmpfs none /var/lib/NetworkManager ffff88012a284700 ffff8800b45b9000 tmpfs none /var/lib/systemd/random-seed ffff88012a2848c0 ffff8800b45b9000 tmpfs none /var/spool ffff88012a284a80 ffff8800b45b9000 tmpfs none /var/lib/nfs ffff880137669c00 ffff8800b45b9000 tmpfs none /var/lib/gssproxy ffff88012a284c40 ffff8800b45b9000 tmpfs none /var/lib/logrotate ffff880137669dc0 ffff8800b45b9000 tmpfs none /etc ffff88012a284e00 ffff8800b45b9000 tmpfs none /var/lib/rsyslog ffff88012a284fc0 ffff8800b45b9000 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff880137669180 ffff8800b4776800 nfs4 192.168.200.253:/exports/state/oleg134-server.virtnet /var/lib/stateless/state ffff8800b464a1c0 ffff8800b4776800 nfs4 192.168.200.253:/exports/state/oleg134-server.virtnet /boot ffff8800b464a380 ffff8800b4776800 nfs4 192.168.200.253:/exports/state/oleg134-server.virtnet /etc/etc/kdump.conf ffff8800b464a540 ffff8800b53a8800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff88012a285dc0 ffff88012fcc1800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b464b180 ffff8800b47e3800 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b1950c40 ffff88009ea7d800 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff8800b1951880 ffff88009bf00000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 6378.248100] Lustre: DEBUG MARKER: Iteration 49 [ 6386.227005] Lustre: DEBUG MARKER: oleg134-server.virtnet: executing load_modules_local [ 6387.405865] Lustre: DEBUG MARKER: Iteration 50 [ 6395.130826] Lustre: DEBUG MARKER: oleg134-server.virtnet: executing load_modules_local [ 6399.097971] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 20:07:29 (1745626049) [ 6400.710498] LustreError: 18215:0:(mdt_handler.c:2501:mdt_getattr_name_lock()) cfs_fail_timeout id 534 sleeping for 14000ms [ 6400.714870] LustreError: 18215:0:(mdt_handler.c:2501:mdt_getattr_name_lock()) Skipped 1 previous similar message [ 6414.718337] LustreError: 18215:0:(mdt_handler.c:2501:mdt_getattr_name_lock()) cfs_fail_timeout id 534 awake [ 6414.721864] LustreError: 18215:0:(mdt_handler.c:2501:mdt_getattr_name_lock()) Skipped 1 previous similar message [ 6414.725285] Lustre: 18215:0:(service.c:2506:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (11/3s); client may timeout req@ffff880057dc0a80 x1830421573673856/t0(0) o101->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:377/0 lens 584/640 e 0 to 0 dl 1745626062 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 6415.459126] Lustre: lustre-MDT0000: Client 5abd22ae-4c3d-4573-b473-52696678ada6 (at 192.168.201.34@tcp) reconnecting [ 6415.462732] Lustre: Skipped 1 previous similar message [ 6431.489943] Lustre: lustre-MDT0000: Client 5abd22ae-4c3d-4573-b473-52696678ada6 (at 192.168.201.34@tcp) reconnecting [ 6447.530266] Lustre: lustre-MDT0000: Client 5abd22ae-4c3d-4573-b473-52696678ada6 (at 192.168.201.34@tcp) reconnecting [ 6463.560844] Lustre: lustre-MDT0000: Client 5abd22ae-4c3d-4573-b473-52696678ada6 (at 192.168.201.34@tcp) reconnecting [ 6464.148475] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 20:08:34 (1745626114) [ 6464.627427] Lustre: DEBUG MARKER: SKIP: sanityn test_111 needs >= 2 MDTs [ 6465.174431] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 20:08:36 (1745626116) [ 6465.655653] Lustre: DEBUG MARKER: SKIP: sanityn test_112 We need at least 2 MDTs for this test [ 6466.210622] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 20:08:37 (1745626117) [ 6468.163286] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 20:08:39 (1745626119) [ 6468.605688] Lustre: DEBUG MARKER: SKIP: sanityn test_114 We need at least 2 MDTs for this test [ 6469.162318] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 20:08:40 (1745626120) [ 6469.613661] Lustre: DEBUG MARKER: SKIP: sanityn test_115 ldiskfs only test [ 6470.129744] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 20:08:41 (1745626121) [ 6470.626436] Lustre: DEBUG MARKER: SKIP: sanityn test_116 needs >= 2 MDTs [ 6471.161477] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 20:08:42 (1745626122) [ 6479.024284] Lustre: 8471:0:(service.c:1582:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/4), not sending early reply req@ffff88011bf8ad80 x1830421573700864/t0(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:450/0 lens 4584/448 e 0 to 0 dl 1745626135 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6489.600143] Lustre: lustre-OST0000: Client 5abd22ae-4c3d-4573-b473-52696678ada6 (at 192.168.201.34@tcp) reconnecting [ 6493.016316] LustreError: 27813:0:(ofd_io.c:1283:ofd_commitrw_write()) cfs_fail_timeout id 1e1 awake [ 6493.021021] LustreError: 27813:0:(ofd_io.c:1283:ofd_commitrw_write()) Skipped 4 previous similar messages [ 6505.072262] Lustre: 25042:0:(service.c:1582:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/-2), not sending early reply req@ffff8800ac228e00 x1830421573721088/t0(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:476/0 lens 4584/448 e 0 to 0 dl 1745626161 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6505.082394] Lustre: 25042:0:(service.c:1582:ptlrpc_at_send_early_reply()) Skipped 8 previous similar messages [ 6513.064931] Lustre: 23024:0:(service.c:2506:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (17/3s); client may timeout req@ffff88006cc23b80 x1830421573718656/t4294981085(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:476/0 lens 4584/448 e 0 to 0 dl 1745626161 ref 1 fl Complete:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6525.104470] Lustre: 27819:0:(service.c:1582:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/-2), not sending early reply req@ffff88009a593b80 x1830421573726720/t0(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:496/0 lens 4584/448 e 0 to 0 dl 1745626181 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6525.115482] Lustre: 27819:0:(service.c:1582:ptlrpc_at_send_early_reply()) Skipped 8 previous similar messages [ 6533.097324] Lustre: 23024:0:(service.c:2506:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (17/3s); client may timeout req@ffff880070450e00 x1830421573724672/t4294981094(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:496/0 lens 4584/448 e 0 to 0 dl 1745626181 ref 1 fl Complete:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6533.107738] Lustre: 23024:0:(service.c:2506:ptlrpc_server_handle_request()) Skipped 8 previous similar messages [ 6545.136533] Lustre: 8472:0:(service.c:1582:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/-2), not sending early reply req@ffff88008e34c380 x1830421573734784/t0(0) o4->5abd22ae-4c3d-4573-b473-52696678ada6@192.168.201.34@tcp:516/0 lens 4584/448 e 0 to 0 dl 1745626201 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 6545.148326] Lustre: 8472:0:(service.c:1582:ptlrpc_at_send_early_reply()) Skipped 10 previous similar messages ****************************************************************************** ************************ 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 12.87s (real) 7.30s (CPU), Child processes: 5.50s