nfs-ganesha
nfs-ganesha copied to clipboard
Published
20 hours ago •
nfs-ganesha
nfs-ganesha
Hang when calling `ll` during IO shortly after restart
Calling ll hangs if it is called in a directory with files under IO. strace shows that we hang on statx at the file under IO. Ganesha unhangs after IO is finished. After the first hang the problem does not recur until the next systemctl restart nfs-ganesha.
The underlying file system is ext4, nfs-ganesha v5.5.
What version of Ganesha?
Can you take a tcpdump trace or provide any more details?
Hello! Sorry for the long answer.
Here is tcpdump: https://gist.github.com/SDesya74/df307f65072d13c8035ce44a6fd5ce77
And strace:
12:24:05 execve("/usr/bin/stat", ["stat", "/tmp/nfs/random.bin"], 0x7fffe2cde870 /* 27 vars */) = 0
12:24:05 brk(NULL) = 0x561523f80000
12:24:05 arch_prctl(0x3001 /* ARCH_??? */, 0x7fff304ba860) = -1 EINVAL (Invalid argument)
12:24:05 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f08f7d11000
12:24:05 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=76087, ...}, AT_EMPTY_PATH) = 0
12:24:05 mmap(NULL, 76087, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f08f7cfe000
12:24:05 close(3) = 0
12:24:05 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
12:24:05 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=166280, ...}, AT_EMPTY_PATH) = 0
12:24:05 mmap(NULL, 177672, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f08f7cd2000
12:24:05 mprotect(0x7f08f7cd8000, 139264, PROT_NONE) = 0
12:24:05 mmap(0x7f08f7cd8000, 106496, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f08f7cd8000
12:24:05 mmap(0x7f08f7cf2000, 28672, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x20000) = 0x7f08f7cf2000
12:24:05 mmap(0x7f08f7cfa000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x27000) = 0x7f08f7cfa000
12:24:05 mmap(0x7f08f7cfc000, 5640, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f08f7cfc000
12:24:05 close(3) = 0
12:24:05 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
12:24:05 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832
12:24:05 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
12:24:05 pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48
12:24:05 pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\302\211\332Pq\2439\235\350\223\322\257\201\326\243\f"..., 68, 896) = 68
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=2220400, ...}, AT_EMPTY_PATH) = 0
12:24:05 pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
12:24:05 mmap(NULL, 2264656, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f08f7a00000
12:24:05 mprotect(0x7f08f7a28000, 2023424, PROT_NONE) = 0
12:24:05 mmap(0x7f08f7a28000, 1658880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7f08f7a28000
12:24:05 mmap(0x7f08f7bbd000, 360448, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bd000) = 0x7f08f7bbd000
12:24:05 mmap(0x7f08f7c16000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x215000) = 0x7f08f7c16000
12:24:05 mmap(0x7f08f7c1c000, 52816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f08f7c1c000
12:24:05 close(3) = 0
12:24:05 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3
12:24:05 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=613064, ...}, AT_EMPTY_PATH) = 0
12:24:05 mmap(NULL, 615184, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f08f7c3b000
12:24:05 mmap(0x7f08f7c3d000, 438272, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f08f7c3d000
12:24:05 mmap(0x7f08f7ca8000, 163840, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0x7f08f7ca8000
12:24:05 mmap(0x7f08f7cd0000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x94000) = 0x7f08f7cd0000
12:24:05 close(3) = 0
12:24:05 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f08f7c39000
12:24:05 arch_prctl(ARCH_SET_FS, 0x7f08f7c39c40) = 0
12:24:05 set_tid_address(0x7f08f7c39f10) = 20870
12:24:05 set_robust_list(0x7f08f7c39f20, 24) = 0
12:24:05 rseq(0x7f08f7c3a5e0, 0x20, 0, 0x53053053) = 0
12:24:05 mprotect(0x7f08f7c16000, 16384, PROT_READ) = 0
12:24:05 mprotect(0x7f08f7cd0000, 4096, PROT_READ) = 0
12:24:05 mprotect(0x7f08f7cfa000, 4096, PROT_READ) = 0
12:24:05 mprotect(0x561522501000, 4096, PROT_READ) = 0
12:24:05 mprotect(0x7f08f7d4b000, 8192, PROT_READ) = 0
12:24:05 prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
12:24:05 munmap(0x7f08f7cfe000, 76087) = 0
12:24:05 statfs("/sys/fs/selinux", 0x7fff304ba8a0) = -1 ENOENT (No such file or directory)
12:24:05 statfs("/selinux", 0x7fff304ba8a0) = -1 ENOENT (No such file or directory)
12:24:05 getrandom("\x39\xfb\x0f\x21\xfd\x5a\xa8\x26", 8, GRND_NONBLOCK) = 8
12:24:05 brk(NULL) = 0x561523f80000
12:24:05 brk(0x561523fa1000) = 0x561523fa1000
12:24:05 openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0444, st_size=0, ...}, AT_EMPTY_PATH) = 0
12:24:05 read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 456
12:24:05 read(3, "", 1024) = 0
12:24:05 close(3) = 0
12:24:05 access("/etc/selinux/config", F_OK) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=5716816, ...}, AT_EMPTY_PATH) = 0
12:24:05 mmap(NULL, 5716816, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f08f7400000
12:24:05 close(3) = 0
12:24:05 openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=2996, ...}, AT_EMPTY_PATH) = 0
12:24:05 read(3, "# Locale name alias data base.\n#"..., 4096) = 2996
12:24:05 read(3, "", 4096) = 0
12:24:05 close(3) = 0
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en_US.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en_US.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en_US.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en_US/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en.utf8/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
12:24:05 openat(AT_FDCWD, "/usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = 3
12:24:05 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=613, ...}, AT_EMPTY_PATH) = 1
12:24:05 mmap(NULL, 613, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f08f7d4a000
12:24:05 close(3) = 0
12:24:05 statx(AT_FDCWD, "/tmp/nfs/random.bin", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=12978302976, ...}) = 0
12:25:45 newfstatat(1, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}, AT_EMPTY_PATH) = 0
12:25:45 write(1, " File: /tmp/nfs/random.bin\n", 28) = 28
12:25:45 write(1, " Size: 12978302976\tBlocks: 2534"..., 70) = 70
12:25:45 write(1, "Device: 3ch/60d\tInode: 8781833 "..., 44) = 44
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12:25:45 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12:25:45 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=553, ...}, 0) = 0
12:25:45 newfstatat(AT_FDCWD, "/", {st_mode=S_IFDIR|0755, st_size=4096, ...}, 0) = 0
12:25:45 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=553, ...}, AT_EMPTY_PATH) = 0
12:25:45 read(3, "# /etc/nsswitch.conf\n#\n# Example"..., 4096) = 553
12:25:45 read(3, "", 4096) = 0
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=553, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=3344, ...}, AT_EMPTY_PATH) = 0
12:25:45 lseek(3, 0, SEEK_SET) = 0
12:25:45 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 3344
12:25:45 read(3, "", 4096) = 0
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=76087, ...}, AT_EMPTY_PATH) = 0
12:25:45 mmap(NULL, 76087, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f08f7cfe000
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_systemd.so.2", O_RDONLY|O_CLOEXEC) = 3
12:25:45 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=309600, ...}, AT_EMPTY_PATH) = 0
12:25:45 mmap(NULL, 313896, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f08f79b3000
12:25:45 mmap(0x7f08f79b9000, 204800, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f08f79b9000
12:25:45 mmap(0x7f08f79eb000, 65536, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x38000) = 0x7f08f79eb000
12:25:45 mmap(0x7f08f79fb000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x47000) = 0x7f08f79fb000
12:25:45 close(3) = 0
12:25:45 mprotect(0x7f08f79fb000, 16384, PROT_READ) = 0
12:25:45 munmap(0x7f08f7cfe000, 76087) = 0
12:25:45 rt_sigprocmask(SIG_BLOCK, [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], [], 8) = 0
12:25:45 futex(0x7f08f79ff9f8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
12:25:45 openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=80, ...}, AT_EMPTY_PATH) = 0
12:25:45 getdents64(3, 0x561523f87c00 /* 4 entries */, 32768) = 136
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
12:25:45 connect(4, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.Machine"}, 41) = 0
12:25:45 getpid() = 20870
12:25:45 epoll_create1(EPOLL_CLOEXEC) = 5
12:25:45 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 6
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 6, {events=EPOLLIN, data={u32=603479392, u64=94648797781344}}) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 4, {events=0, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 gettid() = 20870
12:25:45 futex(0x7f08f79ff0dc, FUTEX_WAKE_PRIVATE, 2147483647) = 0
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 7
12:25:45 connect(7, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.DynamicUser"}, 45) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 7, {events=0, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 getdents64(3, 0x561523f87c00 /* 0 entries */, 32768) = 0
12:25:45 close(3) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=EPOLLIN|EPOLLOUT, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=EPOLLIN|EPOLLOUT, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 openat(AT_FDCWD, "/proc/sys/kernel/random/boot_id", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 3
12:25:45 read(3, "56d6429e-f44d-41c4-92ce-e9fc47fa"..., 38) = 37
12:25:45 read(3, "", 1) = 0
12:25:45 close(3) = 0
12:25:45 timerfd_settime(6, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=10860, tv_nsec=77956000}}, NULL) = 0
12:25:45 epoll_wait(5, [{events=EPOLLOUT, data={u32=603521440, u64=94648797823392}}, {events=EPOLLOUT, data={u32=603524960, u64=94648797826912}}], 16, 0) = 2
12:25:45 timerfd_create(CLOCK_BOOTTIME, TFD_CLOEXEC|TFD_NONBLOCK) = 3
12:25:45 close(3) = 0
12:25:45 sendto(4, "{\"method\":\"io.systemd.UserDataba"..., 108, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 108
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=EPOLLIN, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}, {events=EPOLLOUT, data={u32=603524960, u64=94648797826912}}], 16, 0) = 2
12:25:45 sendto(7, "{\"method\":\"io.systemd.UserDataba"..., 112, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 112
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=EPOLLIN, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}, {events=EPOLLIN, data={u32=603524960, u64=94648797826912}}], 16, 0) = 2
12:25:45 mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f08f7992000
12:25:45 recvfrom(4, "{\"error\":\"io.systemd.UserDatabas"..., 135152, MSG_DONTWAIT, NULL, NULL) = 66
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=0, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603524960, u64=94648797826912}}], 16, 0) = 1
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603524960, u64=94648797826912}}], 16, 0) = 1
12:25:45 epoll_ctl(5, EPOLL_CTL_DEL, 4, NULL) = 0
12:25:45 close(4) = 0
12:25:45 munmap(0x7f08f7992000, 135168) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603524960, u64=94648797826912}}], 16, 0) = 1
12:25:45 brk(0x561523fd2000) = 0x561523fd2000
12:25:45 recvfrom(7, "{\"error\":\"io.systemd.UserDatabas"..., 131080, MSG_DONTWAIT, NULL, NULL) = 66
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=0, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 epoll_wait(5, [], 16, 0) = 0
12:25:45 epoll_wait(5, [], 16, 0) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_DEL, 7, NULL) = 0
12:25:45 close(7) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "etc", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=1280, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=1280, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "host", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "local", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFLNK|0777, st_size=7, ...}, AT_EMPTY_PATH) = 0
12:25:45 readlinkat(3, "lib", "usr/lib", 4096) = 7
12:25:45 close(4) = 0
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/etc/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/run/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/run/host/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/usr/local/lib/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/usr/lib/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/lib/userdb/1501.user", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 close(5) = 0
12:25:45 close(6) = 0
12:25:45 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12:25:45 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12:25:45 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=553, ...}, 0) = 0
12:25:45 openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=1269, ...}, AT_EMPTY_PATH) = 0
12:25:45 lseek(3, 0, SEEK_SET) = 0
12:25:45 read(3, "root:x:0:\ndaemon:x:1:\nbin:x:2:\ns"..., 4096) = 1269
12:25:45 read(3, "", 4096) = 0
12:25:45 close(3) = 0
12:25:45 rt_sigprocmask(SIG_BLOCK, [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], [], 8) = 0
12:25:45 openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=80, ...}, AT_EMPTY_PATH) = 0
12:25:45 getdents64(3, 0x561523f91340 /* 4 entries */, 32768) = 136
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4
12:25:45 connect(4, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.Machine"}, 41) = 0
12:25:45 epoll_create1(EPOLL_CLOEXEC) = 5
12:25:45 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 6
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 6, {events=EPOLLIN, data={u32=603479392, u64=94648797781344}}) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 4, {events=0, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 7
12:25:45 connect(7, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.DynamicUser"}, 45) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_ADD, 7, {events=0, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 getdents64(3, 0x561523f91340 /* 0 entries */, 32768) = 0
12:25:45 close(3) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=EPOLLIN|EPOLLOUT, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=EPOLLIN|EPOLLOUT, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 timerfd_settime(6, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=10860, tv_nsec=77956000}}, NULL) = 0
12:25:45 epoll_wait(5, [{events=EPOLLOUT, data={u32=603524960, u64=94648797826912}}, {events=EPOLLOUT, data={u32=603521440, u64=94648797823392}}], 16, 0) = 2
12:25:45 sendto(4, "{\"method\":\"io.systemd.UserDataba"..., 109, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 109
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=EPOLLIN, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLOUT, data={u32=603521440, u64=94648797823392}}], 16, 0) = 1
12:25:45 sendto(7, "{\"method\":\"io.systemd.UserDataba"..., 113, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 113
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=EPOLLIN, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}, {events=EPOLLIN, data={u32=603524960, u64=94648797826912}}], 16, 0) = 2
12:25:45 recvfrom(4, "{\"error\":\"io.systemd.UserDatabas"..., 131080, MSG_DONTWAIT, NULL, NULL) = 66
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 4, {events=0, data={u32=603524960, u64=94648797826912}}) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}], 16, 0) = 1
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}], 16, 0) = 1
12:25:45 epoll_ctl(5, EPOLL_CTL_DEL, 4, NULL) = 0
12:25:45 close(4) = 0
12:25:45 epoll_wait(5, [{events=EPOLLIN, data={u32=603521440, u64=94648797823392}}], 16, 0) = 1
12:25:45 recvfrom(7, "{\"error\":\"io.systemd.UserDatabas"..., 131080, MSG_DONTWAIT, NULL, NULL) = 66
12:25:45 epoll_ctl(5, EPOLL_CTL_MOD, 7, {events=0, data={u32=603521440, u64=94648797823392}}) = 0
12:25:45 epoll_wait(5, [], 16, 0) = 0
12:25:45 epoll_wait(5, [], 16, 0) = 0
12:25:45 epoll_ctl(5, EPOLL_CTL_DEL, 7, NULL) = 0
12:25:45 close(7) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "etc", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=1280, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "run", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=1280, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "host", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "local", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(4) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 3
12:25:45 openat(3, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFLNK|0777, st_size=7, ...}, AT_EMPTY_PATH) = 0
12:25:45 readlinkat(3, "lib", "usr/lib", 4096) = 7
12:25:45 close(4) = 0
12:25:45 openat(3, "usr", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 4
12:25:45 newfstatat(4, "", {st_mode=S_IFDIR|0755, st_size=4096, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(3) = 0
12:25:45 openat(4, "lib", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_EMPTY_PATH) = 0
12:25:45 close(4) = 0
12:25:45 openat(3, "userdb", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory)
12:25:45 close(3) = 0
12:25:45 openat(AT_FDCWD, "/etc/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/run/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/run/host/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/usr/local/lib/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/usr/lib/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 openat(AT_FDCWD, "/lib/userdb/1501.group", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
12:25:45 close(5) = 0
12:25:45 close(6) = 0
12:25:45 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=553, ...}, 0) = 0
12:25:45 openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=1269, ...}, AT_EMPTY_PATH) = 0
12:25:45 lseek(3, 0, SEEK_SET) = 0
12:25:45 read(3, "root:x:0:\ndaemon:x:1:\nbin:x:2:\ns"..., 4096) = 1269
12:25:45 read(3, "", 4096) = 0
12:25:45 close(3) = 0
12:25:45 rt_sigprocmask(SIG_BLOCK, [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], 8) = 0
12:25:45 rt_sigprocmask(SIG_SETMASK, [HUP USR1 USR2 PIPE ALRM CHLD TSTP URG VTALRM PROF WINCH IO], NULL, 8) = 0
12:25:45 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
12:25:45 write(1, "Access: (0644/-rw-r--r--) Uid: "..., 73) = 73
12:25:45 openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=1535, ...}, AT_EMPTY_PATH) = 0
12:25:45 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=1535, ...}, AT_EMPTY_PATH) = 0
12:25:45 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\21\0\0\0\21\0\0\0\0"..., 4096) = 1535
12:25:45 lseek(3, -927, SEEK_CUR) = 608
12:25:45 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\21\0\0\0\21\0\0\0\0"..., 4096) = 927
12:25:45 close(3) = 0
12:25:45 write(1, "Access: 2024-02-08 12:11:52.0291"..., 44) = 44
12:25:45 write(1, "Modify: 2024-02-08 12:23:48.8191"..., 44) = 44
12:25:45 write(1, "Change: 2024-02-08 12:23:48.8191"..., 44) = 44
12:25:45 write(1, " Birth: -\n", 10) = 10
12:25:45 close(1) = 0
12:25:45 close(2) = 0
12:25:45 exit_group(0) = ?
12:25:45 +++ exited with 0 +++
I have updated nfs-ganesha to version 5.7 and the problem persists