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 =&gt; multiline {
            'negate' =&gt; true
            'pattern' =&gt; '^\[\#\|\d{4}'
            'patterns_dir' =&gt; '/opt/logstash/agent/etc/patterns'
            'what' =&gt; 'previous'
        }
        'path' =&gt; '/var/log/glassfish/greyhound/server.log'
        'type' =&gt; 'glassfish'
    }
}
filter {  
    mutate {
        'add_field' =&gt; ['application', '%{type}']
    }

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

    if [type] == 'application' and [category] == '' {
        mutate {
            'update' =&gt; ['category', 'technical']
        }
    }

    date {
        'match' =&gt; ['timestamp', 'ISO8601']
    }
}

output {  
    redis {
        'data_type' =&gt; 'list'
        'host' =&gt; '172.168.1.250'
        'key' =&gt; '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

Search