Test failed on riscv64

[yuzibo]

Hi,

Strace was built ok on Debian riscv64 but since 6.1 it has ftbfs issue due to test failed:
https://buildd.debian.org/status/logs.php?pkg=strace&arch=riscv64

I grep it on 6.2 also like:

PASS: pidfd_getfd-y.gen.test
PASS: recvmmsg-timeout.gen.test
PASS: recvmsg.gen.test
../../build-aux/test-driver: line 112: 630329 Killed                  "$@" >> "$log_file" 2>&1
FAIL: clock.gen.test
SKIP: s390_sthyi.gen.test
SKIP: s390_sthyi-v.gen.test
../../build-aux/test-driver: line 112: 632850 Killed                  "$@" >> "$log_file" 2>&1
FAIL: clock.gen.test
PASS: openat.gen.test
PASS: quotactl_fd-P.gen.test
PASS: quotactl_fd-y.gen.test
../../build-aux/test-driver: line 112: 667244 Killed                  "$@" >> "$log_file" 2>&1
FAIL: read-write.gen.test
PASS: sched_get_priority_mxx.gen.test
PASS: strace--absolute-timestamps-format-unix-precision-s.gen.test
PASS: strace--absolute-timestamps-format-unix-precision-us.gen.test
PASS: strace--decode-pids-comm.gen.test
../../build-aux/test-driver: line 112: 667453 Killed                  "$@" >> "$log_file" 2>&1
FAIL: regex.gen.test
PASS: strace--relative-timestamps.gen.test
SKIP: tkill--pidns-translation.gen.test
PASS: remap_file_pages-Xabbrev.gen.test
../../build-aux/test-driver: line 112: 671261 Killed                  "$@" >> "$log_file" 2>&1
FAIL: sched.gen.test
../../build-aux/test-driver: line 112: 679228 Killed                  "$@" >> "$log_file" 2>&1
FAIL: read-write.gen.test
SKIP: s390_sthyi.gen.test
SKIP: s390_sthyi-v.gen.test
../../build-aux/test-driver: line 112: 682709 Killed                  "$@" >> "$log_file" 2>&1
FAIL: regex.gen.test
PASS: sched_get_priority_mxx.gen.test
PASS: strace--follow-forks-output-separately.gen.test
PASS: strace--relative-timestamps.gen.test
PASS: strace--relative-timestamps-ms.gen.test
../../build-aux/test-driver: line 112: 685210 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_clock.gen.test
PASS: strace--relative-timestamps-ns.gen.test
PASS: times-fail.gen.test
PASS: tkill.gen.test
SKIP: tkill--pidns-translation.gen.test
../../build-aux/test-driver: line 112: 689849 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_creds.gen.test
../../build-aux/test-driver: line 112: 693147 Killed                  "$@" >> "$log_file" 2>&1
FAIL: sched.gen.test
../../build-aux/test-driver: line 112: 699225 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_fstat.gen.test
../../build-aux/test-driver: line 112: 702597 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_clock.gen.test
../../build-aux/test-driver: line 112: 706816 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_fstatfs.gen.test
SKIP: trace_personality_32.gen.test
../../build-aux/test-driver: line 112: 710114 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_creds.gen.test
../../build-aux/test-driver: line 112: 712966 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_lstat.gen.test
SKIP: trace_personality_all_32.gen.test
SKIP: trace_personality_number_32.gen.test
../../build-aux/test-driver: line 112: 715634 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_fstat.gen.test
../../build-aux/test-driver: line 112: 719586 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_64.gen.test
SKIP: trace_personality_32.gen.test
../../build-aux/test-driver: line 112: 722860 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_fstatfs.gen.test
SKIP: trace_personality_all_x32.gen.test
SKIP: trace_personality_number_32.gen.test
../../build-aux/test-driver: line 112: 726192 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_number_64.gen.test
SKIP: trace_personality_number_x32.gen.test
SKIP: trace_personality_regex_32.gen.test
../../build-aux/test-driver: line 112: 728760 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_lstat.gen.test
SKIP: trace_personality_number_x32.gen.test
SKIP: trace_personality_regex_x32.gen.test
SKIP: trace_personality_statfs_32.gen.test
../../build-aux/test-driver: line 112: 732820 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_64.gen.test
SKIP: trace_personality_regex_32.gen.test
../../build-aux/test-driver: line 112: 736164 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_number_64.gen.test
SKIP: trace_personality_regex_x32.gen.test
SKIP: trace_personality_statfs_32.gen.test
../../build-aux/test-driver: line 112: 739463 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_regex_64.gen.test
SKIP: trace_personality_statfs_x32.gen.test
SKIP: trace_personality_x32.gen.test
../../build-aux/test-driver: line 112: 742036 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_statfs_64.gen.test
../../build-aux/test-driver: line 112: 746117 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_regex_64.gen.test
../../build-aux/test-driver: line 112: 749438 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_personality_statfs_64.gen.test
SKIP: trace_personality_statfs_x32.gen.test
SKIP: trace_personality_x32.gen.test
../../build-aux/test-driver: line 112: 752750 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_question.gen.test
../../build-aux/test-driver: line 112: 755214 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_stat.gen.test
../../build-aux/test-driver: line 112: 759354 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_stat_like.gen.test
PASS: trie_test.gen.test
PASS: filter-unavailable.test
PASS: filtering_fd-syntax.test
../../build-aux/test-driver: line 112: 762671 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_question.gen.test
PASS: inject-nf.test
PASS: interactive_block.test
../../build-aux/test-driver: line 112: 765947 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_statfs.gen.test
PASS: legacy_syscall_info.test
PASS: kill_child.test
../../build-aux/test-driver: line 112: 768527 Killed                  "$@" >> "$log_file" 2>&1
FAIL: trace_statfs_like.gen.test
SKIP: localtime.test
PASS: qual_inject-signal.test
PASS: threads-execve.test
PASS: umovestr_cached.test
======================================
   strace 6.2: tests/test-suite.log
