************************ crashinfo ************************* /exports/testreports/42551/testresults/sanity-flr-zfs-centos7_x86_64-centos7_x86_64/oleg124-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.8PPqi/vmlinux [TAINTED] DUMPFILE: /exports/testreports/42551/testresults/sanity-flr-zfs-centos7_x86_64-centos7_x86_64/oleg124-server-timeout-core [PARTIAL DUMP] CPUS: 4 DATE: Wed May 8 18:34:25 EDT 2024 UPTIME: 00:33:36 LOAD AVERAGE: 0.00, 0.01, 0.04 TASKS: 401 NODENAME: oleg124-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 64 last 60s 75 ----- Total Numbers of Threads per State ------ TASK_INTERRUPTIBLE 397 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 ----- -------------- ------ ---------------------------- 908 in:imjournal 0 ms /usr/sbin/rsyslogd -n 563 kworker/2:1H 0 ms (no user stack) 46 kworker/0:1 0 ms (no user stack) 49 kworker/2:1 0 ms (no user stack) 3212 lnet_discovery 77 ms (no user stack) +------------------------+ >-------------------------| Memory Usage (kmem -i) |-------------------------< +------------------------+ PAGES TOTAL PERCENTAGE TOTAL MEM 955067 3.6 GB ---- FREE 707726 2.7 GB 74% of TOTAL MEM USED 247341 966.2 MB 25% of TOTAL MEM SHARED 8371 32.7 MB 0% of TOTAL MEM BUFFERS 5130 20 MB 0% of TOTAL MEM CACHED 68294 266.8 MB 7% of TOTAL MEM SLAB 25866 101 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 61133 238.8 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 2014.1 eth0 n/a 2.6 RSS_TOTAL=52196 pages, %mem= 0.9 +------------+ >-------------------------------| Mounted FS |-------------------------------< +------------+ MOUNT SUPERBLK TYPE DEVNAME DIRNAME ffff880138cca000 ffff880139940800 rootfs rootfs / ffff88012a2f8000 ffff88012a318000 sysfs sysfs /sys ffff88012a2f81c0 ffff880139944000 proc proc /proc ffff88012a2f8380 ffff880137678000 devtmpfs devtmpfs /dev ffff88012a2f8540 ffff8800b5242000 securityfs securityfs /sys/kernel/security ffff88012a2f8700 ffff88012a318800 tmpfs tmpfs /dev/shm ffff88012a2f88c0 ffff8801372e6000 devpts devpts /dev/pts ffff88012a2f8a80 ffff88012a319000 tmpfs tmpfs /run ffff88012a2f8c40 ffff88012a319800 tmpfs tmpfs /sys/fs/cgroup ffff88012a2f8e00 ffff88012a31a000 cgroup cgroup /sys/fs/cgroup/systemd ffff88012a2f8fc0 ffff88012a31a800 pstore pstore /sys/fs/pstore ffff88012a2f9180 ffff88012a31c800 cgroup cgroup /sys/fs/cgroup/memory ffff88012a2f9340 ffff88012a31c000 cgroup cgroup /sys/fs/cgroup/hugetlb ffff88012a2f9500 ffff88012a31b800 cgroup cgroup /sys/fs/cgroup/cpu,cpuacct ffff88012a2f96c0 ffff88012a31b000 cgroup cgroup /sys/fs/cgroup/blkio ffff88012a2f9880 ffff88012a31d000 cgroup cgroup /sys/fs/cgroup/net_cls,net_prio ffff88012a2f9a40 ffff88012a31d800 cgroup cgroup /sys/fs/cgroup/devices ffff88012a2f9c00 ffff88012a31e000 cgroup cgroup /sys/fs/cgroup/cpuset ffff88012a2f9dc0 ffff88012a31e800 cgroup cgroup /sys/fs/cgroup/pids ffff88012a2ca000 ffff88012a31f000 cgroup cgroup /sys/fs/cgroup/freezer ffff88012a2ca1c0 ffff88012a31f800 cgroup cgroup /sys/fs/cgroup/perf_event ffff880138ccb180 ffff880000094000 configfs configfs /sys/kernel/config ffff880137669500 ffff8800b5246800 ext4 /dev/nbd0 / ffff8801376696c0 ffff88012b387800 rpc_pipefs rpc_pipefs /var/lib/nfs/rpc_pipefs ffff88012a2caa80 ffff8800b40d8800 autofs systemd-1 /proc/sys/fs/binfmt_misc ffff880137669880 ffff880129f09000 hugetlbfs hugetlbfs /dev/hugepages ffff880138ccb500 ffff880139947800 debugfs debugfs /sys/kernel/debug ffff880138ccb6c0 ffff8801372e7800 mqueue mqueue /dev/mqueue ffff88012a2cac40 ffff8800b40d9800 binfmt_misc binfmt_misc /proc/sys/fs/binfmt_misc/ ffff88012b252c40 ffff8800b45ac000 ramfs none /mnt ffff880138ccb880 ffff8800b40e1800 squashfs /dev/vda /home/green/git/lustre-release ffff88012b252e00 ffff8800b45ab800 tmpfs none /var/lib/stateless/writable ffff880137669dc0 ffff8800b45ab800 tmpfs none /var/cache/man ffff8801372fc000 ffff8800b45ab800 tmpfs none /var/log ffff88012a2cae00 ffff8800b45ab800 tmpfs none /var/lib/dbus ffff8801372fc1c0 ffff8800b45ab800 tmpfs none /tmp ffff88012a2cafc0 ffff8800b45ab800 tmpfs none /var/lib/dhclient ffff88012a2cb180 ffff8800b45ab800 tmpfs none /var/tmp ffff8801372fc380 ffff8800b45ab800 tmpfs none /var/lib/NetworkManager ffff8801372fc540 ffff8800b45ab800 tmpfs none /var/lib/systemd/random-seed ffff8801372fc700 ffff8800b45ab800 tmpfs none /var/spool ffff8801372fc8c0 ffff8800b45ab800 tmpfs none /var/lib/nfs ffff8801372fca80 ffff8800b45ab800 tmpfs none /var/lib/gssproxy ffff88012a2cb340 ffff8800b45ab800 tmpfs none /var/lib/logrotate ffff88012b252fc0 ffff8800b45ab800 tmpfs none /etc ffff88012a2cb500 ffff8800b45ab800 tmpfs none /var/lib/rsyslog ffff88012a2cb6c0 ffff8800b45ab800 tmpfs none /var/lib/dhclient/var/lib/dhclient ffff88012a2cb880 ffff880129ca6800 nfs4 192.168.200.253:/exports/state/oleg124-server.virtnet /var/lib/stateless/state ffff88012a2cbdc0 ffff880129ca6800 nfs4 192.168.200.253:/exports/state/oleg124-server.virtnet /boot ffff88012a2cbc00 ffff880129ca6800 nfs4 192.168.200.253:/exports/state/oleg124-server.virtnet /etc/etc/kdump.conf ffff88012b253340 ffff88012b387800 rpc_pipefs sunrpc /var/lib/nfs/var/lib/nfs/rpc_pipefs ffff8801372fd180 ffff8800b40e1800 squashfs /dev/vda /usr/sbin/mount.lustre ffff8800b4420380 ffff880129ca3000 lustre lustre-mdt1/mdt1 /mnt/lustre-mds1 ffff8800b4420a80 ffff880130e1a000 lustre lustre-ost1/ost1 /mnt/lustre-ost1 ffff880137669180 ffff8800943fa000 lustre lustre-ost2/ost2 /mnt/lustre-ost2 +-------------------------------+ >----------------------| Last 40 lines of dmesg buffer |----------------------< +-------------------------------+ [ 73.117041] Lustre: DEBUG MARKER: oleg124-server.virtnet: executing check_logdir /tmp/testlogs/ [ 73.980902] Lustre: DEBUG MARKER: oleg124-server.virtnet: executing yml_node [ 74.953755] Lustre: DEBUG MARKER: Client: 2.15.63.5 [ 75.572943] Lustre: DEBUG MARKER: MDS: 2.15.63.5 [ 76.171034] Lustre: DEBUG MARKER: OSS: 2.15.63.5 [ 76.562258] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-flr ============----- Wed May 8 18:02:05 EDT 2024 [ 80.308871] Lustre: DEBUG MARKER: excepting tests: 6 201 44c 49a [ 80.881404] Lustre: DEBUG MARKER: oleg124-client.virtnet: executing check_config_client /mnt/lustre [ 84.789630] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 85.604140] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 86.173511] Lustre: DEBUG MARKER: oleg124-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 87.640178] Lustre: DEBUG MARKER: == sanity-flr test 0a: lfs mirror create with -N option == 18:02:16 (1715205736) [ 92.819811] Lustre: DEBUG MARKER: == sanity-flr test 0b: lfs mirror create plain layout mirrors ========================================================== 18:02:21 (1715205741) [ 93.199620] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0b need >= 4 OSTs [ 95.256642] Lustre: DEBUG MARKER: == sanity-flr test 0c: lfs mirror create composite layout mirrors ========================================================== 18:02:23 (1715205743) [ 95.615441] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0c need >= 4 OSTs [ 97.571270] Lustre: DEBUG MARKER: == sanity-flr test 0d: lfs mirror extend with -N option == 18:02:26 (1715205746) [ 138.682248] Lustre: ll_ost00_004: service thread pid 11096 was inactive for 40.139 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [ 138.686067] Pid: 11096, comm: ll_ost00_004 3.10.0-7.9-debug #1 SMP Sat Mar 26 23:28:42 EDT 2022 [ 138.688473] Call Trace: [ 138.689269] [<0>] ldlm_completion_ast+0x963/0xd00 [ptlrpc] [ 138.690557] [<0>] ldlm_cli_enqueue_local+0x259/0x880 [ptlrpc] [ 138.692207] [<0>] tgt_extent_lock+0xea/0x2a0 [ptlrpc] [ 138.693246] [<0>] ofd_getattr_hdl+0x385/0x750 [ofd] [ 138.694120] [<0>] tgt_request_handle+0x74e/0x1a50 [ptlrpc] [ 138.695476] [<0>] ptlrpc_server_handle_request+0x26c/0xcb0 [ptlrpc] [ 138.696541] [<0>] ptlrpc_main+0xc76/0x1690 [ptlrpc] [ 138.697551] [<0>] kthread+0xe4/0xf0 [ 138.698501] [<0>] ret_from_fork_nospec_begin+0x7/0x21 [ 138.699501] [<0>] 0xfffffffffffffffe [ 198.842225] LustreError: 6954:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 101s: evicting client at 192.168.201.24@tcp ns: filter-lustre-OST0001_UUID lock: ffff8800a3229680/0x4b8b294827049ec9 lrc: 3/0,0 mode: PR/PR res: [0x280000400:0x11:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->18446744073709551615) gid 0 flags: 0x60000400000020 nid: 192.168.201.24@tcp remote: 0xb85c51e20816100f expref: 8 pid: 11096 timeout: 197 lvb_type: 1 [ 199.179458] Lustre: DEBUG MARKER: sanity-flr test_0d: @@@@@@ FAIL: extend mirror with -f failed [ 203.529390] Lustre: DEBUG MARKER: == sanity-flr test 0e: lfs mirror extend plain layout mirrors ========================================================== 18:04:12 (1715205852) [ 203.838605] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0e need >= 4 OSTs [ 205.611600] Lustre: DEBUG MARKER: == sanity-flr test 0f: lfs mirror extend composite layout mirrors ========================================================== 18:04:14 (1715205854) [ 205.921995] Lustre: DEBUG MARKER: SKIP: sanity-flr test_0f need >= 4 OSTs [ 207.776507] Lustre: DEBUG MARKER: == sanity-flr test 0g: lfs mirror create flags support === 18:04:16 (1715205856) [ 231.754801] Lustre: lustre-OST0001: haven't heard from client bb83ce6d-077a-4dbe-98a0-9954f12bb80f (at 192.168.201.24@tcp) in 33 seconds. I think it's dead, and I am evicting it. exp ffff880135357000, cur 1715205880 expire 1715205850 last 1715205847 [ 307.898299] LustreError: 6954:0:(ldlm_lockd.c:261:expired_lock_main()) ### lock callback timer expired after 100s: evicting client at 192.168.201.24@tcp ns: filter-lustre-OST0000_UUID lock: ffff8800a887d8c0/0x4b8b29482704a0c1 lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x13:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->1048575) gid 0 flags: 0x60000480020020 nid: 192.168.201.24@tcp remote: 0xb85c51e2081610b0 expref: 8 pid: 9337 timeout: 307 lvb_type: 0 [ 340.218511] Lustre: lustre-OST0000: haven't heard from client bb83ce6d-077a-4dbe-98a0-9954f12bb80f (at 192.168.201.24@tcp) in 31 seconds. I think it's dead, and I am evicting it. exp ffff88008df7b800, cur 1715205988 expire 1715205958 last 1715205957 ****************************************************************************** ************************ 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.67s (real) 7.14s (CPU), Child processes: 5.52s