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.

Sign up for GitHub

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

Jump to bottom

Foreman dies during web app boot on Java 9 #5082

Closed
greghuc opened this issue Mar 7, 2018 · 17 comments
Closed

Foreman dies during web app boot on Java 9 #5082

greghuc opened this issue Mar 7, 2018 · 17 comments
Labels
JDK compatibility JRuby 9000
Milestone
JRuby 9.2.11.1

Comments

@greghuc
Copy link

greghuc commented Mar 7, 2018

Environment

jruby -version
jruby 9.1.16.0 (2.3.3) 2018-02-21 8f3f95a OpenJDK 64-Bit Server VM 9.0.4+11
on 9.0.4+11 +jit [linux-x86_64]

java -version
openjdk version "9.0.4"
OpenJDK Runtime Environment (build 9.0.4+11)
OpenJDK 64-Bit Server VM (build 9.0.4+11, mixed mode)

uname -a
Linux vagrant 4.4.0-87-generic #110-Ubuntu SMP Tue Jul 18 12:55:35 UTC 2017
x86_64 x86_64 x86_64 GNU/Linux

puma (3.11.3)

Expected Behavior

I'm exploring upgrading an API to JRuby 9.1.16.0 + Java 9.0.4

The API currently runs under the puma 3.11.3 webserver for JRuby 9.1.16.0 + Java 8.

Actual Behavior

The Puma 3.11.3 web server is failing to start under this combo of JRuby + Java 9, and blows up with the stacktrace below.

I'm opening this issue with jruby, as the stacktrace is all jruby references, not puma. I'm sure you're aware of various Java 9 issues, but I thought I'd submit this one, as running (puma) web servers seems like a common JRuby usage :-)

export JAVA_OPTS="--illegal-access=debug"
puma -e development

16:21:35 web.1  | started with pid 24847
16:21:35 web.1  | exited with code 127
16:21:35 system | sending SIGTERM to all processes

java.base/sun.nio.ch.SelectorImpl.keys(SelectorImpl.java:68)
org.jruby.util.io.SelectorPool.put(SelectorPool.java:88)
org.jruby.util.io.SelectExecutor.selectEnd(SelectExecutor.java:59)
org.jruby.util.io.SelectExecutor.go(SelectExecutor.java:44)
org.jruby.RubyIO.select(RubyIO.java:3534)
org.jruby.RubyIO$INVOKER$s$0$3$select.call(RubyIO$INVOKER$s$0$3$select.gen)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:818)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:77)
org.jruby.ir.instructions.CallBase.interpret(CallBase.java:432)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:360)
org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
org.jruby.ir.interpreter.Interpreter.INTERPRET_BLOCK(Interpreter.java:127)
org.jruby.runtime.InterpretedIRBlockBody.commonYieldPath(InterpretedIRBlockBody.java:141)
org.jruby.runtime.IRBlockBody.yieldSpecific(IRBlockBody.java:84)
org.jruby.runtime.Block.yieldSpecific(Block.java:134)
org.jruby.RubyKernel.loop(RubyKernel.java:1316)
org.jruby.RubyKernel$INVOKER$s$0$0$loop.call(RubyKernel$INVOKER$s$0$0$loop.gen)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodZeroBlock.call(JavaMethod.java:536)
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:278)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:79)
org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:84)
org.jruby.ir.instructions.CallBase.interpret(CallBase.java:429)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:360)
org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
org.jruby.ir.interpreter.Interpreter.INTERPRET_BLOCK(Interpreter.java:127)
org.jruby.runtime.InterpretedIRBlockBody.commonYieldPath(InterpretedIRBlockBody.java:141)
org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:73)
org.jruby.runtime.Block.call(Block.java:124)
org.jruby.RubyProc.call(RubyProc.java:289)
org.jruby.RubyProc.call(RubyProc.java:246)
org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:104)
java.base/java.lang.Thread.run(Thread.java:844)
@greghuc greghuc mentioned this issue Mar 7, 2018
Closed
@headius
Copy link
Member

headius commented Mar 15, 2018

Are you using export JAVA_OPTS="--illegal-access=debug" just to print this out, or for some other reason?

@headius
Copy link
Member

headius commented Mar 15, 2018

FWIW before release I confirmed that JRuby 9.1.16.0 is able to generate a Rails app and boot it (with Puma) on Java 9. We may have regressed, but this should be working.

@headius headius added this to the JRuby 9.1.17.0 milestone Mar 15, 2018
@greghuc
Copy link
Author

greghuc commented Mar 15, 2018

@headius I believe I just used "--illegal-access=debug" because it led to a longer stack-trace.

I also had been having illegal-access issues (with Sequel) when I was running Java "9-internal" (installed with apt-get). These vanished when I switched to Java 9.0.4. See #4834 (comment) and #4834 (comment).

@headius
Copy link
Member

headius commented Mar 16, 2018

@greghuc Yeah I noticed the 9.0.4 update helped. That's interesting.

The illegal access warnings are an ongoing issue. I wonder if 9.0.4 "fixed" some of them by just being quieter.

Here's my session running a Rails app using Puma. This is on OS X, but I'll try Ubuntu tomorrow (unless @enebo tests Fedora and is able to reproduce first).

[--dev] ~/projects/jruby/myapp $ java -version
java version "9.0.4"
Java(TM) SE Runtime Environment (build 9.0.4+11)
Java HotSpot(TM) 64-Bit Server VM (build 9.0.4+11, mixed mode)

[--dev] ~/projects/jruby/myapp $ rails s
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.jruby.ext.openssl.SecurityHelper (file:/Users/headius/projects/jruby/lib/ruby/stdlib/jopenssl.jar) to constructor java.security.cert.CertificateFactory(java.security.cert.CertificateFactorySpi,java.security.Provider,java.lang.String)
WARNING: Please consider reporting this to the maintainers of org.jruby.ext.openssl.SecurityHelper
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
=> Booting Puma
=> Rails 5.1.5 application starting in development 
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.11.3 (jruby 9.1.17.0-SNAPSHOT - ruby 2.3.3), codename: Love Song
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop

@headius
Copy link
Member

headius commented Mar 16, 2018

Same output using puma -e development, again on OS X:

[--dev] ~/projects/jruby/myapp $ puma -e development
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.jruby.ext.openssl.SecurityHelper (file:/Users/headius/projects/jruby/lib/ruby/stdlib/jopenssl.jar) to constructor java.security.cert.CertificateFactory(java.security.cert.CertificateFactorySpi,java.security.Provider,java.lang.String)
WARNING: Please consider reporting this to the maintainers of org.jruby.ext.openssl.SecurityHelper
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Puma starting in single mode...
* Version 3.11.3 (jruby 9.1.17.0-SNAPSHOT - ruby 2.3.3), codename: Love Song
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop

@greghuc
Copy link
Author

greghuc commented Mar 16, 2018 •
edited
Loading

@headius and @enebo so I did some digging, and it turns out that puma is starting just fine in JRuby 1.9.16 and Java 9.0.4. The issue is with the foreman gem I use to start puma:

vagrant@vagrant:/vagrant/bin$ PATH=$HOME/jdk-9.0.4/bin:$PATH ${ROOT_DIR}/bin/foreman start --procfile ${ROOT_DIR}/Procfile

11:38:33 web.1  | started with pid 15190
11:38:33 web.1  | exited with code 127
11:38:33 system | sending SIGTERM to all processes
End of file reached
org/jruby/RubyIO.java:2852:in `read_nonblock'
/home/vagrant/.rbenv/versions/jruby-9.1.16.0/lib/ruby/gems/shared/gems/foreman-0.84.0/lib/foreman/engine.rb:381:in `read_self_pipe'
/home/vagrant/.rbenv/versions/jruby-9.1.16.0/lib/ruby/gems/shared/gems/foreman-0.84.0/lib/foreman/engine.rb:410:in `block in watch_for_output'
org/jruby/RubyKernel.java:1316:in `loop'
/home/vagrant/.rbenv/versions/jruby-9.1.16.0/lib/ruby/gems/shared/gems/foreman-0.84.0/lib/foreman/engine.rb:408:in `block in watch_for_output'

I created a minimal test case at: https://github.com/greghuc/jruby-java9-puma-foreman.

In short, this project is a vagrant box that installs Ubuntu 16.04 + Java 8, Java 9, JRuby 9.1.16, Puma and Foreman. In ./bin, there's a few test scripts for running a tiny rack app via Puma/Foreman/Java8/Java9. The project readme covers it.

Hope this helps, and my bad for thinking the issue was with puma.

Oh, and the Foreman procfile is:

web: bin/puma -b 'tcp://0.0.0.0:5001'

@headius headius changed the title Puma web server busted on Java 9.0.4 Forman dies during web app boot on Java 9 Mar 16, 2018
@headius
Copy link
Member

headius commented Mar 16, 2018

Ok I've managed to reproduce several errors using your example. Thanks!

I've seen three different errors:

  • eof as shown in your report
  • closed stream
  • a Java exception, presumably NullPointerException, inside IO.select logic

I think there's more than one thing at play here..

@headius
Copy link
Member

headius commented Mar 16, 2018

Ok, the additional exception in select logic is because the selector has been closed by the time we reach this point in the code.

java.base/sun.nio.ch.SelectorImpl.keys(SelectorImpl.java:68)
org.jruby.util.io.SelectorPool.put(SelectorPool.java:88)
org.jruby.util.io.SelectExecutor.selectEnd(SelectExecutor.java:59)
org.jruby.util.io.SelectExecutor.go(SelectExecutor.java:44)
org.jruby.RubyIO.select(RubyIO.java:3534)

@headius
Copy link
Member

headius commented Mar 16, 2018

Ok, I guess that selector thing isn't coming through as a fatal error; it is happening during shutdown of the listener thread.

I have attempted to reproduce on OS X with JRuby 9.1 HEAD...and so far I cannot. The server starts fine. So that's another clue.

@headius
Copy link
Member

headius commented Mar 16, 2018

It also works properly with JRuby 9.1.16.0 on OS X.

@greghuc greghuc changed the title Forman dies during web app boot on Java 9 Foreman dies during web app boot on Java 9 Mar 18, 2018
@headius
Copy link
Member

headius commented Apr 12, 2018

I have not had a chance to look into this further. @enebo I do not believe this is a regression...it's likely always been broken on Windows + Java 9 (if we even ran at all on 9 before my recent fixes).

@enebo enebo modified the milestones: JRuby 9.1.17.0, JRuby 9.1.18.0 Apr 19, 2018
@greghuc
Copy link
Author

greghuc commented May 15, 2018

Just noting that "foreman not starting" behaviour is still present on java 10.0.1 (as well as 9).

PATH=/home/vagrant/jdk-10.0.1/bin:$PATH  bin/foreman start --procfile Procfile
14:27:08 web.1  | started with pid 2415
14:27:08 web.1  | exited with code 127
14:27:08 system | sending SIGTERM to all processes

ruby --version
jruby 9.1.17.0 (2.3.3) 2018-04-20 d8b1ff9 Java HotSpot(TM) 64-Bit Server VM 25.172-b11 on 1.8.0_172-b11 +jit [linux-x86_64]

PATH=/home/vagrant/jdk-10.0.1/bin java -version
java version "10.0.1" 2018-04-17
Java(TM) SE Runtime Environment 18.3 (build 10.0.1+10)
Java HotSpot(TM) 64-Bit Server VM 18.3 (build 10.0.1+10, mixed mode)

@headius
Copy link
Member

headius commented May 15, 2018

Does foreman use SSL?

@greghuc
Copy link
Author

greghuc commented May 15, 2018 •
edited
Loading

I'm not 100% sure, but I don't believe foreman uses SSL. The ruby version code is at: https://github.com/ddollar/foreman

Foreman is a process runner, which runs a process as specified in a "Procfile". Unclear why it would need ssl to do that.

@headius
Copy link
Member

headius commented May 22, 2020

I'm back! This one was forgotten but somehow worked its way into my queue again.

Managed to repro using your example:

vagrant@vagrant:/vagrant$ bin/puma-foreman-java9.sh 
19:43:17 web.1  | started with pid 14575
19:43:17 web.1  | exited with code 127
19:43:17 system | sending SIGTERM to all processes
closed stream
org/jruby/RubyIO.java:3534:in `select'
/home/vagrant/.rbenv/versions/jruby-9.1.16.0/lib/ruby/gems/shared/gems/foreman-0.84.0/lib/foreman/engine.rb:409:in `block in watch_for_output'
org/jruby/RubyKernel.java:1316:in `loop'
/home/vagrant/.rbenv/versions/jruby-9.1.16.0/lib/ruby/gems/shared/gems/foreman-0.84.0/lib/foreman/engine.rb:408:in `block in watch_for_output'

@headius
Copy link
Member

headius commented May 22, 2020

Time marches on, and it looks like this no longer reproduces on JRuby 9.2.11.1. We'll mark it fixed there and call it a day.

vagrant@vagrant:/vagrant$ bin/puma-foreman-java9.sh
19:54:24 web.1  | started with pid 16382
19:54:32 web.1  | Puma starting in single mode...
19:54:32 web.1  | * Version 3.11.3 (jruby 9.2.11.1 - ruby 2.5.7), codename: Love Song
19:54:32 web.1  | * Min threads: 0, max threads: 16
19:54:32 web.1  | * Environment: development
19:54:32 web.1  | * Listening on tcp://0.0.0.0:5001
19:54:32 web.1  | Use Ctrl-C to stop

@headius headius closed this as completed May 22, 2020
@greghuc
Copy link
Author

greghuc commented May 22, 2020

@headius thanks for investigating this. Also thanks in general for all your hard work on JRuby. I really appreciate there being a solid Ruby implementation that enables true multi-threading on web servers.

@LoganBarnett LoganBarnett mentioned this issue May 29, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
JDK compatibility JRuby 9000
Projects
None yet
Milestone
JRuby 9.2.11.1
Development

No branches or pull requests
3 participants
@headius @enebo @greghuc