Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Santiago Vila]

tags 853244 + patch
thanks

On Mon, 6 Feb 2017, Chris Lamb wrote:

> The problem is that this package would need a *specific* note/mention
> that it should be ignored. Whilst we could certainly add that for
> Reproducible Builds, what happens, for example, when the next person
> runs a rebuild across the archive to test for something else (etc. etc.)

Hi. I'm afraid I'm such next person...

This package FTBFS randomly for me on START1-S / DEV1-S instances from
Scaleway, and the failure rate is around 30% there.

I've put a bunch of build logs here:

https://people.debian.org/~sanvila/build-logs/ruby-sshkit/

and I've setup a Jenkins job here in case you want to see it failing
in real time:

https://jenkins-2.reliable-builds.org/job/ruby-sshkit/

Even if our packages are built "officially" on buildd.debian.org,
this does not mean that it is a good idea to "target" the specific
(or even approximate) CPU speed of buildd.debian.org autobuilders.

The end user must be able to build packages without failures as well,
because, after all, we don't just provide binary packages, we also
provide the freedom to modify them at will.

This is the reason why I would consider this bug "serious" as well.

In fact, imagine what happened if I wanted to build all packages from
source and all upstream authors did the same (i.e. target a specific
CPU speed which makes the package to FTBFS 30% of the time in some
systems). From 3 source packages I would have to retry on 9000 of
them. From those, 2700 would fail again in the second try, and I would
still have to retry in a geometrical decreasing way until all packages
are successfully build. This certainly does not scale.


Anyway, let's see if we can improve the status of this problem in buster:

There are four tests which fail over and over again in my setup. If I
grep for "FAIL" in the build logs above and count occurrences, this is
what I get:

  23 test_the_connection_manager_can_run_things_with_custom_runner_configs
  21 test_the_connection_manager_can_run_things_in_groups
  15 test_the_connection_manager_can_run_things_in_custom_runner
  10 test_the_connection_manaager_runs_things_in_parallel_by_default
  
So, I strongly suggest disabling those tests for buster, since they
seem to be the ones that fail most.

The patch below (warning: untested) may help.

Thanks.

--- a/test/unit/test_coordinator.rb
+++ b/test/unit/test_coordinator.rb
@@ -43,12 +43,6 @@ module SSHKit
   assert_equal "Command: echo 1.example.com\n", actual_output_commands.last
 end
 
-def test_the_connection_manaager_runs_things_in_parallel_by_default
-  Coordinator.new(%w{1.example.com 2.example.com}).each(_time)
-  assert_equal 2, actual_execution_times.length
-  assert_within_10_ms(actual_execution_times)
-end
-
 def test_the_connection_manager_can_run_things_in_sequence
   Coordinator.new(%w{1.example.com 2.example.com}).each in: :sequence, 
_time
   assert_equal 2, actual_execution_times.length
@@ -68,46 +62,6 @@ module SSHKit
   end
 end
 
-def test_the_connection_manager_can_run_things_in_custom_runner
-  begin
-$original_runner = SSHKit.config.default_runner
-SSHKit.config.default_runner = MyRunner
-
-Coordinator.new(%w{1.example.com 2.example.com}).each(_time)
-assert_equal 2, actual_execution_times.length
-assert_within_10_ms(actual_execution_times)
-assert_match(/custom runner out/, @output)
-  ensure
-SSHKit.config.default_runner = $original_runner
-  end
-end
-
-def test_the_connection_manager_can_run_things_with_custom_runner_configs
-  begin
-$original_runner = SSHKit.config.default_runner
-SSHKit.config.default_runner = :groups
-$original_runner_config = SSHKit.config.default_runner_config
-SSHKit.config.default_runner_config = { limit: 2, wait: 5 }
-
-Coordinator.new(
-  %w{
-1.example.com
-2.example.com
-3.example.com
-4.example.com
-  }
-).each(_time)
-assert_equal 4, actual_execution_times.length
-assert_within_10_ms(actual_execution_times[0..1])
-assert_within_10_ms(actual_execution_times[2..3])
-assert_at_least_5_sec_apart(actual_execution_times[0], 
actual_execution_times[2])
-assert_at_least_5_sec_apart(actual_execution_times[1], 
actual_execution_times[3])
-  ensure
-SSHKit.config.default_runner = $original_runner
-SSHKit.config.default_runner_config = $original_runner_config
-  end
-end
-
 def test_the_connection_manager_can_run_things_in_sequence_with_wait
   start = Time.now
   Coordinator.new(%w{1.example.com 2.example.com}).each in: :sequence, 
wait: 10, _time
@@ -115,25 +69,6 @@ module SSHKit
   assert_operator(stop - start, :>=, 10.0)
 end
 
-def test_the_connection_manager_can_run_things_in_groups
-  Coordinator.new(
-%w{
-  

Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Chris Lamb]

Christian Hofstaedtler wrote:

> Thing is, upstream thought these tests provide value, even if they
> depend on a certain base performance of the machine they are running
> on.

Fair. On the other hand, upstreams can do some crazy things!

> > Would the idea that they interfere with running QA efforts across the
> > archive change your mind? :)
> 
> I can see that, but the reality is that there's only so many people
> looking at bugs. (Assuming "interfere" means you file a note in
> reproducible notes git and move on.)

I think "interfere" was the wrong word, sorry.

