Test fails occasionally #1115

tagomoris · 2016-07-20T04:47:39Z

This failure occurs occasionally on Travis CI environment.
It shows that Time.now is called, but Time is a rr mock object without any expectations about methods.
Output doesn't contain any information about which test case includes this test.

===============================================================================
Failure:
  On subject Time,
  unexpected method invocation:
    now()
  expected invocations:
test_level(PluginLoggerTest)
/Users/travis/build/fluent/fluentd/lib/fluent/log.rb:306:in `dump_stacktrace'
/Users/travis/build/fluent/fluentd/lib/fluent/log.rb:259:in `error_backtrace'
/Users/travis/build/fluent/fluentd/lib/fluent/plugin/output.rb:990:in `rescue in flush_thread_run'
/Users/travis/build/fluent/fluentd/lib/fluent/plugin/output.rb:963:in `flush_thread_run'
/Users/travis/build/fluent/fluentd/lib/fluent/plugin/output.rb:369:in `block (2 levels) in start'
/Users/travis/build/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
===============================================================================
/Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/ui/testrunnermediator.rb:49:in `ensure in run': On subject Time, (RR::Errors::DoubleNotFoundError)
unexpected method invocation:
  now()
expected invocations:
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/ui/testrunnermediator.rb:50:in `run'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/ui/testrunner.rb:40:in `start_mediator'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/ui/testrunner.rb:25:in `start'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/ui/testrunnerutilities.rb:24:in `run'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/autorunner.rb:438:in `block in run'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/autorunner.rb:494:in `change_work_directory'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/autorunner.rb:437:in `run'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit/autorunner.rb:62:in `run'
    from /Users/travis/build/fluent/fluentd/vendor/bundle/ruby/2.2.0/gems/test-unit-3.1.9/lib/test/unit.rb:502:in `block (2 levels) in <top (required)>'
rake aborted!

The text was updated successfully, but these errors were encountered:

tagomoris · 2016-08-26T08:01:25Z

Another pattern: in_dummy

===============================================================================
Failure: test: value of auto increment key is not suspended after stop-and-start(DummyTest::doesn't suspend internal counters in default)
C:/projects/fluentd/test/plugin/test_in_dummy.rb:129:in `block (2 levels) in <class:DummyTest>'
     126:       end
     127: 
     128:       first_id2 = d2.events.first[2]['id']
  => 129:       assert_equal 0, first_id2
     130: 
     131:       assert !File.exist?(File.join(TEST_PLUGIN_STORAGE_PATH, 'json', 'test-01.json'))
     132:     end
<0> expected but was
<1>
===============================================================================

tagomoris · 2016-08-26T13:12:03Z

Another pattern: test_in_tail

===============================================================================
Error: test_z_refresh_watchers(TailInputTest): SystemStackError: stack level too deep
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `inspect'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `inspect'
(snip)
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `inspect'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `inspect'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `inspect'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:91:in `block (2 levels) in format_args'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:63:in `block in forbid_mocking'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:62:in `catch'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:62:in `forbid_mocking'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:90:in `block in format_args'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:89:in `map'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:89:in `format_args'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core_class_methods.rb:82:in `format_call'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/spy_describers.rb:47:in `append_call_record'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/spy_describers.rb:38:in `block in describe_calls'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/spy_describers.rb:37:in `each'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/spy_describers.rb:37:in `describe_calls'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/validators.rb:69:in `construct_validation_count_error_message'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/validators.rb:58:in `validate_count'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/validators.rb:85:in `validate'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation.rb:157:in `block in flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation.rb:156:in `each'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation.rb:156:in `flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation_director.rb:68:in `block in flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation_director.rb:67:in `each'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/expectation_director.rb:67:in `flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core.rb:82:in `block (2 levels) in flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core.rb:81:in `each'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core.rb:81:in `block in flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core.rb:248:in `flexmock_wrap'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/core.rb:80:in `flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/mock_container.rb:41:in `block in flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/mock_container.rb:40:in `each'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/mock_container.rb:40:in `flexmock_verify'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/mock_container.rb:33:in `flexmock_teardown'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/test_unit_testcase_extensions.rb:25:in `teardown'
C:/Ruby22-x64/lib/ruby/gems/2.2.0/gems/flexmock-2.0.6/lib/flexmock/test_unit_integration.rb:37:in `teardown'
C:/projects/fluentd/test/plugin/test_in_tail.rb:25:in `teardown'

