EM dependency too permissive

[ajvondrak]

I don't think the Ruby version matters here, but just in case:

Last login: Thu May 26 13:15:15 on ttys004
/tmp$ bundle exec ruby -v
ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-darwin13]
/tmp$

I've set up a minimal repro in a gist:

/tmp$ git clone [email protected]:e72726e947b1db9387541369ec3b389e.git repro
Cloning into 'repro'...
remote: Counting objects: 12, done.
remote: Compressing objects: 100% (8/8), done.
remote: Total 12 (delta 4), reused 9 (delta 3), pack-reused 0
Receiving objects: 100% (12/12), done.
Resolving deltas: 100% (4/4), done.
Checking connectivity... done.
/tmp$ cd repro
/tmp/repro$

Goliath declares a dependency on eventmachine >= 1.0.0.beta.4. If your Gemfile does not lock to a particular eventmachine version, bundle update (or even your initial bundle install) can wind up installing eventmachine 1.2.0.1 (which, as of this writing is their latest version). This version of EM causes (at the very least) Goliath::TestHelper to fail mysteriously:

/tmp/repro$ bundle update && bundle exec ruby test.rb
Fetching [email protected]:postrank-labs/goliath.git
Fetching gem metadata from https://rubygems.org/..........
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
Resolving dependencies...
Using addressable 2.4.0
Using rack 1.6.4
Using cookiejar 0.3.0
Using einhorn 0.7.1
Using eventmachine 1.2.0.1
Using http_parser.rb 0.6.0
Using git-version-bump 0.15.1
Using log4r 1.1.10
Using multi_json 1.12.1
Using rack-accept-media-types 0.9
Using minitest 5.9.0
Using bundler 1.11.2
Using async-rack 0.5.1
Using em-socksify 0.3.1
Using em-synchrony 1.0.5
Using em-websocket 0.3.8
Using rack-contrib 1.4.0
Using rack-respond_to 0.9.8
Using em-http-request 1.1.3
Using goliath 1.0.4 from [email protected]:postrank-labs/goliath.git (at 1aeb2ae@1aeb2ae)
Bundle updated!
Run options: --seed 32896

# Running:

E

Finished in 0.011878s, 84.1900 runs/s, 0.0000 assertions/s.

  1) Error:
