[DRE-maint] Bug#845164: ruby-spy: FTBFS randomly (failing tests)

[Santiago Vila]

Package: src:ruby-spy
Version: 0.4.3-1
Severity: serious

Dear maintainer:

I tried to build this package in stretch with "dpkg-buildpackage -A"
(which is what the "Arch: all" autobuilder would do to build it)
but it failed:

--------------------------------------------------------------------------------
[...]
 debian/rules build-indep
dh build-indep --buildsystem=ruby --with ruby
   dh_testdir -i -O--buildsystem=ruby
   dh_update_autotools_config -i -O--buildsystem=ruby
   dh_auto_configure -i -O--buildsystem=ruby
	dh_ruby --configure
   dh_auto_build -i -O--buildsystem=ruby
	dh_ruby --build
   dh_ruby --build
   dh_auto_test -i -O--buildsystem=ruby
	dh_ruby --test
 fakeroot debian/rules binary-indep
dh binary-indep --buildsystem=ruby --with ruby

[... snipped ...]

TestAnyInstanceOf#test_it_overides_all_methods = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_class_protected_visibility = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_protected_visibility = 0.00 s = .
Spy::TestSubroutine#test_spy_can_hook_record_and_unhook_a_meta_method = 0.00 s = .
Spy::TestSubroutine#test_spy_cannot_hook_a_non_existent_method = 0.00 s = .
Spy::TestSubroutine#test_spy_hook_raises_an_error_on_an_already_hooked_method = 0.00 s = .
Spy::TestSubroutine#test_has_been_called_with? = 0.00 s = .
Spy::TestSubroutine#test_that_method_spy_keeps_arity = 0.00 s = .
Spy::TestSubroutine#test_spy_get_can_retrieve_a_spy = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_class_private_visibility = 0.00 s = .
Spy::TestSubroutine#test_spy_and_return_can_call_a_block_that_recieves_a_block = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_private_visibility = 0.00 s = .
Spy::TestSubroutine#test_spy_hook_records_number_of_calls = 0.00 s = .
Spy::TestSubroutine#test_spy_can_hook_and_record_a_method_call_on_a_constant = 0.00 s = .
Spy::TestSubroutine#test_spy_can_unhook_a_method = 0.00 s = .
Spy::TestSubroutine#test_spy_and_return_can_call_a_block_raises_when_there_is_an_arity_mismatch = 0.00 s = .
Spy::TestSubroutine#test_spy_can_hook_a_non_existent_method_if_param_set = 0.00 s = .
Spy::TestSubroutine#test_spy_and_return_returns_the_set_value = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_class_public_visibility = 0.00 s = .
Spy::TestSubroutine#test_spy_and_return_can_call_a_block = 0.00 s = .
Spy::TestSubroutine#test_spy_can_hook_and_record_a_method_call = 0.00 s = .
Spy::TestSubroutine#test_spy_can_hook_and_record_a_meta_method_call_on_a_constant = 0.00 s = .
Spy::TestSubroutine#test_hook_mimics_public_visibility = 0.00 s = .
Spy::TestSubroutine#test_spy_on_hook_and_saves_spy = 0.00 s = .

Finished in 0.043358s, 1476.0886 runs/s, 2606.2189 assertions/s.

  1) Failure:
TestSpy#test_spy_on_hooks_and_saves_spy_with_array [/<<PKGBUILDDIR>>/test/integration/test_subroutine_spying.rb:31]:
--- expected
+++ actual
@@ -1 +1 @@
-[#<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_subroutine_spying.rb:26:in `test_spy_on_hooks_and_saves_spy_with_array'", @args=[nil], @block=nil, @result="hello">], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}, @plan=#<Proc:0xXXXXXX@/<<PKGBUILDDIR>>/debian/ruby-spy/usr/lib/ruby/vendor_ruby/spy/subroutine.rb:120>>, #<Spy::Subroutine:0xXXXXXX @method_name=:write_hello, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test
 /integration/test_subroutine_spying.rb:27:in `test_spy_on_hooks_and_saves_spy_with_array'", @args=[], @block=nil, @result="world">], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=0..0, @original_method=#<Method: Pen#write_hello>, @hook_opts={:visibility=>:public}, @plan=#<Proc:0xXXXXXX@/<<PKGBUILDDIR>>/debian/ruby-spy/usr/lib/ruby/vendor_ruby/spy/subroutine.rb:120>>]
+[#<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_api.rb:12:in `test_assert_received'", @args=[:hello], @block=nil, @result=nil>], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}>, #<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_api.rb:25:in `test_have_received'", @args=[:foo], @block=nil, @result=nil>], @do_not_check_plan_arity=false, @hooked=false, @meth
 od_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}>, #<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_api.rb:17:in `test_assert_received_with'", @args=[:world], @block=nil, @result=nil>], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}>, #<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from
 ="/<<PKGBUILDDIR>>/test/integration/test_api.rb:31:in `test_have_received_with'", @args=[:bar], @block=nil, @result=nil>], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}>, #<Spy::Subroutine:0xXXXXXX @method_name=:write, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_subroutine_spying.rb:26:in `test_spy_on_hooks_and_saves_spy_with_array'", @args=[nil], @block=nil, @result="hello">], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=1..1, @original_method=#<Method: Pen#write>, @hook_opts={:visibility=>:public}, @plan=#<Proc:0xXXXXXX@/<<PKGBUILDDIR>
 >/debian/ruby-spy/usr/lib/ruby/vendor_ruby/spy/subroutine.rb:120>>, #<Spy::Subroutine:0xXXXXXX @method_name=:write_hello, @base_object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @singleton_method=true, @was_hooked=true, @calls=[#<Spy::CallLog:0xXXXXXX @object=#<Pen:0xXXXXXX @color=:black, @written=[]>, @called_from="/<<PKGBUILDDIR>>/test/integration/test_subroutine_spying.rb:27:in `test_spy_on_hooks_and_saves_spy_with_array'", @args=[], @block=nil, @result="world">], @do_not_check_plan_arity=false, @hooked=false, @method_owner=#<Class:#<Pen:0xXXXXXX>>, @original_method_visibility=:public, @arity_range=0..0, @original_method=#<Method: Pen#write_hello>, @hook_opts={:visibility=>:public}, @plan=#<Proc:0xXXXXXX@/<<PKGBUILDDIR>>/debian/ruby-spy/usr/lib/ruby/vendor_ruby/spy/subroutine.rb:120>>]


64 runs, 113 assertions, 1 failures, 0 errors, 0 skips
rake aborted!
Command failed with status (1): [ruby -I"test"  "/usr/lib/ruby/vendor_ruby/rake/rake_test_loader.rb" "test/integration/test_api.rb" "test/integration/test_constant_spying.rb" "test/integration/test_instance_method.rb" "test/integration/test_mocking.rb" "test/integration/test_subroutine_spying.rb" "test/spy/test_mock.rb" "test/spy/test_subroutine.rb" "test/test_helper.rb" -v]

Tasks: TOP => default
(See full trace by running task with --trace)
ERROR: Test "ruby2.3" failed. Exiting.
dh_auto_install: dh_ruby --install /<<PKGBUILDDIR>>/debian/ruby-spy returned exit code 1
debian/rules:18: recipe for target 'binary-indep' failed
make: *** [binary-indep] Error 1
dpkg-buildpackage: error: fakeroot debian/rules binary-indep gave error exit status 2
--------------------------------------------------------------------------------

The build was made on several QEMU/KVM virtual machines with one CPU using sbuild.
The failure happens randomly. Sometimes it fails, sometimes it does not.

The failing tests are not always the same. As a summary, these are the
two which I have seen to fail so far:

Spy::TestSubroutine#test_spy_on_hook_and_saves_spy [/<<PKGBUILDDIR>>/test/spy/test_subroutine.rb:21]:
TestSpy#test_spy_on_hooks_and_saves_spy_with_array [/<<PKGBUILDDIR>>/test/integration/test_subroutine_spying.rb:31]:

I attach several build logs.

Thanks.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161112T200958Z.gz
Type: application/gzip
Size: 8858 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0007.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161115T005910Z.gz
Type: application/gzip
Size: 8626 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0008.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161115T173908Z.gz
Type: application/gzip
Size: 9037 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0009.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161115T174025Z.gz
Type: application/gzip
Size: 9034 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0010.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161120T231939Z.gz
Type: application/gzip
Size: 8624 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0011.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161120T232054Z.gz
Type: application/gzip
Size: 8584 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0012.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ruby-spy_0.4.3-1_amd64-20161120T232204Z.gz
Type: application/gzip
Size: 8618 bytes
Desc: 
URL: <http://lists.alioth.debian.org/pipermail/pkg-ruby-extras-maintainers/attachments/20161121/299967f3/attachment-0013.bin>