CDN Observability

Full Recipe

Shared by: Allan Konar

Real-time computation of CDN cache node efficiency from pseudonymized Fastly CDN logs, with graph association of each log entry to serving PoP, cache server, client, client ASN, asset and origin to identify potential root cause of issues.

Full CDN Observability Recipe

Download Recipe

Scenario

Pseudonymized CDN log data is imported from a JSON file (cdn_data_50k.json) via a file ingest, and nodes are manifested for the elements associated with each event (e.g., client, server, pop, etc.).

Each of the manifested nodes increment counters to track the number of cache hits and misses at each level (e.g., source ASN, server, pop, etc.). Selecting any node allows you to query at each level to identify potential root cause of poor performance.

A standing query is defined to match consecutive cache misses within a configurable fixed period of time for the purpose of alerting.

Sample Data

Download the sample data to the same directory where Quine will be run.

• cdn_data_50k.json - https://that.re/cdn_data_50k

How it Works

The recipe reads observations from the sample data file using ingest streams to manifest a graph in Quine. An ingest stream is configured to process the data file, containing Cypher that parses the log entries, manifests nodes, and relates them to each other in the graph.

The log entries take the form of:

{
    "backend_ip": "157.52.79.52",
    "backend_ttlb": 73.206,
    "business_unit": "68ae725c3fd8d6831735753269a727c9ce05baae6715bb0191ddb7f6d67842bd",
    "bytes_in": 377,
    "bytes_out": 902,
    "cached": false,
    "cache_shield": "false",
    "cache_status": "MISS-CLUSTER",
    "client_asn": 7922,
    "client_geo_country": "US",
    "client_ip": "1localhost",
    "client_ttfb": 73.198,
    "environment": "prod",
    "failover_status": "",
    "forward_for": "",
    "host": "682d313399617e3d194679e8422a6a5f2666b60c54ab6eead5908040443c793f",
    "if_modified_since": "",
    "if_none_match": "",
    "if_unmodified_since": "",
    "method": "GET",
    "path": "/flavi7d79/master/flavi7d79_6.m3u8",
    "pop": "SJC",
    "range_request": "(null)",
    "range_response": "",
    "request_id": "cache-sjc10025-SJC-2614091026",
    "restarts": 0,
    "retrans": 0,
    "role": "edge",
    "rtt_msecs": 28,
    "server_id": "cache-sjc10025-SJC",
    "server_ip": "2a04:4e42:a::645",
    "server_ttlb": 73.261,
    "shield_failover": "",
    "stream": 0,
    "status_code": 200,
    "timestamp": "2020-07-14 22:55:31.729734",
    "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36",
    "workflow": "f2757f5a18302320de05caa509ac98370b6a9cec",
    "origin_request_id": "",
    "query": ""
}

INGEST-1 processes the cdn_data_50k.json file:

YAMLJSON

  - type: FileIngest
    path: cdn_data_50k.json
    format:
    type: CypherJson
    query: |-
      MATCH (event), (client), (asset), (asn), (server), (pop), (origin), (clientGeo)
      WHERE $that.cache_status IS NOT NULL
        AND id(event) = idFrom('event', $that.timestamp, $that.request_id)
        AND id(client) = idFrom('client', $that.client_ip, $that.business_unit)
        AND id(asset) = idFrom('asset', $that.path)
        AND id(asn) = idFrom('asn', toString($that.client_asn))
        AND id(server) = idFrom('server', $that.pop, $that.server_id)
        AND id(pop) = idFrom('pop', $that.pop)
        AND id(origin) = idFrom('origin', $that.backend_ip)
        AND id(clientGeo) = idFrom('clientGeo', $that.client_geo_country)

      ////////////////////////////////////////
      //Bucketing for HITs and MISSes counters
      ////////////////////////////////////////
      // RegEx deets here: https://regex101.com/r/uP0KMm/1
      WITH *, text.regexFirstMatch($that.cache_status, '(HIT|MISS(?!.*HIT)).*') AS hmp WHERE hmp[1] IS NOT NULL

      ////////////////////////////////////////
      // Bucketing for node type counters
      ////////////////////////////////////////
      CALL incrementCounter(client, "count",1) YIELD count AS clientCount
      CALL incrementCounter(client, toLower(hmp[1]),1) YIELD count AS clientHitMissCount
      CALL incrementCounter(asset, "count",1) YIELD count AS assetCount
      CALL incrementCounter(asset, toLower(hmp[1]),1) YIELD count AS assetHitMissCount
      CALL incrementCounter(asn, "count",1) YIELD count AS asnCount
      CALL incrementCounter(asn, toLower(hmp[1]),1) YIELD count AS asnHitMissCount
      CALL incrementCounter(server, "count",1) YIELD count AS serverCount
      CALL incrementCounter(server, toLower(hmp[1]),1) YIELD count AS serverHitMissCount
      CALL incrementCounter(pop, "count",1) YIELD count AS popCount
      CALL incrementCounter(pop, toLower(hmp[1]),1) YIELD count AS popHitMissCount
      CALL incrementCounter(clientGeo, "count",1) YIELD count AS clientGeoCount
      CALL incrementCounter(clientGeo, toLower(hmp[1]),1) YIELD count AS clientGeoHitMissCount
      CALL incrementCounter(origin, "count",1) YIELD count AS originGeoCount
      CALL incrementCounter(origin, toLower(hmp[1]),1) YIELD count AS originGeoHitMissCount

      ////////////////////////////////////////////////////////
      // Event
      ////////////////////////////////////////////////////////
      SET event = $that,
          event.cache_class = hmp[1],
          event: event

      ////////////////////////////////////////////////////////
      // Origin
      ////////////////////////////////////////////////////////
      SET origin.backend_ip = $that.backend_ip,
          origin: origin

      ////////////////////////////////////////////////////////
      // Client
      ////////////////////////////////////////////////////////
      SET client.client_geo_country = $that.client_geo_country,
          client.client_ip = $that.client_ip,
          client.user_agent = $that.user_agent,
          client: client

      // Extract Browser and Version
      // RegEx here: https://regex101.com/r/T0MThZ/2
      WITH *, text.regexFirstMatch($that.user_agent, '\\((.*?)\\)(\\s|$)|(.*?)\\/(.*?)(\\s|$)') AS cb
      SET client.browser = cb[3],
          client.browserVer = cb[4],
          client.first_seen = coll.min([$that.timestamp, coalesce(client.first_seen, $that.timestamp)]),
          client.last_seen = coll.max([$that.timestamp, coalesce(client.last_seen, $that.timestamp)])

      ////////////////////////////////////////////////////////
      // Client Geo
      ////////////////////////////////////////////////////////
      SET clientGeo.client_geo_country = $that.client_geo_country,
          clientGeo: clientGeo

      ////////////////////////////////////////////////////////
      // Asset
      ////////////////////////////////////////////////////////
      // RegEx here: https://regex101.com/r/tB8cd4/1
      WITH *, text.regexFirstMatch($that.path, '^(.+\\/)([^\\/]+)$') AS ap
      SET asset.path = ap[1],
          asset.name = ap[2],
          asset.full_path = $that.path,
          asset.if_modified_since = coll.max([$that.timestamp, coalesce(asset.if_modified_since, $that.timestamp)]),
          asset: asset

      ////////////////////////////////////////////////////////
      // ASN
      ////////////////////////////////////////////////////////
      SET asn.asn_id = toString($that.client_asn),
          asn: asn

      ////////////////////////////////////////////////////////
      // Server
      ////////////////////////////////////////////////////////
      SET server.server_id = $that.server_id,
          server.server_ip = $that.server_ip,
          server.cache_shield = $that.cache_shield,
          server.environment = $that.environment,
          server.host = $that.host,
          server.role = $that.role,
          server.pop = $that.pop,
          server: server

      ////////////////////////////////////////////////////////
      // PoP
      ////////////////////////////////////////////////////////
      SET pop.source = $that.pop,
          pop.environment = $that.environment,
          pop: pop

      ////////////////////////////////////////////////////////
      // Create relationship between nodes
      ////////////////////////////////////////////////////////
      CREATE (asset)<-[:REQUESTED]-(event)-[:REQUESTED_OVER]->(asn)-[:IN_CLIENT_GEO]->(clientGeo),
             (origin)<-[:FROM]-(pop)<-[:WITHIN]-(server)<-[:TARGETED]-(event)<-[:ORIGINATED]-(client)

POST /api/v1/ingest/INGEST-1

{
  "type": "FileIngest",
  "path": "cdn_data_50k.json",
  "format": {
    "type": "CypherJson",
    "query":   "MATCH (event), (client), (asset), (asn), (server), (pop), (origin), (clientGeo) WHERE $that.cache_status IS NOT NULL AND id(event) = idFrom('event', $that.timestamp, $that.request_id) AND id(client) = idFrom('client', $that.client_ip, $that.business_unit) AND id(asset) = idFrom('asset', $that.path) AND id(asn) = idFrom('asn', toString($that.client_asn)) AND id(server) = idFrom('server', $that.pop, $that.server_id) AND id(pop) = idFrom('pop', $that.pop) AND id(origin) = idFrom('origin', $that.backend_ip) AND id(clientGeo) = idFrom('clientGeo', $that.client_geo_country) WITH *, text.regexFirstMatch($that.cache_status, '(HIT|MISS(?!.*HIT)).*') AS hmp WHERE hmp[1] IS NOT NULL CALL incrementCounter(client, "count",1) YIELD count AS clientCount CALL incrementCounter(client, toLower(hmp[1]),1) YIELD count AS clientHitMissCount CALL incrementCounter(asset, "count",1) YIELD count AS assetCount CALL incrementCounter(asset, toLower(hmp[1]),1) YIELD count AS assetHitMissCount CALL incrementCounter(asn, "count",1) YIELD count AS asnCount CALL incrementCounter(asn, toLower(hmp[1]),1) YIELD count AS asnHitMissCount CALL incrementCounter(server, "count",1) YIELD count AS serverCount CALL incrementCounter(server, toLower(hmp[1]),1) YIELD count AS serverHitMissCount CALL incrementCounter(pop, "count",1) YIELD count AS popCount CALL incrementCounter(pop, toLower(hmp[1]),1) YIELD count AS popHitMissCount CALL incrementCounter(clientGeo, "count",1) YIELD count AS clientGeoCount CALL incrementCounter(clientGeo, toLower(hmp[1]),1) YIELD count AS clientGeoHitMissCount CALL incrementCounter(origin, "count",1) YIELD count AS originGeoCount CALL incrementCounter(origin, toLower(hmp[1]),1) YIELD count AS originGeoHitMissCount SET event = $that, event.cache_class = hmp[1], event: event SET origin.backend_ip = $that.backend_ip, origin: origin SET client.client_geo_country = $that.client_geo_country, client.client_ip = $that.client_ip, client.user_agent = $that.user_agent, client: client WITH *, text.regexFirstMatch($that.user_agent, '\\((.*?)\\)(\\s|$)|(.*?)\\/(.*?)(\\s|$)') AS cb SET client.browser = cb[3], client.browserVer = cb[4], client.first_seen = coll.min([$that.timestamp, coalesce(client.first_seen, $that.timestamp)]), client.last_seen = coll.max([$that.timestamp, coalesce(client.last_seen, $that.timestamp)]) SET clientGeo.client_geo_country = $that.client_geo_country, clientGeo: clientGeo WITH *, text.regexFirstMatch($that.path, '^(.+\\/)([^\\/]+)$') AS ap SET asset.path = ap[1], asset.name = ap[2], asset.full_path = $that.path, asset.if_modified_since = coll.max([$that.timestamp, coalesce(asset.if_modified_since, $that.timestamp)]), asset: asset SET asn.asn_id = toString($that.client_asn), asn: asn SET server.server_id = $that.server_id, server.server_ip = $that.server_ip, server.cache_shield = $that.cache_shield, server.environment = $that.environment, server.host = $that.host, server.role = $that.role, server.pop = $that.pop, server: server SET pop.source = $that.pop, pop.environment = $that.environment, pop: pop CREATE (asset)<-[:REQUESTED]-(event)-[:REQUESTED_OVER]->(asn)-[:IN_CLIENT_GEO]->(clientGeo),(origin)<-[:FROM]-(pop)<-[:WITHIN]-(server)<-[:TARGETED]-(event)<-[:ORIGINATED]-(client)
  }
}

A standing query is configured to look for 10 consecutive cache MISS events involving the same server and asset pair within a defined duration.

YAMLJSON

- pattern:
    type: Cypher
    query: |-
        MATCH (server1:server)<-[:TARGETED]-(event1 {cache_class:"MISS"})-[:REQUESTED]->(asset)<-[:REQUESTED]-(event2 {cache_class:"MISS"})-[:TARGETED]->(server2:server)

        RETURN DISTINCT id(event1) AS event1

/api/v1/query/standing/STANDING-1