Test#test_reproducing_em_dependency_issue:
RuntimeError: API request failed
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-1aeb2ae7e6d9/lib/goliath/test_helper.rb:30:in `block in <module:TestHelper>'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/gems/eventmachine-1.2.0.1/lib/em/deferrable.rb:74:in `errback'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-1aeb2ae7e6d9/lib/goliath/test_helper.rb:110:in `hookup_request_callbacks'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-1aeb2ae7e6d9/lib/goliath/test_helper.rb:131:in `get_request'
    test.rb:10:in `block in test_reproducing_em_dependency_issue'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-1aeb2ae7e6d9/lib/goliath/server.rb:105:in `block in start'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/gems/em-synchrony-1.0.5/lib/em-synchrony.rb:39:in `block (2 levels) in synchrony'

1 runs, 0 assertions, 0 failures, 1 errors, 0 skips
/tmp/repro$

I do not know what the bug is, but it seems to have been introduced by EM 1.2.0.1. If I lock the Gemfile to the previously released version, 1.0.9.1, I do not get these errors:

/tmp/repro$ LOCK_EM_VERSION=1 bundle update && bundle exec ruby test.rb
Fetching [email protected]:postrank-labs/goliath.git
Fetching gem metadata from https://rubygems.org/..........
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
Resolving dependencies...
Using addressable 2.4.0
Using rack 1.6.4
Using cookiejar 0.3.0
Using einhorn 0.7.1
Using eventmachine 1.0.9.1 (was 1.2.0.1)
Using http_parser.rb 0.6.0
Using git-version-bump 0.15.1
Using log4r 1.1.10
Using multi_json 1.12.1
Using rack-accept-media-types 0.9
Using minitest 5.9.0
Using bundler 1.11.2
Using async-rack 0.5.1
Using em-socksify 0.3.1
Using em-synchrony 1.0.5
Using em-websocket 0.3.8
Using rack-contrib 1.4.0
Using rack-respond_to 0.9.8
Using em-http-request 1.1.3
Using goliath 1.0.4 from [email protected]:postrank-labs/goliath.git (at 1aeb2ae@1aeb2ae)
Bundle updated!
Run options: --seed 54290

# Running:

.

Finished in 0.010082s, 99.1886 runs/s, 99.1886 assertions/s.

1 runs, 1 assertions, 0 failures, 0 errors, 0 skips
/tmp/repro$

At the very least, Goliath's >= dependency is too permissive. I don't know how to make Goliath compatible with EM 1.2.0.1, but I do know that a recent bundle update on my project has broken basically all of the tests. (Also, I get runtime errors when I don't declare an em-http-request dependency - should this be added explicitly to the Goliath gemspec?)

[igrigorik]

Hmm, I think there is something else going on here. We did have a failing test, which I just pushed a fix for, and with that, everything is A-OK with 1.2.0.1:

https://travis-ci.org/postrank-labs/goliath/jobs/133768450#L185

[code-bunny]

Was having the same issue until I locked the gem file to 1.0.9.1, it appeared the test was making requests to localhost:9900 and this responded with nothing to the EM. I need to dig a bit deeper to find out the issue, for now the fix is locking your gem file

[janko]

The error happens for me too. Inspecting shows that it's due to an Errno::ECONNREFUSED error being raised, which I think means that nothing is listening on the requested port. Locking EventMachine to 1.0.9.1 works for me as well.

[igrigorik]

Are you guys running the latest code from master? I can't reproduce the errror locally with 1.2.0.1

[ajvondrak]

Haven't had a chance to debug further, myself. Per the repro gist in the original comment, Goliath was locked to 1aeb2ae (latest master when I initially opened the issue). Updating it to 6c06cd3 still fails on my machine:

/tmp/repro$ grep -B2 ref Gemfile
gem 'goliath',
    git: '[email protected]:postrank-labs/goliath.git',
    ref: '6c06cd38702e3335168a7507ebf8fc8c8eb62bf1'
/tmp/repro$ bundle update && bundle exec ruby test.rb
Fetching [email protected]:postrank-labs/goliath.git
Fetching gem metadata from https://rubygems.org/..........
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
Resolving dependencies...
Using addressable 2.4.0
Using rack 1.6.4
Installing cookiejar 0.3.3
Installing einhorn 0.7.4
Using eventmachine 1.2.0.1
Using http_parser.rb 0.6.0
Using git-version-bump 0.15.1
Using log4r 1.1.10
Using multi_json 1.12.1
Using rack-accept-media-types 0.9
Using minitest 5.9.0
Using bundler 1.11.2
Using async-rack 0.5.1
Using em-socksify 0.3.1
Using em-synchrony 1.0.5
Using em-websocket 0.3.8
Using rack-contrib 1.4.0
Using rack-respond_to 0.9.8
Installing em-http-request 1.1.5
Using goliath 1.0.4 from [email protected]:postrank-labs/goliath.git (at 6c06cd3@6c06cd3)
Bundle updated!
Run options: --seed 32698

# Running:

E

Finished in 0.050316s, 19.8745 runs/s, 0.0000 assertions/s.

  1) Error:
Test#test_reproducing_em_dependency_issue:
RuntimeError: API request failed
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-6c06cd38702e/lib/goliath/test_helper.rb:30:in `block in <module:TestHelper>'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/gems/eventmachine-1.2.0.1/lib/em/deferrable.rb:74:in `errback'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-6c06cd38702e/lib/goliath/test_helper.rb:110:in `hookup_request_callbacks'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-6c06cd38702e/lib/goliath/test_helper.rb:131:in `get_request'
    test.rb:10:in `block in test_reproducing_em_dependency_issue'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/bundler/gems/goliath-6c06cd38702e/lib/goliath/server.rb:105:in `block in start'
    /Users/avondrak/.rvm/gems/ruby-2.3.0/gems/em-synchrony-1.0.5/lib/em-synchrony.rb:39:in `block (2 levels) in synchrony'

1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

Note:

Using eventmachine 1.2.0.1

Locking eventmachine to 1.0.9.1 still works:

/tmp/repro$ LOCK_EM_VERSION=1 bundle update && bundle exec ruby test.rb
Fetching [email protected]:postrank-labs/goliath.git
Fetching gem metadata from https://rubygems.org/..........
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
Resolving dependencies...
Using addressable 2.4.0
Using rack 1.6.4
Using cookiejar 0.3.3
Using einhorn 0.7.4
Using eventmachine 1.0.9.1 (was 1.2.0.1)
Using http_parser.rb 0.6.0
Using git-version-bump 0.15.1
Using log4r 1.1.10
Using multi_json 1.12.1
Using rack-accept-media-types 0.9
Using minitest 5.9.0
Using bundler 1.11.2
Using async-rack 0.5.1
Using em-socksify 0.3.1
Using em-synchrony 1.0.5
Using em-websocket 0.3.8
Using rack-contrib 1.4.0
Using rack-respond_to 0.9.8
Using em-http-request 1.1.5
Using goliath 1.0.4 from [email protected]:postrank-labs/goliath.git (at 6c06cd3@6c06cd3)
Bundle updated!
Run options: --seed 11406

# Running:

.

Finished in 0.011637s, 85.9338 runs/s, 85.9338 assertions/s.

1 runs, 1 assertions, 0 failures, 0 errors, 0 skips

Note:

Using eventmachine 1.0.9.1 (was 1.2.0.1)

I'm on OSX Version 10.9.5, if that helps/matters. Any other variables about my environment I might provide?

[Bonias]

I'm not a Goliath's user, but I may know what the problem is here.

Let me cite @sodabrew (eventmachine/eventmachine#703 (comment)):

localhost is resolving to IPv6's ::1 localhost first and then to IPv4's 127.0.0.1 localhost.

EM 1.2 does a name resolution on "localhost" and simply uses the first address it gets back from the system, whereas EM 1.0 did an explicit IPv4 lookup and so it would not have seen the IPv6 address.

---

About reproduction gist (https://gist.github.com/ajvondrak/e72726e947b1db9387541369ec3b389e). It is failing also for me (it's also throwing Segmentation fault for me but it's probably problem for another issue for eventmachine). You can pass the test in two ways (which proves that problem is with resolving hostname to IPv6 address):

1. Add Goliath::Server::DEFAULT_ADDRESS = '0:0:0:0:0:0:0:0' to your test.rb, or:
2. Change get_request do |http| to get_request(domain: "127.0.0.1:#{@test_server_port}") do |http|

---

I experienced similar problem with Thin. After upgrading some gems in rails project (including eventmachine to 1.2.0.1) the server stopped responding on custom host defined in /etc/hosts as 127.0.0.1 my-host. The possible workaround there would be bind server to 127.0.0.1 instead of localhost (which is default for rails): bin/rails s -b 127.0.0.1. I'm planning add issue about that at https://github.com/macournoyer/thin.

[igrigorik]

@Bonias thanks, this is very helpful. Binding to 127.0.0.1 seems like a reasonable solution.

[sodabrew]

I've just posted EventMachine 1.2.1, with a few smaller fixes, not specifically related to the issues here, but just as an FYI.

I'm very interested if there's anything I can do to improve / help this scenario, either with tunable knobs in EM, or suggesting knobs for Thin (i.e. prefer IPv4 vs. IPv6, or bind to all local address by default, etc.)

[ajvondrak]

@Bonias Verified on my machine. I know my comment comes late, but just wanted to give a huge thanks for solving this mystery! I feel less crazy now. 😄