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

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

I'll have a look at it for master.

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.

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.

This patch fixes the issue.

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

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
  ...

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

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. :)

(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...

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'

FYI, the metal code running in the stack trace above:

http://github.com/stepheneb/rigse/blob/e8bbbb7b0c18de4893397b3d875d...

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...

@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?

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...

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.

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.

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.

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.

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'

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

Applied with small Ruby 1.9 compatibility fix.

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

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

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

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

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 .

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

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.

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.

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.

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?

https://github.com/rails/rails/pull/137

(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...

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.

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

José beat me to it: https://github.com/rails/rails/commit/819b8cae40623d26ce3c050d482b4...

Sam, does that fix the failure?

John: yes it does! Thanks!