Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

The consistently failing spec #126

Open
ghost opened this issue Oct 21, 2013 · 64 comments
Open

The consistently failing spec #126

ghost opened this issue Oct 21, 2013 · 64 comments
Labels

Comments

@ghost
Copy link

ghost commented Oct 21, 2013

This has been mentioned in the other PR, and I remember a couple of random build failures in the past. Can someone point me to a failed build or provide intel? Let's try to come up with a fix. ⚡

@samwgoldman
Copy link
Contributor

Pretty sure this is a cascading failure in the adapter specs. Seems the most common culprit is the Reel adapter spec. If it fails, the next adapter test fails too. I struggled with the flakiness of these tests for a long time. They pass consistently on my machine every time, but not so much on Travis.

@tarcieri
Copy link
Contributor

Can you point me at one of the Reel failures?

@samwgoldman
Copy link
Contributor

Here's a JRuby test run where the Reel adapter fails. Later, the Rack adapter fails.

https://travis-ci.org/seancribbs/webmachine-ruby/jobs/12748305

@ghost ghost mentioned this issue Oct 23, 2013
@ghost
Copy link
Author

ghost commented Oct 23, 2013

I'm able to unreliably reproduce this with bundle exec rspec --order rand:53167 spec/webmachine/.

@ghost
Copy link
Author

ghost commented Oct 23, 2013

@ghost
Copy link
Author

ghost commented Oct 23, 2013

I'm not sure we should bother fixing the root cause of this leak. We could as well just use a fresh random port for each example, and let garbage collection take care of the rest. And when the process exits, they'll get released anyway.

Example: https://github.com/lgierth/aeee/blob/master/spec/support/helper.rb#L15-L20

@samwgoldman
Copy link
Contributor

Yeah, I previously had the adapter tests do just that (89ce86e). I removed that because I thought I had gotten the servers to play nice and shut down.

Seems like web servers generally expect to be at the center of the universe. Maybe the Adapter#shutdown API is just a pipe dream.

@nyarly
Copy link
Contributor

nyarly commented Oct 24, 2013

(PR reference was a typo)

@ghost
Copy link
Author

ghost commented Nov 19, 2013

One of today's builds shows a new error from Reel on rbx-19mode: https://travis-ci.org/seancribbs/webmachine-ruby/jobs/14224187#L1622

Could it be this is the actual error? Maybe the error gets swallowed most of the time due to something. It also always seem to be the same three examples that fail, except for the mentioned JRuby failure - where it's all of the examples in that example group.

On the other hand, the error could as well just be a different symptom of something network-related.

cc @tarcieri

@tarcieri
Copy link
Contributor

@lgierth hmmm...

ArgumentError: Data object has already been freed

This could either be an http_parser.rb bug on a Reel bug. Not sure? /cc @tmm1

@ghost
Copy link
Author

ghost commented Nov 20, 2013

I just experienced another symptom, the first example hangs indefinitely, and isn't even affected by timeout(5) in #reel_server: https://gist.github.com/lgierth/7554999

Note how i send SIGINT in line 6, and the difference in time between the former and latter log timestamps.

@ghost
Copy link
Author

ghost commented Nov 20, 2013

Also note the spec command which uses --order rand:53167, as an earlier CI failure did (see my first comment after opening this issue), but runs only the Reel spec.

@ghost
Copy link
Author

ghost commented Nov 20, 2013

the first example hangs indefinitely

And obviously also the second example, as I sent SIGINT again in line 7...

@tarcieri
Copy link
Contributor

This is possibly inside of Celluloid's at_exit handler /cc @halorgium

@ghost
Copy link

ghost commented Nov 20, 2013

here's an example of random Reel errors I see often:
https://travis-ci.org/seancribbs/webmachine-ruby/jobs/14209468
it happened on rbx this time.

@tarcieri
Copy link
Contributor

@robgleeson that's the same error:

