Bug #8523

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

Added by Cyle Riggs about 2 years ago. Updated about 1 year ago.

[ruby-core:<unknown>]
Status:Closed
Priority:Normal
Assignee:-
ruby -v:ruby 1.9.3p392 (2013-02-22 revision 39386) [x86_64-linux] Backport:2.0.0: DONE, 2.1: DONE

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]:
.
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.

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

Associated revisions

Revision 46159
Added by Hiroshi SHIBATA over 1 year ago

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

Revision 46159
Added by Hiroshi SHIBATA over 1 year ago

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

Revision 46196
Added by Nobuyoshi Nakada over 1 year ago

test_thread.rb: move thread switch test

  • test/ruby/test_thread.rb (test_switch_while_busy_loop): move
    from test/test_timeout.rb. [Bug #1402]

  • test/test_timeout.rb (test_timeout): no longer related to
    [Bug #1402]. [Bug #8523]

Revision 46196
Added by Nobuyoshi Nakada over 1 year ago

test_thread.rb: move thread switch test

  • test/ruby/test_thread.rb (test_switch_while_busy_loop): move
    from test/test_timeout.rb. [Bug #1402]

  • test/test_timeout.rb (test_timeout): no longer related to
    [Bug #1402]. [Bug #8523]

Revision 46748
Added by Usaku NAKAMURA about 1 year ago

merge revision(s) 46159,46196: [Backport #8523]

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

Revision 46810
Added by Tomoyuki Chikanaga about 1 year ago

merge revision(s) r44516,r46159,r46196: [Backport #8523]

test_timeout.rb: shorten waiting times
* test/test_timeout.rb (test_timeout): inverted test condition.
  [Bug #8523]

History

#1 Updated by Hiroshi SHIBATA over 1 year 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]

#2 Updated by Nobuyoshi Nakada over 1 year ago

  • Description updated (diff)

#3 Updated by Usaku NAKAMURA about 1 year ago

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

#4 Updated by Usaku NAKAMURA about 1 year 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.

#5 Updated by Tomoyuki Chikanaga about 1 year 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.

Also available in: Atom PDF