Here at Sematext we use Java (8!) and rely on centralized logging a lot. We like them so much that we regularly share our logging experience with everyone and help others with logging, especially, ELK stack. Centralized logging plays nice with Java (and anything else that can write pretty logs). However, there is one tricky thing that can be hard to get right: properly capturing exception stack traces. Unlike your typical single-line log events, stack traces have multiple lines and they aren’t always perfectly uniform. As such, most log shipper don’t handle them properly out of the box and typically treat each stack trace line as a separate event – clearly the wrong thing to do (n.b., if you are sending logs to Logsene this way, you are going to hit your plan limits faster, so make sure you send stack traces properly!). Thus, in most cases, a special configuration is needed in order to get stack traces right. Let’s see how one needs to configure Logstash for this task. We’ll be using Logstash 1.5.
Prerequisites
We start from the following assumptions:
- you have a working Logstash setup
- local logs are written to a file named: /var/log/test.log
- the conversion pattern for log4j/logback/log4j2 is: “%d %p %m%n”
Based on the above pattern, logs should look like this, for example:
2015-03-23 11:11:50,778 INFO Initializing Systems Cache
2015-03-23 11:11:58,666 ERROR Processing request failed
kafka.common.FailedToSendMessageException: Failed to send messages after 3 tries.
at kafka.producer.async.DefaultEventHandler.handle(DefaultEventHandler.scala:90)
at kafka.producer.Producer.send(Producer.scala:77)
at kafka.javaapi.producer.Producer.send(Producer.scala:42)
...
Extracting Exception Stack Traces Correctly
Stack traces are multiline messages or events. Logstash has the ability to parse a log file and merge multiple log lines into a single event. You can do this using either the multiline codec or the multiline filter, depending on the desired effect. A codec is attached to an input and a filter can process events from multiple inputs.
The most popular example that allows matching log lines that are a part of an exception uses a not so simple regexp:
input {
file {
path => "/var/log/test.log"
start_position => "beginning"
codec => multiline {
pattern => "(^\d+\serror)|(^.+Exception: .+)|(^\s+at .+)|(^\s+... \d+ more)|(^\s*Caused by:.+)"
what => "previous"
}
}
}
If the log line is part of an exception, it is appended to the last received log line. Once a new log line is received, the complete exception is sent to be processed. The downside of this approach is that it might not match all exceptions correctly. Sure, you could keep fine-tuning and expanding the regexp and attempt to capture all possible variants of stack trace format, but … there is a better (way.
input {
file {
path => "/var/log/test.log"
start_position => "beginning"
codec => multiline {
pattern => "^%{TIMESTAMP_ISO8601}"
negate => true
what => "previous"
}
}
}
The pattern looks for log lines starting with a timestamp and, until a new match is found, all lines are considered part of the event. This is done by setting the negate parameter to true.
Structuring Logs with Grok
To structure the information before storing the event, a filter section should be used for parsing the logs.
filter {
mutate {
gsub => [ "message", "\r", "" ]
}
grok {
match => [ "message", "(?m)%{TIMESTAMP_ISO8601:timestamp} %{LOGLEVEL:severity} %{GREEDYDATA:message}" ]
overwrite => [ "message" ]
}
date {
match => [ "timestamp" , "yyyy-MM-dd HH:mm:ss,SSS" ]
}
}
output {
stdout { codec => rubydebug }
}
The output section, in this case, is only used for debugging. In the next section we show how to actually ship your logs.
First, the mutate filter removes any “\r” characters from the event. Usually, this is something you want to do, to prevent later issues when storing and visualizing the logs where “\r” could be interpreted as a “\n”.
The grok filter splits the event content into 3 parts: timestamp, severity and message (which overwrites original message). The (?m) in the beginning of the regexp is used for multiline matching and, without it, only the first line would be read. The patterns used in the regexp are provided with Logstash and should be used when possible to simplify regexps.
By default, the timestamp of the log line is considered the moment when the log line is read from the file. The date filter fixes the timestamp, by changing it to the one matched earlier with the grok filter.
Shipping the Logs
Finally, now that you’ve got all your logs extracted, even those with multiple lines like exception stack traces, it’s time to ship them to wherever you keep your logs. Here’s how you’d ship them to Logsene:
output {
elasticsearch {
host => "logsene-receiver.sematext.com"
ssl => true
port => 443
index => "YOUR LOGSENE APP TOKEN GOES HERE"
protocol => http
manage_template => false
}
}
Final Words
If you are looking for a way to ship logs containing stack traces or other complicated multi line events, Logstash is the simplest way to do it at the moment.
It is written JRuby, which makes it possible for many people to contribute to the project. The downside of this ease of use and maintainability is that it is not the fastest tool for the job and it is also quite resource hungry (both CPU and memory). Though, depending on the log volume that needs to be shipped, this might not be a problem.
For those looking for tips on how to ship multiline logs with rsyslog or syslog-ng, subscribe to this blog or follow @sematext – tips for handling stack traces with rsyslog and syslog-ng are coming.
If your organization need help with logging (ELK stack, but also rsyslog, Fluentd, Flume…), let us know. If you like to build tools and products around logs and logging, join us – we’re always looking for good toolmakers world-wide.
sematext.wordpress.com 