As I mentioned in my recent post, I got a chance to upgrade the drupal.org ELK stack last week. In doing so, I got to take a look at a Logstash configuration that I created over a year ago, and in the course of doing so, clean up some less-than-optimal configurations based on a year worth of experience and simplify the configuration file a great deal.

The Drupal.org Logging Setup

Drupal.org is served by a large (and growing) number of servers. They all ship their logs to a central logging server for archival, and around a month’s worth are kept in the ELK stack for analysis.

Logs for Varnish, Apache, and syslog are forwarded to a centralized log server for analysis by Logstash. Drupal messages are output to syslog using Drupal core’s syslog module so that logging does not add writes to Drupal.org’s busy database servers. (@TODO: Check if these paths can be published.) Apache logs end up in/var/log/apache_logs/$MACHINE/$VHOST/transfer/$DATE.log, Varnish logs end up in/var/log/varnish_logs/$MACHINE/varnishncsa-$DATE.log and syslog logs end up in /var/log/HOSTS/$MACHINE/$DATE.log. All types of logs get gzipped 1 day after they are closed to save disk space.

Pulling Contextual Smarts From Logs

The Varnish and Apache logs do not contain any content in the logfiles to identify which machine they are from, but the file input sets a path field that can be matched with grok to pull out the machine name from the path and put it into the logsource field, which Grok’s SYSLOGLINE pattern will set when analyzing syslog logs.

Filtering on the logsource field can be quite helpful in the Kibana web UI if a single machine is suspected of behaving weirdly.

Using Grok Overwrite

Consider this snippet from the original version of the Varnish configuration. As I mentioned in my presentation, Varnish logs are nice in that they inclue the HTTP Host header so that you can see exactly which hostname or IP was requested. This makes sense for a daemon like Varnish which does not necessarily have a native concept of virtual hosts (vhosts,) whereas nginx and Apache default to logging by vhost.

Each Logstash configuration snippet shown below assumes that Apache and Varnish logs have already been processed using theCOMBINEDAPACHELOG grok pattern, like so.

filter {
if [type] == "varnish" or [type] == "apache" {
grok {
match => [ "message", "%{COMBINEDAPACHELOG}" ]
}
}
}

The following snippet was used to normalize Varnish’s request headers to not include https?:// and the Host header so that therequest field in Apache and Varnish logs will be exactly the same and any filtering of web logs can be performed with the vhost andlogsource fields.

filter {
if [type] == "varnish" {
grok {
# Overwrite host for Varnish messages so that it's not always "loghost".
match => [ "path", "/var/log/varnish_logs/%{HOST:logsource}" ]
}
# Grab the vhost and a "request" that matches Apache from the "request" variable for now.
mutate {
add_field => [ "full_request", "%{request}" ]
}
mutate {
remove_field => "request"
}
grok {
match => [ "full_request", "https?://%{IPORHOST:vhost}%{GREEDYDATA:request}" ]
}
mutate {
remove_field => "full_request"
}
}
}

As written, this snippet copies the request field into a new field called full_request and then unsets the original request field and then uses a grok filter to parse both the vhost and request fields out of that synthesized full_request field. Finally, it deletesfull_request.

The original approach works, but it takes a number of step and mutations to work. The grok filter has a parameter calledoverwrite that allows this configuration stanza to be considerably simlified. The overwrite paramter accepts an array of values thatgrok should overwrite if it finds matches. By using overwrite, I was able to remove all of the mutate filters from my configuration, and the enture thing now looks like the following.

filter {
if [type] == "varnish" {
grok {
# Overwrite host for Varnish messages so that it's not always "loghost".
# Grab the vhost and a "request" that matches Apache from the "request" variable for now.
match => {
"path" => "/var/log/varnish_logs/%{HOST:logsource}"
"request" => "https?://%{IPORHOST:vhost}%{GREEDYDATA:request}"
}
overwrite => [ "request" ]
}
}
}

Much simpler, isn’t it? 2 grok filters and 3 mutate filters have been combined into a single grok filter with two matching patterns and a single field that it can overwrite. Also note that this version of the configuration passes a hash into the grok filter. Every example I’ve seen just passes an array to grok, but the documentation for the grok filter states that it takes a hash, and this works fine.

Ensuring Field Types

Recent versions of Kibana have also gotten the useful ability to do statistics calculations on the current working dataset. So for example, you can have Kibana display the mean number of bytes sent or the standard deviation of backend response times (if you are capturing them – see my DrupalCon Amsterdam slides for more information on how to do this and how to normalize it between Apache, nginx, and Varnish.) Then, if you filter down to all requests for a single vhost or a set of paths, the statistics will update.

Kibana will only show this option for numerical fields, however, and by default any data that has been parsed with a grok filter will be a string. Converting string fields to other types is a much better use of the mutate filter. Here is an example of converting the bytes and the response code to integers using a mutate filer.

@TODO: Test that hash syntax works here!

filter {
if [type] == "varnish" or [type] == "apache" {
mutate {
convert => {
[ "bytes", "response" ] => "integer",
}
}
}
}

Lessons Learned

Logstash is a very powerful tool, and small things like the grokoverwrite parameter and the mutate convert parameter can help make your log processing configuration simpler and result in more usefulness out of your ELK cluster. Check out Chris Johnson’s post about adding MySQL Slow Query Logs to Logstash!

If you have any other useful Logstash tips and tricks, leave them in the comments!