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

Issue with rails 2.3.14 #82

Closed
leenasn opened this issue Jan 9, 2012 · 10 comments
Closed

Issue with rails 2.3.14 #82

leenasn opened this issue Jan 9, 2012 · 10 comments
Milestone

Comments

@leenasn
Copy link

leenasn commented Jan 9, 2012

I am getting the following error when I run the app with latest trinidad server.

undefined method 'raw_post' for nil:NilClass org/jruby/RubyKernel.java:238:in 'method_missing' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/activesupport-2.3.14/lib/active_support/whiny_nil.rb:52:in 'method_missing' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/params_parser.rb:50:in 'parse_formatted_parameters' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/params_parser.rb:11:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:99:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/failsafe.rb:26:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/rack-1.1.3/lib/rack/lock.rb:11:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/rack-1.1.3/lib/rack/lock.rb:11:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/dispatcher.rb:114:in 'call' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/reloader.rb:34:in 'run' /mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/actionpack-2.3.14/lib/action_controller/dispatcher.rb:108:in 'call' file:/mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/jruby-rack-1.1.2/lib/jruby-rack- 1.1.2.jar!/rack/adapter/rails.rb:36:in 'serve_rails' file:/mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/jruby-rack-1.1.2/lib/jruby-rack-1.1.2.jar!/rack/adapter/rails.rb:52:in 'call' file:/mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/jruby-rack-1.1.2/lib/jruby-rack-1.1.2.jar!/jruby/rack/rails.rb:186:in 'call' file:/mnt/cc/installables/jruby-1.6.5.1/lib/ruby/gems/1.8/gems/jruby-rack-1.1.2/lib/jruby-rack-1.1.2.jar!/rack/handler/servlet.rb:20:in 'call'

And as a fix I downgraded the jruby-rack version to 1.0.10 and now it works fine. Any patch to make it work with rails 2.3?

@kares
Copy link
Member

kares commented Jan 9, 2012

hey @leenasn, thanks for reporting.

unfortunately, this issue seems a bit weird and I'm somehow unable to reproduce it on a simple 2.3.14 app.
there seems to be a parsing error that we do not see cause it attempts to log the request (and fails) :
https://github.com/rails/rails/blob/2-3-stable/actionpack/lib/action_controller/params_parser.rb#L50
the request obviously should not have been nil there ... could you maybe investigate this further:
printing the backtrace that is rescued or providing more details about the request that caused this ?

most likely it's going to be something about Request.new(env) from the start of the method.

I have tried reproducing on https://github.com/jruby/jruby-rack/tree/master/examples/rails
while upgrading it to RAILS_GEM_VERSION = '2.3.14' with the following local gems :

*** LOCAL GEMS ***

actionmailer (2.3.14)
actionpack (2.3.14)
activerecord (2.3.14)
activeresource (2.3.14)
activesupport (2.3.14)
bouncy-castle-java (1.5.0146.1)
bundler (1.0.21)
jruby-openssl (0.7.4)
jruby-rack (1.1.2)
json (1.6.1 java)
rack (1.1.3)
rails (2.3.14)
rake (0.9.2.2)
rdoc (3.11)
trinidad (1.3.1)
trinidad_jars (1.0.2)

@leenasn
Copy link
Author

leenasn commented Jan 14, 2012

Sorry for being late in my reply. I was getting this for the first request that hits the server. I am using bundler for my app thats the difference I could see between the rails example and my app. Not sure whether that will make any difference.

@kares
Copy link
Member

kares commented Jan 14, 2012

I think bundler does not matter, to fix this we need to be able to reproduce it.

Either you provide us with a minimal rails/sinatra app where this does happen or we need more input from you as I already mentioned in the previous comment - try to monkey patch the ParamsParser to print out the error with the backtrace before attempting to log the request.raw_post for starters.

@ghost
Copy link

ghost commented Jan 22, 2012

I ran into this issue with a warbled redmine (1.3-stable, requires rails 2.3.14) and jruby 1.6.5.1. I wasn't able to use a warbled war in tomcat 6.0.33 until reverting jruby-rack from 1.1.x to 1.0.10 and re-warbling. I'm not much of a ruby coder so I can't help with a minimal example.

@kares
Copy link
Member

kares commented Jan 22, 2012

could someone please print that exception from the rescue block - would most probably be a time saver for us trying to reproduce. here's what I'm talking about - notice the added puts statements before logging request.raw_post - apply this monkey patch and when the error happens paste here what has been printed out :

require 'action_controller/params_parser'

