Bug #16492: TestBugReporter#test_bug_reporter_add test failures

• Status: Closed
• Assignee: jaruga (Jun Aruga)
• Target version: -
• ruby -v: ruby 2.7.0p0 (2019-12-25 revision 647ee6f091) [s390x-linux]
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN

[vo.x (Vit Ondruch)]

Building Ruby packages on Fedora, in 90% of cases, I observe the following error on s390:

  1) Error:
TestBugReporter#test_bug_reporter_add:
Timeout::Error: execution of assert_in_out_err expired timeout (10 sec)
pid 2061293 killed by SIGKILL (signal 9)
| 
| -:1: [BUG] Segmentation fault at 0x001f73ed000003e8
| ruby 2.7.0p0 (2019-12-25 revision 647ee6f091) [s390x-linux]
| 
| -- Control frame information -----------------------------------------------
| c:0003 p:---- s:0012 e:000011 CFUNC  :kill
| c:0002 p:0021 s:0006 e:000005 EVAL   -:1 [FINISH]
| c:0001 p:0000 s:0003 E:000430 (none) [FINISH]
| 
| -- Ruby level backtrace information ----------------------------------------
| -:1:in `<main>'
| -:1:in `kill'
| 
| -- Other runtime information -----------------------------------------------
| 
| * Loaded script: -
| 
| * Loaded features:
| 
|     0 enumerator.so
|     1 thread.rb
|     2 rational.so
|     3 complex.so
|     4 ruby2_keywords.rb
|     5 /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/encdb.so
|     6 /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/trans/transdb.so
|     7 /builddir/build/BUILD/ruby-2.7.0/abrt.rb
|     8 /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/-test-/bug_reporter.so
| 
| * Process memory map:
| 
| 2aa27a00000-2aa27a01000 r-xp 00000000 fc:03 1845127                      /builddir/build/BUILD/ruby-2.7.0/ruby
| 2aa27a01000-2aa27a02000 r--p 00000000 fc:03 1845127                      /builddir/build/BUILD/ruby-2.7.0/ruby
| 2aa27a02000-2aa27a03000 rw-p 00001000 fc:03 1845127                      /builddir/build/BUILD/ruby-2.7.0/ruby
| 2aa28a7e000-2aa28bfe000 rw-p 00000000 00:00 0                            [heap]
| 3ff9ff80000-3ff9ff81000 r-xp 00000000 fc:03 1844756                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/-test-/bug_reporter.so
| 3ff9ff81000-3ff9ff82000 r--p 00000000 fc:03 1844756                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/-test-/bug_reporter.so
| 3ff9ff82000-3ff9ff83000 rw-p 00000000 00:00 0 
| 3ffa0000000-3ffa0002000 r-xp 00000000 fc:03 1844387                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/trans/transdb.so
| 3ffa0002000-3ffa0003000 r--p 00001000 fc:03 1844387                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/trans/transdb.so
| 3ffa0003000-3ffa0004000 rw-p 00000000 00:00 0 
| 3ffa0036000-3ffa0037000 ---p 00000000 00:00 0 
| 3ffa0037000-3ffa0078000 rw-p 00000000 00:00 0 
| 3ffa0078000-3ffa0079000 ---p 00000000 00:00 0 
| 3ffa0079000-3ffa00ba000 rw-p 00000000 00:00 0 
| 3ffa00ba000-3ffa00bb000 ---p 00000000 00:00 0 
| 3ffa00bb000-3ffa00fc000 rw-p 00000000 00:00 0 
| 3ffa00fc000-3ffa00fd000 ---p 00000000 00:00 0 
| 3ffa00fd000-3ffa013e000 rw-p 00000000 00:00 0 
| 3ffa013e000-3ffa013f000 ---p 00000000 00:00 0 
| 3ffa013f000-3ffa0180000 rw-p 00000000 00:00 0 
| 3ffa0180000-3ffa0181000 ---p 00000000 00:00 0 
| 3ffa0181000-3ffa01c2000 rw-p 00000000 00:00 0 
| 3ffa01c2000-3ffa01c3000 ---p 00000000 00:00 0 
| 3ffa01c3000-3ffa0204000 rw-p 00000000 00:00 0 
| 3ffa0204000-3ffa0205000 ---p 00000000 00:00 0 
| 3ffa0205000-3ffa0246000 rw-p 00000000 00:00 0 
| 3ffa0246000-3ffa0247000 ---p 00000000 00:00 0 
| 3ffa0247000-3ffa0288000 rw-p 00000000 00:00 0 
| 3ffa0288000-3ffa0289000 ---p 00000000 00:00 0 
| 3ffa0289000-3ffa02ca000 rw-p 00000000 00:00 0 
| 3ffa02ca000-3ffa02cb000 ---p 00000000 00:00 0 
| 3ffa02cb000-3ffa030c000 rw-p 00000000 00:00 0 
| 3ffa030c000-3ffa030d000 ---p 00000000 00:00 0 
| 3ffa030d000-3ffa034e000 rw-p 00000000 00:00 0 
| 3ffa034e000-3ffa034f000 ---p 00000000 00:00 0 
| 3ffa034f000-3ffa0390000 rw-p 00000000 00:00 0 
| 3ffa0390000-3ffa0391000 ---p 00000000 00:00 0 
| 3ffa0391000-3ffa03d2000 rw-p 00000000 00:00 0 
| 3ffa03d2000-3ffa03d3000 ---p 00000000 00:00 0 
| 3ffa03d3000-3ffa0414000 rw-p 00000000 00:00 0 
| 3ffa0414000-3ffa0415000 ---p 00000000 00:00 0 
| 3ffa0415000-3ffa0456000 rw-p 00000000 00:00 0 
| 3ffa0456000-3ffa0457000 ---p 00000000 00:00 0 
| 3ffa0457000-3ffa0498000 rw-p 00000000 00:00 0 
| 3ffa0498000-3ffa0499000 ---p 00000000 00:00 0 
| 3ffa0499000-3ffa04da000 rw-p 00000000 00:00 0 
| 3ffa04da000-3ffa04db000 ---p 00000000 00:00 0 
| 3ffa04db000-3ffa051c000 rw-p 00000000 00:00 0 
| 3ffa051c000-3ffa051d000 ---p 00000000 00:00 0 
| 3ffa051d000-3ffa055e000 rw-p 00000000 00:00 0 
| 3ffa055e000-3ffa055f000 ---p 00000000 00:00 0 
| 3ffa055f000-3ffa05a0000 rw-p 00000000 00:00 0 
| 3ffa05a0000-3ffa05a1000 ---p 00000000 00:00 0 
| 3ffa05a1000-3ffa05e2000 rw-p 00000000 00:00 0 
| 3ffa05e2000-3ffa05e3000 ---p 00000000 00:00 0 
| 3ffa05e3000-3ffa0624000 rw-p 00000000 00:00 0 
| 3ffa0624000-3ffa0625000 ---p 00000000 00:00 0 
| 3ffa0625000-3ffa0666000 rw-p 00000000 00:00 0 
| 3ffa0666000-3ffa0667000 ---p 00000000 00:00 0 
| 3ffa0667000-3ffa06a8000 rw-p 00000000 00:00 0 
| 3ffa06a8000-3ffa06a9000 ---p 00000000 00:00 0 
| 3ffa06a9000-3ffa06ea000 rw-p 00000000 00:00 0 
| 3ffa06ea000-3ffa06eb000 ---p 00000000 00:00 0 
| 3ffa06eb000-3ffa072c000 rw-p 00000000 00:00 0 
| 3ffa072c000-3ffa072d000 ---p 00000000 00:00 0 
| 3ffa072d000-3ffa076e000 rw-p 00000000 00:00 0 
| 3ffa076e000-3ffa076f000 ---p 00000000 00:00 0 
| 3ffa076f000-3ffa07b0000 rw-p 00000000 00:00 0 
| 3ffa07b0000-3ffa07b1000 ---p 00000000 00:00 0 
| 3ffa07b1000-3ffa07f2000 rw-p 00000000 00:00 0 
| 3ffa07f2000-3ffa07f3000 ---p 00000000 00:00 0 
| 3ffa07f3000-3ffa0834000 rw-p 00000000 00:00 0 
| 3ffa0834000-3ffa0835000 ---p 00000000 00:00 0 
| 3ffa0835000-3ffa2980000 rw-p 00000000 00:00 0 
| 3ffa2980000-3ffa2a17000 r-xp 00000000 fc:03 1813828                      /usr/lib64/libm-2.30.9000.so
| 3ffa2a17000-3ffa2a18000 r--p 00096000 fc:03 1813828                      /usr/lib64/libm-2.30.9000.so
| 3ffa2a18000-3ffa2a19000 rw-p 00097000 fc:03 1813828                      /usr/lib64/libm-2.30.9000.so
| 3ffa2a80000-3ffa2ab2000 r-xp 00000000 fc:03 1814596                      /usr/lib64/libcrypt.so.2.0.0
| 3ffa2ab2000-3ffa2ab3000 ---p 00032000 fc:03 1814596                      /usr/lib64/libcrypt.so.2.0.0
| 3ffa2ab3000-3ffa2ab4000 r--p 00032000 fc:03 1814596                      /usr/lib64/libcrypt.so.2.0.0
| 3ffa2ab4000-3ffa2abd000 rw-p 00000000 00:00 0 
| 3ffa2b00000-3ffa2b03000 r-xp 00000000 fc:03 1813826                      /usr/lib64/libdl-2.30.9000.so
| 3ffa2b03000-3ffa2b04000 r--p 00002000 fc:03 1813826                      /usr/lib64/libdl-2.30.9000.so
| 3ffa2b04000-3ffa2b05000 rw-p 00000000 00:00 0 
| 3ffa2b80000-3ffa2c05000 r-xp 00000000 fc:03 1814658                      /usr/lib64/libgmp.so.10.3.2
| 3ffa2c05000-3ffa2c07000 r--p 00084000 fc:03 1814658                      /usr/lib64/libgmp.so.10.3.2
| 3ffa2c07000-3ffa2c08000 rw-p 00086000 fc:03 1814658                      /usr/lib64/libgmp.so.10.3.2
| 3ffa2c80000-3ffa2c88000 r-xp 00000000 fc:03 1813840                      /usr/lib64/librt-2.30.9000.so
| 3ffa2c88000-3ffa2c89000 r--p 00007000 fc:03 1813840                      /usr/lib64/librt-2.30.9000.so
| 3ffa2c89000-3ffa2c8a000 rw-p 00008000 fc:03 1813840                      /usr/lib64/librt-2.30.9000.so
| 3ffa2d00000-3ffa2d1e000 r-xp 00000000 fc:03 1813836                      /usr/lib64/libpthread-2.30.9000.so
| 3ffa2d1e000-3ffa2d1f000 r--p 0001d000 fc:03 1813836                      /usr/lib64/libpthread-2.30.9000.so
| 3ffa2d1f000-3ffa2d20000 rw-p 0001e000 fc:03 1813836                      /usr/lib64/libpthread-2.30.9000.so
| 3ffa2d20000-3ffa2d24000 rw-p 00000000 00:00 0 
| 3ffa2d80000-3ffa2f1e000 r-xp 00000000 fc:03 1813824                      /usr/lib64/libc-2.30.9000.so
| 3ffa2f1e000-3ffa2f22000 r--p 0019d000 fc:03 1813824                      /usr/lib64/libc-2.30.9000.so
| 3ffa2f22000-3ffa2f25000 rw-p 001a1000 fc:03 1813824                      /usr/lib64/libc-2.30.9000.so
| 3ffa2f25000-3ffa2f28000 rw-p 00000000 00:00 0 
| 3ffa2f80000-3ffa2f82000 r-xp 00000000 fc:03 1844333                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/encdb.so
| 3ffa2f82000-3ffa2f83000 r--p 00001000 fc:03 1844333                      /builddir/build/BUILD/ruby-2.7.0/.ext/s390x-linux/enc/encdb.so
| 3ffa2f83000-3ffa2f84000 rw-p 00000000 00:00 0 
| 3ffa3000000-3ffa336e000 r-xp 00000000 fc:03 1844256                      /builddir/build/BUILD/ruby-2.7.0/libruby.so.2.7.0
| 3ffa336e000-3ffa3377000 r--p 0036d000 fc:03 1844256                      /builddir/build/BUILD/ruby-2.7.0/libruby.so.2.7.0
| 3ffa3377000-3ffa3378000 rw-p 00376000 fc:03 1844256                      /builddir/build/BUILD/ruby-2.7.0/libruby.so.2.7.0
| 3ffa3378000-3ffa338f000 rw-p 00000000 00:00 0 
| 3ffa3400000-3ffa3426000 r-xp 00000000 fc:03 1813817                      /usr/lib64/ld-2.30.9000.so
| 3ffa3426000-3ffa3427000 r--p 00025000 fc:03 1813817                      /usr/lib64/ld-2.30.9000.so
| 3ffa3427000-3ffa3428000 rw-p 00026000 fc:03 1813817                      /usr/lib64/ld-2.30.9000.so
| 3ffa3428000-3ffa3429000 rw-p 00000000 00:00 0 
| 3ffa3476000-3ffa347e000 rw-p 00000000 00:00 0 
| 3ffa347e000-3ffa3480000 r-xp 00000000 00:00 0                            [vdso]
| 3ffc5301000-3ffc5b00000 rw-p 00000000 00:00 0                            [stack]
| 
| 
| Sample bug reporter: 12345
    /builddir/build/BUILD/ruby-2.7.0/test/-ext-/bug_reporter/test_bug_reporter.rb:22:in `test_bug_reporter_add'
Finished tests in 544.051367s, 38.5515 tests/s, 4998.1953 assertions/s.
20974 tests, 2719275 assertions, 0 failures, 1 errors, 68 skips
ruby -v: ruby 2.7.0p0 (2019-12-25 revision 647ee6f091) [s390x-linux]

Since the default timeout is 10s, I tried to increase the timeout to 30s via simple sed -i '/assert_in_out_err/ s/)/, timeout: 30)/' test/-ext-/bug_reporter/test_bug_reporter.rb and this seems to help to avoid this issue.

However, I am not really sure why s390x is so slow handling this test case :/

[jaruga (Jun Aruga)]

Note seeing Travis's latest 5 s390x jobs, the s390x jobs have done successfully.
This error does not happen on Travis s390x case.
https://travis-ci.org/ruby/ruby/branches

Could you attach the reported error log's build.log file?

In this case, the possible steps to debug I think is

1. Run only "TestBugReporter#test_bug_reporter_add" case, then check if the error still happens.
2. For "1.", the error still happens, use strace for the command running only the "TestBugReporter#test_bug_reporter_add" case, and compare the outputted logs between s390x and other architectures. Check if some system calls returns error.
3. Check the source code with the clues of "2.".

[jaruga (Jun Aruga)]

Could you attach the reported error log's build.log file?

I meant that people might want to compare the build environment between Fedora project's build system and Travis, such as gcc version, the compiler flags, make command options, and etc.

[vo.x (Vit Ondruch)]

• Subject changed from TestBugReporter#test_bug_reporter_add test failures on s390x to TestBugReporter#test_bug_reporter_add test failures

Digging a bit into this issue, I was wrong that this is just s390x.

for i in {1..10000}
do
  echo "******** $i"
  make runruby TESTRUN_SCRIPT="-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v"
done

... snip ...

******** 1103
+ for i in {1..10000}
+ echo '******** 1103'
+ make runruby 'TESTRUN_SCRIPT=-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v'
./revision.h unchanged
./miniruby -I./lib -I. -I.ext/common  ./tool/runruby.rb --extout=.ext  -- --disable-gems -Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v
Run options: -v
# Running tests:
[1/1] TestBugReporter#test_bug_reporter_add = 12.01 s
  1) Error:
TestBugReporter#test_bug_reporter_add:
Timeout::Error: execution of assert_in_out_err expired timeout (10 sec)
pid 3442171 killed by SIGKILL (signal 9)
| 
| -:1: [BUG] Segmentation fault at 0x000003e8003485fb
| ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]
| 
| -- Control frame information -----------------------------------------------
| c:0003 p:---- s:0012 e:000011 CFUNC  :kill
| c:0002 p:0021 s:0006 e:000005 EVAL   -:1 [FINISH]
| c:0001 p:0000 s:0003 E:000210 (none) [FINISH]
| 
| -- Ruby level backtrace information ----------------------------------------
| -:1:in `<main>'
| -:1:in `kill'
| 
| -- Machine register context ------------------------------------------------
|  RIP: 0x00007f76dc8b3e0b RBP: 0x000000000000000b RSP: 0x00007ffdc485aeb8
|  RAX: 0x0000000000000000 RBX: 0x0000000000000001 RCX: 0x00007f76dc8b3e0b
|  RDX: 0x00000000003485fb RDI: 0x00000000003485fb RSI: 0x000000000000000b
|   R8: 0x00000000003485fb  R9: 0x00000000ffffffff R10: 0x0000000000000000
|  R11: 0x0000000000000206 R12: 0x0000000000000002 R13: 0x00007f76dc519048
|  R14: 0x00000000003485fb R15: 0x0000000000000001 EFL: 0x0000000000000206
| 
| -- Other runtime information -----------------------------------------------
| 
| * Loaded script: -
| 
| * Loaded features:
| 
|     0 enumerator.so
|     1 thread.rb
|     2 rational.so
|     3 complex.so
|     4 ruby2_keywords.rb
|     5 /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/encdb.so
|     6 /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/trans/transdb.so
|     7 /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/-test-/bug_reporter.so
| 
| * Process memory map:
| 
| 55d14a238000-55d14a239000 r--p 00000000 fc:02 145422722                  /builddir/build/BUILD/ruby-2.7.1/ruby
| 55d14a239000-55d14a23a000 r-xp 00001000 fc:02 145422722                  /builddir/build/BUILD/ruby-2.7.1/ruby
| 55d14a23a000-55d14a23b000 r--p 00002000 fc:02 145422722                  /builddir/build/BUILD/ruby-2.7.1/ruby
| 55d14a23b000-55d14a23c000 r--p 00002000 fc:02 145422722                  /builddir/build/BUILD/ruby-2.7.1/ruby
| 55d14a23c000-55d14a23d000 rw-p 00003000 fc:02 145422722                  /builddir/build/BUILD/ruby-2.7.1/ruby
| 55d14aab5000-55d14ac26000 rw-p 00000000 00:00 0                          [heap]
| 7f76d9c5f000-7f76d9c60000 r--p 00000000 fc:02 7954088                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/-test-/bug_reporter.so
| 7f76d9c60000-7f76d9c61000 r-xp 00001000 fc:02 7954088                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/-test-/bug_reporter.so
| 7f76d9c61000-7f76d9c62000 r--p 00002000 fc:02 7954088                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/-test-/bug_reporter.so
| 7f76d9c62000-7f76d9c63000 r--p 00002000 fc:02 7954088                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/-test-/bug_reporter.so
| 7f76d9c63000-7f76d9c64000 rw-p 00000000 00:00 0 
| 7f76d9c64000-7f76d9c65000 r--p 00000000 fc:02 71528115                   /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/trans/transdb.so
| 7f76d9c65000-7f76d9c67000 r-xp 00001000 fc:02 71528115                   /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/trans/transdb.so
| 7f76d9c67000-7f76d9c68000 r--p 00003000 fc:02 71528115                   /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/trans/transdb.so
| 7f76d9c68000-7f76d9c69000 r--p 00003000 fc:02 71528115                   /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/trans/transdb.so
| 7f76d9c69000-7f76d9c6a000 rw-p 00000000 00:00 0 
| 7f76d9c6a000-7f76d9c6b000 r--p 00000000 fc:02 4022274                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/encdb.so
| 7f76d9c6b000-7f76d9c6c000 r-xp 00001000 fc:02 4022274                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/encdb.so
| 7f76d9c6c000-7f76d9c6d000 r--p 00002000 fc:02 4022274                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/encdb.so
| 7f76d9c6d000-7f76d9c6e000 r--p 00002000 fc:02 4022274                    /builddir/build/BUILD/ruby-2.7.1/.ext/x86_64-linux/enc/encdb.so
| 7f76d9c6e000-7f76d9c6f000 rw-p 00000000 00:00 0 
| 7f76d9c6f000-7f76d9c70000 ---p 00000000 00:00 0 
| 7f76d9c70000-7f76d9cb1000 rw-p 00000000 00:00 0 
| 7f76d9cb1000-7f76d9cb2000 ---p 00000000 00:00 0 
| 7f76d9cb2000-7f76d9cf3000 rw-p 00000000 00:00 0 
| 7f76d9cf3000-7f76d9cf4000 ---p 00000000 00:00 0 
| 7f76d9cf4000-7f76d9d35000 rw-p 00000000 00:00 0 
| 7f76d9d35000-7f76d9d36000 ---p 00000000 00:00 0 
| 7f76d9d36000-7f76d9d77000 rw-p 00000000 00:00 0 
| 7f76d9d77000-7f76d9d78000 ---p 00000000 00:00 0 
| 7f76d9d78000-7f76d9db9000 rw-p 00000000 00:00 0 
| 7f76d9db9000-7f76d9dba000 ---p 00000000 00:00 0 
| 7f76d9dba000-7f76d9dfb000 rw-p 00000000 00:00 0 
| 7f76d9dfb000-7f76d9dfc000 ---p 00000000 00:00 0 
| 7f76d9dfc000-7f76d9e3d000 rw-p 00000000 00:00 0 
| 7f76d9e3d000-7f76d9e3e000 ---p 00000000 00:00 0 
| 7f76d9e3e000-7f76d9e7f000 rw-p 00000000 00:00 0 
| 7f76d9e7f000-7f76d9e80000 ---p 00000000 00:00 0 
| 7f76d9e80000-7f76d9ec1000 rw-p 00000000 00:00 0 
| 7f76d9ec1000-7f76d9ec2000 ---p 00000000 00:00 0 
| 7f76d9ec2000-7f76d9f03000 rw-p 00000000 00:00 0 
| 7f76d9f03000-7f76d9f04000 ---p 00000000 00:00 0 
| 7f76d9f04000-7f76d9f45000 rw-p 00000000 00:00 0 
| 7f76d9f45000-7f76d9f46000 ---p 00000000 00:00 0 
| 7f76d9f46000-7f76d9f87000 rw-p 00000000 00:00 0 
| 7f76d9f87000-7f76d9f88000 ---p 00000000 00:00 0 
| 7f76d9f88000-7f76d9fc9000 rw-p 00000000 00:00 0 
| 7f76d9fc9000-7f76d9fca000 ---p 00000000 00:00 0 
| 7f76d9fca000-7f76da00b000 rw-p 00000000 00:00 0 
| 7f76da00b000-7f76da00c000 ---p 00000000 00:00 0 
| 7f76da00c000-7f76da04d000 rw-p 00000000 00:00 0 
| 7f76da04d000-7f76da04e000 ---p 00000000 00:00 0 
| 7f76da04e000-7f76da08f000 rw-p 00000000 00:00 0 
| 7f76da08f000-7f76da090000 ---p 00000000 00:00 0 
| 7f76da090000-7f76da0d1000 rw-p 00000000 00:00 0 
| 7f76da0d1000-7f76da0d2000 ---p 00000000 00:00 0 
| 7f76da0d2000-7f76da113000 rw-p 00000000 00:00 0 
| 7f76da113000-7f76da114000 ---p 00000000 00:00 0 
| 7f76da114000-7f76da155000 rw-p 00000000 00:00 0 
| 7f76da155000-7f76da156000 ---p 00000000 00:00 0 
| 7f76da156000-7f76da197000 rw-p 00000000 00:00 0 
| 7f76da197000-7f76da198000 ---p 00000000 00:00 0 
| 7f76da198000-7f76da1d9000 rw-p 00000000 00:00 0 
| 7f76da1d9000-7f76da1da000 ---p 00000000 00:00 0 
| 7f76da1da000-7f76da21b000 rw-p 00000000 00:00 0 
| 7f76da21b000-7f76da21c000 ---p 00000000 00:00 0 
| 7f76da21c000-7f76da25d000 rw-p 00000000 00:00 0 
| 7f76da25d000-7f76da25e000 ---p 00000000 00:00 0 
| 7f76da25e000-7f76da29f000 rw-p 00000000 00:00 0 
| 7f76da29f000-7f76da2a0000 ---p 00000000 00:00 0 
| 7f76da2a0000-7f76da2e1000 rw-p 00000000 00:00 0 
| 7f76da2e1000-7f76da2e2000 ---p 00000000 00:00 0 
| 7f76da2e2000-7f76da323000 rw-p 00000000 00:00 0 
| 7f76da323000-7f76da324000 ---p 00000000 00:00 0 
| 7f76da324000-7f76da365000 rw-p 00000000 00:00 0 
| 7f76da365000-7f76da366000 ---p 00000000 00:00 0 
| 7f76da366000-7f76da3a7000 rw-p 00000000 00:00 0 
| 7f76da3a7000-7f76da3a8000 ---p 00000000 00:00 0 
| 7f76da3a8000-7f76da3e9000 rw-p 00000000 00:00 0 
| 7f76da3e9000-7f76da3ea000 ---p 00000000 00:00 0 
| 7f76da3ea000-7f76da42b000 rw-p 00000000 00:00 0 
| 7f76da42b000-7f76da42c000 ---p 00000000 00:00 0 
| 7f76da42c000-7f76da46d000 rw-p 00000000 00:00 0 
| 7f76da46d000-7f76da46e000 ---p 00000000 00:00 0 
| 7f76da46e000-7f76dc61c000 rw-p 00000000 00:00 0 
| 7f76dc61c000-7f76dc62b000 r--p 00000000 fc:02 137156855                  /usr/lib64/libm-2.31.9000.so
| 7f76dc62b000-7f76dc6c7000 r-xp 0000f000 fc:02 137156855                  /usr/lib64/libm-2.31.9000.so
| 7f76dc6c7000-7f76dc760000 r--p 000ab000 fc:02 137156855                  /usr/lib64/libm-2.31.9000.so
| 7f76dc760000-7f76dc761000 r--p 00143000 fc:02 137156855                  /usr/lib64/libm-2.31.9000.so
| 7f76dc761000-7f76dc762000 rw-p 00144000 fc:02 137156855                  /usr/lib64/libm-2.31.9000.so
| 7f76dc762000-7f76dc764000 r--p 00000000 fc:02 137197846                  /usr/lib64/libcrypt.so.2.0.0
| 7f76dc764000-7f76dc779000 r-xp 00002000 fc:02 137197846                  /usr/lib64/libcrypt.so.2.0.0
| 7f76dc779000-7f76dc793000 r--p 00017000 fc:02 137197846                  /usr/lib64/libcrypt.so.2.0.0
| 7f76dc793000-7f76dc794000 r--p 00030000 fc:02 137197846                  /usr/lib64/libcrypt.so.2.0.0
| 7f76dc794000-7f76dc79f000 rw-p 00000000 00:00 0 
| 7f76dc79f000-7f76dc7a1000 r--p 00000000 fc:02 137156853                  /usr/lib64/libdl-2.31.9000.so
| 7f76dc7a1000-7f76dc7a3000 r-xp 00002000 fc:02 137156853                  /usr/lib64/libdl-2.31.9000.so
| 7f76dc7a3000-7f76dc7a4000 r--p 00004000 fc:02 137156853                  /usr/lib64/libdl-2.31.9000.so
| 7f76dc7a4000-7f76dc7a5000 r--p 00004000 fc:02 137156853                  /usr/lib64/libdl-2.31.9000.so
| 7f76dc7a5000-7f76dc7a6000 rw-p 00000000 00:00 0 
| 7f76dc7a6000-7f76dc7b6000 r--p 00000000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc7b6000-7f76dc82f000 r-xp 00010000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc82f000-7f76dc846000 r--p 00089000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc846000-7f76dc847000 ---p 000a0000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc847000-7f76dc849000 r--p 000a0000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc849000-7f76dc84a000 rw-p 000a2000 fc:02 137775300                  /usr/lib64/libgmp.so.10.4.0
| 7f76dc84a000-7f76dc84d000 r--p 00000000 fc:02 137160069                  /usr/lib64/librt-2.31.9000.so
| 7f76dc84d000-7f76dc851000 r-xp 00003000 fc:02 137160069                  /usr/lib64/librt-2.31.9000.so
| 7f76dc851000-7f76dc853000 r--p 00007000 fc:02 137160069                  /usr/lib64/librt-2.31.9000.so
| 7f76dc853000-7f76dc854000 r--p 00008000 fc:02 137160069                  /usr/lib64/librt-2.31.9000.so
| 7f76dc854000-7f76dc855000 rw-p 00009000 fc:02 137160069                  /usr/lib64/librt-2.31.9000.so
| 7f76dc855000-7f76dc85c000 r--p 00000000 fc:02 137160065                  /usr/lib64/libpthread-2.31.9000.so
| 7f76dc85c000-7f76dc86c000 r-xp 00007000 fc:02 137160065                  /usr/lib64/libpthread-2.31.9000.so
| 7f76dc86c000-7f76dc871000 r--p 00017000 fc:02 137160065                  /usr/lib64/libpthread-2.31.9000.so
| 7f76dc871000-7f76dc872000 r--p 0001b000 fc:02 137160065                  /usr/lib64/libpthread-2.31.9000.so
| 7f76dc872000-7f76dc873000 rw-p 0001c000 fc:02 137160065                  /usr/lib64/libpthread-2.31.9000.so
| 7f76dc873000-7f76dc877000 rw-p 00000000 00:00 0 
| 7f76dc877000-7f76dc89c000 r--p 00000000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dc89c000-7f76dc9ed000 r-xp 00025000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dc9ed000-7f76dca38000 r--p 00176000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dca38000-7f76dca39000 ---p 001c1000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dca39000-7f76dca3c000 r--p 001c1000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dca3c000-7f76dca3f000 rw-p 001c4000 fc:02 137156851                  /usr/lib64/libc-2.31.9000.so
| 7f76dca3f000-7f76dca43000 rw-p 00000000 00:00 0 
| 7f76dca46000-7f76dca74000 r--p 00000000 fc:02 145031565                  /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 7f76dca74000-7f76dcc8d000 r-xp 0002e000 fc:02 145031565                  /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 7f76dcc8d000-7f76dcd85000 r--p 00247000 fc:02 145031565                  /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 7f76dcd85000-7f76dcd8e000 r--p 0033e000 fc:02 145031565                  /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 7f76dcd8e000-7f76dcd8f000 rw-p 00347000 fc:02 145031565                  /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 7f76dcd8f000-7f76dcda9000 rw-p 00000000 00:00 0 
| 7f76dcda9000-7f76dcdaa000 r--p 00000000 fc:02 137156844                  /usr/lib64/ld-2.31.9000.so
| 7f76dcdaa000-7f76dcdcb000 r-xp 00001000 fc:02 137156844                  /usr/lib64/ld-2.31.9000.so
| 7f76dcdcb000-7f76dcdd3000 r--p 00022000 fc:02 137156844                  /usr/lib64/ld-2.31.9000.so
| 7f76dcdd4000-7f76dcdd5000 r--p 0002a000 fc:02 137156844                  /usr/lib64/ld-2.31.9000.so
| 7f76dcdd5000-7f76dcdd7000 rw-p 0002b000 fc:02 137156844                  /usr/lib64/ld-2.31.9000.so
| 7ffdc405f000-7ffdc485e000 rw-p 00000000 00:00 0                          [stack]
| 7ffdc48d0000-7ffdc48d4000 r--p 00000000 00:00 0                          [vvar]
| 7ffdc48d4000-7ffdc48d6000 r-xp 00000000 00:00 0                          [vdso]
| ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
| 
| 
| Sample bug reporter: 12345
    test/-ext-/bug_reporter/test_bug_reporter.rb:22:in `test_bug_reporter_add'