[
    {
        "pattern": {
        "type": "Cypher",
        "query": "MATCH (server1:server)<-[:TARGETED]-(event1 {cache_class:"MISS"})-[:REQUESTED]->(asset)<-[:REQUESTED]-(event2 {cache_class:"MISS"})-[:TARGETED]->(server2:server) RETURN DISTINCT id(event1) AS event1"
        },
        "outputs": {
        "cacheMissAlert": {
            "type": "CypherQuery",
            "query": "MATCH (server1:server)<-[:TARGETED]-(event1 {cache_class:"MISS"})-[:REQUESTED]->(asset)<-[:REQUESTED]-(event2 {cache_class:"MISS"})-[:TARGETED]->(server2:server) WHERE id(event1) = $that.data.event1 AND duration("PT45M") > duration.between(localdatetime(event1.timestamp, "yyyy-MM-dd HH:mm:ss.SSSSSS"), localdatetime(event2.timestamp, "yyyy-MM-dd HH:mm:ss.SSSSSS")) > duration("PT5M") AND event1.client_asn = event2.client_asn AND id(server1) = id(server2) AND id(event1) <> id(event2) MATCH (missEvents) WHERE id(missEvents) = idFrom('missEvents', server1.server_id, asset.full_path) SET missEvents.asset = event1.path, missEvents.server = event1.server_id, missEvents.pop = event1.pop, missEvents.firstMiss = coll.min([event1.timestamp, coalesce(missEvents.firstMiss, event1.timestamp)]), missEvents.latestMiss = coll.max([event1.timestamp, coalesce(missEvents.latestMiss, event1.timestamp)]), missEvents: missEvents CREATE (asset)-[:HAD]->(missEvents)-[:FROM]->(server1)<-[:TARGETED]-(event1), (server1)<-[:TARGETED]-(event2) WITH missEvents CALL incrementCounter(missEvents, "cumulativeCount", 1) YIELD count AS cumulativeCount MATCH (missEvents) WHERE missEvents.cumulativeCount = 10 RETURN 'http://localhost:8080/#' + text.urlencode('MATCH(missEvents:missEvents) WHERE id(missEvents)="' + toString(strId(missEvents)) + '" MATCH (event {cache_class:"MISS"})-[:TARGETED]->(server)<-[:FROM]-(missEvents)<-[:HAD]-(asset)<-[:REQUESTED]-(event {cache_class:"MISS"}) RETURN DISTINCT missEvents, event, server, asset LIMIT 10') AS Alert",
            "andThen": {
            "type": "PrintToStandardOut"
            }
        }
        }
    }
]

Once Quine detects the pattern, the event is sent to a standing query output for additional processing and action.

    outputs:
      cacheMissAlert:
        type: Cypher
        query: |-
          // Add constraints to the cache MISS events match involving the same server and asset pair.
          MATCH (server1:server)<-[:TARGETED]-(event1 {cache_class:"MISS"})-[:REQUESTED]->(asset)<-[:REQUESTED]-(event2 {cache_class:"MISS"})-[:TARGETED]->(server2:server)
          WHERE id(event1) = $that.data.event1
            // Time between consecutive cache MISSes between 5-45 minutes expressed in ISO 8601 duration format (https://en.wikipedia.org/wiki/ISO_8601#Durations)
            // Feel free to alter the range to meet your requirements
            AND duration("PT45M") > duration.between(localdatetime(event1.timestamp, "yyyy-MM-dd HH:mm:ss.SSSSSS"), localdatetime(event2.timestamp, "yyyy-MM-dd HH:mm:ss.SSSSSS")) > duration("PT5M")
            AND event1.client_asn = event2.client_asn
            AND id(server1) = id(server2)
            AND id(event1) <> id(event2)

          ////////////////////////////////////////////////////////
          // missEvents
          ////////////////////////////////////////////////////////
          // Manifest missEvents node to track metadata relative to consecutive cache MISSes that match the previous constraints
          MATCH (missEvents) 
          WHERE id(missEvents) = idFrom('missEvents', server1.server_id, asset.full_path)
          SET missEvents.asset = event1.path, 
              missEvents.server = event1.server_id, 
              missEvents.pop = event1.pop, 
              missEvents.firstMiss = coll.min([event1.timestamp, coalesce(missEvents.firstMiss, event1.timestamp)]), 
              missEvents.latestMiss = coll.max([event1.timestamp, coalesce(missEvents.latestMiss, event1.timestamp)]), 
              missEvents: missEvents

          // Create subgraph from consecutive cache MISS events to provide a visualization in the Quine Exploration UI
          CREATE (asset)-[:HAD]->(missEvents)-[:FROM]->(server1)<-[:TARGETED]-(event1),
                 (server1)<-[:TARGETED]-(event2)

          // Increment the missEvents counter for the purpose of triggering an alert at a specified threshold
          WITH missEvents CALL incrementCounter(missEvents, "cumulativeCount", 1) YIELD count AS cumulativeCount

          // Trigger alert (RETURN clause) that prints URL to local running Quine instance
          MATCH (missEvents)
          // Threshold at which to emit alert
          // Feel free to alter it to meet your requirements
          WHERE missEvents.cumulativeCount = 10
          RETURN 'http://localhost:8080/#' + text.urlencode('MATCH(missEvents:missEvents) WHERE id(missEvents)="' + toString(strId(missEvents)) + '" MATCH (event {cache_class:"MISS"})-[:TARGETED]->(server)<-[:FROM]-(missEvents)<-[:HAD]-(asset)<-[:REQUESTED]-(event {cache_class:"MISS"}) RETURN DISTINCT missEvents, event, server, asset LIMIT 10') AS Alert
        andThen:
          type: PrintToStandardOut

