JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-5179

Tomcat processes JRuby on Rails request before environment.rb is parsed

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major Major
    • Resolution: Incomplete
    • Affects Version/s: JRuby 1.5.2
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:
      SunOS ri-dev1 5.10 Generic_127112-08 i86pc i386 i86pc
      Apache Tomcat Version 5.5.26
      JRuby 1.5.2
      Ruby on Rails 2.3.8
    • Number of attachments :
      0

      Description

      There is an edge case in our implementation of JRuby on Rails where Tomcat allows processing requests to the application framework before environment.rb is done parsing. I cannot verify for sure this is the case, however in our environment.rb where this bug is reproduced consistently, we explicitly require active_support. If Tomcat is stopped and restarted, we can call a service that invokes ActiveSupport::TimeZone.all and that will come back nil. We noticed this as an exception was being thrown and we collected the following backtrace in our logs:

      === begin backtrace ===
      -------------------------------
      Backtrace:
      -------------------------------

      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/values/time_zone.rb:206:in `<=>'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/values/time_zone.rb:318:in `sort'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/values/time_zone.rb:318:in `all'
      [RAILS_ROOT]/app/controllers/geographies_controller.rb:16:in `timezones'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/base.rb:1331:in `perform_action'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:617:in `call_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:638:in `run_before_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:206:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:206:in `around_proc'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/callbacks.rb:182:in `call'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/callbacks.rb:182:in `evaluate_method'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:184:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:635:in `run_before_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:615:in `call_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:610:in `perform_action_with_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/benchmarking.rb:68:in `perform_action_with_benchmark'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/core_ext/benchmark.rb:17:in `ms'
      file:/reuters/coolstack/tomcat5/webapps/insider/WEB-INF/lib/jruby-complete-1.5.2.jar!/META-INF/jruby.home/lib/ruby/1.8/benchmark.rb:308:in `realtime'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/core_ext/benchmark.rb:17:in `ms'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/benchmarking.rb:68:in `perform_action_with_benchmark'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/rescue.rb:160:in `perform_action_with_rescue'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/flash.rb:151:in `perform_action_with_flash'
      [RAILS_ROOT]/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:255:in `perform_action_with_newrelic_trace'
      [RAILS_ROOT]/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:141:in `trace_execution_scoped'
      [RAILS_ROOT]/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:248:in `perform_action_with_newrelic_trace'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/base.rb:532:in `process'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/filters.rb:606:in `process_with_filters'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/base.rb:391:in `process'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/base.rb:386:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/routing/route_set.rb:438:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:87:in `dispatch'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:121:in `_call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:130:in `build_middleware_stack'
      [RAILS_ROOT]/app/middleware/flash_session_cookie_middleware.rb:29:in `call'
      [RAILS_ROOT]/app/middleware/flash_session_cookie_middleware.rb:29:in `call'
      [RAILS_ROOT]/app/middleware/set_cookie_domain.rb:16:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/string_coercion.rb:25:in `call'
      [RAILS_ROOT]/gems/gems/rack-1.1.0/lib/rack/head.rb:9:in `call'
      [RAILS_ROOT]/lib/rack_method_override_patch.rb:24:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/params_parser.rb:15:in `call'
      [RAILS_ROOT]/gems/gems/rails-2.3.8/lib/rails/rack/metal.rb:47:in `call'
      [RAILS_ROOT]/app/middleware/set_cookie_domain.rb:16:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/session/abstract_store.rb:128:in `call'
      [RAILS_ROOT]/app/middleware/flash_session_cookie_middleware.rb:29:in `call'
      [RAILS_ROOT]/gems/gems/activerecord-2.3.8/lib/active_record/query_cache.rb:29:in `call'
      [RAILS_ROOT]/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/query_cache.rb:34:in `cache'
      [RAILS_ROOT]/gems/gems/activerecord-2.3.8/lib/active_record/query_cache.rb:9:in `cache'
      [RAILS_ROOT]/gems/gems/activerecord-2.3.8/lib/active_record/query_cache.rb:28:in `call'
      [RAILS_ROOT]/gems/gems/activerecord-2.3.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
      [RAILS_ROOT]/gems/gems/activesupport-2.3.8/lib/active_support/cache/strategy/local_cache.rb:36:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/failsafe.rb:26:in `call'
      [RAILS_ROOT]/gems/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:106:in `call'
      file:/reuters/coolstack/tomcat5/webapps/insider/WEB-INF/lib/jruby-rack-0.9.5.jar!/rack/adapter/rails.rb:35:in `serve_rails'
      file:/reuters/coolstack/tomcat5/webapps/insider/WEB-INF/lib/jruby-rack-0.9.5.jar!/rack/adapter/rails.rb:40:in `call'
      file:/reuters/coolstack/tomcat5/webapps/insider/WEB-INF/lib/jruby-rack-0.9.5.jar!/jruby/rack/rails.rb:148:in `call'
      file:/reuters/coolstack/tomcat5/webapps/insider/WEB-INF/lib/jruby-rack-0.9.5.jar!/rack/handler/servlet.rb:18:in `call'
      :1
      === end backtrace ===

      If you make subsequent requests, the invocation to the web service works fine, because one can assume at that point ActiveSupport was loaded into memory and can be accessed. The exception never gets thrown again, only reproduced when we restart Tomcat.

      some more relevant information from newrelic:

      • action_controller.request.path_parameters : controllergeographiesactiontimezonesformatxml
      • action_controller.request.query_parameters :
      • action_controller.request.request_parameters:
      • action_controller.rescue.request : #<ActionController::Request:0x384af712>
      • action_controller.rescue.response : #<ActionController::Response:0x41a2db9d>
      • java.servlet_context : org.jruby.rack.servlet.ServletRackContext@5492de02
      • java.servlet_request : org.apache.catalina.connector.RequestFacade@145c38c1
      • jruby.rack.dynamic.requests.only : true
      • jruby.rack.jruby.version : 1.5.2
      • jruby.rack.rack.release : 1.1
      • jruby.rack.version : 0.9.5
      • rack.errors : #<JRuby::Rack::ServletLog:0x2b004215>
      • rack.input : #<JRuby::RackRewindableInput:0x1df286c1>
      • rack.multiprocess : false
      • rack.multithread : true
      • rack.request.query_hash :
      • rack.request.query_string :
      • rack.run_once : false
      • rack.session.record : #<ActiveRecord::SessionStore::Session:0x13b2558e>
      • rack.url_scheme : http
      • rack.version : 11

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        Hmmm. Are you able to consistently cause this to happen, or is it intermittent?

        Show
        Charles Oliver Nutter added a comment - Hmmm. Are you able to consistently cause this to happen, or is it intermittent?
        Hide
        Charles Oliver Nutter added a comment -

        Old bug, no follow-up, and should be filed with jruby-rack anyway.

        Show
        Charles Oliver Nutter added a comment - Old bug, no follow-up, and should be filed with jruby-rack anyway.
        Charles Oliver Nutter made changes -
        Field Original Value New Value
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Thomas E Enebo [ enebo ] Charles Oliver Nutter [ headius ]
        Resolution Incomplete [ 4 ]

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Steve Finkelstein
          • Votes:
            1 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: