This project is archived and is in readonly mode.
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 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 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.
-
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.
-
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.
-
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 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...
-
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:
- obtain the lock
- call the next handler
- return the status, headers, and BodyWrapper
- 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
- obtain the lock
-
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 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'
-
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...
-
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 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 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.
-
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 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 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'
-
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... -
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
-
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 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 September 11th, 2009 @ 11:04 PM
- Milestone changed from 2.3.4 to 2.3.6
[milestone:id#50064 bulk edit command]
-
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 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
-
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 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'safter
callbacks: one forActiveSupport::DescendantsTracker.clear
andActiveSupport::Dependencies.clear
(via the:set_clear_dependencies_hook
initializer) and one forActiveRecord::Base.clear_reloadable_connections!
(via theactive_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 ofafter
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 theset_clear_dependencies_hook
andactive_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.
- Delay all ActionDispatch
-
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 stackunless config.allow_concurrency
. Unfortunately, it unlocks ascall
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 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 callingrespond_to?
with a secondinclude_private
parameter. -
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? -
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.
-
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 December 23rd, 2010 @ 09:59 PM
José beat me to it: https://github.com/rails/rails/commit/819b8cae40623d26ce3c050d482b4...
Sam, does that fix the failure?
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>
People watching this ticket
- Alistair Holt
- Anil Wadghule
- arash
- Betelgeuse
- Christian Hølmer
- codesnik
- Dmitry Polushkin
- Hongli Lai
- Jeremy Kemper
- Joel Chippindale
- John
- John Firebaugh
- Kenneth Kalmer
- Michael Koziarski
- Mick Hollins
- Piotr Sarnacki
- Prem Sichanugrist (sikachu)
- Raphael Emourgeon
- Rik
- Sam Ruby
- Uwe Kubosch
- Yehuda Katz (wycats)
Attachments
Tags
Referenced by
- 2873 Application reloading should be deferred to end of request, currently interferes with 'render :text => lambda { ... }' streaming [#2873 state:incomplete]
- 2873 Application reloading should be deferred to end of request, currently interferes with 'render :text => lambda { ... }' streaming [#2873 state:committed]
- 3758 Rack middleware is exploding in Rails 3 Yes, it's a bug and already fixed in 2-3-stable. Please s...
- 3758 Rack middleware is exploding in Rails 3 I would mark this as duplicate of #2873, and you can foll...
- 2948 Exception: A copy of ActorsController has been removed from the module tree but is still active! Should this one be marked as duplicate of #2873 again?
- 2893 Rails 2.3.x - "render :text => proc" - problems with output buffer [Note: I am aware of #2873. I don't believe that it's the...
- 2948 Exception: A copy of ActorsController has been removed from the module tree but is still active! #2873
- 2873 Application reloading should be deferred to end of request, currently interferes with 'render :text => lambda { ... }' streaming [#2873]
- 2873 Application reloading should be deferred to end of request, currently interferes with 'render :text => lambda { ... }' streaming (from [e683ab7c390f26e110387822c7ffb5ac6aafebca]) Use AD:...