tagomoris · 2016-08-30T08:26:40Z

Another pattern: FD_SETSIZE:

Assertion failed!
Program: C:\Ruby23\bin\ruby.exe
File: ../../../../ext/cool.io/../libev/ev_select.c, Line 133
Expression: ("libev: fd >= FD_SETSIZE passed to fd_set-based select backend", fd < FD_SETSIZE)

cosmo0920 · 2016-08-31T13:00:52Z

Unfortunately, I've confirmed that #1115 (comment) pattern is still existing in Fluentd 29fa4b9.

cosmo0920 · 2016-09-01T09:22:41Z

Now, I'm investigating this issue, but I didn't meet any tests failure.
And tests does not fail in AppVeyor recently: https://ci.appveyor.com/project/fluent/fluentd/history

tagomoris · 2016-09-01T10:24:19Z

I edited the title, because I also found suspicious case on Travis...

No output has been received in the last 10m0s, this potentially indicates a stalled build or something wrong with the build itself.
Check the details on how to adjust your build configuration on: https://docs.travis-ci.com/user/common-build-problems/#Build-times-out-because-no-output-was-received
The build has been terminated

tagomoris · 2016-09-02T04:12:44Z

2 cases in test_in_tail.rb.

Failure: test_rotate_file_with_read_from_head[parse](TailInputTest::rotate file)
/home/travis/build/fluent/fluentd/test/plugin/test_in_tail.rb:308:in `test_rotate_file_with_read_from_head'
     305:     def test_rotate_file_with_read_from_head(data)
     306:       config = data
     307:       events = sub_test_rotate_file(config, expect_records: 6)
  => 308:       assert_equal(6, events.length)
     309:       assert_equal({"message" => "test1"}, events[0][2])
     310:       assert_equal({"message" => "test2"}, events[1][2])
     311:       assert_equal({"message" => "test3"}, events[2][2])
<6> expected but was
<8>

Failure: test_rotate_file_with_write_old[parse](TailInputTest::rotate file)
/home/travis/build/fluent/fluentd/test/plugin/test_in_tail.rb:333:in `test_rotate_file_with_write_old'
     330:           f.puts "test6"
     331:         }
     332:       }
  => 333:       assert_equal(6, events.length)
     334:       assert_equal({"message" => "test3"}, events[0][2])
     335:       assert_equal({"message" => "test4"}, events[1][2])
     336:       assert_equal({"message" => "test7"}, events[2][2])
<6> expected but was
<8>

tagomoris · 2016-09-02T04:13:41Z

Failure: test_message(ForwardInputTest)
C:/projects/fluentd/lib/fluent/test/input_test.rb:153:in `block (2 levels) in run'
C:/projects/fluentd/lib/fluent/test/input_test.rb:151:in `each'
C:/projects/fluentd/lib/fluent/test/input_test.rb:151:in `block in run'
C:/projects/fluentd/lib/fluent/test/base.rb:71:in `run'
C:/projects/fluentd/lib/fluent/test/input_test.rb:122:in `run'
C:/projects/fluentd/test/plugin/test_in_forward.rb:77:in `test_message'
     74:     d.expect_emit "tag1", time, {"a"=>1}
     75:     d.expect_emit "tag2", time, {"a"=>2}
     76: 
  => 77:     d.run do
     78:       d.expected_emits.each {|tag, _time, record|
     79:         send_data Fluent::Engine.msgpack_factory.packer.write([tag, _time, record]).to_s
     80:       }
