Project

General

Profile

Actions

Bug #8523

closed

intermittent unit test failure in test_timeout.rb results in build failures

Added by cyleratamzn (Cyle Riggs) almost 11 years ago. Updated over 9 years ago.

Status:
Closed
Assignee:
-
Target version:
-
ruby -v:
ruby 1.9.3p392 (2013-02-22 revision 39386) [x86_64-linux]
[ruby-core:<unknown>]

Description

This bug was found in 1.9.3-p392 from fedora. About 20% of our koji builds failed with unit test failures originating in test_timeout.rb.

The following build log shows this problem:

54) Failure:
test_timeout(TestTimeout) [/builddir/ruby19/srpm/ruby-1.9.3-p392/test/test_timeout.rb:19]:
[ruby-dev:38319].
Exception raised:
<#<Timeout::Error: execution expired>>.
10359 tests, 2235326 assertions, 1 failures, 0 errors, 53 skips
make[1]: *** [yes-test-all] Error 1
make[1]: Leaving directory `/builddir/ruby19/srpm/ruby-1.9.3-p392'
error: Bad exit status from /var/tmp/rpm-tmp.C2OW6z (%check)
RPM build errors:
Bad exit status from /var/tmp/rpm-tmp.C2OW6z (%check)
make: *** [rpmbuild] Error 1
```

I expected the unit test to pass consistently, but found that it intermittently failed, causing builds to fail. The build failures that occur due to this unit test failure within koji were reproducible on my local machine as well by performing an rpmbuild.

I have identified the problem in the unit test `TestTimeout` and supplied a patch.

A description of the flawed unit test logic follows:

1. A flag, `@flag` is set to true.
2. A background thread is started which waits 0.1 seconds and then sets `@flag` to `false`.
3. A block of code which busy waits for `@flag` to become false is executed within the timeout module, which mandates that @flag becomes false in 1 second or less.
4. An assertion is made that the timeout module will not raise an exception of any kind and that the background thread stops the code block before the timeout module does.

The unit test fails when the background thread, which is responsible for setting `@flag` to false does not set the value within the expected amount of time and the timeout module, working properly, raises a `Timeout::Error` due to the code block monitoring the `@flag` value running for more than 1 second. This design of the unit test is too sensitive to thread scheduling issues, and routinely fails despite the timeout module working properly.

My supplied patch inverts the design of the unit test, such that the background thread operates merely as a secondary method of preventing the unit test from running forever in the case that the timeout module does stop working properly. With my patch the flow will now be:

1. A flag, `@flag` is set to true.
2. A background thread is started which waits 2 seconds and then sets `@flag` to `false`.
3. A code block of "`nil while @flag`" is ran within the timeout module, with a specified maximum execution time of 0.1 seconds.
4. An assertion is made that the timeout module must stop the code block with a `Timeout::Error` before the background thread does.

After applying my patch I was able to execute 30 builds sequentially and experienced no failures.

Files

fix-test_timeout.patch (660 Bytes) fix-test_timeout.patch cyleratamzn (Cyle Riggs), 06/13/2013 08:21 AM

Updated by hsbt (Hiroshi SHIBATA) almost 10 years ago

  • Status changed from Open to Closed
  • % Done changed from 90 to 100

Applied in changeset r46159.


  • test/test_timeout.rb (test_timeout): inverted test condition.
    [Bug #8523]

Updated by nobu (Nobuyoshi Nakada) almost 10 years ago

  • Description updated (diff)

Updated by usa (Usaku NAKAMURA) over 9 years ago

  • Backport changed from 1.9.3: UNKNOWN, 2.0.0: UNKNOWN to 1.9.3: REQUIRED, 2.0.0: REQUIRED

Updated by usa (Usaku NAKAMURA) over 9 years ago

  • Backport changed from 1.9.3: REQUIRED, 2.0.0: REQUIRED to 2.0.0: DONE, 2.1: REQUIRED

backported into ruby_2_0_0 at r46748.

Updated by nagachika (Tomoyuki Chikanaga) over 9 years ago

  • Backport changed from 2.0.0: DONE, 2.1: REQUIRED to 2.0.0: DONE, 2.1: DONE

r44516, r46159 and r46196 were backported into ruby_2_1 branch at r46810.

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0