This project is archived and is in readonly mode.

#2873 ✓resolved
Hongli Lai

Application reloading should be deferred to end of request, currently interferes with 'render :text => lambda { ... }' streaming

Reported by Hongli Lai | July 6th, 2009 @ 01:19 PM | in 2.3.10

Consider the following:

render :text => lambda { |response, output|

User.each do |user|
  output.write("#{user.username}\n")
end

}

This doesn't work correctly in development mode because AC::Reloader cleans up the application code in an ensure block. However, the lambda passed to 'render :text' is evaluated outside AC::Dispatcher#call, so by the time the lambda is called, the User class has already been cleaned up, resulting in all kinds of "interesting" behavior.

The attached patch for Rails 2.3 defers reloading to the very end of the request, when #close is called on the Rack response body. This makes my above example work correctly.

Comments and changes to this ticket

  • Jeremy Kemper

    Jeremy Kemper July 7th, 2009 @ 08:32 PM

    • Milestone changed from 2.x to 2.3.4
    • State changed from “new” to “open”

    Nice. Do you have a diff against master as well?

  • Hongli Lai

    Hongli Lai July 7th, 2009 @ 08:39 PM

    No I don't. The code reloader on master is significantly different so it's not just a simple port.

  • Yehuda Katz (wycats)

    Yehuda Katz (wycats) July 8th, 2009 @ 12:00 AM

    • State changed from “open” to “incomplete”
    • Assigned user set to “Yehuda Katz (wycats)”

    Hongli -- How hard would it be to make the patch work on master. It would seem weird to have a fix on 2.3 but leave master broken.

  • Yehuda Katz (wycats)

    Yehuda Katz (wycats) July 9th, 2009 @ 12:19 AM

    • State changed from “incomplete” to “resolved”

    Was closed by bc2c4a45959be21e6314fba7876b32c1f04cd08a

  • Yehuda Katz (wycats)

    Yehuda Katz (wycats) July 9th, 2009 @ 12:23 AM

    • Milestone cleared.
    • State changed from “resolved” to “incomplete”
    • Tag changed from 2-3-stable, actionpack, patch to actionpack, patch

    Sorry. This was resolved in 2-3-stable but is still incomplete on edge. Reopening in 3.0 and marking as incomplete.

  • Hongli Lai

    Hongli Lai July 9th, 2009 @ 09:59 AM

    I'll have a look at it for master.

  • Michael Koziarski

    Michael Koziarski July 31st, 2009 @ 07:16 AM

    • Assigned user changed from “Yehuda Katz (wycats)” to “Michael Koziarski”
    • State changed from “incomplete” to “open”
    • Milestone set to 2.3.4

    Pulling this back to 2.3 until we tidy up the error reports in #2948

  • Michael Koziarski

    Michael Koziarski July 31st, 2009 @ 07:20 AM

    So the problem with this change is that reloading is no longer deterministic.

    The next request into the system can therefore be half-way through being processed while the original request is busily removing constants.

    Unless someone can figure out a nice fix, I'll have no choice but to revert it.

  • Hongli Lai

    Hongli Lai July 31st, 2009 @ 02:08 PM

    I've seen this in Mongrel but not in Phusion Passenger. I thought it was a fluke but apparently not.

    I think it's related to locking. The Rails lock should be released after #close on the body is called, not right before the Rack app object's call method returns.

  • Hongli Lai
  • Michael Koziarski

    Michael Koziarski July 31st, 2009 @ 11:37 PM

    Is the reloader middleware skipped in production (cache_classes=true)?
    Otherwise we're just reintroducing the global lock we so painstakingly removed ;)

  • Hongli Lai

    Hongli Lai August 1st, 2009 @ 11:54 AM

    Yes it is. The reloader is only inserted into the middleware stack when cache_classes = false:

    unless cache_classes
      unless self.middleware.include?(Reloader)
        self.middleware.insert_after(Failsafe, Reloader)
      end
      ...
    
  • Jeremy Kemper

    Jeremy Kemper August 1st, 2009 @ 09:45 PM

    • State changed from “open” to “incomplete”
  • Brian Durand

    Brian Durand August 10th, 2009 @ 06:54 PM

    I've applied this patch locally, and now I have a problem with the lock not being released. In my case, I posted an invalid XML document to an action which caused the parameter parsing to fail and the Rails failsafe error handling to kick in.

    The problem looks to be that the order of operations is:

    1. obtain the lock
    2. call the next handler
    3. return the status, headers, and BodyWrapper
    4. on close of the BodyWrapper, release the lock

    In the case of an exception occurring during step 2, the BodyWrapper is never created and so close will never be called and the lock will never be released.

    Adding this code to the bottom of the call method in the patch fixes the issue so that if the failsafe error handling kicks in so will releasing the lock:

        rescue Exception => e
          @lock.unlock
          raise e
    
  • Hongli Lai

    Hongli Lai August 10th, 2009 @ 08:49 PM

    Good call. Here's a patch which fixes this problem and also happens to fix a unit test that I didn't write correctly last time.

    Amazing how so many things can go wrong in so few lines of code. :)

  • Jeremy Kemper

    Jeremy Kemper August 10th, 2009 @ 10:16 PM

    • Assigned user changed from “Michael Koziarski” to “Yehuda Katz (wycats)”

    Thanks for the update Hongli.

    Yehuda, could you look at getting master on par with this change? Otherwise I'll revert before 2.3.4 release.

  • Repository

    Repository August 10th, 2009 @ 10:19 PM

    (from [a91969803e96b4f66cebd65ac67c8cdc4ca4fcef]) Correctly unlock the reloader lock if the underlying app raises an exception.

    [#2873 state:incomplete]

    Signed-off-by: Jeremy Kemper jeremy@bitsweat.net
    http://github.com/rails/rails/commit/a91969803e96b4f66cebd65ac67c8c...

  • Stephen Bannasch

    Stephen Bannasch August 11th, 2009 @ 01:35 AM

    I've pulled the latest 2-3-stable, a91969803e96b4f66cebd65ac67c8cdc4ca4fcef

    I have an external app that sends two POSTS in quick succession, that are intercepted by two different metal endpoints.

    I'm still getting the error that my metal class: "has been removed from the module tree but is still active".

    This only happens in dev mode. The problem does not happen when running in production.

    Was this behavior intended to be fixed by Hongli's latest patch?

    Partial stack trace:

    A copy of ConsoleContent has been removed from the module tree but is still active!
      ... /vendor/rails/activesupport/lib/active_support/dependencies.rb:414:in `load_missing_constant'
      ... /vendor/rails/activesupport/lib/active_support/dependencies.rb:96:in `const_missing'
      ... /app/metal/console_content.rb:13:in `call'
      ... /vendor/rails/railties/lib/rails/rack/metal.rb:44:in `call'
      ... /vendor/rails/railties/lib/rails/rack/metal.rb:43:in `each'
      ... /vendor/rails/railties/lib/rails/rack/metal.rb:43:in `call'
      ... /lib/rack/expand_b64_gzip.rb:36:in `call'
      ... /vendor/rails/actionpack/lib/action_controller/session/abstract_store.rb:122:in `call'
      ... /vendor/rails/activerecord/lib/active_record/query_cache.rb:29:in `call'
      ... /vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:34:in `cache'
      ... /vendor/rails/activerecord/lib/active_record/query_cache.rb:9:in `cache'
      ... /vendor/rails/activerecord/lib/active_record/query_cache.rb:28:in `call'
      ... /vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
      ... /vendor/rails/actionpack/lib/action_controller/reloader.rb:38:in `call'
      ... /vendor/rails/actionpack/lib/action_controller/failsafe.rb:26:in `call'
      ... /vendor/gems/rack-1.0.0/lib/rack/lock.rb:11:in `call'
      ... /vendor/gems/rack-1.0.0/lib/rack/lock.rb:11:in `synchronize'
      ... /vendor/gems/rack-1.0.0/lib/rack/lock.rb:11:in `call'
    
  • Stephen Bannasch
  • Stephen Bannasch

    Stephen Bannasch August 11th, 2009 @ 07:10 AM

    I was able to fix the problem:

    ... has been removed from the module tree but is still active!
    

    In both 2-3-3 and 2-3-stable by forcing references to ActiveRecord models in my metal classes to start with '::'.

    See:
    http://github.com/stepheneb/rigse/commit/ce57fbaacf1b1d97c25860a07e...

    Flip Sasser suggested this fixe in a comment here:
    https://rails.lighthouseapp.com/projects/8994-ruby-on-rails/tickets...

  • Hongli Lai

    Hongli Lai August 11th, 2009 @ 10:44 AM

    @Stephen: yes it's supposed to be fixed. You shouldn't had to make those changes in your code.

    I'm unable to reproduce the problem using Flip Sasser's test case. Are you?

  • Hongli Lai

    Hongli Lai August 11th, 2009 @ 11:03 AM

    It seems I spoke too soon. With some changes I was able to reproduce the problem with both 2.3.3 and 2-3-stable. Investigating this...

  • Hongli Lai

    Hongli Lai August 11th, 2009 @ 11:31 AM

    It looks like the problem isn't related to the Reloader but to something else. A test case can be created as follows:

    rails reloadtest  (using Rails 2.3.3's 'rails' command)
    cd reloadtest
    ln -s /path-to-rails-2-3-git vendor/rails
    ./script/generate metal test
    ./script/generate model user
    ./script/generate controller streaming
    rake db:migrate
    

    Edit app/metal/test.rb:

    # Allow the metal piece to run in isolation
    require(File.dirname(__FILE__) + "/../../config/environment") unless defined?(Rails)
    
    class Test
      def self.call(env)
        if env["PATH_INFO"] =~ /^\/test/
          [200, {"Content-Type" => "text/html"}, [User.inspect]]
        else
          [404, {"Content-Type" => "text/html"}, ["Not Found"]]
        end
      end
    end
    

    Edit app/controllers/streaming.rb:

    class StreamingController < ApplicationController
      def index
        render :text => lambda { |response, output| output.write(User.inspect) }
      end
    end
    

    Start the server under Mongrel:

    ./script/server mongrel
    

    Use curl to access the metal twice. Upon the second access, it will raise an error:

    curl http://127.0.0.1:3000/test     # works
    curl http://127.0.0.1:3000/test     # error
    

    Interestingly, accessing the streaming controller works fine:

    curl http://127.0.0.1:3000/streaming   # works
    curl http://127.0.0.1:3000/streaming   # still works
    

    This problem is reproducible as well on master, even though master doesn't contain my Reloader changes. This all makes me suspect that the problem is in the metal code.

    A git bisect on the 2-3-stable branch says that 49169f7a6ab2699c500032e6e14570512c674274 is the cause of the problem.

  • Hongli Lai

    Hongli Lai August 11th, 2009 @ 12:42 PM

    After several hours of debugging I managed to find the cause of the problem. The Dispatcher was holding references to old metal objects. So even though we reload the classes after every request, at the next request the Dispatcher will access the metal objects that were created before the classes were reloaded.

    This patch fixes the problem for 2-3-stable. I'm not very familiar with master's code so I don't have a patch for that yet.

  • Hongli Lai

    Hongli Lai August 11th, 2009 @ 01:42 PM

    It looks like my previous patch was inadequate. Accessing a metal piece in development mode under high concurrency still fails with reload errors. The problem is that the middleware stack is built outside the Reloader lock, so metal pieces are being concurrently reloaded.

    This patch makes sure that the lock is obtained before middleware stack building. Is is to be applied without my previous patch.

  • Kenneth Kalmer

    Kenneth Kalmer August 12th, 2009 @ 11:23 PM

    Applied the latest patch from Hongli to 2-3-stable (6f5d1f31) and could ran a short ab test on a metal app (ab2 -c 10 -n 100 http://localhost:3000/metal) without any traces of the reloading problems.

  • Jeremy Kemper

    Jeremy Kemper August 15th, 2009 @ 07:49 PM

    Getting test failures with the latest patch, Hongli:

     77) Error:
    test_parses_single_file(XmlParamsParsingTest):
    ThreadError: stopping only thread
    
    
    note: use sleep to stop forever
    ./test/../lib/action_controller/reloader.rb:31:in `lock'
    ./test/../lib/action_controller/reloader.rb:31:in `run'
    ./test/../lib/action_controller/dispatcher.rb:108:in `call'
    /usr/local/ruby/1.8.6-ree/lib/ruby/gems/1.8/gems/rack-1.0.0/lib/rack/lint.rb:47:in `_call'
    /usr/local/ruby/1.8.6-ree/lib/ruby/gems/1.8/gems/rack-1.0.0/lib/rack/lint.rb:35:in `call'
    ./test/../lib/action_controller/integration.rb:313:in `process'
    ./test/../lib/action_controller/integration.rb:202:in `post'
    ./test/../lib/action_controller/integration.rb:491:in `__send__'
    ./test/../lib/action_controller/integration.rb:491:in `post'
    ./test/controller/request/xml_params_parsing_test.rb:31:in `test_parses_single_file'
    ./test/controller/request/xml_params_parsing_test.rb:74:in `with_test_routing'
    ./test/../lib/action_controller/test_process.rb:552:in `with_routing'
    ./test/../lib/action_controller/integration.rb:546:in `__send__'
    ./test/../lib/action_controller/integration.rb:546:in `method_missing'
    ./test/controller/request/xml_params_parsing_test.rb:70:in `with_test_routing'
    ./test/controller/request/xml_params_parsing_test.rb:29:in `test_parses_single_file'
    ./test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `__send__'
    ./test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `run'
    ./test/../lib/action_controller/integration.rb:645:in `run'
    
    
    
    
  • Hongli Lai

    Hongli Lai August 15th, 2009 @ 08:35 PM

    My last patch broke some unit tests. This fixes it.

  • Repository

    Repository August 16th, 2009 @ 02:01 AM

    • State changed from “incomplete” to “committed”

    (from [14b6ab0f013f01541fca9fd42b33da96313e0a2e]) Fix reloading of metal pieces. - Do not hold references to old metal objects after metal classes have been reloaded. - Obtain the reloader lock before building the middleware stack, so that reloading of metal pieces works in the face of multithreading.

    [#2873 state:committed]

    Signed-off-by: Jeremy Kemper jeremy@bitsweat.net
    http://github.com/rails/rails/commit/14b6ab0f013f01541fca9fd42b33da...

  • Jeremy Kemper

    Jeremy Kemper August 16th, 2009 @ 02:01 AM

    Applied with small Ruby 1.9 compatibility fix.

  • Hongli Lai

    Hongli Lai August 16th, 2009 @ 08:05 AM

    Ticket state should be 'incomplete'. Needs to be ported to master.

  • Jeremy Kemper

    Jeremy Kemper August 16th, 2009 @ 08:08 AM

    • State changed from “committed” to “incomplete”
  • Alistair Holt

    Alistair Holt August 16th, 2009 @ 03:37 PM

    I just came across this same issue. Any idea when this will make it into master?

  • Hongli Lai

    Hongli Lai August 21st, 2009 @ 08:41 PM

    Here's a preview patch which shows how it's done in master. I don't have any unit tests yet.

  • Jeremy Kemper

    Jeremy Kemper September 11th, 2009 @ 11:04 PM

    • Milestone changed from 2.3.4 to 2.3.6

    [milestone:id#50064 bulk edit command]

  • jrochkind

    jrochkind September 29th, 2009 @ 08:09 PM

    ( Just mentioning that I've run into this problem too, and would be quite pleased if you managed to fix it!)

  • Richard Fairhurst

    Richard Fairhurst October 19th, 2009 @ 07:38 PM

    Another voice to say I'd be really pleased if this was fixed - it'll let us stream output to the browser at openstreetmap.org. It appears to have been reported earlier in #2546 .

  • Jeremy Kemper

    Jeremy Kemper April 30th, 2010 @ 02:34 AM

    This will block 2.3.6 release until it's ported to and tested on master.

  • Rizwan Reza

    Rizwan Reza May 16th, 2010 @ 02:41 AM

    • Tag changed from actionpack, patch to actionpack, bugmash, patch
  • Jeremy Kemper

    Jeremy Kemper May 23rd, 2010 @ 05:54 PM

    • Milestone changed from 2.3.6 to 2.3.7
  • Jeremy Kemper

    Jeremy Kemper May 24th, 2010 @ 09:40 AM

    • Milestone changed from 2.3.7 to 2.3.8
  • Jeremy Kemper

    Jeremy Kemper May 25th, 2010 @ 11:45 PM

    • Milestone changed from 2.3.8 to 2.3.9
  • Jeremy Kemper

    Jeremy Kemper August 30th, 2010 @ 02:28 AM

    • Milestone changed from 2.3.9 to 2.3.10
    • Importance changed from “” to “High”
  • John Firebaugh

    John Firebaugh November 21st, 2010 @ 09:25 PM

    I've been investigating this and wanted to give a status update.

    Hongli's patch was applied to the 2.3 branch and (AFAICT) not reverted; it was included in 2.3.6 and later. However, the problem still exists in 3.0 stable and master, where the relevant code has changed extensively since Hongli posted his preview patch. Reloading is now done via the ActionDispatch::Callbacks middleware's after callbacks: one for ActiveSupport::DescendantsTracker.clear and ActiveSupport::Dependencies.clear (via the :set_clear_dependencies_hook initializer) and one for ActiveRecord::Base.clear_reloadable_connections! (via the active_record.set_dispatch_hooks initializer). I presume that the fix on master should delay both of those until after #close on the response body, since a streaming response might make use of either reloadable classes or connections.

    I'm not sure about the status of the second part of Hongli's patch, dealing with references to old metal classes in the middleware stack. Is it still a problem on master?

    I can think of several approaches to fixing the class reloading issue on master:

    • Delay all ActionDispatch after callbacks until after #close is called on the response body. This would be a change in behavior, though perhaps a desired one -- all uses of after callbacks in Rails itself would benefit from the change. There could be uses in third-party code that depend on the callback happening earlier however.
    • Introduce a new callback (after_close) with the desired semantics, and convert the set_clear_dependencies_hook and active_record.set_dispatch_hooks initializers to use it instead.

    Both of these would be complicated by the need (in the !config.cache_classes case) to lock a mutex before the dispatch and unlock it after reloading is complete (and on the appropriate error paths). It's not clear to me that this can be accomplished cleanly within the callback mechanism. Hence a third approach:

    • Introduce a new middleware, ActionDispatch::Reloader, included in the stack only in the !config.cache_classes case, which provides an appropriate callback hook and is responsible for lock management.
  • John Firebaugh

    John Firebaugh November 24th, 2010 @ 04:19 AM

    I'm thinking the lock synchronization should be handled by Rack::Lock, which is included in the stack unless config.allow_concurrency. Unfortunately, it unlocks as call exits, rather than on the body's #close, as required if the body's #each generates data dynamically. I filed a rack bug for that.

  • John Firebaugh

    John Firebaugh November 24th, 2010 @ 04:26 AM

    Here's my current patch:

    https://github.com/bigfix/rails/tree/2873

    It causes several failures in the railties isolation tests that I'm not sure how to fix. Some of the failures are caused by failing to close the response body and thus leaving the lock locked, and there also seems to be some problem with calling respond_to? with a second include_private parameter.

  • John Firebaugh

    John Firebaugh November 24th, 2010 @ 04:32 AM

    BTW, I've been assuming there's some reason that reloading happens after each request, rather than via ActionDispatch::Callbacks.to_prepare (i.e. before each request). Anyone know what it is? Performance?

  • John Firebaugh
  • Repository

    Repository December 20th, 2010 @ 11:44 AM

    (from [0f7c970e4f1cf0f3bcc01c22a6a3038cb3e34668]) Introduce ActionDispatch::Reloader

    Based on the implementation on the 2-3-stable branch, patches by Hongli
    Lai hongli@phusion.nl, and helpful suggestions from José Valim.

    Hongli Lai's patches included locking around the request cycle; this is
    now handled by Rack::Lock (https://github.com/rack/rack/issues/issue/87/).

    [#2873]

    Signed-off-by: José Valim jose.valim@gmail.com
    https://github.com/rails/rails/commit/0f7c970e4f1cf0f3bcc01c22a6a30...

  • Repository

    Repository December 20th, 2010 @ 11:44 AM

    • State changed from “incomplete” to “resolved”

    (from [e683ab7c390f26e110387822c7ffb5ac6aafebca]) Use AD::Reloader.to_cleanup for reloading [#2873 state:resolved]

    Signed-off-by: José Valim jose.valim@gmail.com
    https://github.com/rails/rails/commit/e683ab7c390f26e110387822c7ffb...

  • Sam Ruby

    Sam Ruby December 23rd, 2010 @ 02:33 PM

    This commit causes the following failure:

    http://intertwingly.net/projects/AWDwR4/checkdepot-192/section-10.2...

    Reverting this commit causes the test to pass again.

  • John Firebaugh

    John Firebaugh December 23rd, 2010 @ 04:47 PM

    Reloading is no longer happening after a request that raises an exception. I'll have a patch shortly.

  • John Firebaugh
  • Sam Ruby

    Sam Ruby December 24th, 2010 @ 12:34 AM

    John: yes it does! Thanks!

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

<h2 style="font-size: 14px">Tickets have moved to Github</h2>

The new ticket tracker is available at <a href="https://github.com/rails/rails/issues">https://github.com/rails/rails/issues</a>