Understanding Log-Cache

Products

• VMware Tanzu Application Service for VMs

Issue/Introduction

In this Knowledge base article, we will explore all things Log-Cache. For starters, be aware this will be less of a "deep dive into the lower level technicals" and more of a "what it does, and how it does it".

Of course we will touch on some technical details, but the main goal of this knowledge base article is to bring an understanding to what the Log-Cache is, how to use it, and how to tune it. To do so, we have prepared visualizations to elaborate on concepts that will incrementally build upon each other, ultimately making the Log-Cache not so complicated!

The outline of this knowledge base article is listed below:

• What is Log-Cache?

• A brief history of Log-Cache

• Key Components

• Log-Cache effect on VM memory

• How Log-Cache ingests and stores data

• How to interact with Log-Cache

• Scaling Log Cache

• A fun comparison of Log-Cache to a game 

What is Log-Cache?

Log-Cache is an ephemeral, self-pruning, in-memory, caching layer for all logs and metrics flowing through a cloud foundry environment. Prior to TAS v2.13, it was located on the Doppler instance group. Starting in TAS v2.13, it has since split off from the Doppler instance group and now has its own instance group. It is horizontally scalable and it has its own BOSH release. 

Please note that the pictures throughout this KB display the architecture from an environment prior to TAS v2.13 and thus the log-cache job will be displayed as being located on the Doppler VM. These same concepts apply to log-cache on TAS v2.13+ (including TAS 3.x, 4.x and beyond), however the location of the log-cache job will be on the Log-Cache VMs instead of Doppler VMs.

A brief History of Log-Cache

Log-Cache first showed up in TAS v2.2. It came about because of the limitations imposed by the traditional approach of getting recent logs and metrics in a cloud foundry environment from the firehose, especially in large environments. Prior to Log-Cache, if you wanted recent logs and metrics, it would require a stream request the loggregator component called the Traffic Controller. The Traffic Controller would, in turn, open a connection to every Doppler to receive those logs and then proxy them to the requesting client. See the following picture:

Without going into too much detail, just know that all logs and metrics are egressed from a Diego Cell (or any CF VM) to the Dopplers through a component called the Loggregator Agent (formerly known as metron). Notice how appA sits on Diego Cell VM 1. Diego Cell VM 1 is streaming its logs and metrics to both Doppler VM 1 and Doppler VM 2. This is because the Loggregator Agent opens up multiple connections to different dopplers, then round-robins the logs and metrics to them in an effort to "spread the load."  This means that logs from appA can end up on Doppler VM 1 and Doppler VM 2. This is why the Traffic Controller must open a connection to every Doppler, because the logs we are interested in could be on any Doppler. The Traffic Controller would then take all of appA's available logs from the Dopplers, order them, and then forward them to the requesting client (cf logs appA --recent).

This approach became age limited and slow as foundations grew larger and something new was needed; Log Cache was introduced. Log Cache brings a more optimized way to store logs and metrics plus offers a restful API to interact with, which is especially beneficial to various components including Autoscaler, Apps Manager, and the cf-cli. 

For completeness, let's look at how recent logs have been obtained since Log Cache was introduced. The flow for obtaining recent logs looks like the following if using a cf cli < v6.5:

 

And if using a cf cli >= v6.5, we will bypass the Traffic Controller altogether and instead travel through the Log Cache Gateway after being authorized by the Log Cache CF Auth Proxy:

Note: In the above pictures, we covered how to get data from Log Cache but omitted how Log Cache actually gets its data. We will cover this more in depth this in the section, How Log-Cache Ingests and Stores Data.

More official images and documentation can be found here.  

Environment

Product Version: 2.11 and above

Resolution

Log Cache Key Components

In this section, we will review some of the key components to be aware of for Log Cache. In the following picture, there may be some names that you have not seen before and that is ok. Some of it pertains to the internals of Log-Cache, but it is super helpful to be aware of when we get to the section on how Log Cache manages its data. Here is a high level outline of the components that are relevant to us in this KB:

Red Star #1 - This is just simply to show that the Log Cache job runs on the Doppler VM (In TAS v2.13+ the Log Cache job runs on the Log Cache VM). One of the internal components of Log Cache is called a Store (not to be confused with Metric-Store or Log-Store. This is the Log Cache's internal store).

Red Star #2 - This is the store for this Log Cache node. This is where all logs and metrics are stored in binary avl trees per source-id. Lets elaborate on source-id a bit. A source-id is a way to uniquely identify a source in the environment. If it is an app, the source-id will be the app's guid. If it is a platform component, the source-id is the name of the component, for example gorouter or reverse-log-proxy. Within the store there is a syncMap.

