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

Application boot fails due to exhausted stack frames. #5759

Open
whitingjr opened this issue Jun 3, 2019 · 8 comments

Comments

Projects
None yet
2 participants
@whitingjr
Copy link

commented Jun 3, 2019

Environment

Provide at least:

  • JRuby version (jruby -v) and command line (flags, JRUBY_OPTS, etc)
    jruby --version
 $ jruby 9.2.6.0 (2.5.3) 2019-02-11 15ba00b OpenJDK 64-Bit Server VM 11.0.3+7 on 11.0.3+7 +jit [linux-x86_64]
  • Operating system and platform (e.g. uname -a)
 $ uname -a
Linux f29lite 5.0.17-200.fc29.x86_64 #1 SMP Mon May 20 15:39:10 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux 

Other relevant info you may wish to add:

  • Installed or activated gems
  • Application/framework version (e.g. Rails, Sinatra)

Expected Behavior

Ported JRuby application boots, interprets all Ruby code and the apisonator applictaion runs.

Actual Behavior

I am seeing an issue when booting an application using JRuby. This porting project that's being tried for the first time.
The isse I am seeing is the JVM is reporting a StackOverflow error when the application boots.

I've tried tuning the JVM to permit larger stack frames. From the default (on my system) from 1024 to 32,768. 32 times larger. Setting the jvm options here

My reproducer is the ported project branch. Using that branch the project can be built then run.

You can build and run the code using these commands.

$ make -f openshift/Makefile build
$ docker run -it -p 3001:3001 amp:apisonator-$(git describe --dirty) 3scale_backend start -p 3001 -x /dev/stdout

Should I continue searching for the magical stack size or, does this smell like a defect to you as well ?

@headius

This comment has been minimized.

Copy link
Member

commented Jun 4, 2019

It definitely sounds like a defect, either in JRuby or in some code you're loading. I would suspect JRuby first, of course.

I will try to reproduce using your instructions.

@headius

This comment has been minimized.

Copy link
Member

commented Jun 4, 2019

Here's the repeating part of the stack trace; it appears to be something odd about how it's loading the 3scale_backend binary:

  opt.app.bin.$3scale_backend.invokeOther26:load(/opt/app/bin/3scale_backend:29)
  opt.app.bin.$3scale_backend.RUBY$script(/opt/app/bin/3scale_backend:29)
  java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)
  org.jruby.ir.Compiler$1.load(Compiler.java:94)
  org.jruby.Ruby.runScript(Ruby.java:854)
  org.jruby.Ruby.runNormally(Ruby.java:777)
  org.jruby.Ruby.compileAndLoadFile(Ruby.java:2993)
  org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:234)
  org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:34)
  org.jruby.runtime.load.LoadService.load(LoadService.java:343)
  org.jruby.RubyKernel.loadCommon(RubyKernel.java:1038)
  org.jruby.RubyKernel.load(RubyKernel.java:1008)
  org.jruby.RubyKernel$INVOKER$s$load.call(RubyKernel$INVOKER$s$load.gen)
  org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:399)
  org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:346)
  org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:172)
  opt.app.bin.$3scale_backend.invokeOther26:load(/opt/app/bin/3scale_backend:29)
  opt.app.bin.$3scale_backend.RUBY$script(/opt/app/bin/3scale_backend:29)

This trace was produced by passing -X+C to force JRuby to compile all scripts as they load.

I also enabled -Xdebug.loadService which prints out files as they are loaded; that produced this output:

