What is the difference between [X,Y,Z].each {|m| include m} and include X, Y, Z?

Question

Note This originally started as a question about 404 errors, but now it's a question why the patch that I applied would make a difference.

How do you get a cached action to return a 404 on all requests that raise an ActiveRecord::RecordNotFound exception, not just the first request?

For example, if you start an empty rails project, add a Product model and controller, setup your database.yml, setup your cache backend in production.rb, rake db:migrate, then start in production and hit the site for a non-existent object, e.g. http://localhost:3000/product/show/1234

class ProductController < ApplicationController

  caches_action :show

  def show
    @product = Product.find(params[:id])
    render :text => "asdf"
  end

end

The first time the page is hit, it returns the 404 page as expected. However, every subsequent hit to that URL returns a blank page with 200 OK. How do you get it to return 404 every time?

Here are the CURL requests, followed by the logs

~ $ curl -I http://0.0.0.0:3000/product/show/1234
HTTP/1.1 404 Not Found
Connection: close
Date: Mon, 20 Apr 2009 22:49:18 GMT
Content-Type: text/html; charset=utf-8
Cache-Control: no-cache
Content-Length: 14097

~ $ curl -I http://0.0.0.0:3000/product/show/1234
HTTP/1.1 200 OK
Connection: close
Date: Mon, 20 Apr 2009 22:49:19 GMT
X-Runtime: 6
Content-Type: text/html; charset=utf-8
Cache-Control: no-cache
Content-Length: 0

The second response is clearly wrong.

Here is a copy of the log for the 2 requests:

Processing ProductController#show (for 127.0.0.1 at 2009-04-20 17:35:24) [GET]
  Parameters: {"id"=>"1234"}

ActiveRecord::RecordNotFound (Couldn't find Product with ID=1234):
  app/controllers/product_controller.rb:6:in `show'

Rendering rescues/layout (not_found)


Processing ProductController#show (for 127.0.0.1 at 2009-04-20 17:35:30) [GET]
  Parameters: {"id"=>"1234"}
Filter chain halted as [#<ActionController::Caching::Actions::ActionCacheFilter:0x23e36d4 @options={:cache_path=>nil, :store_options=>{}, :layout=>nil}>] rendered_or_redirected.
Filter chain halted as [#<ActionController::Filters::AroundFilter:0x23e3580 @kind=:filter, @options={:unless=>nil, :if=>nil, :only=>#<Set: {"show"}>}, @method=#<ActionController::Caching::Actions::ActionCacheFilter:0x23e36d4 @options={:cache_path=>nil, :store_options=>{}, :layout=>nil}>, @identifier=nil>] did_not_yield.
Completed in 12ms (View: 0, DB: 0) | 200 OK [http://0.0.0.0/product/show/1234]

Indeed, if you pull the cached action out of the cache, it has some sort of empty garbage in there.

cache.fetch("views/0.0.0.0:3000/product/show/1234")
=> ["", nil, [], []]

What am I doing wrong here?

Edit

I've confirmed that Rails 2.1.2 and 2.2.2 don't exhibit this behavior, but 2.3.2 does. (i.e. the older versions don't store an empty response into the cache and they indeed throw a 404 for the subsequent requests)

I'm having trouble testing against edge Rails, because loading it causes the following error when starting the server: foobar/vendor/rails/activesupport/lib/active_support/dependencies.rb:440:in `load_missing_constant': uninitialized constant ActionController::Failsafe (NameError)

I've tested against the current head of the 2-3-stable branch, 375e8976e3, and it too exhibits this behavior.

Edit #2 I attempted to track down when the change occurred in the Rails codebase to determine if it was intentional. It seems that this seemingly innocuous commit is where the bug starts.

Here are the details of the bisection, where 404 denotes the desired behavior, 200 being undesired.

2-3-stable branch
    375e8976e3 - 200
    b1c989f28d - 200
    beca1f2e15 - 200
    f1fff0a48  - 200
    f1e20ce9a7 - 200
    a5004573d8 - 200
    2e1132fad8 - 200 - the difference seems to start at this commit
    c69d8c043f - 404
    d961592886 - 404
    276ec16007 - 404
    0efec6452  - 404
    13c6c3cfc5 - 404
    fb2325e35  - 404

2-2 stable
    3cb89257b4 - 404

Here is a patch that reverses the change, which when applied to tag v2.3.2.1, i.e. dc88847e5ce392eed210b97525c14fca55852867, fixes the problem. I, however, am not smart enough to fathom why this seemingly small change would actually make a difference! Perhaps someone smarter than me could shed some light on the situation?

diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb
index 0facf70..0790807 100644
--- a/actionpack/lib/action_controller/base.rb
+++ b/actionpack/lib/action_controller/base.rb
@@ -1403,12 +1403,9 @@ module ActionController #:nodoc:
   end

   Base.class_eval do
-    [ Filters, Layout, Benchmarking, Rescue, Flash, MimeResponds, Helpers,
-      Cookies, Caching, Verification, Streaming, SessionManagement,
-      HttpAuthentication::Basic::ControllerMethods, HttpAuthentication::Digest::ControllerMethods,
-      RecordIdentifier, RequestForgeryProtection, Translation
-    ].each do |mod|
-      include mod
-    end
+    include Filters, Layout, Benchmarking, Rescue, Flash, MimeResponds, Helpers
+    include Cookies, Caching, Verification, Streaming, SessionManagement
+    include HttpAuthentication::Basic::ControllerMethods, HttpAuthentication::Digest::ControllerMethods
+    include RecordIdentifier, RequestForgeryProtection, Translation
   end
 end

Edit #3 The patch seems to also fix the related bug, showcased above, where the "Completed in XYms (DB: Z) | 404 Not Found [http://0.0.0.0/product/1234]" did not show up in the log.

Edit #4 The above patch broke other things in ActionPack, so I delved in and generated a fix for the issue that doesn't cause collateral damage. The patch and any subsequent updates will be at the rails lighthouse

Answer 1

It appears that include(X, Y, Z) actually operates in a different order than include X; include Y; include Z.

Below I've pasted the C code that implements the Module#include method in Ruby 1.8.6.

static VALUE
rb_mod_include(argc, argv, module)
    int argc;
    VALUE *argv;
    VALUE module;
{
    int i;

    for (i=0; i<argc; i++) Check_Type(argv[i], T_MODULE);
    while (argc--) {
      rb_funcall(argv[argc], rb_intern("append_features"), 1, module);
      rb_funcall(argv[argc], rb_intern("included"), 1, module);
    }
    return module;
}

Even if you're not familiar with Ruby's C internals, it's pretty clear that this function has a for loop iterating upward to check that the type of all the arguments is T_MODULE, and then uses a while loop iterating downward to actually include the modules - so the modules in include(X, Y, Z) would actually be included in the order Z, Y, X. I haven't gone through all the Rails modules in question, but I imagine there's something order-dependent that started failing once the include order was switched around.