Finished tests in 12.019894s, 0.0832 tests/s, 0.0000 assertions/s.
1 tests, 0 assertions, 0 failures, 1 errors, 0 skips
ruby -v: ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [x86_64-linux]

I also triggered this on i686 after 607 iterations. So can somebody please help to address this?

[vo.x (Vit Ondruch)]

So I did quite a lot of testing focusing especially on internals of EnvUtils.invoke_ruby and I am not sure if there is a fix. It seems that especially the s390x build cluster is sometimes under heavy load. I extended the timeout and so far the test was executed in the more then 56 seconds for the worst case. I am afraid that even 60 seconds timeout would not be enough in some case.

Therefore I wonder if there is any other possible solution?

For example I have tried for the process to exit prior waiting for the threads to join, but I don't think I see any difference.

Now I am going to test with the disabled timeout error, because it seems to me that the output consumed from the stdout/stderr contains the expected content, just the threads/process does not exit in time.

Last option could be to repeat the test several times until it succeeds. It does not look that the worst cases happens one after another, although there might be periods of time when the situation is worse.

[vo.x (Vit Ondruch)]

Just two examples from my testing:

+ make runruby 'TESTRUN_SCRIPT=-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v'
./miniruby -I./lib -I. -I.ext/common  ./tool/runruby.rb --extout=.ext  -- --disable-gems -Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v
Run options: -v
# Running tests:
[1/1] TestBugReporter#test_bug_reporter_add = 12.02 s
  1) Error:
