LTP: madvise08.c:203: TFAIL: No sequence in dump after MADV_DODUMP.

From: Naresh Kamboju
Date: Tue Jan 26 2021 - 01:43:25 EST

Next message: Marc Zyngier: "Re: [PATCH] genirq/msi: Activate Multi-MSI early when MSI_FLAG_ACTIVATE_EARLY is set"
Previous message: Steven Rostedt: "Re: [PATCH v2] tracing: precise log info for kretprobe addr err"
Next in thread: Arnd Bergmann: "Re: LTP: madvise08.c:203: TFAIL: No sequence in dump after MADV_DODUMP."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

LTP syscalls madvise08 test case failed on all devices from
Linux next 20210118 to till day.
strace log attached to this email and link provided below.

BAD: next-20210118
GOOD: next-20210115

This failure is easily reproducible on Linux next tag 20210118 above.

tst_test.c:1250: TINFO: Timeout per run is 0h 15m 00s
madvise08.c:73: TINFO: Temporary core pattern is
'/scratch/ltp-2nftQzNI1K/HclFMH/dump-%p'
madvise08.c:112: TINFO: Dump file should be dump-10109
madvise08.c:196: TPASS: madvise(..., MADV_DONTDUMP)
madvise08.c:112: TINFO: Dump file should be dump-10110
madvise08.c:203: TFAIL: No sequence in dump after MADV_DODUMP.

strace log,
https://lkft.validation.linaro.org/scheduler/job/2184866#L1257

Full test log link,
https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20210118/testrun/3771572/suite/ltp-syscalls-tests/test/madvise08/log

Test case link,
https://github.com/linux-test-project/ltp/blob/master/testcases/kernel/syscalls/madvise/madvise08.c#L203

metadata:
git branch: master
git repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
git describe: next-20210118
kernel-config: https://builds.tuxbuild.com/1nERt1Y6o3JSvLbiPXYTb9PMo1O/config

