Useful variables to log


#1

In addition to the list of variables you can log here in our docs, we all have the following variables available:

  • fastly_info.state: logging the value of this internal variable will report misses, passes, hits, hit-passes, whether a request waited for request collapsing or whether it clustered. This provides more specific information than resp.http.X-Cache, which differentiates between only HITs and MISSes.

  • obj.hits: number of hits for an asset from a cache node (server.identity will then tell you the specific cache node that received the hit)

  • obj.lastuse: approximate time elapsed since the object was last accessed, specific to each cache node. Per our other community post here:

The variable obj.lastuse works a bit differently in Fastly. Each edge node will have it’s own last accessed time. If the object is cached within the node, returned is the relative time in seconds since the object was last requested. If it is not cached, returned is now-lastuse. Except that lastuse is 0 if the cache does not remember seeing the object.

  • time.elapsed: the time between the start of the request when it hits Fastly and when we deliver the first byte in the response

#2

Any details on what the various states returned by fastly_info.state are/mean? So far I’ve found:

  • HIT-CLUSTER
  • MISS-CLUSTER
  • HIT-WAIT-CLUSTER
  • HIT-WAIT
  • HIT
  • MISS

#3

Hi rcoup,

We have some internal documentation that should cover all possible values.

fastly_info.state - STRING - Read Only - Available in all subroutines
State of the request, with optional additional suffixes describing particulars
of the request. Possible values are:

States:

  • NONE: No state assigned by Varnish yet.
  • HIT-: We are serving previously-cached content.
  • HITPASS-: This request has been previously marked as pass (uncacheable) in vcl_fetch.
  • HIT-STALE-: We are transitioning into a Hit state but the object’s TTL has expired.
  • HIT-SYNTH-: We are serving a synthetic response.
  • MISS-: We are serving uncached content.
  • PASS-: We are serving uncached content that we do not intend to cache for future requests.

Error states:

  • BG-ERROR-[state]: An error occurred during a background fetch in [state] (possible options: PASS, RECV, ERROR)
  • ERROR: Transitioned into vcl_error with a 4xx or 5xx response code.
  • ERROR-LOSTHDR: Returned a 503 because Varnish ran out of memory during header processing. A common cause with a header is when it was too large and has exceeded a limit. See General Size Limits for more details.

Suffixes:

  • -CLUSTER: The response will be served internally from another node within the POP.
  • -REFRESH: We got back a 304, and served the cached If-Modified-Since content.
  • -WAIT: This request had to wait for a highly-contended object.

#4

We were able to load yet another custom VCL to enable the extended logging. We’re using SumoLogic as the log aggregator and the resulting logs are limited to only request types and http response codes. For example this is what we’re getting back in Sumo;

<134>2017-04-10T17:29:05Z cache-atl6238 FASTLY-WFMCOM-DEV5[94020]: 64.132.0.202 “-” “-” Mon, 10 Apr 2017 17:29:05 GMT GET /selwyn-500-test 200
Name:
Http Input
Category:
wfmcom_fastly_dev5

We’re using the following code in the VCL for the logging;

sub vcl_log {
#FASTLY log

set req.http.X-Shield = “0”;
if (req.http.fastly-ff) { set req.http.X-Shield = “1”; }

log {"syslog  xxxxx logging-endpoint :: "}
{" client_ip="}     req.http.Fastly-Client-IP
{" timestamp="}     now.sec
{" reqmethod="}     req.request
{" host="}          req.http.host
{" url="}           {"""}req.url{"""}
{" contenttype="}   resp.http.content-type
{" status="}        resp.status
{" response="}      {"""}resp.response{"""}
{" infostate="}     fastly_info.state
{" age="}           resp.http.age
{" setcookie="}     {"""}resp.http.Set-Cookie{"""}
{" size="}          resp.bytes_written
{" pop="}           server.datacenter
{" shield="}        req.http.x-shield
{" fastlyregion="}  server.region
{" clientcontinent="}     geoip.continent_code
{" clientcountry="}       geoip.country_code
{" clientregion="}        geoip.region
{" referrer="}      {"""}req.http.referer{"""}
{" useragent="}     req.http.Orig-User-Agent
{" hits="}          obj.hits
{" restarts="}      req.restarts
{" elapsed="}       time.elapsed.msec
{" ttl="}           obj.ttl
{" grace="}         obj.grace;
{" serving stale content="} fastly_info.state;

# server.identity == cachenode and POP

}

Could you please explain why we don’t see any of the above data in our logs from Fastly? What are we doing wrong?


#5

Hi @pavel.kinev,

The reason you’re not seeing logs is there isn’t a logging endpoint created for your service. While you can use custom VCL to configure your log output, you will still need to first create the logging endpoint either in the UI or with our API.

If you create it using the UI, you’ll want to attached a condition in the UI that will always be false, for example:
Apply if: !req.url
Then you can use custom VCL for your logging endpoint.

If you use the API, you can also set the always false condition or you can use placement: none when setting up the logging endpoint to achieve the same behavior.

If you have other questions or issues setting up your logging endpoints, open a support ticket and include your service ID and name of the logging endpoint.