<["tag1", #<Fluent::EventTime:0x47936e8 @nsec=0, @sec=1293974055>, {"a"=>1}]> expected but was
<["tag2", #<Fluent::EventTime:0x4783170 @nsec=0, @sec=1293974055>, {"a"=>2}]>
diff:
? ["tag1", #<Fluent::EventTime:0x47936e8 @nsec=0, @sec=1293974055>, {"a"=>1}]
?      2                           8 170                                  2

tagomoris · 2016-09-06T12:12:48Z

test_in_tail is so unstable...

tagomoris · 2016-09-14T03:03:43Z

New one on AppVeyor about test_out_secondary_file.
@ganmacs Can you fix this? https://ci.appveyor.com/project/fluent/fluentd/build/1511/job/th4xjjpuuwiplsf6

Failure: test: should output plain text when compress option is default(text)(FileOutputSecondaryTest::write)
C:/projects/fluentd/test/plugin/test_out_secondary_file.rb:161:in `block (2 levels) in <class:FileOutputSecondaryTest>'
     158:       path = d.instance.write(@chunk)
     159: 
     160:       assert_equal "#{TMP_DIR}/out_file_test.0", path
  => 161:       assert_equal File.read(path), @es.to_msgpack_stream.force_encoding('ASCII-8BIT')
     162:     end
     163: 
     164:     test 'path should be incremental when append option is false' do
<"\x92\xD7\x00W\xD8\xA8\x88#"> expected but was
<"\x92\xD7\x00W\xD8\xA8\x88#\x1A<\x90\x81\xA3key\xA5value">
diff:
? ��Wب�#�<���key�value

ganmacs · 2016-09-14T03:23:04Z

@tagomoris
I'll look into it.

tagomoris · 2016-09-28T03:04:24Z

#1243, #1244, #1250

okkez · 2016-09-29T00:58:47Z

#1251

okkez · 2016-09-29T01:00:13Z

===============================================================================
Failure: test_lf(TailInputTest)
/Users/travis/build/fluent/fluentd/test/plugin/test_in_tail.rb:418:in `test_lf'
     415:     end
     416: 
     417:     events = d.events
  => 418:     assert_equal(true, events.length > 0)
     419:     assert_equal({"message" => "test3test4"}, events[0][2])
     420:   end
     421: 
<true> expected but was
<false>
diff:
? tru e
? fals 
===============================================================================

tagomoris added the v0.14 label Jul 21, 2016

tagomoris mentioned this issue Jul 21, 2016

Use rr instead of flexmock #790

Closed

4 tasks

tagomoris mentioned this issue Aug 30, 2016

Use pipe command sender mechanism of ServerEngine on Windows #1171

Merged

tagomoris changed the title ~~Test fails occasionally~~ Test fails occasionally on AppVayor Aug 30, 2016

cosmo0920 mentioned this issue Aug 30, 2016

Use timecop instead of stub in test_log #1194

Merged

tagomoris changed the title ~~Test fails occasionally on AppVayor~~ Test fails occasionally Sep 1, 2016

tagomoris mentioned this issue Sep 28, 2016

test_out_secondary_file: wait for disk I/O completion in tests #1250

Merged

tagomoris closed this as completed in #1250 Sep 28, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Test fails occasionally #1115

Test fails occasionally #1115

tagomoris commented Jul 20, 2016

tagomoris commented Aug 26, 2016

tagomoris commented Aug 26, 2016

tagomoris commented Aug 30, 2016

cosmo0920 commented Aug 31, 2016

cosmo0920 commented Sep 1, 2016

tagomoris commented Sep 1, 2016

tagomoris commented Sep 2, 2016 •

edited

Loading

tagomoris commented Sep 2, 2016

tagomoris commented Sep 6, 2016

tagomoris commented Sep 14, 2016

ganmacs commented Sep 14, 2016 •

edited

Loading

tagomoris commented Sep 28, 2016

okkez commented Sep 29, 2016

okkez commented Sep 29, 2016

Test fails occasionally #1115

Test fails occasionally #1115

Comments

tagomoris commented Jul 20, 2016

tagomoris commented Aug 26, 2016

tagomoris commented Aug 26, 2016

tagomoris commented Aug 30, 2016

cosmo0920 commented Aug 31, 2016

cosmo0920 commented Sep 1, 2016

tagomoris commented Sep 1, 2016

tagomoris commented Sep 2, 2016 • edited Loading

tagomoris commented Sep 2, 2016

tagomoris commented Sep 6, 2016

tagomoris commented Sep 14, 2016

ganmacs commented Sep 14, 2016 • edited Loading

tagomoris commented Sep 28, 2016

okkez commented Sep 29, 2016

okkez commented Sep 29, 2016

tagomoris commented Sep 2, 2016 •

edited

Loading

ganmacs commented Sep 14, 2016 •

edited

Loading