The result once the pattern is detected is to output a link to the console that an analyst can use to review the event further within Quine's Exploration UI.

2023-02-03 16:00:43,345 Standing query `cacheMissAlert` match: {"meta":{"isPositiveMatch":true,"resultId":"0e38c93e-338c-e964-8867-8487eb083e5b"},"data":{"Alert":"http://localhost:8080/#MATCH%28missEvents%3AmissEvents%29%20WHERE%20id%28missEvents%29%3D%2263c2f862-ea0f-3a3a-9f4a-09b11f176ad0%22%20MATCH%20%28event%20%7Bcache_class%3A%22MISS%22%7D%29-%5B%3ATARGETED%5D-%3E%28server%29%3C-%5B%3AFROM%5D-%28missEvents%29%3C-%5B%3AHAD%5D-%28asset%29%3C-%5B%3AREQUESTED%5D-%28event%20%7Bcache_class%3A%22MISS%22%7D%29%20RETURN%20DISTINCT%20missEvents%2C%20event%2C%20server%2C%20asset%20LIMIT%2010"}}

Running the Recipe

❯ java -jar quine-1.8.2.jar -r cdn.yaml --recipe-value in_file=cdn_data_50k.json
Graph is ready
Running Recipe: CDN Cache Efficiency By Segment
Using 11 node appearances
Using 14 quick queries
Using 9 sample queries
2023-02-03 17:05:00,342 WARN [NotFromActor] [graph-service-akka.quine.graph-shard-dispatcher-18] com.thatdot.quine.app.StandingQueryResultOutput$ - Could not verify that the provided Cypher query is idempotent. If timeouts or external system errors occur, query execution may be retried and duplicate data may be created. To avoid this, set shouldRetry = false in the Standing Query output
Running Standing Query STANDING-1
2023-02-03 17:05:00,847 WARN [NotFromActor] [graph-service-akka.quine.graph-shard-dispatcher-18] com.thatdot.quine.app.ingest.serialization.CypherJsonInputFormat - Could not verify that the provided ingest query is idempotent. If timeouts occur, query execution may be retried and duplicate data may be created.
Running Ingest Stream INGEST-1
Quine web server available at http://localhost:8080

 | => STANDING-1 count 4248
 | => INGEST-1 status is running and ingested 5560

Summary

When the standing query detects the cache miss pattern, it will output a link to the console that can be copied and pasted into a browser to explore the event in the Quine Exploration UI. Copy and paste the URL section of the match JSON from your console into your browser.

The nodes will be jumbled together when you first open the graph. Arrange the nodes to look similar to the image below before you start exploring.

Tip

Quick Queries are available by right clicking on a node.

Quick Query	Node Type	Description
Adjacent Nodes	All	Display the nodes that are adjacent to this node.
Refresh	All	Refresh the content stored in a node
Local Properties	All	Display the properties stored by the node
Reset Counter	missedEvent	Deletes the missedEvent
Server Pop	server	Displays the associated PoP
Cache Hit/Miss Percentage	server	Calculates the Hit/Miss percentages for the server
PoP Hit/Miss Percentage	pop	Calculates the Hit/Miss percentages for the PoP
PoP Origins	pop	Displays the asset origins the PoP is serving
Origin Hit/Miss Percentage	origin	Calculates the Hit/Miss percentages for the origin
Client Hit/Miss Percentage	client	Calculates the Hit/Miss percentages for the client
clientGeo Hit/Miss Percentage	clientGeo	Calculates the Hit/Miss percentages for the clientGeo
Asset Hit/Miss Percentage	asset	Calculates the Hit/Miss percentages for the asset
Client Geo	asn	Displays the clientGeo associated with the ASN
ASN Hit/Miss Percentage	asn