"superclass mismatch for class" when running in JRuby

Sadaf_N · July 18, 2013, 3:37am

I’m trying to integrate google-api-client Ruby gem into a project that
runs
in JRuby 1.7.4 (logstash). When I run this code on Ruby in an RVM
environment (JRuby 1.7.4) directly, the code works just fine. However,
when
I create the jar file (make jar) and try to run it on the JVM, it fails
with the error below:

The error reported is:
superclass mismatch for class Request

Debugging with DEBUG=require shows that the offending class (request.rb)
is
loaded only once before I actually hit the error. Also, when I look at
gem
that hits the problem, only one file (connection.rb) actually requires
“request” (through their require_libs method), so it doesn’t seem to be
the
case that multiple code paths load the same class.

Would you have any tips on how to investigate this further? (More
details
can be found at the end of the email).

Thanks,
Rodrigo

Detailed error:
sudo DEBUG=require /usr/lib/jvm/default-java/bin/java -Xms512m -Xmx512m
-jar /usr/share/logstash/logstash.jar agent -f
/etc/logstash/syslog-shipper.conf --log /var/log/logstash.log -vv
Sending all output to /var/log/logstash.log.

[…]

require(“etc”) => false (from:
jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/1.9/fileutils.rb:1084:in
FileUtils') require("fileutils") => true (from: file:/usr/share/logstash/logstash.jar!/logstash/outputs/gcs.rb:43:in register’)
require(“timeout”) => true (from:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:47:in
Faraday') require("cgi") => false (from: file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils.rb:1:in (root)‘)
require(“jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils”)
=> true (from:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:17:in
require_libs') require("cgi") => false (from: file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb:1:in (root)’)
require(“set”) => true (from:
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb:2:in
(root)') require("forwardable") => true (from: file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb:3:in (root)‘)
require(“uri”) => false (from:
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb:4:in
(root)') require("jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder") => true (from: jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:17:in require_libs’)
±--------------------------------------------------------+
| An unexpected error occurred. This is probably a bug. |
| You can find help with this problem in a few places: |
| |
| * chat: #logstash IRC channel on freenode irc. |
| IRC via the web: http://goo.gl/TI4Ro |
| * email: [email protected] |
| * bug system: https://logstash.jira.com/ |
| |
±--------------------------------------------------------+
The error reported is:
superclass mismatch for class Request
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request.rb:12:in
Faraday' file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request.rb:1:in (root)’
org/jruby/RubyKernel.java:1054:in require' jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/custom_require.rb:36:in require’
file:/usr/share/logstash/logstash.jar!/logstash/JRUBY-6970.rb:13:in
require' jar:file:/usr/share/logstash/logstash.jar!/gems/polyglot-0.3.3/lib/polyglot.rb:63:in require’
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:1:in
(root)' org/jruby/RubyArray.java:1617:in each’
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:17:in
require_libs' jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:15:in require_libs’
org/jruby/RubyKernel.java:1054:in require' jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/custom_require.rb:36:in require’
file:/usr/share/logstash/logstash.jar!/logstash/JRUBY-6970.rb:13:in
require' jar:file:/usr/share/logstash/logstash.jar!/gems/polyglot-0.3.3/lib/polyglot.rb:63:in require’
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb:6:in
(root)' org/jruby/RubyArray.java:1617:in each’
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:1:in
(root)' jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:17:in require_libs’
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:15:in
require_libs' org/jruby/RubyKernel.java:1054:in require’
jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/custom_require.rb:36:in
require' file:/usr/share/logstash/logstash.jar!/logstash/JRUBY-6970.rb:13:in require’
jar:file:/usr/share/logstash/logstash.jar!/gems/polyglot-0.3.3/lib/polyglot.rb:63:in
require' jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:130:in Faraday’
org/jruby/RubyKernel.java:1054:in require' jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/custom_require.rb:60:in require’
jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/shared/rubygems/custom_require.rb:55:in
require' file:/usr/share/logstash/logstash.jar!/logstash/JRUBY-6970.rb:13:in require’
jar:file:/usr/share/logstash/logstash.jar!/gems/polyglot-0.3.3/lib/polyglot.rb:63:in
require' jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb:1:in (root)’
org/jruby/RubyArray.java:1617:in each' jar:file:/usr/share/logstash/logstash.jar!/gems/google-api-client-0.6.4/lib/google/api_client.rb:1:in (root)’
jar:file:/usr/share/logstash/logstash.jar!/gems/google-api-client-0.6.4/lib/google/api_client.rb:16:in
`(root)’

Rodrigo_De_Castro · July 18, 2013, 5:47am

Hi Rodrigo,

In ruby, a class definition can be spread out over several declarations
and in several files. The superclass is taken from the first
declaration. Subsequent declarations either have to have the same
superclass or none. E.g.:

class Foo < String; end
class Foo; end # okay
class Foo < String; end # okay
class Foo < Fixnum; end # superclass mismatch

If the first declaration doesn’t have a superclass, the same rules
apply:

class Bar; end
class Bar; end # okay
class Bar < Object; end # okay
class Bar < String; end # superclass mismatch

So, my guess is that in this codebase, the Request class has
declarations in multiple files, something like this:

File A

class Request < Something; end

File B

class Request; end

Loading A then B works, but B then A gives a superclass mismatch when
loading A.

To check this hypothesis, I suggest grepping the gems for ‘class
Request’ and seeing if there are multiple declarations. If so, see if
you can see how they are being required that could be different in the
different envs.

HTH,
Rhett

Rodrigo_De_Castro · July 18, 2013, 6:59am

Thanks so much for the explanation, Rhett.

The class hitting the error does not have any other declaration in the
same
module (“Faraday”). There are other Request class in different modules,
but
I understand that modules provide different namespaces, so this class
should not be colliding with any other Request class (in other modules).
Is
this understanding correct? Any other suggestion?

Rodrigo_De_Castro · July 19, 2013, 7:29pm

Rodrigo De Castro wrote in post #1115810:

Thanks so much for the explanation, Rhett.

The class hitting the error does not have any other declaration in the
same
module (“Faraday”). There are other Request class in different modules,
but
I understand that modules provide different namespaces, so this class
should not be colliding with any other Request class (in other modules).
Is
this understanding correct? Any other suggestion?

there is a defined? method that might help

Rodrigo_De_Castro · July 19, 2013, 10:20pm

Hi,

So, Faraday::Request is declared like this:

class Request < Struct.new(:method, :path, :params, :headers, :body,
:options)

Struct.new creates a new Class instance every time it’s invoked, so
loading this file twice would cause the superclass mismatch error. So
now I think your original suspicion that the file is being loaded more
than once somehow is more likely to be correct.

require in ruby should prevent this. Specifically, it prevents the
same file from being interpreted more than once. “Same file” is
determined by absolute path (on ruby 1.9 and later). So, my guess is
that there are two copies of Faraday visible to your app and somehow
both are being loaded from different code.

(Something I have encountered when trying to run java apps with gems
packaged into jars is that sometimes the jar version isn’t used an copy
that’s visible on the filesystem is used instead. A variation on that
could be happening: a version visible on the filesystem is being loaded
in addition to the one from the jar.)

I’m not familiar with the DEBUG=require env var you’re using. What
provides that? I wonder if it’s possible for something to be required
before it takes effect.

For further debugging, you could look at the $LOADED_FEATURES global.
This is an array of all the absolute paths of every file that’s been
required up to the point that you look at it. If you could see the
contents of that array just before this exception, you might be able to
see where Faraday::Request was previously declared.

Rhett

Rodrigo_De_Castro · July 24, 2013, 12:46am

On Fri, Jul 19, 2013 at 3:19 PM, Rhett S. [email protected]
wrote:

Hi,

So, Faraday::Request is declared like this:

class Request < Struct.new(:method, :path, :params, :headers, :body, :options)

Struct.new creates a new Class instance every time it’s invoked, so loading this
file twice would cause the superclass mismatch error. So now I think your original
suspicion — that the file is being loaded more than once somehow — is more likely
to be correct.

That seems like a good theory at this point.

require in ruby should prevent this. Specifically, it prevents the same file
from being interpreted more than once. “Same file” is determined by absolute path
(on ruby 1.9 and later). So, my guess is that there are two copies of Faraday
visible to your app and somehow both are being loaded from different code.

(Something I have encountered when trying to run java apps with gems packaged
into jars is that sometimes the jar version isn’t used — an copy that’s visible on
the filesystem is used instead. A variation on that could be happening: a version
visible on the filesystem is being loaded in addition to the one from the jar.)

Yes, that can happen, especially if paths are added to load path (like
new jars, etc) later on. I believe the searching logic may find new
files after loading old ones (and I think this is a bug, too).

I’m not familiar with the DEBUG=require env var you’re using. What provides
that? I wonder if it’s possible for something to be required before it takes
effect.

For further debugging, you could look at the $LOADED_FEATURES global. This is an
array of all the absolute paths of every file that’s been required up to the point
that you look at it. If you could see the contents of that array just before this
exception, you might be able to see where Faraday::Request was previously
declared.

There’s also a JRuby property you can specify to log loading of files…

Passed to JRuby: -Xdebug.loadService=true

or

Passed to Java: -Djruby.debug.loadService=true

This will show all files as they’re loaded, with nested requires
indented appropriately. You may be able to see the file loaded twice
using this output.

Charlie

Rodrigo_De_Castro · July 24, 2013, 1:14am

I debugged with $LOADED_FEATURES and the first thing I noticed is that
there isn’t any other Faraday gem being loaded at all or any duplicate
request.rb being loaded either.

After adding debugging code to Faraday, though, I found some differences
between running in the RVM environment with Ruby and on the JVM that may
help us understand what is going on:

$LOADED_FEATURES output on the JVM shows two “builder.rb” (which
requires
request.rb) being loaded.
LoadService also shows builder.rb being “found” twice. The only class
that requires builder is connection, and it’s been shown as being loaded
only once.

It seems that the root cause is not actually in request.rb being loaded
twice, but the class that requires it (builder.rb). And I understand
that
reloading builder.rb does not cause a problem because it does not have
any
superclass (unlike request.rb):

module Faraday
class Builder

Any clues on why builder.rb is being loaded twice? Any other debug flag
I
can use investigate it further?

Some more info below:

— JRuby/JVM output
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils
BEFORE utils

AFTER utils
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils.rb

REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/connection
BEFORE connection
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils.rb
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder
BEFORE builder
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils.rb
AFTER builder* (no TYPO, there are two builder.rb!)*
*
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
*
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
REQUIRE:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request
BEFORE request
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
FAILED (rescue block) - request
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/git/logstash/file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request.rb

— Ruby/RVM output
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils
BEFORE utils

AFTER utils
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb

REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/connection
BEFORE connection
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder
BEFORE builder
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
AFTER builder
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder.rb
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/request
BEFORE request
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/request.rb
REQUIRE:
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/response
BEFORE response
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/request.rb
AFTER response
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/utils.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/builder.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/request.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/middleware.rb
/home/rdc/.rvm/gems/jruby-1.7.4/gems/faraday-0.8.7/lib/faraday/response.rb
[…]

— LoadService:
2013-07-23T22:54:33.371Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/google-api-client-0.6.4/lib/google/api_client.rb
2013-07-23T22:54:33.406Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday.rb
2013-07-23T22:54:33.409Z: LoadService: LoadService: found builtinLib:
timeout.rb
2013-07-23T22:54:33.450Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/utils.rb
2013-07-23T22:54:33.521Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/connection.rb
2013-07-23T22:54:33.556Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/1.9/set.rb
2013-07-23T22:54:33.586Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/META-INF/jruby.home/lib/ruby/1.9/forwardable.rb
*2013-07-23T22:54:33.605Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
*2013-07-23T22:54:33.606Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
2013-07-23T22:54:33.644Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request.rb
2013-07-23T22:54:33.646Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/request.rb

On Tue, Jul 23, 2013 at 3:45 PM, Charles Oliver N.

Rodrigo_De_Castro · July 24, 2013, 11:00pm

Jordan, from Logstash, in case he has anything to add on how Logstash
is
using JRuby that may be causing that.

This is running in Logstash, and as far as I can tell, not in any
development mode.

Some more logs on the LoadService below. You can see some differences in
bold. All other loaded ruby class show only “trying builtinLib:
file:…”,
but in the builder.rb and request.rb cases, they show first “trying
builtinLib: file” and then “trying builtinLib: jar:file”, apparently
causing the issue:

2013-07-23T22:54:33.604Z: LoadService: LoadService: trying builtinLib: *
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
2013-07-23T22:54:33.604Z: LoadService: LoadService: trying builtinLib:
file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.class
2013-07-23T22:54:33.605Z: LoadService: LoadService: trying
resourceFromJarURL: gems/faraday-0.8.7/lib/faraday/builder.rb
2013-07-23T22:54:33.605Z: LoadService: LoadService: found:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
2013-07-23T22:54:33.606Z: LoadService: LoadService: trying builtinLib: *
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.rb
*
2013-07-23T22:54:33.606Z: LoadService: LoadService: trying builtinLib:
jar:file:/usr/share/logstash/logstash.jar!/gems/faraday-0.8.7/lib/faraday/builder.class
2013-07-23T22:54:33.606Z: LoadService: LoadService: trying
resourceFromJarURL: gems/faraday-0.8.7/lib/faraday/builder.rb

On Tue, Jul 23, 2013 at 6:19 PM, Charles Oliver N.

Rodrigo_De_Castro · July 24, 2013, 3:21am

Is this running under development mode in Rails, or some other
library/mode that causes reloading to happen?

Charlie

Rodrigo_De_Castro · July 25, 2013, 5:58pm

On Wed, Jul 24, 2013 at 2:41 PM, Jordan S. [email protected]
wrote:

development mode.
2013-07-23T22:54:33.604Z: LoadService: LoadService: trying builtinLib:
2013-07-23T22:54:33.606Z: LoadService: LoadService: trying
under logstash, but my hunch is that logstash’s monkeypatches for
(perceived or actual) JRuby issues is probably the culprit here as the
cause for the double-loading. I need more data (or time to reproduce it) to
determine this.

Removing the monkey patches fixed the problem. Logstash and my plugin
using
google-api-client (incl. faraday) is working fine now when running on
the
JRuby.

Let’s continue the discussion on how to get this fixed on
logstash-users.

For now, thanks for the help, Rhett, Roger, and Charles!

Rodrigo_De_Castro · July 25, 2013, 4:44pm

Resending since I wasn’t previously on the mailling list —