Search code examples
ruby-on-railscachingrack-cache

HTTP cache with Rails + Rack::Cache not invalidating

My Rails 3 app generates pages that will change for a specified period of time and then be static (no changes) for the rest of their lifetime (think: sports scoreboard)

This seems like the perfect opportunity for full page caching, so I opted for Rack::Cache, using the Last-Modified part of the response to indicate when the cache was invalid.

The cache works well - too well. It seems that even when the Last-Modified field is updated with a date/time that is later than the If-Modified-Since field of the request and the response generates a status 200 (as opposed to 304), the browser still loads the version of the page that is cached on the server.

Here is what I see in the server debug logs: 

App 16638 stdout: Started GET "/games/2014/2/10" for xx.xx.xx.xxx at 2014-02-11 04:04:11 +0000
App 16638 stdout: Processing by GamesController#index as HTML
App 16638 stdout:   Parameters: {"year"=>"2014", "month"=>"2", "day"=>"10"}
App 16638 stdout:   Game Load (2.8ms)  SELECT "games".* FROM "games" WHERE "games"."date" = '2014-02-10'
App 16638 stdout:   Game Load (2.8ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 877 LIMIT 1
App 16638 stdout:   Team Load (1.3ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 10 LIMIT 1
App 16638 stdout:   Team Load (0.7ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 23 LIMIT 1
App 16638 stdout:   Game Load (4.2ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 875 LIMIT 1
App 16638 stdout:   Team Load (0.6ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 17 LIMIT 1
App 16638 stdout:   Team Load (5.4ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 2 LIMIT 1
App 16638 stdout:   Game Load (7.0ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 874 LIMIT 1
App 16638 stdout:   Team Load (0.7ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 9 LIMIT 1
App 16638 stdout:   Team Load (7.9ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 27 LIMIT 1
App 16638 stdout:   Game Load (0.7ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 876 LIMIT 1
App 16638 stdout:   Team Load (0.4ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 18 LIMIT 1
App 16638 stdout:   Team Load (0.4ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 11 LIMIT 1
App 16638 stdout:   Game Load (0.6ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 873 LIMIT 1
App 16638 stdout:   Team Load (4.0ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 12 LIMIT 1
App 16638 stdout:   Team Load (0.6ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 8 LIMIT 1
App 16638 stdout:   Game Load (5.4ms)  SELECT "games".* FROM "games" WHERE "games"."id" = 872 LIMIT 1
App 16638 stdout:   Team Load (0.6ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 28 LIMIT 1
App 16638 stdout:   Team Load (3.9ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = 19 LIMIT 1
App 16638 stdout: Latest game: 2014-02-11 03:44:50 UTC
App 16638 stdout: Cache read: views/xxxx/games/2014/2/10
App 16638 stdout: Dalli::Server#connect 127.0.0.1:11211
App 16638 stdout: Read fragment views/xxxxx/games/2014/2/10 2.6ms
App 16638 stdout: Completed 200 OK in 618.2ms (ActiveRecord: 128.8ms)
App 15100 stderr: cache: [GET /games/2014/2/10] stale, invalid, store
App 16638 stdout: Started GET "/assets/bootstrap.css" for 66.55.150.181 at 2014-02-11 04:04:12 +0000
App 16638 stdout: Served asset /bootstrap.css - 304 Not Modified (12ms)
App 15100 stderr: cache: [GET /assets/bootstrap.css] stale, valid, store
App 15100 stderr: cache: [GET /assets/application-85cd667c6ae785b5d80f452fe6ad811e.js] fresh
App 15100 stderr: cache: [GET /assets/application-50dd9f33494a58a079e7417a68763e42.css] fresh

Here is a sample request/response (see the 200 status):

    Request URL:http://xxxxxxx.com/games/2014/2/10
Request Method:GET
Status Code:200 OK
Request Headersview source
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Charset:ISO-8859-1,utf-8;q=0.7,*;q=0.3
Accept-Encoding:gzip,deflate,sdch
Accept-Language:en-US,en;q=0.8
Cache-Control:max-age=0
Connection:keep-alive
Cookie:_gamestory_app_session=BAh7B0kiD3Nlc3Npb25faWQGOgZFVEkiJWIwYjAwNWQ3NTBmYTk4YjQ0YWRjYjEwMWQ5Y2ZjYTA2BjsAVEkiEF9jcx3JmX3Rva2VuBjsARkkiMXdKNWZZUWFhZDVHN3hEeEJjaWxYclp1NmN4OGUrSkI4VzJ2eXdWOUsrc1E9BjsARg%3D%3D--6f99b71bca632560c069c371fdb6a4477a26dfa3
Host:xxxxxxxxx.com
If-Modified-Since:Tue, 11 Feb 2014 03:43:06 GMT
If-None-Match:"e282d8be52fbe437d3c2d3908288100d"
User-Agent:Mozilla/5.0 (X11; Linux i686) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.56 Safari/537.17
Response Headersview source
Age:0
Cache-Control:public
Connection:keep-alive
Content-Length:10411
Content-Type:text/html; charset=utf-8
Date:Tue, 11 Feb 2014 04:04:11 GMT

ETag:"d6d4c1f573a56353e0abbe14de76e306"
Last-Modified:Tue, 11 Feb 2014 03:44:50 GMT
Server:nginx/1.4.4 + Phusion Passenger 4.0.29
Status:200 OK
X-Content-Digest:7b2caeed19cc4674669f4c386271054427342b5e
X-Powered-By:Phusion Passenger 4.0.29
X-Rack-Cache:stale, invalid, store
X-Request-Id:c19584efff9941bf5c456cb68d85b192
X-Runtime:0.661659
X-UA-Compatible:IE=Edge,chrome=1

In the relevant controller, I use a before_filter for the given action and in that filter, I use fresh_when on the last updated object on the page. This seems to generate the right date/times in the response, but I'm including the code for any possible errors (I removed the show action, for brevity):

class GamesController < ApplicationController
  helper ApplicationHelper
  before_filter :set_index_cache_headers, :only => [:index]
  caches_action :index

  def set_index_cache_headers
    @date = Date.today

    if params[:year] && params[:month] && params[:day]
      @date = Date.new(params[:year].to_i, params[:month].to_i, params[:day].to_i)
    else
      most_recent_game = Game.where(status: [:final, :in_progress]).order("date DESC").first

      if most_recent_game != nil
        @date = most_recent_game.date
      end
    end

    @games = Game.where(:date => @date).compact

    @game_infos = []

    @games.each do |g|
      @game_infos.push GameInfo.new(g.id)
    end

    @latest_game = @games.max_by{|g| g.updated_at}

    Rails.logger.debug "Latest game: #{@latest_game.updated_at}"
    fresh_when(@latest_game, public: true)
  end

  def index

  end
end
Solution

  • It turns out that this line in the controller:

    caches_action :index

    was the culprit. It was my intent to only use the Rack::Cache HTTP cache, but this line activates Rails action caching, which was not my intent. Having the two caching systems run together was what was causing the issues. Removing this line, resolved the problem.