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

Type	To find
responsible:me	tickets assigned to you
tagged:"@high"	tickets tagged @high
milestone:next	tickets in the upcoming milestone
state:invalid	tickets with the state invalid
created:"last week"	tickets created last week
sort:number, importance, updated	tickets sorted by #, importance or updated
Combine keywords for powerful searching.
Use advanced searching »

This project is archived and is in readonly mode.

#2873 ✓resolved

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.

0001-Cleanup-application-after-close-has-been-called-on.patch 5.3 KB

Comments and changes to this ticket

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?
You flagged this item as spam.
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) 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) July 9th, 2009 @ 12:19 AM
- State changed from “incomplete” to “resolved”
Was closed by bc2c4a45959be21e6314fba7876b32c1f04cd08a
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.
You flagged this item as spam.
Hongli Lai July 9th, 2009 @ 09:59 AM
I'll have a look at it for master.
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 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.
You flagged this item as spam.
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.
You flagged this item as spam.
Hongli Lai July 31st, 2009 @ 02:36 PM
This patch fixes the issue.
- 0001-Make-the-new-code-reloading-behavior-work-with-multi.patch 3.6 KB
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 ;)
You flagged this item as spam.
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 August 1st, 2009 @ 09:45 PM
- State changed from “open” to “incomplete”
applied to 2-3-stable: http://github.com/rails/rails/commit/d37ac7958fc88fdbf37a8948102f6b...
You flagged this item as spam.
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
```
You flagged this item as spam.
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. :)
- 0001-Correctly-unlock-the-reloader-lock-if-the-underlying.patch 3.5 KB
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 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 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'

You flagged this item as spam.
Stephen Bannasch August 11th, 2009 @ 01:38 AM
FYI, the metal code running in the stack trace above:

http://github.com/stepheneb/rigse/blob/e8bbbb7b0c18de4893397b3d875d...
You flagged this item as spam.
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...
You flagged this item as spam.
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?
You flagged this item as spam.
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 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.

You flagged this item as spam.
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.
- 0001-Fix-reloading-of-metal-pieces-do-not-hold-reference.patch 3.3 KB
You flagged this item as spam.
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.
- 0001-Fix-reloading-of-metal-pieces.patch 10.8 KB
You flagged this item as spam.
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 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'

You flagged this item as spam.
Hongli Lai August 15th, 2009 @ 08:35 PM
My last patch broke some unit tests. This fixes it.
- 0001-Fix-reloading-of-metal-pieces.patch 13.2 KB
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 August 16th, 2009 @ 02:01 AM
Applied with small Ruby 1.9 compatibility fix.
You flagged this item as spam.
Hongli Lai August 16th, 2009 @ 08:05 AM
Ticket state should be 'incomplete'. Needs to be ported to master.
Jeremy Kemper August 16th, 2009 @ 08:08 AM
- State changed from “committed” to “incomplete”
You flagged this item as spam.
Alistair Holt August 16th, 2009 @ 03:37 PM
I just came across this same issue. Any idea when this will make it into master?
You flagged this item as spam.
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.
- 0001-Fix-metal-class-reloading.patch 8.1 KB
Jeremy Kemper September 11th, 2009 @ 11:04 PM
- Milestone changed from “2.3.4” to “2.3.6”
[milestone:id#50064 bulk edit command]
You flagged this item as spam.
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!)
You flagged this item as spam.
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 April 30th, 2010 @ 02:34 AM
This will block 2.3.6 release until it's ported to and tested on master.
Rizwan Reza May 16th, 2010 @ 02:41 AM
- Tag changed from “actionpack, patch” to “actionpack, bugmash, patch”
[bulk edit]
Jeremy Kemper May 23rd, 2010 @ 05:54 PM
- Milestone changed from “2.3.6” to “2.3.7”
[bulk edit]
Jeremy Kemper May 24th, 2010 @ 09:40 AM
- Milestone changed from “2.3.7” to “2.3.8”
[bulk edit]
Jeremy Kemper May 25th, 2010 @ 11:45 PM
- Milestone changed from “2.3.8” to “2.3.9”
[bulk edit]
Jeremy Kemper August 30th, 2010 @ 02:28 AM
- Milestone changed from “2.3.9” to “2.3.10”
- Importance changed from “” to “High”
[bulk edit]
You flagged this item as spam.
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.
You flagged this item as spam.
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.
You flagged this item as spam.
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.
You flagged this item as spam.
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?
You flagged this item as spam.
John Firebaugh December 19th, 2010 @ 08:34 PM
https://github.com/rails/rails/pull/137
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 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 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.
You flagged this item as spam.
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.
You flagged this item as spam.
John Firebaugh December 23rd, 2010 @ 09:59 PM
José beat me to it: https://github.com/rails/rails/commit/819b8cae40623d26ce3c050d482b4...

Sam, does that fix the failure?
Sam Ruby December 24th, 2010 @ 12:34 AM
John: yes it does! Thanks!