dagblog.
← Archive

Logging patterns: request tracing, progress logging, aggregated messages, and exceptions to the rule

Roman Pichlík ·

This article looks at several logging patterns that make logs easier to read, help you run a system more efficiently, and show what just happened.

Background

GoodData is a business intelligence platform delivered as software as a service. End users work with interactive charts and reports in the browser. They do not need to install anything. The services needed for data analysis, including ETL, ROLAP, and the model, run in the GoodData cloud platform. REST is the interface both to the outside world and within the platform, apart from data uploads over WebDAV. Broadly speaking, any interaction with GoodData is an HTTP request. The same is true of interactions between internal services. A single incoming HTTP request corresponds to several internal HTTP requests and usually to several SQL statements or calls to NoSQL stores such as Cassandra or MongoDB.

Request tracing

When one HTTP request breaks down into several subrequests distributed across services, you need a way to trace it. If processing fails, the client also needs a way to identify that request. When each HTTP request arrives, we generate a unique identifier that follows it through GoodData and is eventually returned to the client. Every service reads and forwards that identifier in the X-GDC-REQUEST HTTP header. Messaging systems pass it as part of the message. Whatever form the identifier takes at the protocol level, every component must set it in its logging context. That ensures every log message carries the unique identifier.

The identifier can be divided further into colon-separated segments. Every service can append its own segment. This lets you filter for log messages related to request processing in a given service and all downstream services. The client can also generate the identifier. For example, our browser UI generates its first segment when it displays a new dashboard. All the HTTP requests for that dashboard share the same first segment. This lets you analyze how fast the dashboard loads, how many HTTP requests it takes, and so on. The segment provides a context for relating other information in the log.

When tracing a request, it is worth logging the request size, user agent, processing time, the unique identifier described above, request URI, user, HTTP status, and client IP address. Most of these values correspond to the standard Apache access log. It also helps to log the event time, thread, category, and severity. We use Splunk to process our logs, so we prefer to structure log messages as key=value pairs.

[The IP addresses, request path, and identifiers in this example have been replaced with documentation values.]

2013-11-10T17:50:49.891+0100 http-bio-8080-exec-194 c.g.c.web.filter.RequestLoggingFilter INFO: action=processing_request status=end uri=/gdc/example/resources method=GET time=74 size=8361 httpStatus=200 userAgent='Mozilla/5.0 ...' remote_address=192.0.2.10 forwarded_for='198.51.100.20' component=webapp request_id=request_example:service_example auth_user=user-example project_id=project-example

A log message this complete gives you quite a lot to work with. You can measure the ratio of reads to writes and request processing times, or watch for anomalies that may indicate a problem, such as changes in the mix of HTTP statuses or downward deviations from long-term measurements. The following dashboard illustrates anomaly measurement. Long-term data tells us the response times for individual REST resources. Each square represents one hour of measurement, and its color indicates the deviation. Green is normal, yellow is a slight slowdown, and red is a larger slowdown. White squares indicate insufficient data or downtime.

Progress logging

A request normally goes through several stages. There are at least three: start, successful completion, and unsuccessful completion.

try {
    log.info("action=started ...");
    doSomething();
    log.info("action=finished_ok ...");
}catch(RuntimeException e) {
    log.info("action=finished_error", e);
}

This simple approach lets you measure the ratio of successful to unsuccessful runs. If you only threw an exception, it would be much harder to match the entries in the log, especially when a run has several stages.

Aggregating log messages

When logging details such as the execution times of different parts of a program, and processing constraints limit log size, it is worth aggregating messages at the application level. This is especially helpful if every message has substantial overhead from the logging context.

long start = currentTimeMillis();
foo();
log.info("foo time={}", currentTimeMillis() - start);
start = currentTimeMillis();
hoo();
log.info("hoo time={}", currentTimeMillis() - start);
start = currentTimeMillis();
bar();
log.info("bar time={}", currentTimeMillis() - start);
long start1 = currentTimeMillis();
foo();
long start2 = currentTimeMillis();
hoo();
long start3 = currentTimeMillis();
bar();
log.info("foo time={} hoo time={}  bar time={} ", start2 - start1, start3 - start2, currentTimeMillis() - start3);

We produce on the order of hundreds of gigabytes of logs per day. Two more or two fewer lines may seem inconsequential, but the reverse is true. Imagine generating either three lines or one line with each HTTP request. Say one line, including the logging context, is 500 bytes, and production handles 13 million HTTP calls in 24 hours. At one line that comes to 6 GB of logs per day, compared with 18 GB at three lines. Aggregated messages are also easier for people to read. When hundreds of lines arrive each second, you have to find the related messages somehow. With an aggregated message everything is in one place. Better readability and smaller logs come at the cost of more complex logging code.

The exception to the rule

Whatever tool you use to process logs, there will be limits you have to work within. It is hard to generalize about the right balance between essential information and what you can regard as noise. Finding that balance is iterative. You contend with missing or excessive information in the logs while dealing with data spilling out elsewhere. My preferred compromise is to log exceptions to the rule. If you need more detail, raise the log level for the relevant category at runtime or change the code directly.

public boolean verifyCredentials(String userName, String password) {
    log.info("Username '{}' exists", userName);
    ...
    log.info("Password matches", password);
    ...
    log.info("Account is active");
    ...
    return ...
}

The exception to the rule here is invalid login credentials. There is no need to log that every condition was met, namely that the account exists, the password is correct, and the account is valid. Log when a condition fails instead.

public boolean verifyCredentials(String userName, String password) {
    log.info("Unknown username={}", userName);
    ...
    return false;
    
    log.info("Password doesn't match", password);
    ...
    return false;
    
    log.info("Account for username={} has not been activated", username);
    ...
    return false;
    
    return ...
}

This reversal gives us zero logging overhead in 99% of cases because everything behaves as expected. In the one percent of cases where a customer reports being unable to sign in, the log tells us exactly what went wrong. Of course, this code can still be refactored.

public boolean verifyCredentials(String userName, String password) {
    boolean verified = false;
    String reason = "Password doesn't match";
    try {
        ...
        reason = "";
        return verified;
    } finally {
        if(!verified) {
          log.info("Supplied credentials for username={} are not valid. reason={}", username, reason);
        }
    }
}

I have tried to share a few observations about logging. I am sure you have developed tips and observations of your own, and I would be glad to hear them.

Earlier articles on the subject

Related articles

Related CZ Podcast episodes