Red Star #3 - This is the Store's internal syncMap. The store itself holds all of the logs and metrics and the syncMap is the store's internal component that maps each source-id to it's memory location within the store. For example if we extract part of the syncMap, we would see something similar to the following: 

b82fee98-76f6-46b2-b3d4-ef92d559f361:0xc00018afa0 bbs:0xc000010408

The syncMap says the avl binary tree for app with guid b82fee98-76f6-46b2-b3d4-ef92d559f361 is at memory location 0xc00018afa0. The avl binary tree for the platform component bbs is at memory location 0xc000010408.

The Store has a few parameters that are of interest to us and we should look at them a little closer, as they are especially important to understand when considering the hosting VM's memory and cache duration. These two parameters are:
 

• MEMORY_LIMIT_PERCENT - The total amount of VM memory the Log Cache Store is allowed to use at any time. If it is over this amount, Log Cache will prune the oldest envelopes first to get back under this limit. This limit defaults to 50% and is non-configurable.

• MAX_PER_SOURCE - The total number of envelopes the Log Cache Store is allowed to store per source-id. This defaults to 100,000 and is configurable in the TAS tile at TAS tile -> Advanced Features -> Maximum number of envelopes stored in Log Cache per source. See the following:
  
  

We will revisit these two parameters as well as Log Cache's pruning behavior a little more in-depth when we get to the section, Log-Cache effect on VM memory. The following picture helps visualize what we just learned in the Star #3 section:

Red Star #4 - These jobs are actually separate from the Log Cache but Log Cache relies on one of them to receive it's envelopes (logs and metrics). Log Cache can ingest from the log-cache-nozzle job via the firehose or it can ingest from the log-cache-syslog-server via the shared nothing architecture. Prior to TAS v2.13 the log-cache-syslog-server is disabled by default but can be manually enabled. If log-cache-syslog-server is enabled, then the log-cache-nozzle will be automatically disabled. Starting with TAS v2.13 the log-cache-syslog-server is enabled by default and thus the log-cache-nozzle is disabled by default. Starting with TAS v3.0 the log-cache-nozzle is removed completely and thus the only option for log-cache ingestion is via log-cache-syslog-server.

It doesn't matter which source Log Cache gets it's messages from but only one should be present at a time (either the log-cache-nozzle or log-cache-syslog-server). This setting is configurable in an OpsMan environment at TAS tile -> System Logging section -> Enable Log Cache syslog ingestion. See the following picture:

For the rest of this KB, we will refer to either of these jobs collectively as the Log Cache Ingestor for simplicity. When you see Log Cache Ingestor, it is referring to either log-cache-nozzle or log-cache-syslog-server, whichever one is enabled in the environment.

Log-Cache effect on VM memory

Lets imagine that we have a TAS v2.11 environment with only one Doppler VM, thus only one Log Cache Node. This Doppler VM only has 4GB of memory. There are 100 different source-ids in the environment. With everything we have learned so far, it should be a little more clear now that this Doppler VM memory will be heavily utilized. Lets look at the numbers:

100 source-ids with a MAX_PER_SOURCE of 100,000 at an average message size of 512 bytes = 5120000000 bytes = 5GB (512 bytes is the average metric envelope size but large log envelopes can actually reach up to 61440 bytes. To keep things simple for this example, let's pretend every source-id is emitting metric envelopes only).

If the Doppler VM is only 4GB in total and we have enough source-ids to fill up 5GB worth of data in Log Cache, what will happen?

This is where Log Cache's self pruning functionality kicks in. Log Cache has two ways to governs it's memory consumption on the hosting VM:

 

1. If the MEMORY_LIMIT_PERCENT of the Log Cache Store is exceeded, it will prune until it gets back under that limit (remember this is 50% and non-configurable). Let's elaborate on this a little. When Log Cache starts up initially, it triggers a truncation loop to start within the Store and the truncation loop runs infinitely at the specified truncation interval. This truncation loop will check to see if the Store is utilizing over 50% of the hosting VM memory. If it is under 50%, the truncation loop will do nothing and continue checking specified truncation interval. If the Store is utilizing over 50% of the hosting VM memory, then it performs some math to determine how many messages it will need to prune to get back under 50% VM memory utilization. It will then cycle across all source-ids and build an expiration heap of envelopes based on timestamps of all the oldest envelopes regardless of source-id and mark them for expiration. Even though the envelopes are marked as expired, the memory on the VM isn't actually released until golang garbage collection runs. Prior to Log Cache v2.11.3 (not TAS version, but Log Cache version), the truncation interval was set to 500ms and garbage collection ran every iteration. Starting in Log Cache v2.11.3, the truncation interval is set to 1s and garbage collection is ran after 3 iterations.

2. The MAX_PER_SOURCE per source-id will ensure that no one source-id exceeds more than it's allotted footprint in the Store. For example, the gorouter is a very active logging component due to the different metrics it emits, especially for http latency tracking. If the MAX_PER_SOURCE is 100,000, then the gorouter source-id will only be able to store up to 100,000 messages at a time in the Store. What happens when the 100,001st envelope comes in? A push and pop mechanism is used for the gorouter's avl tree. It will push out the oldest message and pop in the newest message in a FIFO (First In First Out) style. This ensures we always have the latest 100,000 messages available in the cache without overrunning the Store's per source limit.

Options:

How to interact with Log-Cache

Log Cache packages a simple yet powerful api to interact with. We can interact with this api via curl or the log-cache-cli.

The documentation linked above is pretty straight forward so we will use this section to only go over a few commands and examples.

One powerful command to be aware of is cf log-meta:

$ cf log-meta
Retrieving log cache metadata as admin...
 
Retrieving app and service names as admin...
 
Source                                Source Type  Count   Expired   Cache Duration
app-usage-scheduler                   application  100000  492411    173h24m14s
gorouter                              platform     100000  257337312 1m2s
appA                                  application  35582   1618173   3h50m55s
....data removed for brevity

It gives us 5 columns:
 

• Source - The name of the source
• Source Type - The type of the source (application / platform / unknown)
• Count - The number of messages available in the cache currently for that source-id
• Expired - The number of messages that have been expired from the cache for that source-id
• Cache Duration - The amount of time between the very first and very last message for that source-id

In this example, we can see app-usage-scheduler has reached it's max per source of 100,000 messages. This means all new messages will trigger a push and pop action that will push out the oldest messages and pop on the newest messages. Every time a message gets pushed out, it is expired and the expired count goes up. This is the desired behavior of log-cache. We want all source-id's to able to reach the max per source and expire the old ones as new ones come in.

Gorouter does the same thing, but one difference is that it is a platform component. Also note how the cache duration is 1m2s. This means that Gorouter has logged 100,000 messages in 1m2s. There is a lot of http activity going on here and Gorouter would be considered a "more active" logger than appA or app-usage-scheduler.

appA is a little bit different though. We can see that it has 35582 messages available but 1618173 have expired. This tells us that the log-cache is expiring messages before that unique source reached its max per source limit of 100000. This means that those messages were victims of the truncation loop mentioned earlier in this KB.

When log-cache prunes old messages for source-id's that haven't reached a max per source limit, this typically means that there are too many active source-id's on that specific Log Cache node and/or there are not enough Log Cache hosting VMs for the log-cache to spread out it's source-ids more evenly and/or we need to vertically scale the Log Cache hosting VMs.

The log-meta command is great for identifying active logging sources in an environment. See this KB for an example of how to use it to identify noisy sources.

The metrics in Log Cache can be obtained via promql queries. Again, the documentation goes more in-depth on this, so we will only look at one example here.

To get the per-second rate of doppler ingress across all dopplers for the last 10 minutes:

cf query "rate(ingress{source_id='doppler'}[10m])"

 

Scaling Log Cache

The Log Cache repo has scaling recommendations near the bottom of the Read-me. 

Vertical scaling and horizontal scaling the Log Cache hosting VMs are both optional and each have their own strengths depending on needs. There is no "one size fits all" when it comes to scaling Log Cache but here are some things to consider:
 

• Horizontally scaling adds more members to the cluster for Log Cache and the per Log Cache node caching load will be more spread out. When adding more nodes to the cluster, Log Cache hosting VM recreates are not necessary as the bpm.yml on them will be updated during the deploy and the jobs will be restarted. The hashing algorithm will immediately pick up the new nodes and spread out the source-id's accordingly. 
• Vertical scaling in regards to memory will allow more space for log-cache to use. One thing to consider here with this is, if we vertically scale in regards to memory, it will allow log-cache to store more messages per source-id and it might require more CPU power as well in order to manage those extra messages, especially if we get a wave of doppler ingress (Doppler VMs prior to TAS v2.13 will need CPU to manage routing messages from itself to it's many subscribers and managing Log Cache).

How Log Cache Ingests and Stores data

In this section, we will learn how Log Cache handles an envelope as it is receiving it from the Log Cache Ingestor.

1. Envelope is received by Log Cache from the Log Cache Ingestor.

2. Log Cache obtains the source-id of the envelope, hashes it, and checks it's syncMap to see if it already has storage initialized for that source-id. If it does not, it will create an avl tree for that source-id, map the memory location to that source-id in its syncMap, and finally place the envelope in that source-id's avl tree. If the syncMap does have a reference to that source-id already, then it will simply obtain the memory location of the already existing avl tree and place the message in that tree. It is important to note that this avl tree is simply an optimized storage mechanism that allows it to store the envelopes in a binary format sorted by timestamp.

And that's it, for a single node Log Cache cluster!

The story is not over. What if we have 2 Log Cache hosting VMs?

When Log Cache is clustered, the behavior is overall the same but there is an additional step that can occur during the step 2 above that is slightly different. Let's explore this:

You may have noticed the bolded "hashes it" in step 2. This is important as it helps route the envelopes to different nodes when Log Cache is clustered. A hashing algorithm is used to spread the source-id's among the Log Cache nodes in the cluster. Log Cache is aware of when it is clustered due to its configuration file bpm.yml. For example, if we ssh onto a Doppler VM (prior to TAS v2.13) and run the following:

 cat /var/vcap/jobs/log-cache/config/bpm.yml 

We will see the Log Cache Cluster information similar to the following:

    # Cluster Configuration
    NODE_INDEX: "1"
    NODE_ADDRS: "10.213.49.158:8080,10.213.49.159:8080"

As Log Cache starts up initially, it is fed this bpm.yml file data and Log Cache is automatically aware of it's cluster peers. This is important because it will know how many Log Cache nodes are in the cluster as well as their indexes and their IP addresses. The hashing algorithm is set up in such a way that when it is given a source-id, it will return a node index to store that envelope on. If the Log Cache node that it returns is not the Log Cache node itself that the envelope was received on, it will route the envelope to the proper node accordingly. This is especially important because this sets the standard of which source-id's belong to which nodes.

To reiterate:

Imagine that there are three Log Cache nodes and a new app was pushed. Log Cache node 1 and Log Cache node 2 both receive an envelope for this new app at the exact same time. Do they both see that the source-id doesn't exist anywhere in their syncMaps and proceed to create storage locally for it and alert the peer members? No, that would result in two different Log Cache nodes holding the same source-id. Regardless of the node that hashes the source-id, the algorithm will always point to the same node index. To illustrate this example more, see the following output from a hacked Log Cache Server custom endpoint that hashes a string given to it and returns the node to store it on (this is not an active endpoint, it is only here for the purpose of this KB):

doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source33
name source33 lookup result: [0]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source33
name source33 lookup result: [0]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source1
name source1 lookup result: [1]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source33
name source33 lookup result: [0]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source1
name source1 lookup result: [1]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source4
name source4 lookup result: [2]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source1
name source1 lookup result: [1]
doppler/c3c638e9-db2c-4c88-a2c4-a0647de47980:~# curl localhost:8999/lookup?name=source4
name source4 lookup result: [2]

Notice how the sources always hash to the same node index:
 

source33 will be placed on node 0
source1 will be placed on node 1
source4 will be placed on node 2

The hashing algorithm will return the same node index regardless of which Log-Cache node hashes the source-id. 

If this still seems kind of challenging to grasp, take a look at the section at the end of this KB called A fun comparison of Log-Cache to a game for a very simple, relatable example to help it make more sense and then re-read this section.

Additional Information

A fun comparison of Log-Cache to a game 

This section is an attempt to help visualize how Log Cache works. 

Imagine there is a room.

There are 3 buckets in this room. 

Each bucket has a number on it: Bucket 0, Bucket 1, Bucket 2. 

In front of each bucket is a person. Person 0 is at Bucket 0. Person 1 is at Bucket 1. Person 2 is at Bucket 2.

On the wall there is a dry erase board.

The dry erase board reads:

Red ping pong balls go in Bucket 2
Blue ping pong balls go in Bucket 1
Yellow ping pong balls go in bucket 3
Purple ping pong balls go in bucket 2
Green ping pong balls go in bucket 1

Now, in the game there will be a stream of randomly different colored ping pong balls (red, blue, yellow, purple, or green) bounced to each person. The ping pong balls must be placed in the buckets grouped according to like color. All red ping pong balls must go in the same bucket, all blue ping pong balls must go into the same bucket...etc.

The person must catch each ping pong ball one by one, look at it's color, then look at the dry erase board to see which bucket it goes in and place it accordingly. No matter which person looks at that dry erase board, they all see the same ping pong ball color-to-bucket placement.

If the person holding the ping pong ball has the bucket it is supposed to go in, she simply places it in the bucket. However, if the ping pong ball needs to go to another bucket, she must give it to the person in front of the associated bucket so that person can place it in his bucket.

This is how Log Cache handles envelopes in a nutshell. The only difference that we didn't highlight is batching. Instead of a stream of ping pong balls one by one, they get a box full of different color ping pong balls pushed to them and the person must grab the ping pong balls out of the box one by one. This part isn't as important but I  wanted to share that information for completeness.

The ping pong balls are envelopes. The person is the Log Cache Ingestor. The Bucket is the Log Cache Store. The dry erase board is the hashing algorithm.