2019-06-04T18:12:10.247Z [main] INFO LoadService : trying fileResource: /opt/app/bin/3scale_backend
2019-06-04T18:12:10.247Z [main] INFO LoadService : found fileResource: /opt/app/bin/3scale_backend
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/app/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/bundler-2.0.1/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/whenever-0.9.7/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/statsd-ruby-1.4.0/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/sinatra-contrib-2.0.5/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/scientist-1.0.0/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/bundler/gems/resque-88839e71756e/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/vegas-0.1.11/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/sinatra-2.0.5/lib/rubygems.rb
2019-06-04T18:12:10.253Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/tilt-2.0.9/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/redis-namespace-1.6.0/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/redis-3.3.3/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/rack-protection-2.0.5/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/rack-2.0.7/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/puma-3.12.1-java/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/mustermann-1.0.3/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/mono_logger-1.1.0/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/hiredis-0.6.1-java/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/gli-2.16.1/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/daemons-1.2.4/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/chronic-0.10.2/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/bugsnag-6.11.1/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/concurrent-ruby-1.1.5/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/backports-3.15.0/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/aws-sdk-2.4.2/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/aws-sdk-resources-2.4.2/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/aws-sdk-core-2.4.2/lib/rubygems.rb
2019-06-04T18:12:10.254Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/jmespath-1.3.1/lib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/airbrake-4.3.1/lib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/multi_json-1.13.1/lib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/builder-3.2.3/lib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/extensions/universal-java-1.8/2.5.0/3scale_backend-2.91.1/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/gems/shared/gems/rake-10.4.2/lib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/2.5/site_ruby/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/stdlib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : found fileResource: /opt/jruby/jruby-9.2.6.0/lib/ruby/stdlib/rubygems.rb
2019-06-04T18:12:10.255Z [main] INFO LoadService : trying fileResource: /opt/app/bin/3scale_backend
@headius

This comment has been minimized.

Copy link
Member

commented Jun 4, 2019

It looks like the logic here in the binstub is failing to find the installed bin location, instead falling back to the same script. This causes the stack overflow.

bin/3scale_backend:

...
require "rubygems"
require "bundler/setup"

puts "Loading: #{Gem.bin_path("3scale_backend", "3scale_backend")}"
load Gem.bin_path("3scale_backend", "3scale_backend")

The load line is the one that keeps recursing, because bin_path is returning the path of this script. The output ends up looking like this:

Loading: /opt/app/bin/3scale_backend
2019-06-04T18:23:57.722Z [main] INFO LoadService : trying fileResource: /opt/app/bin/3scale_backend
2019-06-04T18:23:57.722Z [main] INFO LoadService : found fileResource: /opt/app/bin/3scale_backend

I'm not sure what would cause this, but it seems that in your configuration, the 3scale_backend's bin script resolves to this top bin dir, rather than the unpacked version of the gem.

@whitingjr

This comment has been minimized.

Copy link
Author

commented Jun 5, 2019

Are you sure. Using bundle gem it reports the top bin directory.

$ docker run -it --entrypoint /bin/bash amp:apisonator-$(git describe --dirty)
bash-4.2$ jruby -S bundle show 3scale_backend
/opt/app
bash-4.2$ find .. -iname 3scale_backend
../app/bin/3scale_backend
../jruby/jruby-9.2.6.0/lib/ruby/gems/shared/bin/3scale_backend
../ruby/3scale_backend-2.91.1/vendor/bundle/jruby/2.5.0/bin/3scale_backend
../ruby/3scale_backend-2.91.1/bin/3scale_backend
bash-4.2$

@headius I suspect you are expecting the path returned should be one of 2nd, 3rd or 4th path. Is that right ?

@headius

This comment has been minimized.

Copy link
Member

commented Jun 7, 2019

Right, it seems like since it's picking the /opt/app dir as the gem location for 3scale_backend, when it tries to resolve the binscript it's looping back on itself. I'm not sure if this is something we're doing or something Bundler is doing or something odd about your environment, though.

@whitingjr

This comment has been minimized.

Copy link
Author

commented Jun 7, 2019

Does this reveal anything useful ?

@headius

This comment has been minimized.

Copy link
Member

commented Jun 7, 2019

@whitingjr Not really, I'm afraid.

I notice you did not mention any non-JRuby Ruby impl...does this work with CRuby? If so we could at least confirm whether the same issue exists there. This seems to be a problem in either bundler or RG or something specific to how you have this configured and deployed. The question in my mind is whether this should work...it's clearly using the app dir as the location for the gem, which certainly isn't right when it tries to resolve the bin script again.

Or perhaps the bin script inside /opt/app should be the real script for the gem rather than this RubyGems-generated stub?

@whitingjr

This comment has been minimized.

Copy link
Author

commented Jun 11, 2019

@headius you'll need to bear with me for a bit. I branched off a tagged v2.91.1 version. Which does not cleanly build after checkout. Getting through those issues before comparing and answering.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.