This project is archived and is in readonly mode.

#2533 ✓ committed
John Douthat

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

Reported by John Douthat | April 21st, 2009 @ 05:35 AM | in 2.x

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

Comments and changes to this ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

Tickets have moved to Github

The new ticket tracker is available at https://github.com/rails/rails/issues

Shared Ticket Bins

People watching this ticket

Attachments