Logging Cache State about ledge

[pintsized]

I used to have a response header called X-Cache-Action which was one of FETCHED, COLLAPSED, or ABSTAINED (a WARM hit which was already being COLLAPSED).

I'm not sure we should be passing X-Cache-Action along as a response header anyway.. giving away too much information? So setting a log variable might well be nicer, and more flexible. Trouble is you can't create variables in nginx from Lua, but you can update them if they are set.

I guess we could come up with a system where ledge sets $ledge_version to ledge.__VERSION (for example) if the variable exists? So something like:

server {
    set $ledge_cache_state null;
    set $ledge_cache_action null;
    set $ledge_version null;
}

If those variables are defined (to anything), ledge will update them?

What info would you like to see for logging?

[hamishforbes]

Agreed on the headers thing, not only is it too much information to pass on but its just going to be bloating the responses.

Would be good if we could access this information in the logs:
Upstream server hit - useful if theres more than one or if it changed over
Age of cached response

I'm sure we'll come up with more stuff but at the moment that's all I can think of

[pintsized]

Do you think we should drop X-Cache and X-Cache-State as response headers then? Seems unnecessary clutter, especially when the presence of Age implies a "hit" of some kind, and our logging vars will show admins what they need?

[hamishforbes]

I think it can be quite useful to be able to see the Cache State when running a curl or debugging issues in a browser rather than having to grep through logs at the same time.

The X-Cache hit/miss is slightly less useful if the Age and via headers are there as you can tell if the request is going through a proxy and whether or not it was cached from the combination of those 2.

[pintsized]

Feature spec

X-Cache

The X-Cache header should be compatible with the Squid (and other) conventions, for convenience of integration.

• X-Cache: HIT from ledge.tld:80 A cache hit, with no (known) cache layer upstream.
• X-Cache: HIT from ledge.tld:80, HIT from proxy.upstream.tld:80 A cache hit, also hit upstream.
• X-Cache: MISS from ledge.tld:80, HIT from proxy.upstream.tld:80 A cache miss, but hit upstream.
• X-Cache: MISS from ledge.tld:80, MISS from proxy.upstream.tld:80 Regenerated at the origin.

This header is only present for cacheable responses.

X-Cache-Ledge

The X-Cache-Lookup header is a little Squid specific, and hard to interpret. I'm proposing a custom header called X-Cache-Ledge, which like X-Cache and Age is only present for cacheable responses.

• X-Cache-Ledge: REVALIDATED from ledge.tld:80 The cache was revalidated. The item is fresh (and may have been fetched).
• X-Cache-Ledge: IGNORED from ledge.tld:80 The cache was ignored (no-cache). The item is fresh (and was fetched).
• X-Cache-Ledge: HOT from ledge.tld:80 The ttl is greater than 0.
• X-Cache-Ledge: WARM from ledge:tld:80 ttl + max_stale is greater than 0.
• X-Cache-Ledge: COLD from ledge:tld:80 ttl + max_stale is less than 0, but we have an old cache item.
• X-Cache-Ledge: SUBZERO from ledge:tld:80 We have nothing for this key.
• X-Cache-Ledge: PRIVATE from ledge:tld:80 The response is not cacheable. You will never see this in the headers, but it will be available in the log.

Log variables

$ledge_version

In the format ledge/REV.

$ledge_x_cache

As the X-Cache header above, but also present (MISS) for non cacheable responses.

$ledge_x_cache_ledge

As the X-Cache-Ledge header above, with the addition of PRIVATE for non-cacheable responses.

$ledge_fetch_action

• NONE We served from cache.
• FETCHED We went to the origin.
• COLLAPSED We received a shared (newly cached) response after waiting for another connection to fetch.

Example

http {
    log_format ledge '$remote_addr - $remote_user [$time_local]  '
        '"$request" $status $bytes_sent '"$http_referer" "$http_user_agent" '
        '"$ledge_version" "$ledge_x_cache" "$ledge_x_cache_ledge" "$ledge_fetch_action"';

    access_log logs/access.log ledge;

    server {
        set $ledge_version 0;
        set $ledge_x_cache 0;
        set $ledge_x_cache_ledge 0;
        set $ledge_fetch_action 0;

        location / {
            ...
        }
    }
}

Feedback welcome!

[keen99]

As a heads up to the next person who reads this thread looking for logging:

The examples above wont work anymore (5/23/16) - the code to support the variables was removed. I ran out of time trying to backtrack when it was removed.

An example using combined + the available headers:

    log_format ledge '$remote_addr - $remote_user [$time_local] '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent" '
                    '"Cache:$sent_http_x_cache"  "Age:$sent_http_age" "Via:$sent_http_via"'
                    ;

    access_log /var/log/nginx/access_log ledge;

192.168.59.3 - - [23/May/2016:22:22:18 +0000] "GET /x/y/z HTTP/1.1" 200 57840 "-" "curl/7.37.1""Cache:HIT from 159e8241f519:8080"  "Age:724"