--
Linaro LKFT
https://lkft.linaro.org
+ cd /opt/ltp/testcases/bin/
+ strace -f ./madvise08
execve(\"./madvise08\", [\"./madvise08\"], 0x7ffd189342b8 /* 22 vars */) = 0
brk(NULL) = 0x2542000
access(\"/etc/ld.so.preload\", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, \"/etc/ld.so.cache\", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=20188, ...}) = 0
mmap(NULL, 20188, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc414fd7000
close(3) = 0
openat(AT_FDCWD, \"/lib/libc.so.6\", O_RDONLY|O_CLOEXEC) = 3
read(3, \"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\33\2\0\0\0\0\0\"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1771456, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc414fd5000
mmap(NULL, 3877600, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc414a05000
mprotect(0x7fc414baf000, 2093056, PROT_NONE) = 0
mmap(0x7fc414dae000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a9000) = 0x7fc414dae000
mmap(0x7fc414db4000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fc414db4000
close(3) = 0
arch_prctl(ARCH_SET_FS, 0x7fc414fd65c0) = 0
mprotect(0x7fc414dae000, 16384, PROT_READ) = 0
mprotect(0x61e000, 4096, PROT_READ) = 0
mprotect(0x7fc414fdc000, 4096, PROT_READ) = 0
munmap(0x7fc414fd7000, 20188) = 0
getpid() = 484
geteuid() = 0
uname({sysname=\"Linux\", nodename=\"intel-corei7-64\", ...}) = 0
access(\"/dev/shm\", F_OK) = 0
getpid() = 484
openat(AT_FDCWD, \"/dev/shm/ltp_madvise08_484\", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
chmod(\"/dev/shm/ltp_madvise08_484\", 0666) = 0
ftruncate(3, 4096) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 3, 0) = 0x7fc414fdb000
unlink(\"/dev/shm/ltp_madvise08_484\") = 0
close(3) = 0
getpid() = 484
mkdir(\"/tmp/YtwWXr\", 0700) = 0
brk(NULL) = 0x2542000
brk(0x2563000) = 0x2563000
getgid() = 0
chown(\"/tmp/YtwWXr\", -1, 0) = 0
chmod(\"/tmp/YtwWXr\", 0777) = 0
getcwd(\"/opt/ltp/testcases/bin\", 4096) = 23
chdir(\"/tmp/YtwWXr\") = 0
access(\"/proc/sys/kernel/core_pattern\", F_OK) = 0
openat(AT_FDCWD, \"/proc/sys/kernel/core_pattern\", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
read(3, \"|/bin/false\n\", 1024) = 12
close(3) = 0
rt_sigaction(SIGALRM, {sa_handler=0x406360, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x406200, sa_mask=[USR1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
ioctl(2, TCGETS, {B115200 opost isig icanon echo ...}) = 0
write(2, \"tst_test.c:1250: \33[1;34mTINFO: \33\"..., 65tst_test.c:1250: [1;34mTINFO: [0mTimeout per run is 0h 05m 00s
) = 65
getpid() = 484
alarm(300) = 0
rt_sigaction(SIGINT, {sa_handler=0x406310, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fc414fd6890) = 485
strace: Process 485 attached
[pid 484] wait4(485, <unfinished ...>
[pid 485] rt_sigaction(SIGALRM, {sa_handler=SIG_DFL, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=0x406360, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, 8) = 0
[pid 485] rt_sigaction(SIGUSR1, {sa_handler=SIG_DFL, sa_mask=[USR1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=0x406200, sa_mask=[USR1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, 8) = 0
[pid 485] rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=0x406310, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, 8) = 0
[pid 485] setpgid(0, 0) = 0
[pid 485] clock_gettime(CLOCK_REALTIME, NULL) = -1 EFAULT (Bad address)
[pid 485] clock_gettime(CLOCK_MONOTONIC, {tv_sec=43, tv_nsec=350935439}) = 0
[pid 485] getppid() = 484
[pid 485] kill(484, SIGUSR1 <unfinished ...>
[pid 484] <... wait4 resumed> 0x7ffe616cc818, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 485] <... kill resumed> ) = 0
[pid 484] --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=485, si_uid=0} ---
[pid 484] alarm(300) = 300
[pid 484] rt_sigreturn({mask=[]} <unfinished ...>
[pid 485] getpid( <unfinished ...>
[pid 484] <[ 44.736394] audit: type=1701 audit(1611570186.639:3): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=486 comm=\"madvise08\" exe=\"/opt/ltp/testcases/bin/madvise08\" sig=6 res=1
... rt_sigreturn[ 44.754167] audit: type=1701 audit(1611570186.657:4): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=487 comm=\"madvise08\" exe=\"/opt/ltp/testcases/bin/madvise08\" sig=6 res=1
resumed> ) = 61
[pid 485] <... getpid resumed> ) = 485
[pid 484] wait4(485, <unfinished ...>
[pid 485] prlimit64(0, RLIMIT_CORE, {rlim_cur=RLIM64_INFINITY, rlim_max=RLIM64_INFINITY}, NULL) = 0
[pid 485] prctl(PR_GET_DUMPABLE) = 1 (SUID_DUMP_USER)
[pid 485] openat(AT_FDCWD, \"/proc/self/coredump_filter\", O_RDONLY) = 3
[pid 485] fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid 485] read(3, \"00000033\n\", 1024) = 9
[pid 485] close(3) = 0
[pid 485] getcwd(\"/tmp/YtwWXr\", 1024) = 12
[pid 485] write(2, \"madvise08.c:78: \33[1;34mTINFO: \33[\"..., 82madvise08.c:78: [1;34mTINFO: [0mTemporary core pattern is '/tmp/YtwWXr/dump-%p'
) = 82
[pid 485] openat(AT_FDCWD, \"/proc/sys/kernel/core_pattern\", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[pid 485] fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid 485] write(3, \"/tmp/YtwWXr/dump-%p\", 19) = 19
[pid 485] close(3) = 0
[pid 485] mmap(NULL, 1282, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc414fda000
[pid 485] getpid() = 485
[pid 485] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fc414fd6890) = 486
strace: Process 486 attached
[pid 485] wait4(486, <unfinished ...>
[pid 486] madvise(0x7fc414fda000, 1282, MADV_DONTDUMP) = 0
[pid 486] rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
[pid 486] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
[pid 486] getpid() = 486
[pid 486] gettid() = 486
[pid 486] tgkill(486, 486, SIGABRT) = 0
[pid 486] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 486] --- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=486, si_uid=0} ---
[pid 486] +++ killed by SIGABRT (core dumped) +++
[pid 485] <... wait4 resumed> [{WIFSIGNALED(s) && WTERMSIG(s) == SIGABRT && WCOREDUMP(s)}], 0, NULL) = 486
[pid 485] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_DUMPED, si_pid=486, si_uid=0, si_status=SIGABRT, si_utime=0, si_stime=0} ---
[pid 485] write(2, \"madvise08.c:117: \33[1;34mTINFO: \33\"..., 64madvise08.c:117: [1;34mTINFO: [0mDump file should be dump-486
) = 64
[pid 485] access(\"dump-486\", F_OK) = 0
[pid 485] openat(AT_FDCWD, \"dump-486\", O_RDONLY) = 3
[pid 485] read(3, \"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\4\0>\0\1\0\0\0\0\0\0\0\0\0\0\0\"..., 1024) = 1024
[pid 485] read(3, \"\0\300\3\0\0\0\0\0\0\340\375\24\304\177\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\"..., 1024) = 292
[pid 485] read(3, \"\", 1024) = 0
[pid 485] close(3) = 0
[pid 485] write(2, \"madvise08.c:201: \33[1;32mTPASS: \33\"..., 63madvise08.c:201: [1;32mTPASS: [0mmadvise(..., MADV_DONTDUMP)
) = 63
[pid 485] getpid() = 485
[pid 485] wait4(-1, 0x7ffe616cc7dc, 0, NULL) = -1 ECHILD (No child processes)
[pid 485] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fc414fd6890) = 487
strace: Process 487 attached
[pid 485] wait4(487, <unfinished ...>
[pid 487] madvise(0x7fc414fda000, 1282, MADV_DODUMP) = 0
[pid 487] rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
[pid 487] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
[pid 487] getpid() = 487
[pid 487] gettid() = 487
[pid 487] tgkill(487, 487, SIGABRT) = 0
[pid 487] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 487] --- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=487, si_uid=0} ---
[pid 487] +++ killed by SIGABRT (core dumped) +++
[pid 485] <... wait4 resumed> [{WIFSIGNALED(s) && WTERMSIG(s) == SIGABRT && WCOREDUMP(s)}], 0, NULL) = 487
[pid 485] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_DUMPED, si_pid=487, si_uid=0, si_status=SIGABRT, si_utime=0, si_stime=0} ---
[pid 485] write(2, \"madvise08.c:117: \33[1;34mTINFO: \33\"..., 64madvise08.c:117: [1;34mTINFO: [0mDump file should be dump-487
) = 64
[pid 485] access(\"dump-487\", F_OK) = 0
[pid 485] openat(AT_FDCWD, \"dump-487\", O_RDONLY) = 3
[pid 485] read(3, \"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\4\0>\0\1\0\0\0\0\0\0\0\0\0\0\0\"..., 1024) = 1024
[pid 485] read(3, \"\0\320\3\0\0\0\0\0\0\340\375\24\304\177\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\"..., 1024) = 292
[pid 485] read(3, \"\", 1024) = 0
[pid 485] close(3) = 0
[pid 485] write(2, \"madvise08.c:208: \33[1;31mTFAIL: \33\"..., 74madvise08.c:208: [1;31mTFAIL: [0mNo sequence in dump after MADV_DODUMP.
) = 74
[pid 485] getpid() = 485
[pid 485] wait4(-1, 0x7ffe616cc7dc, 0, NULL) = -1 ECHILD (No child processes)
[pid 485] clock_gettime(CLOCK_MONOTONIC, {tv_sec=44, tv_nsec=100424064}) = 0
[pid 485] getppid() = 484
[pid 485] kill(484, SIGUSR1) = 0
[pid 485] munmap(0x7fc414fda000, 1282 <unfinished ...>
[pid 484] <... wait4 resumed> 0x7ffe616cc818, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 485] <... munmap resumed> ) = 0
[pid 484] --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=485, si_uid=0} ---
[pid 485] exit_group(0 <unfinished ...>
[pid 484] alarm(300 <unfinished ...>
[pid 485] <... exit_group resumed>) = ?
[pid 484] <... alarm resumed> ) = 299
[pid 484] rt_sigreturn({mask=[]} <unfinished ...>
[pid 485] +++ exited with 0 +++
<... rt_sigreturn resumed> ) = 61
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=485, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
wait4(485, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 485
alarm(0) = 300
rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, {sa_handler=0x406310, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fc414a395b0}, 8) = 0
fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(4, 64), ...}) = 0
ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0
write(1, \"\n\", 1
) = 1
write(1, \"Summary:\n\", 9Summary:
) = 9
write(1, \"passed 1\n\", 11passed 1
) = 11
write(1, \"failed 1\n\", 11failed 1
) = 11
write(1, \"skipped 0\n\", 11skipped 0
) = 11
write(1, \"warnings 0\n\", 11warnings 0
) = 11
openat(AT_FDCWD, \"/tmp/YtwWXr\", O_RDONLY|O_DIRECTORY|O_NOFOLLOW) = 3
close(3) = 0
openat(AT_FDCWD, \"/tmp/YtwWXr\", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFDIR|0777, st_size=80, ...}) = 0
getdents(3, /* 4 entries */, 32768) = 112
openat(AT_FDCWD, \"/tmp/YtwWXr/dump-487\", O_RDONLY|O_DIRECTORY|O_NOFOLLOW) = -1 ENOTDIR (Not a directory)
unlink(\"/tmp/YtwWXr/dump-487\") = 0
openat(AT_FDCWD, \"/tmp/YtwWXr/dump-486\", O_RDONLY|O_DIRECTORY|O_NOFOLLOW) = -1 ENOTDIR (Not a directory)
unlink(\"/tmp/YtwWXr/dump-486\") = 0
getdents(3, /* 0 entries */, 32768) = 0
close(3) = 0
lstat(\"/tmp/YtwWXr\", {st_mode=S_IFDIR|0777, st_size=40, ...}) = 0
unlink(\"/tmp/YtwWXr\") = -1 EISDIR (Is a directory)
rmdir(\"/tmp/YtwWXr\") = 0
openat(AT_FDCWD, \"/proc/sys/kernel/core_pattern\", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(3, \"|/bin/false\n\", 12) = 12
close(3) = 0
access(\"/dev/shm/ltp_madvise08_484\", F_OK) = -1 ENOENT (No such file or directory)
msync(0x7fc414fdb000, 4096, MS_SYNC) = 0
munmap(0x7fc414fdb000, 4096) = 0
exit_group(1) = ?
+++ exited with 1 +++

Next message: Marc Zyngier: "Re: [PATCH] genirq/msi: Activate Multi-MSI early when MSI_FLAG_ACTIVATE_EARLY is set"
Previous message: Steven Rostedt: "Re: [PATCH v2] tracing: precise log info for kretprobe addr err"
Next in thread: Arnd Bergmann: "Re: LTP: madvise08.c:203: TFAIL: No sequence in dump after MADV_DODUMP."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]