Engineering Blog

We love us some metrics. We pull data from all kinds of places including our monitoring system agent, from log data, from mbeans & from client timers. We pull all this stuff together into a variety of tools and slice and dice it into pretty graphs & ultimately turn it into knowledge about our service & our customers. You really cannot collect too much data about your service and we could talk all day about all the ways we watch things. But, since we don’t have all day, I wanted to focus this post on the foundation of much of our analysis – per-request logging

Why per-request logging?

There are a variety of ways to observe the performance of your systems & applications. Most folks are familiar with what we would call aggregate metrics. Aggregate metrics represent a group of measurements over time. This could be load average over the last 5 minutes, the number of transactions in the last minute, or the number of seconds spent waiting for the database over some period of time. Aggregate metrics are good because they are usually lightweight and easy to collect and they provide you with a view into changing trends. They are great for plugging into tools like Cacti or Nagios for trending and alerting.

However, once you identify a trend change, how do you get more detail about that change & understand why it occurred? This is where per-request metrics come in. Per-request metrics let you understand specifically what types of activity drove changes in a trend & allow you to get very specific about where you spend your time diagnosing your system. They also provide you with forensics data to use after the fact so that you can reproduce what led up to a problem, which is sometimes the only way to reproduce & fix it.

It all starts with your log format

There are endless different ways to log information about your system. We recommend you pick just one & standardize on that across the organization. Having a standard log format makes processing those logs a lot easier & makes sure that everyone is including similar metrics. The actual format of the logs isn’t super critical as long as it meets a few criteria:

• Machine parseable. It should be trivial for your tools to extract fields out of your log data – ideally directly into a data structure you can reference or easily store for future use. JSON (if you are cool) & XML (if you enjoy pain) are reasonable candidates for this but there are plenty of other formats.
• Precise timestamps. Transactions happen very fast and you want to be able to sequence events & measure the time taken. Your logs should at least have millisecond timing in the timestamps. If you can get microsecond timing that is even better.
• Make it easy to extend. You don’t want to have to re-write your log processing tools every time you need to add a field to your log. Make this process easy to handle. This is partly to do with your log format and part to do with the tools you use.
• Document it! Don’t complain that the guys building your new widget aren’t following an undocumented convention – document it, make it a standard.

At Rally we have a pretty verbose log format to track requests. We want to log any detail the application is aware of that is reasonable to log on a per-request basis. It’s important to remember that you will often want to go back and look at the data from a variety of perspectives, so just because you aren’t using the data today does not mean you shouldn’t log it. Defining a log

Important Note: Rally takes the security of customer data very seriously. One thing our logs do not contain is any information about the data in a customer’s account. We intentionally exclude anything which might be confidential from the logs so that we can safely allow our Operations & Engineering staff to view these logs for diagnostic purposes. Keep this in mind when deciding on a log implementation.

What details should you log?

In general there are a few categories of information you want to include in every log message. Within each of these categories you may choose to log more or less data – it depends a lot on what type of application you are creating and what data is relevant to you. This is based on what Rally has found useful.

Session information

You want to be able to find a series of requests from a single session. For this we include detail about the session such as a sessionID & timestamp. In this way we can understand all the requests that were made in sequence. You can include whatever details here are relevant but the most important part is that you are able to construct a series of events that belong to a single session or a group of sessions that have something in common.

Request Details

You want to understand what the user is interacting with in your system so you should be including any details relevant to the request. This could include the URI, GET/POST parameters (remember, keep confidential data out of logs) as well as possibly details about what hostname they made the request to, what protocol was used, etc. Add anything here that helps you identify what the user was trying to do when they made the request.

Response Detail

In the next post we’ll talk more about the details in a response but in general we want to include information about the success/failure of the request (did it generate a successful response or not). At Rally this is also where we include a lot of detail about timing, which we will expand on next time.

Gotchas – log the request ASAP

One of the problems we have run into is that if you wait for the completion of a request/response before you log data about the request there is a potential for data loss. What happens if your application fails after receiving a request but before sending a response? This hasn’t been a huge problem, the Rally application is pretty stable, but it has been a problem from time to time. We have chosen to address this by logging both at the start of a request as well as once the request is satisfied by a response. This assures that if something bad happens during the request we still have information about what request was in flight when that problem occurred and helps us to diagnose that issue.

More in the next post

In the next post we’ll talk more about the detail you can capture in the response and how you could use that – this is where using your log data for analytics becomes really interesting.