Pages

Sunday, 9 February 2014

How to Configure Logstash to handle Glassfish’s server logs

Logstash is a nice tool for managing events and logs. After you finished the setup, the next step is the configuration of the agents/shippers. Since one of the strengths of logstash is the ability to query your logs and make some nice statistics about them, it is key to ‘convert’ your logs somehow in a more structured way. Here’s a little example on how to do this…
The configuration of a shipper is done through a config file (ex. logstash.conf). Below is an example to handle Glassfish’s server log.
input {
    file {
        codec => multiline {
            'negate' => true
            'pattern' => '^\[\#\|\d{4}'
            'patterns_dir' => '/opt/logstash/agent/etc/patterns'
            'what' => 'previous'
        }
        'path' => '/var/log/glassfish/greyhound/server.log'
        'type' => 'glassfish'
    }
}

filter {
    mutate {
        'add_field' => ['application', '%{type}']
    }

    if [message] =~ /\[GLF_INT\]/ {
        mutate {
            'update' => ['type', 'application']
        }
        grok {
            'keep_empty_captures' => true
            'named_captures_only' => true
            'pattern' => '(?m)\[\#\|%{TIMESTAMP_ISO8601:timestamp}\|%{LOGLEVEL}\|%{DATA:server_version}\|%{JAVACLASS}\|%{DATA:thread}\|\[GLF_INT\]%{DATA:category}\|%{DATA:loglevel}\|%{DATA:class}\|line:%{DATA:linenumber}\|%{DATA:message_detail}\|\#\]'
            'patterns_dir' => '/opt/logstash/agent/etc/patterns'
        }
    } else {
        mutate {
            'add_field' => ['category', 'technical']
            'update' => ['type', 'internal']
        }
        grok {
            'keep_empty_captures' => true
            'named_captures_only' => true
            'pattern' => '(?m)\[\#\|%{TIMESTAMP_ISO8601:timestamp}\|%{LOGLEVEL:loglevel}\|%{DATA:server_version}\|%{JAVACLASS:class}\|%{DATA:thread}\|%{DATA:message_detail}\|\#\]'
    'patterns_dir' => '/opt/logstash/agent/etc/patterns'
        }
    }

    if [type] == 'application' and [category] == '' {
        mutate {
            'update' => ['category', 'technical']
        }
    }

    date {
        'match' => ['timestamp', 'ISO8601']
    }
}

output {
    redis {
        'data_type' => 'list'
        'host' => '172.168.1.250'
        'key' => 'logstash'
    }
}
This file is also available on Github: https://gist.github.com/glnds/8774267


Some remarks

Multiline filter

By default Logstash will treat every new line from your log as a new event. Since events often consists of multiple lines, you have to tell Logstash how to group multiple lines into a single event. For Glassfish’s server logs the Logstash multiline filter from my example will start a new event for every line starting with ‘[#|’ + 4 digits. You can easily test this here: http://rubular.com

Grok that log

One of the basic things you’ll do with your logs is applying a grok filter to them. This process is all about parsing the arbitrary text and structure it.
Here are two grok examples based on the above config.
Example 1
[#|2014-02-02T02:08:50.114+0000|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=45;_ThreadName=Thread-2;|[GLF_INT]functional|INFO|com.ex.controller.AuthenticationController|line:148|[LOGIN] Successful re-login with token for user ...|#]
This pattern will be parsed by the first grok pattern (through the occurrence of [GLF_INT]) resulting in the following structure:
{
    "timestamp": ["2014-02-02T02:08:50.114+0000"],
    "server_version": ["glassfish3.1.2"],
    "thread": ["_ThreadID=45;_ThreadName=Thread-2;"],
    "category": ["functional"],
    "loglevel": ["INFO"],
    "class": ["com.ex.controller.AuthenticationController"],
    "linenumber": ["148"],
    "message_detail": ["[LOGIN] Successful re-login with token for user ..."]
} 
Example 2
[#|2014-02-01T17:50:17.139+0000|INFO|glassfish3.1.2|javax.enterprise.system.core.com.sun.enterprise.v3.server|_ThreadID=1;_ThreadName=Thread-2;|GlassFish Server Open Source Edition 3.1.2.2 (5) startup time : Felix (7,359ms), startup services(76,273ms), total(83,632ms)|#]
This pattern will be parsed by the second grok pattern resulting in the following structure:
{
    "timestamp": ["2014-02-01T17:50:17.139+0000"],
    "loglevel": ["INFO"],
    "server_version": ["glassfish3.1.2"],
    "class": ["javax.enterprise.system.core.com.sun.enterprise.v3.server"],
    "thread": ["_ThreadID=1;_ThreadName=Thread-2;"],
    "message_detail": ["GlassFish Server Open Source Edition 3.1.2.2 (5) startup time : Felix (7,359ms), startup services(76,273ms), total(83,632ms)"]
}
Here’s a nice tool to test your own grok patterns: http://grokdebug.herokuapp.com


A Little about SLF4J and Logback

Under the hood my java application is using SLF4J and Logback. Although Logback is not the most common choice, it has a nice advantage compared to other logging frameworks: currently it is the only framework implementing SLF4J Markers. Since my application contains both functional and technical log messages it was a requirement to have both types of messages marked properly in logstash. Although there are multiple solutions to handle this, I solved it through the use of an SLF4J Marker. Here’s an example.
Java Class:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

    ...
    private static final Marker FM = MarkerFactory.getMarker("functional");
    private static final Logger LOG = LoggerFactory.getLogger(AuthenticationController.class);
    ...
    LOG.info(FM, "[LOGIN] Successful login with username/password for user " + user.getName());
    ...
Logback config:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
        <Pattern>[GLF_INT]%marker|%level|%logger|line:%line|%msg%n</Pattern>
    </layout>
</appender>

Kibana

Here are some screenshots from the end result in kibana:
Kibana Functional Kibana Technical