ArgumentError: Data object has already been freed

Again this is either a bug in:

  1. rbx
  2. http_parser.rb

@ghost
Copy link

ghost commented Nov 20, 2013

I would guess http_parser.rb if the same fail occurs on jruby.

@nyarly
Copy link
Contributor

nyarly commented Nov 25, 2013

If the problem is Travis running multiple adapters in one build, and granted that that's not a real use case (?), could the adapter be parameterized to an env var and the build split into per-adapter?

@ghost
Copy link
Author

ghost commented Dec 3, 2013

@samwgoldman regarding shutdown vs. random port assignment, I'm having trouble with shutdown and Rack+Mongrel. @server.server.shutdown seems to work only with WEBrick.

On a sidenote, I also noticed that only the WEBrick and Hatetepe adapters register shutdown as a SIGINT handler. FWIW, Rack::Handler#start traps SIGINT as well, and it simply exits the process unless the adapter implements shutdown.

@samwgoldman
Copy link
Contributor

@lgierth Confirm that the shutdown implementation on the Rack adapter only works with Rack+WEBrick. This is definitely a problem. From the land of wishes, I really wish Ruby web servers provided usable shutdown methods. Until they do, it would seem that Adapter#shutdown is not a realistic API to maintain.

I guess that leaves us with two options: 1) random port assignment for adapter tests in a single test process and 2) separate test processes for each adapter. I'll also note that adapters can now be extracted into gems which depend on the exported RSpec shared examples.

I somewhat snuck the Adapter#shutdown method into the public API, so its removal might require a greater-than-patch-level version bump.

@ghost
Copy link
Author

ghost commented Dec 3, 2013

I somewhat snuck the Adapter#shutdown method into the public API, so its removal might require a greater-than-patch-level version bump.

From what I understand, adding support for PUT will require a major bump as well, so maybe we could combine the two.

@ghost
Copy link

ghost commented Dec 3, 2013

@tarcieri
Copy link
Contributor

tarcieri commented Dec 3, 2013

@robgleeson the Reel adapter is crashing on rbx. Not sure what's at fault: rbx or http_parser.rb. See:

ArgumentError: Data object has already been freed

Maybe @brixen or @dbussink can help? (or @tmm1 on the http_parser.rb side perhaps)

@ghost
Copy link

ghost commented Dec 3, 2013

and my comments mysteriously disappear, anyway the failures I linked to are not related to that error. it looks like reel can't acquire a port in one of its specs.

@tarcieri
Copy link
Contributor

tarcieri commented Dec 3, 2013

@robgleeson in those tests I'm seeing Reel crash due to that error, and a connection refused error because the server isn't running... unless there's a different test failure I'm not seeing

@ghost
Copy link

ghost commented Dec 3, 2013

ah youre right, i didn't see that happen earlier in the trace. im not sure where the other failures are coming from(jruby/MRI). they look different and not related.

@ghost
Copy link

ghost commented Dec 3, 2013

jruby on travis refers to a 1.9 implementation right? I think we can get rid of the RUBY_VERSION guards from the gemfile if it is. i dont think 1.8 is being tested against anymore.

@ghost
Copy link

ghost commented Dec 3, 2013

build passed this time: https://travis-ci.org/seancribbs/webmachine-ruby/builds/14881037
dropped RUBY_VERSION guard.

@Asmod4n
Copy link
Member

Asmod4n commented Jan 20, 2014

@tarcieri have gotten already freed errors when reading request.body objects on MRI 2.1 in https://github.com/celluloid/reel/blob/master/lib/reel/request/parser.rb#L44, have gotten around it by assigning a instance variable to request.body.to_s

@Asmod4n
Copy link
Member

Asmod4n commented Jan 20, 2014

      def is_authorized?(auth = nil)
        if request.get?
          if request.query['hub.challenge']
            validate_challenge
          elsif request.query['code']
            validate_access_token
          else
            authenticate_user(auth)
          end
        elsif request.post?
          @request_body = request.body.to_s
          Celluloid::Actor[:facebook].validate_update(@request_body, request.headers)
        else
          false
        end
      end

      def process_post
        begin
          info MultiJson.load(@request_body)
        rescue StandardError => e
          error e
          raise Webmachine::MalformedRequest, 'Invalid body'
          false
        end
      end

when i try to use request.body.to_s in both i get the already freed error, also happens when i try to do

@request_body = ''
request.body.each do |body|
  @request_body << body
end

@Asmod4n
Copy link
Member

Asmod4n commented Jan 20, 2014

Oh and, the Error happens when you try to access the Resource concurrently

@ghost
Copy link
Author

ghost commented Jan 20, 2014

This one is new: https://gist.github.com/lgierth/8516794 looks like a total lockup. That's 1.9.3 with the while true loop again.

@Asmod4n
Copy link
Member

Asmod4n commented Jan 26, 2014

Ugh, i got a quite strange error with Reel now, once i set RACK_ENV to development it does request.body.to_s somewhere inside Webmachine and stops request.body.each from working then.
I believe it has something to do with https://github.com/seancribbs/webmachine-ruby/blob/master/lib/webmachine/dispatcher.rb#L47

@tarcieri
Copy link
Contributor

