Occasionally failed by "JRuby runtime is not loaded successfully" error

[kamikaseda]

trafficstars

Summary

The Embulk process occationally fails due to following error when doing input-file and output-postgresql.

2018-03-08 03:02:53.999 +0900 [INFO] (main): Started Embulk v0.9.4
2018-03-08 03:02:54.477 +0900 [INFO] (0001:transaction): Gem's home and path are set by default: "/root/.embulk/lib/gems"
SystemCallError: Unknown error (SystemCallError) - channel: org.jruby.util.io.ChannelFD@1da5c19d uri:classloader:/META-INF/jruby.home/lib/ruby/gems/shared/specifications/default/minitest-5.4.1.gemspec
              gets at org/jruby/RubyIO.java:2301
          readline at org/jruby/RubyIO.java:2692
     block in data at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:118
              open at org/jruby/RubyIO.java:1156
              open at org/jruby/RubyKernel.java:306
              data at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:116
            valid? at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:207
            select at org/jruby/RubyArray.java:2566
  gemspec_stubs_in at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:751
     default_stubs at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:758
             stubs at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:833
      find_by_path at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:1038
      try_activate at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems.rb:209
           require at uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:126
            <main> at <script>:1
org.embulk.jruby.JRubyNotLoadedException: JRuby runtime is not loaded successfully.
        at org.embulk.jruby.ScriptingContainerDelegateImpl.runScriptlet(ScriptingContainerDelegateImpl.java:725)
        at org.embulk.jruby.JRubyInitializer.initialize(JRubyInitializer.java:128)
        at org.embulk.jruby.LazyScriptingContainerDelegate.getInitialized(LazyScriptingContainerDelegate.java:206)
        at org.embulk.jruby.LazyScriptingContainerDelegate.runScriptlet(LazyScriptingContainerDelegate.java:186)
        at org.embulk.jruby.JRubyPluginSource.newPlugin(JRubyPluginSource.java:60)
        at org.embulk.plugin.PluginManager.newPluginWithoutWrapper(PluginManager.java:59)
        at org.embulk.plugin.PluginManager.newPlugin(PluginManager.java:31)
        at org.embulk.spi.ExecSession.newPlugin(ExecSession.java:147)
        at org.embulk.spi.Exec.newPlugin(Exec.java:63)
        at org.embulk.exec.BulkLoader$ProcessPluginSet.<init>(BulkLoader.java:410)
        at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:484)
        at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:35)
        at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:353)
        at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:350)
        at org.embulk.spi.Exec.doWith(Exec.java:22)
        at org.embulk.exec.BulkLoader.run(BulkLoader.java:350)
        at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:162)
        at org.embulk.EmbulkRunner.runInternal(EmbulkRunner.java:292)
        at org.embulk.EmbulkRunner.run(EmbulkRunner.java:156)
        at org.embulk.cli.EmbulkRun.runSubcommand(EmbulkRun.java:437)
        at org.embulk.cli.EmbulkRun.run(EmbulkRun.java:92)
        at org.embulk.cli.Main.main(Main.java:26)
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.embulk.jruby.ScriptingContainerDelegateImpl.runScriptlet(ScriptingContainerDelegateImpl.java:718)
        ... 21 more
Caused by: org.jruby.embed.EvalFailedException: (SystemCallError) Unknown error (SystemCallError) - channel: org.jruby.util.io.ChannelFD@1da5c19d uri:classloader:/META-INF/jruby.home/lib/ruby/gems/shared/specifications/default/minitest-5.4.1.gemspec
        at org.jruby.embed.internal.EmbedEvalUnitImpl.run(EmbedEvalUnitImpl.java:131)
        at org.jruby.embed.ScriptingContainer.runUnit(ScriptingContainer.java:1307)
        at org.jruby.embed.ScriptingContainer.runScriptlet(ScriptingContainer.java:1300)
        ... 26 more
Caused by: org.jruby.exceptions.RaiseException: (SystemCallError) Unknown error (SystemCallError) - channel: org.jruby.util.io.ChannelFD@1da5c19d uri:classloader:/META-INF/jruby.home/lib/ruby/gems/shared/specifications/default/minitest-5.4.1.gemspec
        at org.jruby.RubyIO.gets(org/jruby/RubyIO.java:2301)
        at org.jruby.RubyIO.readline(org/jruby/RubyIO.java:2692)
        at RUBY.block in data(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:118)
        at org.jruby.RubyIO.open(org/jruby/RubyIO.java:1156)
        at org.jruby.RubyKernel.open(org/jruby/RubyKernel.java:306)
        at RUBY.data(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:116)
        at RUBY.valid?(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/stub_specification.rb:207)
        at org.jruby.RubyArray.select(org/jruby/RubyArray.java:2566)
        at RUBY.gemspec_stubs_in(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:751)
        at RUBY.default_stubs(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:758)
        at RUBY.stubs(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:833)
        at RUBY.find_by_path(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/specification.rb:1038)
        at RUBY.try_activate(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems.rb:209)
        at RUBY.require(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:126)
        at RUBY.<main>(<script>:1)
Error: JRuby runtime is not loaded successfully.
2018-03-08 03:02:54.857 +0900: Embulk v0.9.4

Goal

Figure out the cause and resolution or workaround.

Environment information

EC2: t2.medium OS: CentOS 7.4 Java: OpenJDK 1.8.0 PostgreSQL: 9.6.7 embulk: 0.9.4

Situation

Our workflow over view is:

1. Data import from csv file to local postgresql server. (Embulk + input-file + output-postgresql)
2. Data analizing in postgresql.
3. Data export from postgresql to csv file. (Embulk + input-postgresql + output-file)

Above process is looped every csv file by shell script. The error happens at step 1. And it seems happen when importing slightly larger file (200MB or 500MB).

[dmikurube]

Thanks for reporting, @kamikaseda!

Its most recognizable message was JRuby runtime is not loaded successfully., but actually this was wrong. JRuby is loaded successfully, but it is failing by (SystemCallError) Unknown error (SystemCallError) - channel: org.jruby.util.io.ChannelFD@1da5c19d uri:classloader:/META-INF/jruby.home/lib/ruby/gems/shared/specifications/default/minitest-5.4.1.gemspec.

Hmm, it looks like an error really internal in JRuby's I/O. One possibility is their heavy load, but not very sure yet...

Anyways, I'm trying to fix the error message to be more readable at #979.

[dmikurube]

@kamikaseda Jfyi, Embulk v0.9.5 has been released. The issue is not fixed, but the Exception message may be more understandable.

[jsolomon8080]

I have filed a similar issue: https://github.com/jruby/jruby/issues/6218

I think the problem is with jruby itself.

[headius]

@jsolomon8080 Thanks for the footwork on jruby/jruby#6218. Your reproduction made it possible to finally investigate this issue.

To all: I have diagnosed this problem as being a pretty nasty JDK bug: https://bugs.openjdk.java.net/browse/JDK-8246714

Basically, whenever you use URLClassLoader to access jar files, there's a potential for rogue "zip file closed" or NullPointerException to happen, due to the way that URLClassLoader shuts down jar files it encounters.

I have fixed this in jruby/jruby#6273 by avoiding our call to URLClassLoader#close and only closing the jar files that we know are specific to a given JRuby runtime (unpacked nested jars). This does not prevent other non-JRuby URLClassLoaders from damaging the same opened jar files, but it should eliminate the issue for JRuby-only jar file usage.