This project is archived and is in readonly mode.

Action cached page, after first 404, returns 200 OK, empty body on every subsequent request

#2533

original formatted details here http://stackoverflow.com/questio...

If an action_cached method throws an error, such as an ActiveRecord::RecordNotFound exception, an empty entry is added to the action cache that causes every subsequent request to return 200 instead of 404, 500, or whatever appropriate status code should be there.

The attached patch has tests and was branched from the v2.3.2.1 tag.

Steps to reproduce:

Start an empty rails project
Add a Product model and controller like the following


class ProductController < ApplicationController
  caches_action :show

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

Setup your database.yml, setup and enable your cache backend
rake db:migrate
start the server
hit the site for a non-existent object, e.g. http://0.0.0.0:3000/product/show..., twice.

What was expected

A 404 error on both responses

What happened:

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.

headers

~ $ curl -I http://0.0.0.0:3000/product/show...
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...
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

log results

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 [#nil, :store_options=>{}, :layout=>nil}>] rendered_or_redirected.
Filter chain halted as [#nil, :if=>nil, :only=>#}, @method=#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]

What's put in the cache after the first request

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

When did the change occur in Rails?

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.

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

I've attached a test that fixes the problem without disturbing the other actionpack tests.

Results of the new tests, before changing actions.rb


~/Projects/open_source/rails/actionpack/test $ rake test_action_pack 2> /dev/null
(in /Users/john/Projects/open_source/rails/actionpack)
Loaded suite /Library/Ruby/Gems/1.8/gems/rake-0.8.4/lib/rake/rake_test_loader
Started
...................F...F...................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
Finished in 28.419301 seconds.

  1) Failure:
test_record_not_found_returns_404_for_multiple_requests(ActionCacheTest)
    [/Users/john/Projects/open_source/rails/actionpack/test/../lib/action_controller/test_case.rb:114:in `clean_backtrace'
     ./test/controller/caching_test.rb:477:in `test_record_not_found_returns_404_for_multiple_requests'
     /Users/john/Projects/open_source/rails/actionpack/test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `__send__'
     /Users/john/Projects/open_source/rails/actionpack/test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `run']:
Expected response to be a <404>, but was <200>

  2) Failure:
test_simple_runtime_error_returns_500_for_multiple_requests(ActionCacheTest)
    [/Users/john/Projects/open_source/rails/actionpack/test/../lib/action_controller/test_case.rb:114:in `clean_backtrace'
     ./test/controller/caching_test.rb:491:in `test_simple_runtime_error_returns_500_for_multiple_requests'
     /Users/john/Projects/open_source/rails/actionpack/test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `__send__'
     /Users/john/Projects/open_source/rails/actionpack/test/../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `run']:
Expected response to be a <500>, but was <200>

2315 tests, 10954 assertions, 2 failures, 0 errors

Results of the new tests, after changing actions.rb


~/Projects/open_source/rails/actionpack/test $ git reset --hard
HEAD is now at a0ab976 Fix action cached methods returning ActiveRecord::RecordNotFound returning 200 OK, blank body on every request after the first. Fixes #2533
~/Projects/open_source/rails/actionpack/test $ rake test_action_pack 2> /dev/null
(in /Users/john/Projects/open_source/rails/actionpack)
Loaded suite /Library/Ruby/Gems/1.8/gems/rake-0.8.4/lib/rake/rake_test_loader
Started
..........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
Finished in 31.174867 seconds.

2315 tests, 10954 assertions, 0 failures, 0 errors

Reported by John Douthat · April 21st, 2009 @ 05:35 AM

Activity

John Douthat
- Tag set to cache, caches_action, caching, patch, rescue
- 2533.diff 3.75 KB
April 21st, 2009 @ 07:41 PM
John Douthat
- Title changed from Action cached page, after first 404, returns 200 OK, empty body on every subsequent request to [Patch] Action cached page, after first 404, returns 200 OK, empty body on every subsequent request
April 22nd, 2009 @ 05:08 PM
John Douthat
- No changes were found…
April 22nd, 2009 @ 06:25 PM
Pratik
- Title changed from [Patch] Action cached page, after first 404, returns 200 OK, empty body on every subsequent request to Action cached page, after first 404, returns 200 OK, empty body on every subsequent request
April 27th, 2009 @ 10:46 PM
John Douthat
I'm having to run a patched version of Rails in production now, because I rely heavily on action caching. Any chance this patch can be reviewed for merging into Rails proper? Comments? I'll make any changes requested.

April 30th, 2009 @ 09:25 PM
Pratik
- Assigned user set to Jeremy Kemper
April 30th, 2009 @ 10:03 PM
Repository
- State changed from new to committed
(from [e59835bd0934a7458b71b13bf65786c8484905bd]) Fix action-cached exception responses.

Methods raising ActiveRecord::RecordNotFound were returning 404 on first request and 200 OK with blank body on subsequent requests.

[#2533 Action cached page, after first 404, returns 200 OK, empty body on every subs... state:committed]

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

May 1st, 2009 @ 12:45 AM
Repository

(from [d1d1894c2f38b7b116a2f756fb879ef0e68ade3f]) Fix action-cached exception responses.

Methods raising ActiveRecord::RecordNotFound were returning 404 on first request and 200 OK with blank body on subsequent requests.

[#2533 Action cached page, after first 404, returns 200 OK, empty body on every subs... state:committed]

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

May 1st, 2009 @ 12:48 AM
John Douthat
Great! Thanks so much!

May 2nd, 2009 @ 03:23 AM