The problem is that this package would need a *specific* note/mention
that it should be ignored. Whilst we could certainly add that for
Reproducible Builds, what happens, for example, when the next person
runs a rebuild across the archive to test for something else (etc. etc.)

Better to fix them once and for all IMHO :)


Regards,

-- 
  ,''`.
 : :'  : Chris Lamb
 `. `'`  la...@debian.org / chris-lamb.co.uk
   `-

Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Christian Hofstaedtler]

* Chris Lamb  [170204 21:46]:
> Christian Hofstaedtler wrote:
> > I agree this is suboptimal, but these operations succeed on modern
> > hardware including the buildd network
> 
> I'm not so sure. Not only are these not "tests" (in the Martin Fowler
> sense that they are nondeterminstic),

Even tests can have bugs :-)

Thing is, upstream thought these tests provide value, even if they
depend on a certain base performance of the machine they are running
on. We can certainly disable those tests, but neither disabling them
or keeping them as is strikes me as the right thing to do.

> but we can actually trigger them
> on the Reproducible Builds testing framework:
>   
> https://tests.reproducible-builds.org/debian/logs/unstable/amd64/ruby-sshkit_1.9.0-1.build2.log.gz

> > so throwing developer manpower at this is a bad investment at
> > this time.
> 
> Would the idea that they interfere with running QA efforts across the
> archive change your mind? :)

I can see that, but the reality is that there's only so many people
looking at bugs. (Assuming "interfere" means you file a note in
reproducible notes git and move on.)

I've asked micah to take a look though.

Cheers,
-ch

Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Chris Lamb]

Christian Hofstaedtler wrote:

> I agree this is suboptimal, but these operations succeed on modern
> hardware including the buildd network

I'm not so sure. Not only are these not "tests" (in the Martin Fowler
sense that they are nondeterminstic) but we can actually trigger them
on the Reproducible Builds testing framework:

  
https://tests.reproducible-builds.org/debian/logs/unstable/amd64/ruby-sshkit_1.9.0-1.build2.log.gz

> so throwing developer manpower at this is a bad investment at
> this time.

Would the idea that they interfere with running QA efforts across the
archive change your mind? :)



Regards,

-- 
  ,''`.
 : :'  : Chris Lamb
 `. `'`  la...@debian.org / chris-lamb.co.uk
   `-

Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Christian Hofstaedtler]

Control: severity -1 important

* Chris Lamb  [170204 13:15]:
> Source: ruby-sshkit
> Version: 1.9.0-1
> Severity: serious

> Dear Maintainer,
> 
> ruby-sshkit's testsuite appears to use method timing/benchmarking in
> such a way that it will non-deterministically FTBFS:
> 
> 117 def assert_within_10_ms(array)
> 118   assert_in_delta(*array, 0.01) # 10 msec
> 119 end

I agree this is suboptimal, but these operations succeed on modern
hardware including the buildd network, so throwing developer
manpower at this is a bad investment at this time.

Best,
-ch

Bug#853244: ruby-sshkit: Non-determistically FTBFS due to unreliable timing in tests

[Chris Lamb]

Source: ruby-sshkit
Version: 1.9.0-1
Severity: serious
Justification: fails to build from source
User: reproducible-bui...@lists.alioth.debian.org
Usertags: ftbfs
X-Debbugs-Cc: reproducible-b...@lists.alioth.debian.org

Dear Maintainer,

ruby-sshkit's testsuite appears to use method timing/benchmarking in
such a way that it will non-deterministically FTBFS:

117 def assert_within_10_ms(array)
118   assert_in_delta(*array, 0.01) # 10 msec
119 end

  […]
  
  Finished in 23.29586s
  179 tests, 3317 assertions, 3 failures, 0 errors, 0 skips
  rake aborted!
  Command failed with status (1): [ruby -I"lib:test"  
"/usr/lib/ruby/vendor_ruby/rake/rake_test_loader.rb" 
"test/unit/backends/test_abstract.rb" 
"test/unit/backends/test_connection_pool.rb" "test/unit/backends/test_local.rb" 
"test/unit/backends/test_netssh.rb" "test/unit/backends/test_printer.rb" 
"test/unit/core_ext/test_string.rb" "test/unit/formatters/test_custom.rb" 
"test/unit/formatters/test_dot.rb" "test/unit/formatters/test_pretty.rb" 
"test/unit/formatters/test_simple_text.rb" "test/unit/test_color.rb" 
"test/unit/test_command.rb" "test/unit/test_command_map.rb" 
"test/unit/test_configuration.rb" "test/unit/test_coordinator.rb" 
"test/unit/test_deprecation_logger.rb" "test/unit/test_dsl.rb" 
"test/unit/test_host.rb" "test/unit/test_logger.rb" 
"test/unit/test_mapping_interaction_handler.rb" ]
  
  Tasks: TOP => default => test
  (See full trace by running task with --trace)
  ERROR: Test "ruby2.3" failed. Exiting.
  dh_auto_install: dh_ruby --install «BUILDDIR»/debian/ruby-sshkit returned 
exit code 1
  debian/rules:6: recipe for target 'binary' failed
  make: *** [binary] Error 1
  dpkg-buildpackage: error: fakeroot debian/rules binary gave error exit status 
2

  […]

The full build log is attached.


Regards,

-- 
  ,''`.
 : :'  : Chris Lamb
 `. `'`  la...@debian.org / chris-lamb.co.uk
   `-


ruby-sshkit.1.9.0-1.unstable.amd64.log.txt.gz
Description: Binary data