module ActionController
  class ParamsParser

    def parse_formatted_parameters(env)
      request = Request.new(env)

      return false if request.content_length.zero?

      mime_type = content_type_from_legacy_post_data_format_header(env) || request.content_type
      strategy = ActionController::Base.param_parsers[mime_type]

      return false unless strategy

      case strategy
        when Proc
          strategy.call(request.raw_post)
        when :xml_simple, :xml_node
          body = request.raw_post
          body.blank? ? {} : Hash.from_xml(body).with_indifferent_access
        when :yaml
          YAML.load(request.raw_post)
        when :json
          body = request.raw_post
          if body.blank?
            {}
          else
            data = ActiveSupport::JSON.decode(body)
            data = {:_json => data} unless data.is_a?(Hash)
            data.with_indifferent_access
          end
        else
          false
      end
    rescue Exception => e # YAML, XML or Ruby code block errors

      puts "parse_formatted_parameters(env) #{env.inspect}"
      puts "exception: #{e.message} (#{e.class})"
      e.backtrace.each { |t| puts t }

      logger.debug "Error occurred while parsing request parameters.\nContents:\n\n#{request.raw_post}"

      raise
        { "body" => request.raw_post,
          "content_type" => request.content_type,
          "content_length" => request.content_length,
          "exception" => "#{e.message} (#{e.class})",
          "backtrace" => e.backtrace }
    end

  end
end

@ghost
Copy link

ghost commented Jan 24, 2012

placed above patch in config/initializers/mp.rb, re-warbled and started application.

Pull following data from logs:

INFO: /!\ FAILSAFE /!\  Tue Jan 24 15:08:10 -0600 2012
Status: 500 Internal Server Error
wrong number of arguments (1 for 0)
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:157:in `unpacked_cookie_data'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:258:in `stale_session_check!'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:156:in `unpacked_cookie_data'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:138:in `extract_session_id'
org/jruby/RubyKernel.java:2097:in `send'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:36:in `load_session_id!'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:24:in `[]'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:147:in `current_session_id'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:151:in `exists?'
org/jruby/RubyKernel.java:2097:in `send'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:107:in `exists?'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:124:in `load_for_read!'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/abstract_store.rb:101:in `inspect'
org/jruby/RubyHash.java:745:in `inspect'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/config/initializers/mp.rb:38:in `parse_formatted_parameters'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/params_parser.rb:11:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:99:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/failsafe.rb:26:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/vendor/rack-1.3.6/rack/lock.rb:15:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/dispatcher.rb:106:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/adapter/rails.rb:36:in `serve_rails'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/adapter/rails.rb:41:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/jruby/rack/rails.rb:186:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/handler/servlet.rb:20:in `call'

@kares
Copy link
Member

kares commented Jan 25, 2012

@tkunicki thanks a lot, appreciate it

unfortunately, seems I expected too much to inspect the request environment on line 38 :
puts "parse_formatted_parameters(env) #{env.inspect}"

could you maybe run it once more with line 38 commented - I was really hoping to reach the following lines where e gets printed ... it might be the very same issue, but just to make sure we're going the right direction, thanks in advance

it seems that Rack::Request.new(env) is failing after all with an ArgumentError - probably cause it does no get loaded.
this has been fixed on master 1cca795 until 1.1.4 is released - as a work around an explicit require 'rack/request' in an initializer might fix this issue ...

@ghost
Copy link

ghost commented Jan 29, 2012

@kares

Here is the log entry with line 38 commented out:

exception: wrong number of arguments (1 for 0) (ArgumentError)
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/config/initializers/mp.rb:7:in `parse_formatted_parameters'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/params_parser.rb:11:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/session/cookie_store.rb:99:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/failsafe.rb:26:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/vendor/rack-1.3.6/rack/lock.rb:15:in `call'
/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/gems/gems/actionpack-2.3.14/lib/action_controller/dispatcher.rb:106:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/adapter/rails.rb:36:in `serve_rails'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/adapter/rails.rb:41:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/jruby/rack/rails.rb:186:in `call'
file:/c/home/tom/apache-tomcat-6.0.33/webapps/mp/WEB-INF/lib/jruby-rack-1.1.3.jar!/rack/handler/servlet.rb:20:in `call'

@kares
Copy link
Member

kares commented Jan 30, 2012

confirming this is definitely an incorrectly loaded rack issue attempted to be fixed with 1cca795
there's still some issues with the current master solution on some containers but Tomcat should be fine.
I'll make sure I add a spec for this, expect this to be fixed in 1.1.4, thank you for reporting and cooperating.

@kares kares closed this as completed Jan 30, 2012
@johndouthat
Copy link

I ran into this issue too and I've confirmed that the latest version of jruby-rack in git fixes the problem. Thanks! Here's an example for anyone else that runs into this issue https://github.com/johndouthat/jruby-rack-issue-82

@kares kares modified the milestones: Release 1.1.4, 1.1.4 Aug 22, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants