FIX: report cached controller and action to loggers

Previously we would treat all cached hits in anon cache as "other"

This hinders analysis of cache performance and makes logging inaccurate
This commit is contained in:
Sam Saffron 2019-09-03 10:51:49 +10:00
parent 441e573439
commit b9954b53bb
2 changed files with 27 additions and 4 deletions

View File

@ -134,6 +134,7 @@ module Middleware
end end
MIN_TIME_TO_CHECK = 0.05 MIN_TIME_TO_CHECK = 0.05
ADP = "action_dispatch.request.parameters"
def should_force_anonymous? def should_force_anonymous?
if (queue_time = @env['REQUEST_QUEUE_SECONDS']) && get? if (queue_time = @env['REQUEST_QUEUE_SECONDS']) && get?
@ -153,10 +154,13 @@ module Middleware
!!(!has_auth_cookie? && get? && no_cache_bypass) !!(!has_auth_cookie? && get? && no_cache_bypass)
end end
def cached def cached(env = {})
if body = $redis.get(cache_key_body) if body = $redis.get(cache_key_body)
if other = $redis.get(cache_key_other) if other = $redis.get(cache_key_other)
other = JSON.parse(other) other = JSON.parse(other)
if req_params = other[1].delete(ADP)
env[ADP] = req_params
end
[other[0], other[1], [body]] [other[0], other[1], [body]]
end end
end end
@ -169,7 +173,7 @@ module Middleware
# NOTE in an ideal world cache still serves out cached content except for one magic worker # NOTE in an ideal world cache still serves out cached content except for one magic worker
# that fills it up, this avoids a herd killing you, we can probably do this using a job or redis tricks # that fills it up, this avoids a herd killing you, we can probably do this using a job or redis tricks
# but coordinating this is tricky # but coordinating this is tricky
def cache(result) def cache(result, env = {})
status, headers, response = result status, headers, response = result
if status == 200 && cache_duration if status == 200 && cache_duration
@ -180,6 +184,13 @@ module Middleware
parts << part parts << part
end end
if req_params = env[ADP]
headers_stripped[ADP] = {
"action" => req_params["action"],
"controller" => req_params["controller"]
}
end
$redis.setex(cache_key_body, cache_duration, parts.join) $redis.setex(cache_key_body, cache_duration, parts.join)
$redis.setex(cache_key_other, cache_duration, [status, headers_stripped].to_json) $redis.setex(cache_key_other, cache_duration, [status, headers_stripped].to_json)
@ -218,7 +229,7 @@ module Middleware
result = result =
if helper.cacheable? if helper.cacheable?
helper.cached || helper.cache(@app.call(env)) helper.cached(env) || helper.cache(@app.call(env), env)
else else
@app.call(env) @app.call(env)
end end

View File

@ -277,12 +277,24 @@ describe Middleware::RequestTracker do
tracker = Middleware::RequestTracker.new(cache) tracker = Middleware::RequestTracker.new(cache)
uri = "/path?#{SecureRandom.hex}" uri = "/path?#{SecureRandom.hex}"
tracker.call(env("REQUEST_URI" => uri, "ANON_CACHE_DURATION" => 60))
request_params = {
"a" => "b",
"action" => "bob",
"controller" => "jane"
}
tracker.call(env("REQUEST_URI" => uri, "ANON_CACHE_DURATION" => 60, "action_dispatch.request.parameters" => request_params))
expect(@data[:cache]).to eq("store") expect(@data[:cache]).to eq("store")
tracker.call(env("REQUEST_URI" => uri, "ANON_CACHE_DURATION" => 60)) tracker.call(env("REQUEST_URI" => uri, "ANON_CACHE_DURATION" => 60))
expect(@data[:cache]).to eq("true") expect(@data[:cache]).to eq("true")
# not whitelisted
request_params.delete("a")
expect(@env["action_dispatch.request.parameters"]).to eq(request_params)
end end
it "can correctly log detailed data" do it "can correctly log detailed data" do