@Asmod4n :(

That sounds like bad method protocol interaction unfortunately. Would it make more sense for one of the sides (probably Reel) to use #to_str instead?

@Asmod4n
Copy link
Member

Asmod4n commented Jan 26, 2014

It works just fine when RACK_ENV is not defined or set to production oO

@tarcieri
Copy link
Contributor

That's really weird, especially considering Reel doesn't use Rack whatsoever! :O (without Reel::Rack anyway)

@Asmod4n
Copy link
Member

Asmod4n commented Jan 26, 2014

Written a repro, happens when reel runs behind a apache 2.2 reverse proxy and $RACK_ENV is set to development
https://gist.github.com/Asmod4n/23a836419d0e9fa4d716

@tarcieri
Copy link
Contributor

Yikes. I might be able to give that a try in a bit. Still trying to wrangle the HTTP Gem into shape...

@Asmod4n
Copy link
Member

Asmod4n commented Feb 23, 2014

From running several builds today (....) i believe what might solve some problems with travis is to assign a random port to each adapter, like:

require 'socket'
port = TCPServer.new('::', 0).addr[1]

@ghost
Copy link

ghost commented Feb 23, 2014

which problems would that solve? a fix for the random failure(s) would be great

@Asmod4n
Copy link
Member

Asmod4n commented Feb 23, 2014

nearly all failures i am getting today is because of the default port set in the spec.

@ghost
Copy link

ghost commented Feb 23, 2014

yeah, that seemed like the most common one for me too. i think it's worth a shot.

@ghost
Copy link

ghost commented Feb 23, 2014

could a sequential bump on a port also work, for each adapter? i did something like that in #150 but it could probably be revived to use unique ports for each adapter instead.

@Asmod4n
Copy link
Member

Asmod4n commented Feb 23, 2014

maybe create a array with a random port for each adapter and have a counter which one to use for the current run.

@ghost
Copy link

ghost commented Feb 23, 2014

yeah, that works. you might be able to make the tests use Webmachine::Test.port and that just returns the port for the current adapter.

@Asmod4n
Copy link
Member

Asmod4n commented Feb 24, 2014

@lgierth @seancribbs @robgleeson made a new branch to hopefully fix some spec fails, will make a PR when it looks good to you, it also changes how adapters work, so i can implement #153.

https://github.com/seancribbs/webmachine-ruby/compare/expose_application

@ghost
Copy link

ghost commented Feb 24, 2014

looks good to me

@ghost
Copy link
Author

ghost commented Jun 14, 2014

I'm having another look at the failing stuff: https://github.com/seancribbs/webmachine-ruby/compare/build-fix

This fixes #154 in that it creates a server before each example, instead of before all examples. It also intercept's IO.select and overrides its timeout, otherwise WEBrick.shutdown would take the whole 2 seconds for each example.

One really interesting observation is that all the applicable adapters (WEBrick, Reel, Rack) fail on the same example now (still only JRuby), which is should behave like adapter_lint handles fiber response bodies. Mongrel is excluded because it doesn't work with JRuby, and Hatetepe does't make use of adapter_lint (my fault).

Platform is java: skipping mongrel adapter spec.
Run options: include {:focus=>true}

All examples were filtered out; ignoring {:focus=>true}
.......................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................:each
F..........................................:each
F......................................................................................................................................................................................................W, [2014-06-14T05:19:49.700000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
W, [2014-06-14T05:19:49.703000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:handle_connection}, status=:iowait
.W, [2014-06-14T05:19:49.833000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:49.955000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.080000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.218000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.341000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.470000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.603000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.:each
E, [2014-06-14T05:19:50.728000 #14719] ERROR -- : Reel::Server::HTTP crashed!
Celluloid::DeadTaskError: cannot resume a dead task (dead fiber called)
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:27:in `deliver'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:23:in `deliver'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:98:in `resume'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/actor.rb:412:in `task'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/actor.rb:321:in `handle_message'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/actor.rb:174:in `run'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/actor.rb:157:in `initialize'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/thread_handle.rb:13:in `initialize'
    org/jruby/RubyProc.java:271:in `call'
    /home/lars/.gem/jruby/1.9.3/gems/celluloid-0.15.2/lib/celluloid/internal_pool.rb:100:in `create'
W, [2014-06-14T05:19:50.731000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
FW, [2014-06-14T05:19:50.856000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
.W, [2014-06-14T05:19:50.984000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
..W, [2014-06-14T05:19:51.017000 #14719]  WARN -- : Terminating task: type=:call, meta={:method_name=>:run}, status=:iowait
..........................................................................................................................

Failures:

  1) Webmachine::Adapters::WEBrick it should behave like adapter_lint handles fiber response bodies
     Failure/Error: expect(response.body).to eq("Fiber response body")

       expected: "Fiber response body"
            got: "<!DOCTYPE HTML PUBLIC \"-//W3C//DTD HTML 4.0//EN\">\n<HTML>\n  <HEAD><TITLE>Internal Server Error</TITLE></HEAD>\n  <BODY>\n    <H1>Internal Server Error</H1>\n    dead fiber called\n    <HR>\n    <ADDRESS>\n     WEBrick/1.3.1 (Ruby/1.9.3/2014-04-15) at\n     0.0.0.0:43933\n    </ADDRESS>\n  </BODY>\n</HTML>\n"

       (compared using ==)

       Diff:
       @@ -1,2 +1,14 @@
       -Fiber response body
       +<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0//EN">
       +<HTML>
       +  <HEAD><TITLE>Internal Server Error</TITLE></HEAD>
       +  <BODY>
       +    <H1>Internal Server Error</H1>
       +    dead fiber called
       +    <HR>
       +    <ADDRESS>
       +     WEBrick/1.3.1 (Ruby/1.9.3/2014-04-15) at
       +     0.0.0.0:43933
       +    </ADDRESS>
       +  </BODY>
       +</HTML>

     Shared Example Group: "adapter_lint" called from ./spec/webmachine/adapters/webrick_spec.rb:5
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-expectations-3.0.0/lib/rspec/expectations/fail_with.rb:33:in `fail_with'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-expectations-3.0.0/lib/rspec/expectations/handler.rb:36:in `handle_failure'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-expectations-3.0.0/lib/rspec/expectations/handler.rb:49:in `handle_matcher'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-expectations-3.0.0/lib/rspec/expectations/expectation_target.rb:54:in `to'
     # ./lib/webmachine/spec/adapter_lint.rb:102:in `(root)'
     # org/jruby/RubyBasicObject.java:1562:in `instance_exec'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:148:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:146:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:299:in `with_around_example_hooks'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:145:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:141:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:494:in `run_examples'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:490:in `run_examples'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:457:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/reporter.rb:54:in `report'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:108:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:86:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:70:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:38:in `invoke'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/exe/rspec:4:in `(root)'
     # org/jruby/RubyKernel.java:1081:in `load'
     # /home/lars/.gem/jruby/1.9.3/bin/rspec:23:in `(root)'

  2) Webmachine::Adapters::Rack it should behave like adapter_lint handles fiber response bodies
     Failure/Error: response = client.request(request)
     EOFError:
       End of file reached
     Shared Example Group: "adapter_lint" called from ./spec/webmachine/adapters/rack_spec.rb:7
     # org/jruby/RubyIO.java:2856:in `read_nonblock'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/protocol.rb:141:in `rbuf_fill'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/protocol.rb:92:in `read'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2787:in `read_chunked'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2758:in `read_body_0'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2718:in `read_body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2743:in `body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2680:in `reading_body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1329:in `transport_request'
     # org/jruby/RubyKernel.java:1264:in `catch'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1324:in `transport_request'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1301:in `request'
     # ./lib/webmachine/spec/adapter_lint.rb:100:in `(root)'
     # org/jruby/RubyBasicObject.java:1562:in `instance_exec'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:148:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:146:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:299:in `with_around_example_hooks'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:145:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:141:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:494:in `run_examples'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:490:in `run_examples'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:457:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/reporter.rb:54:in `report'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:108:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:86:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:70:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:38:in `invoke'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/exe/rspec:4:in `(root)'
     # org/jruby/RubyKernel.java:1081:in `load'
     # /home/lars/.gem/jruby/1.9.3/bin/rspec:23:in `(root)'

  3) Webmachine::Adapters::Reel lint it should behave like adapter_lint handles fiber response bodies
     Failure/Error: response = client.request(request)
     EOFError:
       End of file reached
     Shared Example Group: "adapter_lint" called from ./spec/webmachine/adapters/reel_spec.rb:5
     # org/jruby/RubyIO.java:2856:in `read_nonblock'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/protocol.rb:141:in `rbuf_fill'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/protocol.rb:122:in `readuntil'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/protocol.rb:132:in `readline'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2778:in `read_chunked'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2758:in `read_body_0'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2718:in `read_body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2743:in `body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:2680:in `reading_body'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1329:in `transport_request'
     # org/jruby/RubyKernel.java:1264:in `catch'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1324:in `transport_request'
     # /opt/rubies/jruby-1.7.12/lib/ruby/1.9/net/http.rb:1301:in `request'
     # ./lib/webmachine/spec/adapter_lint.rb:100:in `(root)'
     # org/jruby/RubyBasicObject.java:1562:in `instance_exec'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:148:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:146:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:299:in `with_around_example_hooks'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:145:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example.rb:141:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:494:in `run_examples'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:490:in `run_examples'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:457:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:458:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/example_group.rb:455:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # org/jruby/RubyArray.java:2409:in `map'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:112:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/reporter.rb:54:in `report'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:108:in `run_specs'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:86:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:70:in `run'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/lib/rspec/core/runner.rb:38:in `invoke'
     # /home/lars/.gem/jruby/1.9.3/gems/rspec-core-3.0.0/exe/rspec:4:in `(root)'
     # org/jruby/RubyKernel.java:1081:in `load'
     # /home/lars/.gem/jruby/1.9.3/bin/rspec:23:in `(root)'

Finished in 8.88 seconds (files took 5.84 seconds to load)
1247 examples, 3 failures

Failed examples:

rspec ./lib/webmachine/spec/adapter_lint.rb:97 # Webmachine::Adapters::WEBrick it should behave like adapter_lint handles fiber response bodies
rspec ./lib/webmachine/spec/adapter_lint.rb:97 # Webmachine::Adapters::Rack it should behave like adapter_lint handles fiber response bodies
rspec ./lib/webmachine/spec/adapter_lint.rb:97 # Webmachine::Adapters::Reel lint it should behave like adapter_lint handles fiber response bodies

It seems like the FiberEncoder's fibers die prematurely.

On that note, we can delete fiber18.rb.

@ghost
Copy link
Author

ghost commented Jun 16, 2014

I just ran the build-fix branch against JRuby 1.7.6 to 1.7.12, and this seems to be a bug introduced with 1.7.11. With all tested versions, there were one to three JRuby exceptions like this one.

Exception in thread "Ruby-0-Fiber-2" org.jruby.exceptions.ThreadKill
    at org.jruby.RubyThread.throwThreadKill(RubyThread.java:517)
    at org.jruby.RubyThread.checkMail(RubyThread.java:216)
    at org.jruby.RubyThread.pollThreadEvents(RubyThread.java:513)
    at org.jruby.RubyThread.pollThreadEvents(RubyThread.java:509)
    at org.jruby.RubyThread.executeBlockingTask(RubyThread.java:1069)
    at org.jruby.RubyThread.wait_timeout(RubyThread.java:1413)
    at org.jruby.ext.thread.Queue.pop(Queue.java:152)
    at org.jruby.ext.thread.Queue.pop(Queue.java:127)
    at org.jruby.ext.thread.SizedQueue.pop(SizedQueue.java:105)
    at org.jruby.ext.fiber.ThreadFiber$1.run(ThreadFiber.java:213)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)

Until 1.7.10, these looked this:

Exception in thread "FiberThread#6210" org.jruby.exceptions.ThreadKill
    at org.jruby.RubyThread.throwThreadKill(RubyThread.java:516)
    at org.jruby.RubyThread.checkMail(RubyThread.java:215)
    at org.jruby.RubyThread.pollThreadEvents(RubyThread.java:512)
    at org.jruby.RubyThread.pollThreadEvents(RubyThread.java:508)
    at org.jruby.RubyThread.executeBlockingTask(RubyThread.java:1068)
    at org.jruby.RubyThread.wait_timeout(RubyThread.java:1412)
    at org.jruby.ext.thread.Queue.pop(Queue.java:148)
    at org.jruby.ext.thread.Queue.pop(Queue.java:123)
    at org.jruby.ext.thread.SizedQueue.pop(SizedQueue.java:105)
    at org.jruby.ext.fiber.ThreadFiber$1.run(ThreadFiber.java:189)

The good news is that on JRuby 1.7.10 the build seems to be green!

@ghost
Copy link
Author

ghost commented Jun 16, 2014

I tried to eliminate possible GC/reference issues by modifying TestResource#to_fiber to remember all Fibers.

    def to_fiber
      $fibers ||= []
      $fibers.keep_if { |fiber| fiber.alive? }
      $fibers << fiber = Fiber.new do
        Fiber.yield "Fiber "
        Fiber.yield "response "
        "body"
      end
      fiber
    end

@ghost
Copy link
Author

ghost commented Jun 19, 2014

Okay, that didn't fix it, and I was so frustrated that I'm updating here a couple of days later! ;)

So I'm getting only greens locally, and only reds on Travis. My bet's this is reliant on either timing, or subtle changes between JVM versions. One way or the other, I'm gonna report this with JRuby, and add JRuby to allow_failures.

@tarcieri
Copy link
Contributor

@headius any ideas?

@ghost ghost changed the title The randomly failing spec The consistently failing spec Jun 19, 2014
@Asmod4n
Copy link
Member

Asmod4n commented Apr 24, 2016

@lgierth fixed it by currently ignoring jruby and rbx

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants