Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6.7
    • Fix Version/s: JRuby 1.6.8, JRuby 1.7.0.pre1
    • Component/s: Java Integration
    • Labels:
      None
    • Environment:
      Windows Server 2008 and Windows Server 2008 R2 with JDK 7u3
    • Number of attachments :
      0

      Description

      I have a Rails 2.3.14 app, running on Trinidad. However, when starting up the web app, I am getting sporadic NoMethodError when serving initial pages.

      Application Error
      org.jruby.exceptions.RaiseException: (NoMethodError) undefined method `upcase' for #<Java::JavaLang::String:0x17a4277>
              at LazyEnv.load_headers(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack-1.1.4.jar!/rack/handler/servlet.rb:101)
      

      Here is the section of code from jruby-rack-1.1.4:

      ...
      @servlet_env.getHeaderNames.each do |h|
        next if h =~ /^Content-(Type|Length)$/i
        puts h.inspect; puts h.class.name; k = "HTTP_#{h.upcase.gsub(/-/, '_')}" # line 101 / puts added for tracing.
        env[k] = @servlet_env.getHeader(h) unless env.has_key?(k)
      end
      ...
      
      

      It appears that on line 101 of jruby-rack-1.1.4, when loading headers, JRuby is not automatically converting Java strings into Ruby strings, leading to the NoMethodError.

      Here is a full transcript of two web app launches, with the above trace statements.

      The first one is a normal one.

      C:\work\app>web.bat
      Apr 04, 2012 12:09:48 AM org.apache.coyote.AbstractProtocol init
      INFO: Initializing ProtocolHandler ["http-bio-5000"]
      Apr 04, 2012 12:09:48 AM org.apache.catalina.core.StandardService startInternal
      INFO: Starting service Tomcat
      Apr 04, 2012 12:09:48 AM org.apache.catalina.core.StandardEngine startInternal
      INFO: Starting Servlet Engine: Apache Tomcat/7.0.23
      2012-04-04 05:09:48 INFO: No global web.xml found
      Info: received max runtimes = 1
      jruby 1.6.7 (ruby-1.8.7-p357) (2012-02-22 3e82bc8) (Java HotSpot(TM) Client VM 1.7.0_03) [Windows Server 2008-x86-java]
      Runtime start
      2012-04-04 05:10:00 INFO: Starting ProtocolHandler ["http-bio-5000"]
      "host"
      String
      "user-agent"
      String
      "accept"
      String
      "accept-language"
      String
      "accept-encoding"
      String
      "accept-charset"
      String
      "keep-alive"
      String
      "connection"
      String
      "cookie"
      String
      "if-none-match"
      String
      "cache-control"
      String
      "host"
      String
      "user-agent"
      String
      "accept"
      String
      "accept-language"
      String
      "accept-encoding"
      String
      "accept-charset"
      String
      "keep-alive"
      String
      "connection"
      String
      "referer"
      String
      "cookie"
      String
      "if-modified-since"
      String
      "cache-control"
      String
      "host"
      String
      "user-agent"
      String
      "accept"
      String
      "accept-language"
      String
      "accept-encoding"
      String
      "accept-charset"
      String
      "keep-alive"
      String
      "connection"
      String
      "referer"
      String
      "cookie"
      String
      "if-modified-since"
      String
      "cache-control"
      String
      "host"
      String
      "user-agent"
      String
      "accept"
      String
      "accept-language"
      String
      "accept-encoding"
      String
      "accept-charset"
      String
      "keep-alive"
      String
      "connection"
      String
      "referer"
      String
      "cookie"
      String
      "if-modified-since"
      String
      "cache-control"
      String
      2012-04-04 05:10:05 INFO: Pausing ProtocolHandler ["http-bio-5000"]
      2012-04-04 05:10:05 INFO: Stopping service Tomcat
      Runtime exit
      2012-04-04 05:10:05 INFO: Stopping ProtocolHandler ["http-bio-5000"]
      2012-04-04 05:10:06 INFO: Destroying ProtocolHandler ["http-bio-5000"]
      Terminate batch job (Y/N)? ^C
      

      The second one is the one where JRuby failed to convert Java string to Ruby string:

      
      C:\work\app>web.bat
      Apr 04, 2012 12:10:12 AM org.apache.coyote.AbstractProtocol init
      INFO: Initializing ProtocolHandler ["http-bio-5000"]
      Apr 04, 2012 12:10:12 AM org.apache.catalina.core.StandardService startInternal
      INFO: Starting service Tomcat
      Apr 04, 2012 12:10:12 AM org.apache.catalina.core.StandardEngine startInternal
      INFO: Starting Servlet Engine: Apache Tomcat/7.0.23
      2012-04-04 05:10:13 INFO: No global web.xml found
      Info: received max runtimes = 1
      jruby 1.6.7 (ruby-1.8.7-p357) (2012-02-22 3e82bc8) (Java HotSpot(TM) Client VM 1.7.0_03) [Windows Server 2008-x86-java]
      Runtime start
      2012-04-04 05:10:24 INFO: Starting ProtocolHandler ["http-bio-5000"]
      #<Java::JavaLang::String:0x17a4277>
      Java::JavaLang::String
      Application Error
      org.jruby.exceptions.RaiseException: (NoMethodError) undefined method `upcase' for #<Java::JavaLang::String:0x17a4277>
              at LazyEnv.load_headers(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:101)
              at Enumeration.each(C:/java/xjruby/lib/ruby/site_ruby/shared/builtin/java/java.util.rb:39)
              at LazyEnv.load_headers(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:99)
              at LazyEnv.load_env_key(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:74)
              at LazyEnv.initialize(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-
      rack-1.1.4.jar!/rack/handler/servlet.rb:59)
              at org.jruby.RubyProc.call(org/jruby/RubyProc.java:270)
              at org.jruby.RubyProc.call(org/jruby/RubyProc.java:220)
              at org.jruby.RubyHash.default(org/jruby/RubyHash.java:647)
              at org.jruby.RubyHash.[](org/jruby/RubyHash.java:1007)
              at Env.populate(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack-1
      .1.4.jar!/rack/handler/servlet.rb:47)
              at Env.initialize(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack
      -1.1.4.jar!/rack/handler/servlet.rb:41)
              at Servlet.create_env(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-
      rack-1.1.4.jar!/rack/handler/servlet.rb:24)
              at Servlet.call(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack-1
      .1.4.jar!/rack/handler/servlet.rb:20)
      #<Java::JavaLang::String:0x17a4277>
      Java::JavaLang::String
      Error: Couldn't handle error
      org.jruby.exceptions.RaiseException: (NoMethodError) undefined method `upcase' for #<Java::JavaLang:
      :String:0x17a4277>
              at LazyEnv.load_headers(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:101)
              at Enumeration.each(C:/java/xjruby/lib/ruby/site_ruby/shared/builtin/java/java.util.rb:39)
              at LazyEnv.load_headers(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:99)
              at LazyEnv.load_env_key(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jrub
      y-rack-1.1.4.jar!/rack/handler/servlet.rb:74)
              at LazyEnv.initialize(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-
      rack-1.1.4.jar!/rack/handler/servlet.rb:59)
              at org.jruby.RubyProc.call(org/jruby/RubyProc.java:270)
              at org.jruby.RubyProc.call(org/jruby/RubyProc.java:220)
              at org.jruby.RubyHash.default(org/jruby/RubyHash.java:647)
              at org.jruby.RubyHash.[](org/jruby/RubyHash.java:1007)
              at Env.populate(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack-1
      .1.4.jar!/rack/handler/servlet.rb:47)
              at Env.initialize(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack
      -1.1.4.jar!/rack/handler/servlet.rb:41)
              at Servlet.create_env(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-
      rack-1.1.4.jar!/rack/handler/servlet.rb:24)
              at Servlet.call(file:C:/java/xjruby/lib/ruby/gems/1.8/gems/jruby-rack-1.1.4/lib/jruby-rack-1
      .1.4.jar!/rack/handler/servlet.rb:20)
      

      I can reproduce this about 40% of the time. Generally, if this happens, my webapp will not work and I need to restart it a few times until it works. I am at a loss as to how to debug this further. Any suggestions appreciated.

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        Peter: headius@headius.com, always

        Show
        Charles Oliver Nutter added a comment - Peter: headius@headius.com, always
        Hide
        Charles Oliver Nutter added a comment -

        Heh...I just noticed everyone who has reported this reported it on Windows too...that's another clue at least.

        Show
        Charles Oliver Nutter added a comment - Heh...I just noticed everyone who has reported this reported it on Windows too...that's another clue at least.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, I did some exploration on Peter's machine, and I'm sadly no closer to having a solution.

        Reproducing it was pretty easy, though it wasn't consistent. At first it happened every server startup, but after that it was maybe 75% of the server starts would lead to this.

        I added logic into Enumeration#each to print out the types of elements, and it is indeed getting a wrapped Java string somehow.

        I tried turning on --server mode and could not get it to reproduce. That could simply be a coincidence, but I probably restarted it + hit it 50 or more times.

        Show
        Charles Oliver Nutter added a comment - Ok, I did some exploration on Peter's machine, and I'm sadly no closer to having a solution. Reproducing it was pretty easy, though it wasn't consistent. At first it happened every server startup, but after that it was maybe 75% of the server starts would lead to this. I added logic into Enumeration#each to print out the types of elements, and it is indeed getting a wrapped Java string somehow. I tried turning on --server mode and could not get it to reproduce. That could simply be a coincidence, but I probably restarted it + hit it 50 or more times.
        Hide
        Charles Oliver Nutter added a comment -

        Found it! Epic commit message coming.

        Show
        Charles Oliver Nutter added a comment - Found it! Epic commit message coming.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, it's fixed on master and 1.6 branch, even though we won't be doing a 1.6.8 release. Thanks for the patience on this, everyone, and thanks for the machine access Peter

        1.6 branch commit is d7ffb84.

        commit 545da6c46c62357f475d0279e3a78bdbc060f4f4
        Author: Charles Oliver Nutter <headius@headius.com>
        Date:   Tue May 15 15:02:27 2012 -0500
        
            Fix JRUBY-6619: NoMethodError 'upcase' on Java string
            
            Well, this was a tricky one to find.
            
            The problem stems from the actual Enumeration being walked. In
            this case, when running under a Tomcat-based server (or perhaps
            when running under a server that just uses some Apache libraries)
            it is the NamesEnumerator class.
            
            NamesEnumerator implements Enumeration<String>, which causes javac
            to generate two nextElement methods: one with a String return and
            one with an Object return. Issue number 1 is that JRuby does not
            consider these to be overloads, and so it would randomly pick one
            or the other depending on what order they were retrieved via Java
            reflection. That was the cause of the variability.
            
            JRuby converts return arguments using a cached "converter" that
            it validates is still correct by confirming the object type being
            returned matches the expected object type. If a method returns
            String, we will use the cached String converter if the returned
            object is also a String.
            
            We also had code in place that attempted to find a "more public"
            version of methods defined on non-public classes by searching the
            public classes and interfaces above it.
            
            In the case of NamesEnumerator, which is package-private, whenever
            the String-returning method was encountered first we would proceed
            to search for the Object version even though both were public
            methods. But upon finding the Object version, we did not save it.
            Instead, we only captured the converter based on an Object return
            type and still dispatched using the String version.
            
            So basically, we were calling the String version of the method but
            using the Object converter to convert the result, which is why it
            wrapped rather than converted.
            
            I removed the public method search, since it wasn't actually
            accomplishing anything. Both of the public methods in question
            should dispatch ok without it, and this should avoid the broken
            hybrid of String method with Object converter.
        
        Show
        Charles Oliver Nutter added a comment - Ok, it's fixed on master and 1.6 branch, even though we won't be doing a 1.6.8 release. Thanks for the patience on this, everyone, and thanks for the machine access Peter 1.6 branch commit is d7ffb84. commit 545da6c46c62357f475d0279e3a78bdbc060f4f4 Author: Charles Oliver Nutter <headius@headius.com> Date: Tue May 15 15:02:27 2012 -0500 Fix JRUBY-6619: NoMethodError 'upcase' on Java string Well, this was a tricky one to find. The problem stems from the actual Enumeration being walked. In this case, when running under a Tomcat-based server (or perhaps when running under a server that just uses some Apache libraries) it is the NamesEnumerator class. NamesEnumerator implements Enumeration<String>, which causes javac to generate two nextElement methods: one with a String return and one with an Object return. Issue number 1 is that JRuby does not consider these to be overloads, and so it would randomly pick one or the other depending on what order they were retrieved via Java reflection. That was the cause of the variability. JRuby converts return arguments using a cached "converter" that it validates is still correct by confirming the object type being returned matches the expected object type. If a method returns String, we will use the cached String converter if the returned object is also a String. We also had code in place that attempted to find a "more public" version of methods defined on non-public classes by searching the public classes and interfaces above it. In the case of NamesEnumerator, which is package-private, whenever the String-returning method was encountered first we would proceed to search for the Object version even though both were public methods. But upon finding the Object version, we did not save it. Instead, we only captured the converter based on an Object return type and still dispatched using the String version. So basically, we were calling the String version of the method but using the Object converter to convert the result, which is why it wrapped rather than converted. I removed the public method search, since it wasn't actually accomplishing anything. Both of the public methods in question should dispatch ok without it, and this should avoid the broken hybrid of String method with Object converter.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Peter K Chan
          • Votes:
            1 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: