Test reliant on timing causing nondeterministic results

josephlewis42 commented 6 years ago

It looks like there's a timing issue in this test even with nanoseconds being the timestamp. Maybe replace all instances of the %N with millis and nanos and add a sleep (or mock the calls to Time).

https://github.com/logstash-plugins/logstash-output-google_cloud_storage/blob/db32da1aea5e7980da1d3fb200a7f9530e6095f6/spec/outputs/gcs/path_factory_spec.rb#L117

It's causing this error to show up in CI:

https://travis-ci.org/logstash-plugins/logstash-output-google_cloud_storage/jobs/379924151

josephlewis42 commented 6 years ago

More info:

Failures:

  1) LogStash::Outputs::Gcs::SynchronizedLogFile behaves like a log file #time_since_sync returns a delta
     [31mGot 1 failure and 1 other error:[0m
     [31m[37mShared Example Group: "a log file" called from ./spec/outputs/gcs/temp_log_file_spec.rb:118[0m[0m

     1.1) [31mFailure/Error: [0m[32mexpect[0m([1;34;4mTime[0m).to receive([33m:now[0m).and_return([1;34m30[0m, [1;34m40[0m, [1;34m50[0m)[0m
          [31m[0m
          [31m  (Time (class)).now(*(any args))[0m
          [31m      expected: 3 times with any arguments[0m
          [31m      received: 4 times with any arguments[0m
          [36m# ./spec/outputs/gcs/temp_log_file_spec.rb:71:in `block in (root)'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/rspec-wait-0.0.9/lib/rspec/wait.rb:46:in `block in (root)'[0m

     1.2) [31mFailure/Error: [0m[35mdate[0m: [1;34;4mTime[0m.now.strftime(@date_pattern),[0m
          [31m[0m
          [31mNoMethodError:[0m
          [31m  undefined method `strftime' for 50:Fixnum[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:82:in `template_variables'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:89:in `next_base'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:48:in `block in should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:47:in `should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:67:in `block in should_rotate?'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/concurrent-ruby-1.0.5-java/lib/concurrent/atomic/reentrant_read_write_lock.rb:126:in `with_read_lock'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:66:in `should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:28:in `block in writeln'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/concurrent-ruby-1.0.5-java/lib/concurrent/atomic/reentrant_read_write_lock.rb:145:in `with_write_lock'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:27:in `writeln'[0m
          [36m# ./lib/logstash/outputs/google_cloud_storage.rb:229:in `block in start_uploader'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/stud-0.0.23/lib/stud/interval.rb:20:in `interval'[0m
          [36m# ./lib/logstash/outputs/google_cloud_storage.rb:228:in `block in start_uploader'[0m

  2) LogStash::Outputs::Gcs::SynchronizedLogFile behaves like a log file #time_since_sync returns a delta
     [31mGot 1 failure and 1 other error:[0m
     [31m[37mShared Example Group: "a log file" called from ./spec/outputs/gcs/temp_log_file_spec.rb:118[0m[0m

     2.1) [31mFailure/Error: [0m[32mexpect[0m([1;34;4mTime[0m).to receive([33m:now[0m).and_return([1;34m30[0m, [1;34m40[0m, [1;34m50[0m)[0m
          [31m[0m
          [31m  (Time (class)).now(*(any args))[0m
          [31m      expected: 3 times with any arguments[0m
          [31m      received: 4 times with any arguments[0m
          [36m# ./spec/outputs/gcs/temp_log_file_spec.rb:71:in `block in (root)'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/rspec-wait-0.0.9/lib/rspec/wait.rb:46:in `block in (root)'[0m

     2.2) [31mFailure/Error: [0m[35mdate[0m: [1;34;4mTime[0m.now.strftime(@date_pattern),[0m
          [31m[0m
          [31mNoMethodError:[0m
          [31m  undefined method `strftime' for 50:Fixnum[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:82:in `template_variables'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:89:in `next_base'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:48:in `block in should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/path_factory.rb:47:in `should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:67:in `block in should_rotate?'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/concurrent-ruby-1.0.5-java/lib/concurrent/atomic/reentrant_read_write_lock.rb:126:in `with_read_lock'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:66:in `should_rotate?'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:28:in `block in writeln'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/concurrent-ruby-1.0.5-java/lib/concurrent/atomic/reentrant_read_write_lock.rb:145:in `with_write_lock'[0m
          [36m# ./lib/logstash/outputs/gcs/log_rotate.rb:27:in `writeln'[0m
          [36m# ./lib/logstash/outputs/google_cloud_storage.rb:229:in `block in start_uploader'[0m
          [36m# /home/travis/.rvm/gems/jruby-9.1.13.0/gems/stud-0.0.23/lib/stud/interval.rb:20:in `interval'[0m
          [36m# ./lib/logstash/outputs/google_cloud_storage.rb:228:in `block in start_uploader'[0m

Finished in 3.18 seconds (files took 3.56 seconds to load)
[31m81 examples, 2 failures[0m

Failed examples:

[31mrspec ./spec/outputs/gcs/temp_log_file_spec.rb[3:1:6:1][0m [36m# LogStash::Outputs::Gcs::SynchronizedLogFile behaves like a log file #time_since_sync returns a delta[0m
[31mrspec ./spec/outputs/gcs/temp_log_file_spec.rb[3:1:6:1][0m [36m# LogStash::Outputs::Gcs::SynchronizedLogFile behaves like a log file #time_since_sync returns a delta[0m

Randomized with seed 11809

josephlewis42 commented 6 years ago

Different distinct failure:


Randomized with seed 10964
...................F............................................................
Failures:
  1) LogStash::Outputs::Gcs::PathFactory rotate_path! resets the part number if the base has changed
     Failure/Error: expect(pf.current_path).to include('part000')
       expected "dir/pre_970000000.part001.log" to include "part000"
     # ./spec/outputs/gcs/path_factory_spec.rb:125:in `(root)'
     # /home/travis/.rvm/gems/jruby-1.7.27/gems/rspec-wait-0.0.9/lib/rspec/wait.rb:46:in `(root)'
Finished in 2.74 seconds (files took 6.81 seconds to load)
80 examples, 1 failure
Failed examples:
rspec ./spec/outputs/gcs/path_factory_spec.rb:112 # LogStash::Outputs::Gcs::PathFactory rotate_path! resets the part number if the base has changed
Randomized with seed 10964

These might be caused by a background thread waking up and rotating files; we need to make sure this (and concurrent execution) isn't happening.

logstash-plugins / logstash-output-google_cloud_storage

Test reliant on timing causing nondeterministic results #28