search

linux-test-project / ltp

Linux Test Project (mailing list: https://lists.linux.it/listinfo/ltp)
https://linux-test-project.readthedocs.io/
GNU General Public License v2.0
2.32k stars 1.02k forks source link

futex_wake04 from syscalls failed with Ubuntu Xenial i386 #713

Closed Cypresslin closed 3 years ago

Cypresslin commented 4 years ago

Issue found on Ubuntu Xenial i386 node with 4.4.0-189.219 generic / low-latency kernel (passed on other arches)

Test failed with:

<<>> tag=futex_wake04 stime=1597828807 cmdline="futex_wake04" contacts="" analysis=exit <<>> incrementing stop tst_hugepage.c:58: INFO: 1 hugepage(s) reserved tst_test.c:1250: INFO: Timeout per run is 0h 05m 00s futex_wake04.c:60: INFO: Testing variant: syscall with old kernel spec futex_wake04.c:98: INFO: Hugepagesize 2097152 futex_utils.h:51: INFO: Thread 13011 not sleeping yet futex_wake04.c:85: FAIL: Bug: wait_thread2 did not wake after 30 secs.: EINVAL (22) futex_utils.h:62: INFO: 0 threads sleeping, expected 2 tst_test.c:1250: INFO: Timeout per run is 0h 05m 00s futex_wake04.c:60: INFO: Testing variant: syscall time64 with kernel spec ../../../../include/tst_timer.h:261: CONF: syscall(422) __NR_futex_time64 not supported Summary: passed 0 failed 1 skipped 1 warnings 0 <<>> initiation_status="ok" duration=0 termination_type=exited termination_id=33 corefile=no cutime=0 cstime=4 <<>>

There is no such issue before commit 8d2c9c7d597c4b220c52bbbd0ab849ece86fe12c

https://bugs.launchpad.net/ubuntu-kernel-tests/+bug/1892165

metan-ucw commented 4 years ago

The futex_wait() returns EINVAL, that is strange, can you try to strace the test to see what exact parameters are passed to the futex() syscall that fails that way?

Cypresslin commented 4 years ago

Hello, sorry for the late reply, here is the strace output:

$ sudo strace -tt ./futex_wake04 
07:46:56.993608 execve("./futex_wake04", ["./futex_wake04"], [/* 23 vars */]) = 0
07:46:56.994969 brk(NULL)               = 0x829f000
07:46:56.995142 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
07:46:56.995276 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb76e4000
07:46:56.995414 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
07:46:56.995526 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
07:46:56.995629 fstat64(3, {st_mode=S_IFREG|0644, st_size=34765, ...}) = 0
07:46:56.995722 mmap2(NULL, 34765, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb76db000
07:46:56.995786 close(3)                = 0
07:46:56.995847 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
07:46:56.995915 open("/lib/i386-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
07:46:56.995983 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260O\0\0004\0\0\0"..., 512) = 512
07:46:56.996048 fstat64(3, {st_mode=S_IFREG|0755, st_size=134864, ...}) = 0
07:46:56.996112 mmap2(NULL, 115296, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb76be000
07:46:56.996173 mmap2(0xb76d7000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0xb76d7000
07:46:56.996249 mmap2(0xb76d9000, 4704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb76d9000
07:46:56.996319 close(3)                = 0
07:46:56.996381 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
07:46:56.996447 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
07:46:56.996514 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\207\1\0004\0\0\0"..., 512) = 512
07:46:56.996577 fstat64(3, {st_mode=S_IFREG|0755, st_size=1790580, ...}) = 0
07:46:56.996640 mmap2(NULL, 1796636, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7507000
07:46:56.996701 mprotect(0xb76b7000, 4096, PROT_NONE) = 0
07:46:56.996761 mmap2(0xb76b8000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b0000) = 0xb76b8000
07:46:56.996832 mmap2(0xb76bb000, 10780, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb76bb000
07:46:56.996902 close(3)                = 0
07:46:56.996982 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7506000
07:46:56.997045 set_thread_area({entry_number:-1, base_addr:0xb7506700, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 (entry_number:6)
07:46:56.997179 mprotect(0xb76b8000, 8192, PROT_READ) = 0
07:46:56.997249 mprotect(0xb76d7000, 4096, PROT_READ) = 0
07:46:56.997315 mprotect(0x8069000, 4096, PROT_READ) = 0
07:46:56.997378 mprotect(0xb770b000, 4096, PROT_READ) = 0
07:46:56.997436 munmap(0xb76db000, 34765) = 0
07:46:56.997503 set_tid_address(0xb7506768) = 5623
07:46:56.997556 set_robust_list(0xb7506770, 12) = 0
07:46:56.997616 rt_sigaction(SIGRTMIN, {0xb76c29c0, [], SA_SIGINFO}, NULL, 8) = 0
07:46:56.997681 rt_sigaction(SIGRT_1, {0xb76c2a40, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
07:46:56.997741 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
07:46:56.997809 ugetrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
07:46:56.997893 uname({sysname="Linux", nodename="fozzie", ...}) = 0
07:46:56.998016 geteuid32()             = 0
07:46:56.998082 uname({sysname="Linux", nodename="fozzie", ...}) = 0
07:46:56.998141 access("/sys/kernel/mm/hugepages/", F_OK) = 0
07:46:56.998277 brk(NULL)               = 0x829f000
07:46:56.998331 brk(0x82c0000)          = 0x82c0000
07:46:56.998395 open("/proc/sys/vm/drop_caches", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
07:46:56.998488 fstat64(3, {st_mode=S_IFREG|0200, st_size=0, ...}) = 0
07:46:56.998555 write(3, "3", 1)        = 1
07:46:57.025211 close(3)                = 0
07:46:57.037250 open("/proc/meminfo", O_RDONLY) = 3
07:46:57.037402 fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
07:46:57.037504 read(3, "MemTotal:        8240388 kB\nMemF"..., 1024) = 1024
07:46:57.037780 close(3)                = 0
07:46:57.037898 open("/proc/meminfo", O_RDONLY) = 3
07:46:57.037991 fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
07:46:57.038063 read(3, "MemTotal:        8240388 kB\nMemF"..., 1024) = 1024
07:46:57.038173 read(3, "       0 kB\nVmallocChunk:       "..., 1024) = 308
07:46:57.038248 close(3)                = 0
07:46:57.038304 access("/proc/sys/vm/nr_hugepages", F_OK) = 0
07:46:57.038372 open("/proc/sys/vm/nr_hugepages", O_RDONLY) = 3
07:46:57.038435 fstat64(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
07:46:57.038494 read(3, "0\n", 1024)    = 2
07:46:57.038552 close(3)                = 0
07:46:57.038618 open("/proc/sys/vm/nr_hugepages", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
07:46:57.038689 fstat64(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
07:46:57.038749 write(3, "1", 1)        = 1
07:46:57.038822 close(3)                = 0
07:46:57.038876 open("/proc/sys/vm/nr_hugepages", O_RDONLY) = 3
07:46:57.038964 fstat64(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
07:46:57.039027 read(3, "1\n", 1024)    = 2
07:46:57.039092 close(3)                = 0
07:46:57.039157 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
07:46:57.039230 write(2, "tst_hugepage.c:58: \33[1;34mTINFO:"..., 60tst_hugepage.c:58: TINFO: 1 hugepage(s) reserved
) = 60
07:46:57.039298 access("/dev/shm", F_OK) = 0
07:46:57.039364 open("/dev/shm/ltp_futex_wake04_5623", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
07:46:57.039439 chmod("/dev/shm/ltp_futex_wake04_5623", 0666) = 0
07:46:57.039502 ftruncate(3, 4096)      = 0
07:46:57.039558 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0xb76e3000
07:46:57.039621 unlink("/dev/shm/ltp_futex_wake04_5623") = 0
07:46:57.039684 close(3)                = 0
07:46:57.039782 gettimeofday({1603093617, 39802}, NULL) = 0
07:46:57.039845 mkdir("/tmp/WlsvGa", 0700) = 0
07:46:57.040004 getgid32()              = 0
07:46:57.040063 chown32("/tmp/WlsvGa", -1, 0) = 0
07:46:57.040134 chmod("/tmp/WlsvGa", 0777) = 0
07:46:57.040202 getcwd("/opt/ltp/testcases/bin", 4096) = 23
07:46:57.040270 chdir("/tmp/WlsvGa")    = 0
07:46:57.040335 rt_sigaction(SIGALRM, {0x804bf40, [ALRM], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
07:46:57.040403 rt_sigaction(SIGUSR1, {0x804be20, [USR1], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
07:46:57.040484 write(2, "tst_test.c:1250: \33[1;34mTINFO: \33"..., 65tst_test.c:1250: TINFO: Timeout per run is 0h 05m 00s
) = 65
07:46:57.040554 alarm(300)              = 0
07:46:57.040612 rt_sigaction(SIGINT, {0x804bf00, [INT], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
07:46:57.040679 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7506768) = 5624
07:46:57.040910 waitpid(5624, 0xbffb94d8, 0) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
07:46:57.040989 --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=5624, si_uid=0} ---
futex_wake04.c:60: TINFO: Testing variant: syscall with old kernel spec
07:46:57.041040 alarm(300)              = 300
07:46:57.041106 sigreturn({mask=[]}futex_wake04.c:98: TINFO: Hugepagesize 2097152
)    = 7
07:46:57.041180 waitpid(5624, futex_wake04.c:85: TFAIL: Bug: wait_thread2 did not wake after 30 secs.: EINVAL (22)
safe_file_ops.c:157: TBROK: The FILE '/proc/5624/task/5626/stat' ended prematurely at futex_utils.h:51
[{WIFEXITED(s) && WEXITSTATUS(s) == 2}], 0) = 5624
07:46:57.041997 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=5624, si_uid=0, si_status=2, si_utime=0, si_stime=0} ---
07:46:57.042042 alarm(0)                = 300
07:46:57.042098 rt_sigaction(SIGINT, {SIG_DFL, [INT], SA_RESTART}, {0x804bf00, [INT], SA_RESTART}, 8) = 0
07:46:57.042190 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
07:46:57.042275 write(1, "\n", 1
)       = 1
07:46:57.042373 write(1, "Summary:\n", 9Summary:
) = 9
07:46:57.042440 write(1, "passed   0\n", 11passed   0
) = 11
07:46:57.042504 write(1, "failed   1\n", 11failed   1
) = 11
07:46:57.042566 write(1, "skipped  0\n", 11skipped  0
) = 11
07:46:57.042629 write(1, "warnings 0\n", 11warnings 0
) = 11
07:46:57.042694 open("/tmp/WlsvGa", O_RDONLY|O_DIRECTORY|O_NOFOLLOW) = 3
07:46:57.042763 close(3)                = 0
07:46:57.042821 open("/tmp/WlsvGa", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 3
07:46:57.042883 fstat64(3, {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0
07:46:57.042951 getdents(3, /* 2 entries */, 32768) = 32
07:46:57.043022 getdents(3, /* 0 entries */, 32768) = 0
07:46:57.043078 close(3)                = 0
07:46:57.043134 lstat64("/tmp/WlsvGa", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0
07:46:57.043204 unlink("/tmp/WlsvGa")   = -1 EISDIR (Is a directory)
07:46:57.043269 rmdir("/tmp/WlsvGa")    = 0
07:46:57.043348 open("/proc/sys/vm/nr_hugepages", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
07:46:57.043421 fstat64(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
07:46:57.043483 write(3, "0\n", 2)      = 2
07:46:57.043553 close(3)                = 0
07:46:57.043608 access("/dev/shm/ltp_futex_wake04_5623", F_OK) = -1 ENOENT (No such file or directory)
07:46:57.043678 msync(0xb76e3000, 4096, MS_SYNC) = 0
07:46:57.043770 munmap(0xb76e3000, 4096) = 0
07:46:57.043847 exit_group(3)           = ?
07:46:57.044009 +++ exited with 3 +++

Looks like there is something wrong with /proc/5624/task/5626/stat So, I tried to add a file name print and sleep() in futex_utils.h, so that I could check the /proc/%i/task/%s/stat file:

--- a/testcases/kernel/syscalls/futex/futex_utils.h
+++ b/testcases/kernel/syscalls/futex/futex_utils.h
@@ -45,6 +45,8 @@ static inline int wait_for_threads(unsigned int nr_threads)
                snprintf(name, sizeof(name), "/proc/%i/task/%s/stat",
                         getpid(), dent->d_name);

+               tst_res(TINFO, "FILE NAME: %s", name);
+               sleep(15);
                SAFE_FILE_SCANF(name, "%*i %*s %c", &thread_state);

                if (thread_state != 'S') {

With an execution:

$ sudo ./futex_wake04 
tst_hugepage.c:58: TINFO: 1 hugepage(s) reserved
tst_test.c:1250: TINFO: Timeout per run is 0h 05m 00s
futex_wake04.c:60: TINFO: Testing variant: syscall with old kernel spec
futex_wake04.c:98: TINFO: Hugepagesize 2097152
futex_utils.h:48: TINFO: FILE NAME: /proc/6531/task/6532/stat
futex_wake04.c:85: TFAIL: Bug: wait_thread2 did not wake after 30 secs.: EINVAL (22)
safe_file_ops.c:144: TBROK: Failed to open FILE '/proc/6531/task/6532/stat' for reading at futex_utils.h:50: ENOENT (2)

Turns out there is no /proc/6531/task/6532 directory, but a 6531 directory there:

$ ls /proc/6331/task
6531
$ cat /proc/6531/task/6531/stat
6531 (futex_wake04) S 6530 6531 15409 34817 6529 1077936192 43 0 0 0 0 0 0 0 20 0 1 0 1308727 21409792 27 4294967295 1 1 0 0 0 0 0 0 0 0 0 0 17 3 0 0 0 0 0 0 0 0 0 0 0 0 0
metan-ucw commented 3 years ago

That looks like a some kind of kernel bug. What the code in question does it to loop over all thread ids (tids) of the process in the proc directory. In this test there should be three in there, as main process starts two threads that should sleep in futexes. In your case there is only one the main thread as the pid and tid matches. The other two threads threads exited prematurely, the logs show that the futex_wait() call failed with EINVAL.

Cypresslin commented 3 years ago

Thanks for the reply. I think I will leave this as-is since Ubuntu Xenial 4.4 kernel has already in Extended Security Maintenance mode.

BTW i386 mainline kernel 4.4.266-0404266-generic is still failing with the same issue)

<<<test_output>>>
incrementing stop
tst_hugepage.c:58: TINFO: 1 hugepage(s) reserved
tst_test.c:1313: TINFO: Timeout per run is 0h 05m 00s
futex_wake04.c:56: TINFO: Testing variant: syscall with old kernel spec
futex_wake04.c:94: TINFO: Hugepagesize 2097152
futex_utils.h:51: TINFO: Thread 12896 not sleeping yet
futex_wake04.c:81: TFAIL: Bug: wait_thread2 did not wake after 30 secs.: EINVAL (22)
futex_utils.h:62: TINFO: 0 threads sleeping, expected 2
tst_test.c:1313: TINFO: Timeout per run is 0h 05m 00s
futex_wake04.c:56: TINFO: Testing variant: syscall time64 with kernel spec
../../../../include/tst_timer.h:263: TCONF: syscall(422) __NR_futex_time64 not supported

Please feel free to close this. Thank you.

Cypresslin commented 3 years ago

Test case fixed with commit 9ee3dd9d85133793dd8ecbb2455fd5d720b0952b. Closing this bug. Thanks!