TestBugReporter#test_bug_reporter_add:
Timeout::Error: execution of assert_in_out_err expired timeout (10 sec)
pid 4176032 killed by SIGKILL (signal 9)
| 
| -:1: [BUG] Segmentation fault at 0x003fb8a0000003e8
| ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [s390x-linux]
| 
| -- Control frame information -----------------------------------------------
| c:0003 p:---- s:0012 e:000011 CFUNC  :kill
| c:0002 p:0021 s:0006 e:000005 EVAL   -:1 [FINISH]
| c:0001 p:0000 s:0003 E:002210 (none) [FINISH]
| 
| -- Ruby level backtrace information ----------------------------------------
| -:1:in `<main>'
| -:1:in `kill'
| 
| -- Other runtime information -----------------------------------------------
| 
| * Loaded script: -
| 
| * Loaded features:
| 
|     0 enumerator.so
|     1 thread.rb
|     2 rational.so
|     3 complex.so
|     4 ruby2_keywords.rb
|     5 /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/encdb.so
|     6 /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/trans/transdb.so
|     7 /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/-test-/bug_reporter.so
| 
| * Process memory map:
| 
| 2aa36d00000-2aa36d01000 r-xp 00000000 09:7f 153246242                    /builddir/build/BUILD/ruby-2.7.1/ruby
| 2aa36d01000-2aa36d02000 r--p 00000000 09:7f 153246242                    /builddir/build/BUILD/ruby-2.7.1/ruby
| 2aa36d02000-2aa36d03000 rw-p 00001000 09:7f 153246242                    /builddir/build/BUILD/ruby-2.7.1/ruby
| 2aa38890000-2aa389f7000 rw-p 00000000 00:00 0                            [heap]
| 3ff80580000-3ff80581000 r-xp 00000000 09:7f 187703206                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/-test-/bug_reporter.so
| 3ff80581000-3ff80582000 r--p 00000000 09:7f 187703206                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/-test-/bug_reporter.so
| 3ff80582000-3ff80583000 rw-p 00000000 00:00 0 
| 3ff80600000-3ff80602000 r-xp 00000000 09:7f 170152584                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/trans/transdb.so
| 3ff80602000-3ff80603000 r--p 00001000 09:7f 170152584                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/trans/transdb.so
| 3ff80603000-3ff80604000 rw-p 00000000 00:00 0 
| 3ff80680000-3ff80682000 r-xp 00000000 09:7f 155588284                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/encdb.so
| 3ff80682000-3ff80683000 r--p 00001000 09:7f 155588284                    /builddir/build/BUILD/ruby-2.7.1/.ext/s390x-linux/enc/encdb.so
| 3ff80683000-3ff80684000 rw-p 00000000 00:00 0 
| 3ff806b6000-3ff806b7000 ---p 00000000 00:00 0 
| 3ff806b7000-3ff806f8000 rw-p 00000000 00:00 0 
| 3ff806f8000-3ff806f9000 ---p 00000000 00:00 0 
| 3ff806f9000-3ff8073a000 rw-p 00000000 00:00 0 
| 3ff8073a000-3ff8073b000 ---p 00000000 00:00 0 
| 3ff8073b000-3ff8077c000 rw-p 00000000 00:00 0 
| 3ff8077c000-3ff8077d000 ---p 00000000 00:00 0 
| 3ff8077d000-3ff807be000 rw-p 00000000 00:00 0 
| 3ff807be000-3ff807bf000 ---p 00000000 00:00 0 
| 3ff807bf000-3ff80800000 rw-p 00000000 00:00 0 
| 3ff80800000-3ff80801000 ---p 00000000 00:00 0 
| 3ff80801000-3ff80842000 rw-p 00000000 00:00 0 
| 3ff80842000-3ff80843000 ---p 00000000 00:00 0 
| 3ff80843000-3ff80884000 rw-p 00000000 00:00 0 
| 3ff80884000-3ff80885000 ---p 00000000 00:00 0 
| 3ff80885000-3ff808c6000 rw-p 00000000 00:00 0 
| 3ff808c6000-3ff808c7000 ---p 00000000 00:00 0 
| 3ff808c7000-3ff80908000 rw-p 00000000 00:00 0 
| 3ff80908000-3ff80909000 ---p 00000000 00:00 0 
| 3ff80909000-3ff8094a000 rw-p 00000000 00:00 0 
| 3ff8094a000-3ff8094b000 ---p 00000000 00:00 0 
| 3ff8094b000-3ff8098c000 rw-p 00000000 00:00 0 
| 3ff8098c000-3ff8098d000 ---p 00000000 00:00 0 
| 3ff8098d000-3ff809ce000 rw-p 00000000 00:00 0 
| 3ff809ce000-3ff809cf000 ---p 00000000 00:00 0 
| 3ff809cf000-3ff80a10000 rw-p 00000000 00:00 0 
| 3ff80a10000-3ff80a11000 ---p 00000000 00:00 0 
| 3ff80a11000-3ff80a52000 rw-p 00000000 00:00 0 
| 3ff80a52000-3ff80a53000 ---p 00000000 00:00 0 
| 3ff80a53000-3ff80a94000 rw-p 00000000 00:00 0 
| 3ff80a94000-3ff80a95000 ---p 00000000 00:00 0 
| 3ff80a95000-3ff80ad6000 rw-p 00000000 00:00 0 
| 3ff80ad6000-3ff80ad7000 ---p 00000000 00:00 0 
| 3ff80ad7000-3ff80b18000 rw-p 00000000 00:00 0 
| 3ff80b18000-3ff80b19000 ---p 00000000 00:00 0 
| 3ff80b19000-3ff80b5a000 rw-p 00000000 00:00 0 
| 3ff80b5a000-3ff80b5b000 ---p 00000000 00:00 0 
| 3ff80b5b000-3ff80b9c000 rw-p 00000000 00:00 0 
| 3ff80b9c000-3ff80b9d000 ---p 00000000 00:00 0 
| 3ff80b9d000-3ff80bde000 rw-p 00000000 00:00 0 
| 3ff80bde000-3ff80bdf000 ---p 00000000 00:00 0 
| 3ff80bdf000-3ff80c20000 rw-p 00000000 00:00 0 
| 3ff80c20000-3ff80c21000 ---p 00000000 00:00 0 
| 3ff80c21000-3ff80c62000 rw-p 00000000 00:00 0 
| 3ff80c62000-3ff80c63000 ---p 00000000 00:00 0 
| 3ff80c63000-3ff80ca4000 rw-p 00000000 00:00 0 
| 3ff80ca4000-3ff80ca5000 ---p 00000000 00:00 0 
| 3ff80ca5000-3ff80ce6000 rw-p 00000000 00:00 0 
| 3ff80ce6000-3ff80ce7000 ---p 00000000 00:00 0 
| 3ff80ce7000-3ff80d28000 rw-p 00000000 00:00 0 
| 3ff80d28000-3ff80d29000 ---p 00000000 00:00 0 
| 3ff80d29000-3ff80d6a000 rw-p 00000000 00:00 0 
| 3ff80d6a000-3ff80d6b000 ---p 00000000 00:00 0 
| 3ff80d6b000-3ff80dac000 rw-p 00000000 00:00 0 
| 3ff80dac000-3ff80dad000 ---p 00000000 00:00 0 
| 3ff80dad000-3ff80dee000 rw-p 00000000 00:00 0 
| 3ff80dee000-3ff80def000 ---p 00000000 00:00 0 
| 3ff80def000-3ff80e30000 rw-p 00000000 00:00 0 
| 3ff80e30000-3ff80e31000 ---p 00000000 00:00 0 
| 3ff80e31000-3ff80e72000 rw-p 00000000 00:00 0 
| 3ff80e72000-3ff80e73000 ---p 00000000 00:00 0 
| 3ff80e73000-3ff80eb4000 rw-p 00000000 00:00 0 
| 3ff80eb4000-3ff80eb5000 ---p 00000000 00:00 0 
| 3ff80eb5000-3ff83000000 rw-p 00000000 00:00 0 
| 3ff83000000-3ff83097000 r-xp 00000000 09:7f 51946998                     /usr/lib64/libm-2.31.9000.so
| 3ff83097000-3ff83098000 r--p 00096000 09:7f 51946998                     /usr/lib64/libm-2.31.9000.so
| 3ff83098000-3ff83099000 rw-p 00097000 09:7f 51946998                     /usr/lib64/libm-2.31.9000.so
| 3ff83100000-3ff83134000 r-xp 00000000 09:7f 51842388                     /usr/lib64/libcrypt.so.2.0.0
| 3ff83134000-3ff83135000 ---p 00034000 09:7f 51842388                     /usr/lib64/libcrypt.so.2.0.0
| 3ff83135000-3ff83136000 r--p 00034000 09:7f 51842388                     /usr/lib64/libcrypt.so.2.0.0
| 3ff83136000-3ff8313f000 rw-p 00000000 00:00 0 
| 3ff83180000-3ff83183000 r-xp 00000000 09:7f 51946996                     /usr/lib64/libdl-2.31.9000.so
| 3ff83183000-3ff83184000 r--p 00002000 09:7f 51946996                     /usr/lib64/libdl-2.31.9000.so
| 3ff83184000-3ff83185000 rw-p 00000000 00:00 0 
| 3ff83200000-3ff8328e000 r-xp 00000000 09:7f 51842614                     /usr/lib64/libgmp.so.10.4.0
| 3ff8328e000-3ff83290000 r--p 0008d000 09:7f 51842614                     /usr/lib64/libgmp.so.10.4.0
| 3ff83290000-3ff83291000 rw-p 0008f000 09:7f 51842614                     /usr/lib64/libgmp.so.10.4.0
| 3ff83300000-3ff83308000 r-xp 00000000 09:7f 51947010                     /usr/lib64/librt-2.31.9000.so
| 3ff83308000-3ff83309000 r--p 00007000 09:7f 51947010                     /usr/lib64/librt-2.31.9000.so
| 3ff83309000-3ff8330a000 rw-p 00008000 09:7f 51947010                     /usr/lib64/librt-2.31.9000.so
| 3ff83380000-3ff8339d000 r-xp 00000000 09:7f 51947006                     /usr/lib64/libpthread-2.31.9000.so
| 3ff8339d000-3ff8339e000 r--p 0001c000 09:7f 51947006                     /usr/lib64/libpthread-2.31.9000.so
| 3ff8339e000-3ff8339f000 rw-p 0001d000 09:7f 51947006                     /usr/lib64/libpthread-2.31.9000.so
| 3ff8339f000-3ff833a3000 rw-p 00000000 00:00 0 
| 3ff83400000-3ff835c4000 r-xp 00000000 09:7f 51946994                     /usr/lib64/libc-2.31.9000.so
| 3ff835c4000-3ff835c8000 r--p 001c3000 09:7f 51946994                     /usr/lib64/libc-2.31.9000.so
| 3ff835c8000-3ff835cb000 rw-p 001c7000 09:7f 51946994                     /usr/lib64/libc-2.31.9000.so
| 3ff835cb000-3ff835ce000 rw-p 00000000 00:00 0 
| 3ff8361f000-3ff83680000 rw-p 00000000 00:00 0 
| 3ff83680000-3ff83a4d000 r-xp 00000000 09:7f 155588280                    /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 3ff83a4d000-3ff83a56000 r--p 003cc000 09:7f 155588280                    /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 3ff83a56000-3ff83a57000 rw-p 003d5000 09:7f 155588280                    /builddir/build/BUILD/ruby-2.7.1/libruby.so.2.7.1
| 3ff83a57000-3ff83a6d000 rw-p 00000000 00:00 0 
| 3ff83a80000-3ff83aaa000 r-xp 00000000 09:7f 51946987                     /usr/lib64/ld-2.31.9000.so
| 3ff83aaa000-3ff83aab000 r--p 00029000 09:7f 51946987                     /usr/lib64/ld-2.31.9000.so
| 3ff83aab000-3ff83aad000 rw-p 0002a000 09:7f 51946987                     /usr/lib64/ld-2.31.9000.so
| 3ff83af6000-3ff83afe000 rw-p 00000000 00:00 0 
| 3ff83afe000-3ff83b00000 r-xp 00000000 00:00 0                            [vdso]
| 3fffa081000-3fffa880000 rw-p 00000000 00:00 0                            [stack]
| 
| 
| Sample bug reporter: 12345
    test/-ext-/bug_reporter/test_bug_reporter.rb:22:in `test_bug_reporter_add'
Finished tests in 12.027499s, 0.0831 tests/s, 0.0000 assertions/s.
1 tests, 0 assertions, 0 failures, 1 errors, 0 skips
ruby -v: ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [s390x-linux]

So the test above takes long and it is killed on timeout. But funnily enough, the following iteration succeeds, while apparently taking way longer waiting somewhere else:

+ make runruby 'TESTRUN_SCRIPT=-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v'
./revision.h unchanged
./miniruby -I./lib -I. -I.ext/common  ./tool/runruby.rb --extout=.ext  -- --disable-gems -Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v
Run options: -v
# Running tests:
[1/1] TestBugReporter#test_bug_reporter_add = 28.84 s
Finished tests in 28.845774s, 0.0347 tests/s, 0.0693 assertions/s.
1 tests, 2 assertions, 0 failures, 0 errors, 0 skips
ruby -v: ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [s390x-linux]

[vo.x (Vit Ondruch)]

waiting somewhere else:

Presumably waiting for status ||= Process.wait2(pid)[1]

[vo.x (Vit Ondruch)]

On top of that, I also received following error:

+ make runruby 'TESTRUN_SCRIPT=-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v'
./revision.h unchanged
./miniruby -I./lib -I. -I.ext/common  ./tool/runruby.rb --extout=.ext  -- --disable-gems -Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v
Run options: -v
# Running tests:
[1/1] TestBugReporter#test_bug_reporter_add = 16.92 s
  1) Error:
TestBugReporter#test_bug_reporter_add:
Errno::ECHILD: No child processes
    /builddir/build/BUILD/ruby-2.7.1/tool/lib/envutil.rb:159:in `wait2'
    /builddir/build/BUILD/ruby-2.7.1/tool/lib/envutil.rb:159:in `invoke_ruby'
    /builddir/build/BUILD/ruby-2.7.1/tool/lib/test/unit/core_assertions.rb:64:in `assert_in_out_err'
    test/-ext-/bug_reporter/test_bug_reporter.rb:22:in `test_bug_reporter_add'
Finished tests in 16.920741s, 0.0591 tests/s, 0.0000 assertions/s.
1 tests, 0 assertions, 0 failures, 1 errors, 0 skips
ruby -v: ruby 2.7.1p83 (2020-03-31 revision a0c7c23c9c) [s390x-linux]

[jaruga (Jun Aruga)]

I took a look at the code.

RUBY_TEST_TIMEOUT_SCALE=5 \
  make runruby TESTRUN_SCRIPT="-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v"

test/-ext-/bug_reporter/test_bug_reporter.rb calling
tool/lib/test/unit/core_assertions.rb#assert_in_out_err calling
tool/lib/envutil.rb#invoke_ruby.

https://github.com/ruby/ruby/blob/098e8c2873ed7cfa276aa87967ce28ac711cbb30/tool/lib/envutil.rb#L166

  def invoke_ruby(args, stdin_data = "", capture_stdout = false, capture_stderr = false,
                  encoding: nil, timeout: 10, reprieve: 1, timeout_error: Timeout::Error,
                  stdout_filter: nil, stderr_filter: nil,
                  signal: :TERM,
                  rubybin: EnvUtil.rubybin, precommand: nil,
                  **opt)
    timeout = apply_timeout_scale(timeout)
...

      if (!th_stdout || th_stdout.join(timeout)) && (!th_stderr || th_stderr.join(timeout))
        timeout_error = nil
      else
          # <= If the error will happen, above `th_stdout.join(timeout)` or `th_stderr.join(timeout)` returning `nil`, entering this line.
        status = terminate(pid, signal, opt[:pgroup], reprieve)
        terminated = Time.now
      end
...
      if timeout_error
          # <= The error will happen when entering this line.
        bt = caller_locations
        msg = "execution of #{bt.shift.label} expired timeout (#{timeout} sec)"
        msg = failure_description(status, terminated, msg, [stdout, stderr].join("\n"))
        raise timeout_error, msg, bt.map(&:to_s)
      end
...

So, I could reproduce this error always on my local by setting small value to the scale like 0.01.

$ RUBY_TEST_TIMEOUT_SCALE=0.01 make runruby TESTRUN_SCRIPT="-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v"

I extended the timeout and so far the test was executed in the more then 56 seconds for the worst case. I am afraid that even 60 seconds timeout would not be enough in some case.

I would like to find the way to rescue the long running case improving the logic in the invoke_ruby.

[jaruga (Jun Aruga)]

I extended the timeout and so far the test was executed in the more then 56 seconds for the worst case. I am afraid that even 60 seconds timeout would not be enough in some case.
I would like to find the way to rescue the long running case improving the logic in the invoke_ruby.

How about just running the tests with large timeout number? For example when setting RUBY_TEST_TIMEOUT_SCALE=100, the actual timeout is 1000 (10 * 100) seconds. It's good enough for the "more then 56 seconds", right?

RUBY_TEST_TIMEOUT_SCALE=100 \
  make runruby TESTRUN_SCRIPT="-Itool/lib test/-ext-/bug_reporter/test_bug_reporter.rb -v"

  def invoke_ruby(args, stdin_data = "", capture_stdout = false, capture_stderr = false,
                  encoding: nil, timeout: 10, reprieve: 1, timeout_error: Timeout::Error,
                  stdout_filter: nil, stderr_filter: nil,
                  signal: :TERM,
                  rubybin: EnvUtil.rubybin, precommand: nil,
                  **opt)
    # timeout => 10 seconds
    timeout = apply_timeout_scale(timeout)
    # timeout => 1000 seconds

[jaruga (Jun Aruga)]

Therefore I wonder if there is any other possible solution?

Another option might be using --retry with jobs.
https://github.com/ruby/ruby/blob/098e8c2873ed7cfa276aa87967ce28ac711cbb30/tool/lib/test/unit.rb#L194

But it seems it does not retry the test when having a error in it. Maybe it reties only when having a failure.

$ make test-all TESTOPTS="-n test_bug_reporter_add --timeout-scale=0.01 --retry --jobs=3"

[vo.x (Vit Ondruch)]

• File 0001-Timeout-the-test_bug_reporter_add-witout-raising-err.patch 0001-Timeout-the-test_bug_reporter_add-witout-raising-err.patch added
• File Time.png Time.png added

After a lot of testing, I think that the test should not fail with the timeout, because the input for the asserts is collected quite early and the system just does not have time to finish the threads and the child process. Since we don't want to test the system, but only the Ruby, I think the timeout should be just ignored. Please see the attached patch.

And just for illustration, even though the threads are timeouted, it still can take long seconds to finish the test case, because the test waits for the process exit status status ||= Process.wait2(pid)[1] and it might take a while. Attaching graph of the 10000 iterations of the test and the time it takes to finish the test despite the timeout is ignored.

[vo.x (Vit Ondruch)]

Can anybody please take a look. I think this patch works just fine on Fedora.

[mame (Yusuke Endoh)]

• Assignee set to jaruga (Jun Aruga)

@jaruga (Jun Aruga) If you think the patch is good, can you please merge it after you get a commit bit?

[jaruga (Jun Aruga)]

@mame (Yusuke Endoh) Yes I will do it!

[jaruga (Jun Aruga)]

Note I am planing to check this ticket after reviving Travis s390x (#17818).

[jaruga (Jun Aruga)]

I would just share my update for this ticket. I wanted to check this ticket after fixing another issue #18002 that is needed to print the result of the Ubuntu s390x on rubyci.org. However I may check it in parallel.

[jaruga (Jun Aruga)]

Perhaps this issue is relevant with #17052 .

[xtkoba (Tee KOBAYASHI)]

What I noticed in the description is that "C level backtrace information" is not shown, which suggests that the functions in addr2line.c are never called from rb_vm_bugreport (or its offspring). Thus I suppose #17052 is irrelevant to this.

There is another issue as to why C backtrace does not appear. It is true that we can configure so that it does not, but by default it should on GNU/Linux using glibc.

[jeremyevans0 (Jeremy Evans)]

• Status changed from Open to Closed

I checked all recent ruby-master failures in the RHEL 7.1 s390 CI (http://rubyci.s3.amazonaws.com/rhel_zlinux/ruby-master/recent.html), and none show this issue. Considering this error was occuring in 90% of cases, since it hasn't happened recently, I assume this has been fixed. If you are still seeing this error with current Ruby, please reply and we can reopen.

[vo.x (Vit Ondruch)]

I'm going to drop the patch testing with Ruby 3.3. Just briefly looking at the changes of the test case, I can imagine this one git|308fe1eb858fd8029f67510a18 could have positive influence. But not sure, because I'd say this must have been issue also for Ruby 3.2. I'll see and will be back if I observe some issues.