Skip to content
July 2, 2010 / cohodo

Putting Structure Into Application Logs

Most of us know that application logs can be a fantastically rich source of data, and if you can mine them effectively they can be an extremely valuable resource in lots of contexts. We make use of the app logs from the various Platform components in a number of ways – for trend analysis, monitoring, tracking deployments of new features, fault diagnosis and post-mortem analysis.

Unfortunately for us ops peeps, application logging is a big, moving target. We might dark deploy a version of the software with super verbose output, or we might introduce a new feature which renders our previous perl + regex home brew tool to pull out important values pretty useless, this means that the important data that we want to trend on in March 2009 needs a different regex to June 2010.

Standards! I hear you cry! It seems (to me) existing standards are good at getting the message into the “right” place in the log, which makes them easy to parse and pass around the network, but they rely on the fact that you will be saying the same thing in the logs over and over again – they rely on rigid structure, and a change to logs is the same as adding a new column to an sql database. This means that if you are trying to match values on their position – sometimes adding a new variable will render your previous match useless – and worst still you might not know about it until it is too late!

Basically, string matching just isn’t robust or portable enough for what we want to do so we’ve been adding structure to the data in our logs. We’re currently outputting logs from some of our services as json – this means that we can dynamically add and remove variables as we wish, we can potentially send the logs straight to an indexer, load them into a db, convert them to RDF, or process them using Hadoop-based tools. We can still do our perl based graph building – by converting the json to an array or a hash and pulling out the right fields – irrespective of where they appear in the output.

To get a fully jsonised log line we need to work with 3 main areas, firstly the application itself, the applications logging handler, and finally the centralised logging tool, here is some real output:

    "syslogDate" : "2010-06-28T15:24:45+01:00",
    "syslogFacility" : "local0",
    "syslogPriority" : "info",
    "host" : "somehost.talis",
    "Message" : {
        "Process": "WS",
        "Date": "2010-06-28 15:24:45,834",
        "Priority": "INFO",
        "Category": "MemoryUsageLogger",
        "Thread": "Memory-Usage-Logger-Thread",
        "id": "",
        "Message": {
            "Memory Usage" : {
                "Heap" : {
                    "init" : "60",
                    "committed" : "73",
                    "used" : "26",
                    "max" : "864"
                "Non-Heap" : {
                    "init" : "23",
                    "committed" : "24",
                    "used" : "22",
                    "max" : "216"

The first part of the json comes from syslog-ng, this puts in the details around how syslog sees the Log Message, the first sub “Message” comes from Log4J, and is how Log4J sees the message and the final “Message” is from the application itself, which in this instance gives us some general information about Memory usage.

As well as making our lives easier, it also means we can correlate on events must more quickly, and easily. From the simple Json above – we could write a rule that identifies descrepancies between “syslogDate” and “Date”, which could indicate a problem with the system clock on the application server, or even identify a problem with the syslog server unexpectedly slowing down.

One of the uses we’re putting this too is to build real-time reporting of coarse-grained application events to compliment the views we get from ganglia etc.


Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: