************************ crashinfo ************************* /exports/testreports/48650/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg454-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.54ZHO/vmlinux [TAINTED] DUMPFILE: /exports/testreports/48650/testresults/racer-ldiskfs-DNE-centos7_x86_64-centos7_x86_64/oleg454-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Fri Jan 17 11:36:05 EST 2025 UPTIME: 00:21:24 LOAD AVERAGE: 0.00, 0.17, 0.52 TASKS: 300 NODENAME: oleg454-server.virtnet RELEASE: 3.10.0-7.9-debug VERSION: #1 SMP Sat Mar 26 23:28:42 EDT 2022 MACHINE: x86_64 (2400 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 27 last 5s 65 last 60s 79 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 296 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 ----- -------------- ------ ---------------------------- 9 rcu_sched 0 ms (no user stack) 6839 ldlm_bl_02 0 ms (no user stack) 4084 l2arc_feed 0 ms (no user stack) 917 in:imjournal 0 ms /usr/sbin/rsyslogd -n 1 systemd 5 ms /usr/lib/systemd/systemd --switched-root --system --deserialize 20 +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 678990 2.6 GB 71% of TOTAL MEM USED 276077 1.1 GB 28% of TOTAL MEM SHARED 32512 127 MB 3% of TOTAL MEM BUFFERS 30297 118.3 MB 3% of TOTAL MEM CACHED 101492 396.5 MB 10% of TOTAL MEM SLAB 21531 84.1 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 59007 230.5 MB 7% 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 5 LISTEN 3 NAGLE disabled (TCP_NODELAY): 4 user_data set (NFS etc.): 4 UDP Connection Info ------------------- 2 UDP sockets, 0 in ESTABLISHED Unix Connection Info ------------------------ ESTABLISHED 26 CLOSE 17 LISTEN 8 Raw sockets info -------------------- ESTABLISHED 1 Interfaces Info --------------- How long ago (in seconds) interfaces transmitted/received? Name RX TX ---- ---------- --------- lo n/a 1281.3 eth0 n/a 1.8 RSS_TOTAL=49768 pages, %mem= 0.8 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff8801370e8380 ffff8800b525c000 sysfs sysfs /sys ffff8801370e8540 ffff880139944000 proc proc /proc ffff8801370e8700 ffff880137678000 devtmpfs devtmpfs /dev ffff8801370e88c0 ffff8800b54ca800 securityfs securityfs /sys/kernel/security ffff88012b2628c0 ffff8800b54cb800 tmpfs tmpfs /dev/shm ffff88012b262a80 ffff880137057000 devpts devpts /dev/pts ffff88012b262c40 ffff8800b54cc000 tmpfs tmpfs /run ffff88012b262e00 ffff8800b54cc800 tmpfs tmpfs /sys/fs/cgroup ffff88012b262fc0 ffff8800b54cd000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012b263180 ffff8800b54cd800 pstore pstore /sys/fs/pstore ffff8801370e8a80 ffff8800b525c800 cgroup cgroup /sys/fs/cgroup/hugetlb ffff8801370e8c40 ffff8800b525d000 cgroup cgroup /sys/fs/cgroup/perf_event ffff8801370e8e00 ffff8800b525d800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff8801370e8fc0 ffff8800b525e000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff8801370e9180 ffff8800b525e800 cgroup cgroup /sys/fs/cgroup/devices ffff8801370e9340 ffff8800b525f000 cgroup cgroup /sys/fs/cgroup/pids ffff8801370e9500 ffff8800b525f800 cgroup cgroup /sys/fs/cgroup/blkio ffff8801370e96c0 ffff88012a2e8000 cgroup cgroup /sys/fs/cgroup/cpuset ffff8801370e9880 ffff88012a2e8800 cgroup cgroup /sys/fs/cgroup/freezer ffff8801370e9a40 ffff88012a2e9000 cgroup cgroup /sys/fs/cgroup/memory ffff8801370e9dc0 ffff88012a2eb800 configfs configfs /sys/kernel/config ffff8801376688c0 ffff8800b40dd800 ext4 /dev/nbd0 / ffff8800b4b0cfc0 ffff88012a2ee800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff8800b4b0d6c0 ffff8800b4265800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880138ccae00 ffff88012a2ea800 hugetlbfs hugetlbfs /dev/hugepages ffff880138ccafc0 ffff8801377d7000 mqueue mqueue /dev/mqueue ffff88012b263500 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff88012b2636c0 ffff8800b4902000 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff8800b4b0da40 ffff8800b4267000 ramfs none /mnt ffff88012b263880 ffff8800b4900800 tmpfs none /var/lib/stateless/writable ffff8800b4b0dc00 ffff8800b4263000 squashfs /dev/vda /home/green/git/lustre-release ffff8800b4b0d500 ffff8800b4900800 tmpfs none /var/cache/man ffff88012b263a40 ffff8800b4900800 tmpfs none /var/log ffff8800b4b0d340 ffff8800b4900800 tmpfs none /var/lib/dbus ffff880138ccb340 ffff8800b4900800 tmpfs none /tmp ffff8800b4b0d180 ffff8800b4900800 tmpfs none /var/lib/dhclient ffff8800b1d92000 ffff8800b4900800 tmpfs none /var/tmp ffff8800b1d921c0 ffff8800b4900800 tmpfs none /var/lib/NetworkManager ffff88012b263c00 ffff8800b4900800 tmpfs none /var/lib/systemd/random-seed ffff88012b263dc0 ffff8800b4900800 tmpfs none /var/spool ffff8800b43aa000 ffff8800b4900800 tmpfs none /var/lib/nfs ffff880137668540 ffff8800b4900800 tmpfs none /var/lib/gssproxy ffff880137668a80 ffff8800b4900800 tmpfs none /var/lib/logrotate ffff880137668c40 ffff8800b4900800 tmpfs none /etc ffff8800b1d92380 ffff8800b4900800 tmpfs none /var/lib/rsyslog ffff880137668e00 ffff8800b4900800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff880137668fc0 ffff880129f97000 nfs4 192.168.200.253:/exports/state/oleg454-server.virtnet /var/lib/stateless/state ffff8800b43aa380 ffff880129f97000 nfs4 192.168.200.253:/exports/state/oleg454-server.virtnet /boot ffff8800b1d92540 ffff880129f97000 nfs4 192.168.200.253:/exports/state/oleg454-server.virtnet /etc/etc/kdump.conf ffff8800b43aa1c0 ffff88012a2ee800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8800b2189c00 ffff8800b4263000 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b2188e00 ffff8800b633d800 lustre /dev/mapper/mds1_flakey /mnt/lustre-mds1 ffff8800b2189dc0 ffff880087749000 lustre /dev/mapper/mds2_flakey /mnt/lustre-mds2 ffff8800b2188fc0 ffff880070c3b000 lustre /dev/mapper/ost1_flakey /mnt/lustre-ost1 ffff8800b21888c0 ffff8800706c9800 lustre /dev/mapper/ost2_flakey /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 332.852642] Lustre: 14810:0:(osd_handler.c:1879:osd_trans_dump_creds()) create: 3/12/0, destroy: 2/8/0 [ 332.858127] Lustre: 14810:0:(osd_handler.c:1886:osd_trans_dump_creds()) attr_set: 2/2/0, xattr_set: 31/2674/0 [ 332.862066] Lustre: 14810:0:(osd_handler.c:1896:osd_trans_dump_creds()) write: 5/136/0, punch: 0/0/0, quota 8/152/0 [ 332.866453] Lustre: 14810:0:(osd_handler.c:1903:osd_trans_dump_creds()) insert: 15/263/0, delete: 7/13/0 [ 332.873560] Lustre: 14810:0:(osd_handler.c:1910:osd_trans_dump_creds()) ref_add: 8/8/0, ref_del: 7/7/0 [ 332.878210] Pid: 14810, comm: mdt00_020 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 332.890551] Call Trace: [ 332.891477] [<0>] libcfs_call_trace+0x90/0xf0 [libcfs] [ 332.893481] [<0>] libcfs_debug_dumpstack+0x26/0x30 [libcfs] [ 332.895327] [<0>] osd_trans_start+0x5ba/0x5e0 [osd_ldiskfs] [ 332.901520] [<0>] top_trans_start+0x351/0xa10 [ptlrpc] [ 332.904098] [<0>] lod_trans_start+0x34/0x40 [lod] [ 332.906136] [<0>] mdd_trans_start+0x14/0x20 [mdd] [ 332.910932] [<0>] mdd_migrate_object+0xca2/0x1120 [mdd] [ 332.917802] [<0>] mdd_migrate+0x4ae/0x8d0 [mdd] [ 332.921018] [<0>] mdt_reint_migrate+0x121b/0x1e90 [mdt] [ 332.923813] [<0>] mdt_reint_rec+0x87/0x240 [mdt] [ 332.929113] [<0>] mdt_reint_internal+0x76c/0xb50 [mdt] [ 332.932065] [<0>] mdt_reint+0x67/0x150 [mdt] [ 332.933362] [<0>] tgt_request_handle+0x93a/0x19c0 [ptlrpc] [ 332.936996] [<0>] ptlrpc_server_handle_request+0x250/0xc30 [ptlrpc] [ 332.939691] [<0>] ptlrpc_main+0xbd9/0x15f0 [ptlrpc] [ 332.942970] [<0>] kthread+0xe4/0xf0 [ 332.944632] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 332.946127] [<0>] 0xfffffffffffffffe [ 340.038032] Lustre: 14776:0:(lod_lov.c:1315:lod_parse_striping()) lustre-MDT0000-mdtlov: EXTENSION flags=40 set on component[2]=1 of non-SEL file [0x200000403:0x1022:0x0] with magic=0xbd60bd0 [ 340.047857] Lustre: 14776:0:(lod_lov.c:1315:lod_parse_striping()) Skipped 55 previous similar messages [ 355.809724] LustreError: 14766:0:(mdt_open.c:1217:mdt_cross_open()) lustre-MDT0001: [0x240000404:0x12ee:0x0] doesn't exist!: rc = -14 [ 360.322385] LustreError: 14826:0:(out_lib.c:632:out_tx_attr_set_undo()) lustre-MDT0001-osd: attr set undo [0x240000400:0xa4:0x0] unimplemented yet!: rc = -524 [ 360.329091] LustreError: 14826:0:(out_lib.c:1190:out_tx_index_delete_undo()) lustre-MDT0001-osd: Oops, can not rollback index_delete yet: rc = -524 [ 360.424847] LustreError: 6878:0:(llog_cat.c:753:llog_cat_cancel_arr_rec()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 llog-records: rc = -116 [ 360.431635] LustreError: 6878:0:(llog_cat.c:789:llog_cat_cancel_records()) lustre-MDT0001-osp-MDT0000: fail to cancel 1 of 1 llog-records: rc = -116 [ 373.798080] LustreError: 11046:0:(mdd_object.c:401:mdd_xattr_get()) lustre-MDD0000: object [0x200000402:0x1429:0x0] not found: rc = -2 [ 374.488995] LustreError: 6848:0:(mdt_open.c:1217:mdt_cross_open()) lustre-MDT0000: [0x200000403:0x1848:0x0] doesn't exist!: rc = -14 [ 384.120017] LustreError: 14768:0:(mdd_object.c:401:mdd_xattr_get()) lustre-MDD0000: object [0x200000402:0x154b:0x0] not found: rc = -2 [ 454.178600] LustreError: 6840:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.204.54@tcp ns: filter-lustre-OST0000_UUID lock: ffff880096898480/0x6dd11c19e517ba1d lrc: 3/0,0 mode: PW/PW res: [0x2c8:0x0:0x0].0x0 rrc: 7 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000480020020 nid: 192.168.204.54@tcp remote: 0x5c1f45a02355974a expref: 35 pid: 14832 timeout: 453 lvb_type: 0 [ 482.210952] LustreError: 6840:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.204.54@tcp ns: mdt-lustre-MDT0000_UUID lock: ffff88006f01b180/0x6dd11c19e5279cb4 lrc: 3/0,0 mode: PR/PR res: [0x200000403:0x19e4:0x0].0x0 bits 0x13/0x0 rrc: 4 type: IBT gid 0 flags: 0x60200400000020 nid: 192.168.204.54@tcp remote: 0x5c1f45a0235a1152 expref: 437 pid: 14768 timeout: 481 lvb_type: 0 [ 488.236195] LustreError: 6836:0:(ldlm_lockd.c:2521:ldlm_cancel_handler()) ldlm_cancel from 192.168.204.54@tcp arrived at 1737130968 with bad export cookie 7913136917808290918 [ 511.342216] Lustre: DEBUG MARKER: == racer test complete, duration 395 sec ================= 11:23:10 (1737130990) [ 533.819842] Lustre: lustre-OST0001: haven't heard from client 92a08681-6d61-4393-9fd6-5a4f517a9913 (at 192.168.204.54@tcp) in 50 seconds. I think it's dead, and I am evicting it. exp ffff880098e74800, cur 1737131014 expire 1737130984 last 1737130964 ****************************************************************************** ************************ 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.10s (real) 6.08s (CPU), Child processes: 4.98s