======================================

# TOTAL: 1256
# PASS:  948
# SKIP:  290
# XFAIL: 0
# FAIL:  18
# XPASS: 0
# ERROR: 0

The trouble is that I can not reproduce the test step by step. For example, clock.gen.test, I got almost 10K log like:

...
 args=-qq -esignal=none -e/clock ../ptrace_syscall_info-Xverbose
+ ../../src/strace -o log -qq -esignal=none -e/clock ../ptrace_syscall_info-Xverbose
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../ptrace_syscall_info-Xverbose output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ pwritev = pwritev ]
+ try_run_prog ../pwritev
+ local rc
+ ../pwritev
+ run_strace -qq -esignal=none -e/clock ../pwritev
+
+ args=-qq -esignal=none -e/clock ../pwritev
+ ../../src/strace -o log -qq -esignal=none -e/clock ../pwritev
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../pwritev output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl = quotactl ]
+ try_run_prog ../quotactl
+ local rc
+ ../quotactl
+ run_strace -qq -esignal=none -e/clock ../quotactl
+
+ args=-qq -esignal=none -e/clock ../quotactl
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl-Xabbrev = quotactl-Xabbrev ]
+ try_run_prog ../quotactl-Xabbrev
+ local rc
+ ../quotactl-Xabbrev
+ run_strace -qq -esignal=none -e/clock ../quotactl-Xabbrev
+
+ args=-qq -esignal=none -e/clock ../quotactl-Xabbrev
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl-Xabbrev
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl-Xabbrev output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl-Xraw = quotactl-Xraw ]
+ try_run_prog ../quotactl-Xraw
+ local rc
+ ../quotactl-Xraw
+ run_strace -qq -esignal=none -e/clock ../quotactl-Xraw
+
+ args=-qq -esignal=none -e/clock ../quotactl-Xraw
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl-Xraw
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl-Xraw output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl-Xverbose = quotactl-Xverbose ]
+ try_run_prog ../quotactl-Xverbose
+ local rc
+ ../quotactl-Xverbose
+ run_strace -qq -esignal=none -e/clock ../quotactl-Xverbose
+
+ args=-qq -esignal=none -e/clock ../quotactl-Xverbose
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl-Xverbose
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl-Xverbose output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl-xfs = quotactl-xfs ]
+ try_run_prog ../quotactl-xfs
+ local rc
+ ../quotactl-xfs
+ run_strace -qq -esignal=none -e/clock ../quotactl-xfs
+
+ args=-qq -esignal=none -e/clock ../quotactl-xfs
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl-xfs
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl-xfs output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl_fd = quotactl_fd ]
+ try_run_prog ../quotactl_fd
+ local rc
+ ../quotactl_fd
+ run_strace -qq -esignal=none -e/clock ../quotactl_fd
+
+ args=-qq -esignal=none -e/clock ../quotactl_fd
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl_fd
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl_fd output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl_fd-P = quotactl_fd-P ]
+ try_run_prog ../quotactl_fd-P
+ local rc
+ ../quotactl_fd-P
+ run_strace -qq -esignal=none -e/clock ../quotactl_fd-P
+
+ args=-qq -esignal=none -e/clock ../quotactl_fd-P
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl_fd-P
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl_fd-P output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ quotactl_fd-y = quotactl_fd-y ]
+ try_run_prog ../quotactl_fd-y
+ local rc
+ ../quotactl_fd-y
+ run_strace -qq -esignal=none -e/clock ../quotactl_fd-y
+
+ args=-qq -esignal=none -e/clock ../quotactl_fd-y
+ ../../src/strace -o log -qq -esignal=none -e/clock ../quotactl_fd-y
+ match_diff log /dev/null
+ local output expected error
+ [ 2 -eq 0 ]
+ output=log
+ shift
+ [ 1 -eq 0 ]
+ expected=/dev/null
+ shift
+ [ 0 -eq 0 ]
+ error=../../src/strace -qq -esignal=none -e/clock ../quotactl_fd-y output mismatch
+ check_prog diff
+ type diff
+ diff -u -- /dev/null log
+ read -r t prog_args
+ [ read-write = read-write ]
+ try_run_prog ../read-write
+ local rc
+ ../read-write
FAIL clock.gen.test (exit status: 137)

Could you tell me how to debug this or which directory to look at? TIA.
yeah, I have a real riscv64 hardware, Unmatched boards by hand.

[ldv-alt]

If a simple ../read-write invocation which does nothing fancy is failing, it means that the kernel for some reason doesn't like the read-write executable itself, maybe it hangs somewhere in the kernel. Try running ./read-write >/dev/null and see what happens. since the read-write hasn't been changing for quite a while, my bet is you hit some riscv-specific kernel bug.

[ldv-alt]

OK, the process indeed hangs in one of write syscalls:

write(1, "\0\1\2\3\4\5\6\7\10\t\n\v\f\r\16\17\20\21\22\23\24\25\26\27\30\31\32\33\34\35\36\37"..., 1114113

The kernel is expected to perform a short write, e.g. on x86_64 it does the following:

write(1, "\0\1\2\3\4\5\6\7\10\t\n\v\f\r\16\17\20\21\22\23\24\25\26\27\30\31\32\33\34\35\36\37"..., 1114113) = 1114096

[yuzibo]

OK, the process indeed hangs in one of write syscalls:

write(1, "\0\1\2\3\4\5\6\7\10\t\n\v\f\r\16\17\20\21\22\23\24\25\26\27\30\31\32\33\34\35\36\37"..., 1114113

Yeah, I got this also. thanks for helps. I will try to catch the bug.

[yuzibo]

Here is my some updates.
The hang of strace 6.2 of read-write test already exists since 5.18 kernel on Qemu I tested(kernel 5.17 is ok).
Because there was no the newer version than strace 5.10 on Debian riscv64, So I think we are missing some bugs from there.

Could you tell me which debug options enabled for kernel are helpful to debug the issue? There are no dmesg messages occurred when hang reproduced. Next I have to git bisect bettween kernel 5.18 and 5.17.

BTW, there is one test failed since 5.10 on Qemu:

FAIL: filtering_syscall-syntax.test

[yuzibo]

I guess I found the commit that introduced the issue.

631f871f071746789e9242e514ab0f49067fa97a fs/iomap: Fix buffered write page prefaulting

After I revert the commit, I can pass all test cases that I reported fail tests here expect FAIL: filtering_syscall-syntax.test on kernel 6.2 with strace 6.2 on qemu.

============================================================================
Testsuite summary for strace 6.2
============================================================================
# TOTAL: 1256
# PASS:  1065
# SKIP:  190
# XFAIL: 0
# FAIL:  1
# XPASS: 0
# ERROR: 0
============================================================================
See tests/test-suite.log
Please report to strace-devel@lists.strace.io
...

I am not sure this commit how to effect behavior on riscv and have to cost more time to debug here.
If I can reproduce this bug with a simple code snap that would be great.

[yuzibo]

I have forwarded this to riscv kernel mail list:
http://lists.infradead.org/pipermail/linux-riscv/2023-March/028489.html

I need more time to fix it.

[yuzibo]

The kernel issue has been fixed:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=4b05b993900dd3eba0fc83ef5c5ddc7d65d786c6
so I close the issue.