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

Gem::LoadError: You have already activated rack-cors 1.0.1, but your Gemfile requires rack-cors 1.0.2 #4849

Closed
perlun opened this issue Nov 10, 2017 · 17 comments
Labels

Comments

@perlun
Copy link
Contributor

@perlun perlun commented Nov 10, 2017

Cross post of rubygems/bundler#6164, since the problem only occurs on JRuby. It seems remotely similar to #4740, so it could be the same root cause.

I have only reproduced it so far on macOS, but I'm quite certain that it's not OS specific in that sense.


This is similar to rubygems/bundler#6144 in that it's also related to bundler/setup somehow, but slightly different.

Preconditions:

  • Project is a Ruby gem
  • Ruby gem is installed via bundler
  • Project has an executable.

The executable runs a few lines like this on startup:

require 'bundler/setup'
Bundler.setup

This works well, both with bundler 1.15.4, 1.16.0 and so forth. But, we are utilizing self-restarts with puma and here we are seeing issues. When the process is restarted, bundler chooses the wrong gems and this breaks everything:

$ bundle exec bundler_bug_app_server
Running from /Users/plundberg/.rvm/gems/jruby-9.1.13.0/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.13.0 - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop
* Restarting...
Running from /Users/plundberg/.rvm/gems/jruby-9.1.13.0/bin/bundler_bug_app_server
Gem::LoadError: You have already activated rack-cors 1.0.1, but your Gemfile requires rack-cors 1.0.2. Prepending `bundle exec` to your command may solve this.
  check_for_activated_spec! at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-1.16.0/lib/bundler/runtime.rb:313
             block in setup at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-1.16.0/lib/bundler/runtime.rb:31
                       each at org/jruby/RubyArray.java:1734
                       each at /Users/plundberg/.rvm/rubies/jruby-9.1.13.0/lib/ruby/stdlib/forwardable.rb:189
                        map at org/jruby/RubyEnumerable.java:830
                      setup at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-1.16.0/lib/bundler/runtime.rb:26
                      setup at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-1.16.0/lib/bundler.rb:107
                     <main> at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-1.16.0/lib/bundler/setup.rb:10
                    require at org/jruby/RubyKernel.java:955
                     (root) at /Users/plundberg/.rvm/rubies/jruby-9.1.13.0/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:1
                     <main> at /Users/plundberg/.rvm/rubies/jruby-9.1.13.0/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:55
                       load at org/jruby/RubyKernel.java:973
                     <main> at /Users/plundberg/.rvm/gems/jruby-9.1.13.0/gems/bundler-bug-0.1.0/exe/bundler_bug_app_server:7

I knew this is a tricky problem so I put together an extensive repro repo to be able to debug this in a reasonable way: https://github.com/perlun/bundler-1.16-bug


What I've concluded so far:

  • It works correctly on MRI, have never managed to reproduce it there.
  • The bug is only visible on JRuby.
  • bundler 1.15.4 seems to work correctly, even thought I have on a rare occasion seen it there (but later when testing, the bug usually goes away by downgrading to 1.15.4). bundler 1.16.0 exhibits the problem.
  • I have no idea whether the problem is in bundler or JRuby; will cross-post to both projects to be on the safe side.
  • It only occurs when multiple versions of a gem are installed (which is very common after living with a Ruby installation for some time.)

I will gladly assist in debugging this of course. My repro repo contains extensive instructions on how to trigger the problem. If you need more info or details, just let me know. I did look at the ENV variables in the "first" and "second" startups, but they didn't give me that much; all relevant RUBYOPT and BUNDLER_* variables were identical on both startups.

However, I did see something strange: on the first run, it used the executable from my "own" repo and in the second run, it used the executable from an installed gem version. This only happened in my private GitHub repo, in the repro repo it always used the executable from an installed gem version for whatever reason.

@headius
Copy link
Member

@headius headius commented Nov 10, 2017

Thank you for the repro repo! I'm going to have a look now.

Loading

@headius
Copy link
Member

@headius headius commented Nov 10, 2017

I have successfully reproduced the issue on JRuby 9.1 HEAD.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

Ok, so the first obvious issue here is that when it restarts, it's not running bundle exec. The error message is right! 😁

$ jruby -I lib ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server 
Running from ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Gem::LoadError: You have already activated rack-cors 1.0.1, but your Gemfile requires rack-cors 1.0.2. Prepending `bundle exec` to your command may solve this.
  check_for_activated_spec! at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.16.0/lib/bundler/runtime.rb:313
             block in setup at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.16.0/lib/bundler/runtime.rb:31

Based on that, you can use the following puma configuration to tell it to do the right thing, and then the server restarts gracefully:

diff --git a/config/puma.rb b/config/puma.rb
new file mode 100644
index 0000000..ef54432
--- /dev/null
+++ b/config/puma.rb
@@ -0,0 +1 @@
+restart_command "bundle exec bundler_bug_app_server"

Now, if I log what MRI does, I get a similar command line for the subprocess:

["/Users/headius/.rubies/ruby-2.3.4/bin/ruby", "-I", "/Users/headius/projects/bundler-1.16-bug/lib", "/Users/headius/.gem/ruby/2.3.4/bin/bundler_bug_app_server", {:close_others=>true, 7=>7}]

But running this command line does not work:

$ ruby -I lib ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server 
/Users/headius/.rubies/ruby-2.3.4/lib/ruby/2.3.0/rubygems/dependency.rb:319:in `to_specs': Could not find 'bundler-bug' (>= 0.a) among 118 total gem(s) (Gem::LoadError)
Checked in 'GEM_PATH=/Users/headius/.gem/ruby/2.3.4:/Users/headius/.rubies/ruby-2.3.4/lib/ruby/gems/2.3.0', execute `gem env` for more information
	from /Users/headius/.rubies/ruby-2.3.4/lib/ruby/2.3.0/rubygems/dependency.rb:328:in `to_spec'
	from /Users/headius/.rubies/ruby-2.3.4/lib/ruby/2.3.0/rubygems/core_ext/kernel_gem.rb:65:in `gem'
	from ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server:25:in `<main>'

JRuby and MRI follow different paths in restarting that do different things. I am going to look at the ENV to see what differs.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

I suspect this never worked right with any environment that needs bundle exec.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

*correction...I suspect this version of bundler probably doesn't work on any JRuby version when the app needs bundle exec to restart.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

Inspecting ENV did not yield anything obvious. My chruby-based MRI env has GEM_ROOT and friends set, but that should not make much difference. Both envs had RUBYOPT set to -rbundler/setup.

Now the really baffling part: it suddenly started working for me locally.

$ !bundle
bundle exec bundler_bug_app_server
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop
* Restarting...
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292

😕

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

Ok, nevermind...I had rack-cors back at 1.0.1.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

Ah-ha! So it looks like if I run the bare JRuby command with -rbundler/setup it works correctly. This is put into RUBYOPT env for both JRuby and MRI.

$ jruby -I lib -rbundler/setup /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop

This makes me think perhaps the RUBYOPT env is not propagating to the new process.

Loading

@headius
Copy link
Member

@headius headius commented Nov 11, 2017

Ok, it does seem to be some problem with propagating the RUBYOPT variable to the new process. If I provide it as an env on the command line it works:

$ RUBYOPT=-rbundler/setup jruby -I lib /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
"-rbundler/setup"
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292

It also works with bundle exec if I set RUBYOPT at that point:

$ RUBYOPT=-rbundler/setup bundle exec bundler_bug_app_server
"-rbundler/setup"
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop
* Restarting...
"-rbundler/setup"
Running from /Users/headius/projects/jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server
Puma starting in single mode...
* Version 3.10.0 (jruby 9.1.15.0-SNAPSHOT - ruby 2.3.3), codename: Russell's Teapot
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:9292
Use Ctrl-C to stop

My suspicion is that because the JRuby restart logic uses a direct call to execlp, it is not getting environment variables set up in the parent. Our ENV does not directly write to the real process environment in order to avoid stepping on other JRuby instances in the same process. Our exec and other subprocess logic walks the per-instance ENV before launching to physically set up the new environment.

Loading

@headius
Copy link
Member

@headius headius commented Nov 12, 2017

Sometimes, the dumbest bugs take the most effort to find.

This line works:

RUBYOPT='-rbundler/setup' jruby -Ilib ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server

This line doesn't:

RUBYOPT=' -rbundler/setup' jruby -Ilib ../jruby/lib/ruby/gems/shared/bin/bundler_bug_app_server

Don't strain yourself...the only difference is that RUBYOPT in the second case has whitespace as the first character. My guess is that we're tokenizing the string and since the first token before the first space is a blank string, we figure we're done.

Loading

@headius
Copy link
Member

@headius headius commented Nov 12, 2017

Closing the circle on my env theory: I had forgotten that by default, for the main JRuby instance in a given JVM we do actually set the real env. The RUBYOPT env var was getting passed through, but not parsed properly.

Loading

@perlun
Copy link
Contributor Author

@perlun perlun commented Nov 13, 2017

Thanks a lot for that @headius! 👏 👏 👏 Much appreciated! I feel silly now, should have included the ENV dumps (which I did look at indeed, but I didn't spot the difference between:

"RUBYOPT"=>"-rbundler/setup"

and

"RUBYOPT"=>" -rbundler/setup"

I looked at the Puma code now briefly and this code there is causing the issue: https://github.com/puma/puma/blob/70f309b0260815ce5dec5faacf7e51cc742f0dd5/lib/puma/launcher.rb#L171

It means that the RUBYOPT will indeed have a leading space, which got us confused in the first place. It's good to have this fixed in JRuby core, but I will also file a Puma PR to avoid this at the source as well: puma/puma#1455


Sorry to ask, but when do you anticipate the 9.1.15.0 fix to be released? (We can use an older Bundler for now, but I assume it means we also have to use 9.1.13.0 since 9.1.14.0 has the newer bundler version built-in, which triggers this.)

Loading

nateberkopec added a commit to puma/puma that referenced this issue Nov 16, 2017
The problem is this:

```
2.4.2 :001 > [nil, 'foo'].join(' ')
 => " foo"
```

Note the leading space character. By `lstrip`:ing the result of the join, we avoid this altogether.

(This is a fix for the underlying problem that triggered jruby/jruby#4849.)
@headius
Copy link
Member

@headius headius commented Nov 21, 2017

@perlun We (@enebo and I) are hoping to do a quick release of 9.1.15 because there's a few other good fixes we should get out quickly. What do you think @enebo?

Loading

@perlun
Copy link
Contributor Author

@perlun perlun commented Dec 7, 2017

@headius @enebo How about releasing 9.1.15.0 soon? ❤️ 😉

Loading

@headius
Copy link
Member

@headius headius commented Dec 7, 2017

Loading

@perlun
Copy link
Contributor Author

@perlun perlun commented Dec 7, 2017

Tomorrow soon enough?

Tomorrow is great! 🎉

Loading

@perlun
Copy link
Contributor Author

@perlun perlun commented Dec 12, 2017

For the record: Fixed in http://jruby.org/2017/12/07/jruby-9-1-15-0.html

Thanks for your hard & great work @headius! 👍

Loading

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

Successfully merging a pull request may close this issue.

None yet
2 participants