Handling log levels in logstash

Most logging frameworks include a concept of severity or priority, including tags like “WARNING”, “CRITICAL”, etc.

Breaking these off into their own fields in logstash makes a lot of sense.  Unfortunately, when you go to look for problems, you end up with a search like this:

log_level:("EMERG" OR "ALERT" OR "CRIT" OR "ERROR")

which is both inefficient (5 string comparisons) and unclear (did I miss or misspell one?).

What I like to do is create an additional, numeric representation of the log level, so that my search looks like this:

log_code:<=3

With the two fields, you can easily query for bad stuff, but still use log_level for display (in aggregations, etc).

I have standardized on the Apache LogLevel definitions:

Level Description Example
emerg Emergencies – system is unusable. “Child cannot open lock file. Exiting”
alert Action must be taken immediately. “getpwuid: couldn’t determine user name from uid”
crit Critical Conditions. “socket: Failed to get a socket, exiting child”
error Error conditions. “Premature end of script headers”
warn Warning conditions. “child process 1234 did not exit, sending another SIGHUP”
notice Normal but significant condition. “httpd: caught SIGBUS, attempting to dump core in …”
info Informational. “Server seems busy, (you may need to increase StartServers, or Min/MaxSpareServers)…”
debug Debug-level messages “Opening config file …”

My logstash config is broken into many smaller pieces.  The filter{} stanza for each type of log is contained in a separate file, and there are generic stanzas that run before and after the business logic.

If you’re processing a log file whose levels are different, you need to normalize them.  The translate{} filter is great for this:

translate {
  dictionary => [
    "WRN", "warn",
    "INF", "info",
    "DBG", "debug"
  ]
  field => "[loglevel][tmp]"
  destination => "[loglevel][name]"
  remove_field => [ "[loglevel][tmp]" ]
}

From what I can tell, translate{} won’t replace the source field, so the earlier grok{} matches into a temporary variable that is removed here.

Once [loglevel][name] is normalized, I use a post-processing config file to add the second [loglevel][code] field:

if [loglevel] and [loglevel][name] {
  translate {
    dictionary => [
      "emerg", "0",
      "alert", "1",
      "crit", "2",
      "error", "3",
      "warn", "4",
      "notice", "5",
      "info", "6",
      "debug", "7"
    ]
    field => "[loglevel][name]"
    destination => "[loglevel][code]"
  }

  # make it an int
  mutate {
    convert => [ "[loglevel][code]", "integer" ]
  }

 

Images in Markdown panels

Here’s a sample:

![Alt text](https://www.elastic.co/static/img/logo-elastic.png)

Elasticsearch mappings and templates

Overview

In the relational database world, you create tables to store similar items.  In Elasticsearch, the equivalent of the table is a type.

You eventually get around to defining the properties of each field, be they char, varchar, auto-incrementing unsigned integer, decimal, etc. Elasticsearch is no different, except they call these mappings.

Mappings

Mappings tell Elasticsearch how to deal with your field:

  • what type of data does it contain?
  • should the data be indexed?
  • should it be tokenized (and how)?

If you just blindly throw data at Elasticsearch, it will apply defaults based on the first value it sees.  A value of “foo” would indicate a string; 1.01 would indicate a decimal, etc.

A major problem comes when the value is not indicative of the type.  What if your first string value contained “2015-04-01”?  Elasticsearch thinks that is a date, so your next value of “foo” is now invalid.  The same with basic numbers – if the first value is 1, the type is now integer, and the next value of 1.01 is now invalid.

The best way to deal with this is to create your own mapping, where you explicitly define the types of each field.   Here’s a sample:

$ curl -XPUT 'http://localhost:9200/my_index/_mapping/my_type' -d '
{
  "my_type" : {
    "properties" : {
      "my_field" : {"type" : "string", "store" : true }
    }
  }
}
'

Defined as a string, a value of “2015-04-01” in my_field would not be interpreted as a date.

Nested fields are described as nested properties.  “address.city” could be mapped like this:

{
  "my_type" : {
    "properties" : {
      "address" : {
        "properties" : {
          "city" : {
            "type" : "string"
          }
        }
      }
    }
  }
}

There are a lot of properties that can be specified for a given field.  The Core Types page lists them.

Two of the more important ones are:

  • “index”: “not_analyzed”, which keeps Elasticsearch from tokenizing your value, which is especially useful for log data.
  • “doc_values”: true, which can help with memory usage as described in the doc.

If you use a new index every day, you would need to apply the mapping every day when the index was created.  Or, you can use templates.

Templates

Templates define settings and mappings that will be used when a new index is created.  They are especially useful if you create daily indexes (e.g. from logstash) or you have dynamic field names.

In this example, an index created whose name matches the pattern “my_*” will have its “my_field” field mapped as a string.

curl -XPUT localhost:9200/_template/my_template -d '
{
  "template" : "my_*",
  "mappings" : {
    "my_type" : {
      "my_field" : { "type" : "string" }
    }
  }
}
'

Note that the template name is global to the cluster, so don’t try to create a “fancy_template” on more than one index.

Templates still requires you to know the names of the fields in advance, though.

Dynamic Templates

A dynamic template lets you tell Elasticsearch what to do with any field that matches (or doesn’t match)  the definition, which can include:

  • name, including wildcards or partial path matches
  • type

This dynamic template will take any string and make it not_analyzed and use doc_values:

PUT /my_index
{
  "mappings": {
    "my_type": {
      "dynamic_templates": [
        { "my_dtemplate": { 
            "match_mapping_type": "string",
            "mapping": {
              "type": "string",
              "analyzer": "not_analyzed",
              "doc_values": true
            }
        }}
      ]
    }
  }
}

Or force any nested field that ends in “counter” to be an integer:

PUT /my_index
{
  "mappings": {
    "my_type": {
      "dynamic_templates": [
        { "my_dtemplate": {
            "path_match": "*.counter", 
            "mapping": {
              "type": "integer"
            }
        }
      ]
    }
  }
}

Logstash

One of the first things that early logstash users discovered was that Elasticsearch is a text search engine, not a log search engine.  If you gave it a string field, like:

"logfile": "/var/log/httpd/access_log"

Elasticsearch would tokenize it and index the tokens:

"logfile": ["var", "log", "httpd", "access_log"]

which make it impossible to search on or display the original value.

To alleviate this initial frustration, logstash was shipped with a default mapping that included a “raw” field for every string, set as not_analyzed.  Accessing logfile.raw would return you back the original, un-tokenized string.

This is a great work-around, and helped many logstash users not be immediately frustrated with the product, but it’s not the right solution.  Setting up your own mapping, and treating the fields as you know they should be treated, is the right solution.

Note that the extra “raw” field will be going away in a future release of logstash.

Using the Wrong Mapping

If you try to insert a document whose field types don’t match the mapping, Elasticsearch may try to help.  If possible, it will try to “coerce” (cast) the data from one type to another (“int to string”, etc).  Elasticsearch will even try “string to int” which will work for “2.0”, but not “hello”.  Check the value of the index.mapping.coerce parameter and any messages in the Elasticsearch logs.

Updating a Template

If you’re using logstash, it ships with a default template called “logstash”.  To make changes to this template, first pull it:

curl -XGET 'http://localhost:9200/_template/logstash?pretty' > /tmp/logstash.template

First, edit the file to remove the outside structure – the part that looks like this:

{
 "logstash" :

and the matching } at the end of the file.

Then, edit the file as desired (yes, that’s the tricky part!).

While you’re there, notice this line, which we’ll reference below.

"template" : "logstash-*"

Finally, post the template back into Elasticsearch:

curl -XPUT 'http://localhost:9200/_template/logstash' -d@logstash.template

Now, any index that is created after this with a name that matches the “template” value shown above will use this new template when creating the field mappings.

Testing your Template

Field mappings are set when a field is defined in the index.  They cannot be changed without reindexing all of the data.

If you use daily indexes, your next index will be created with the new mapping.  Rather than wait for that, you can test the template by manually creating a new index that also matches the pattern.

For example, if your template pattern was “logstash-*”, this will match the standard daily indexes like “logstash-2015.04.01” but will also match “logstash-test”.

Create a document by hand into that index:

$ curl -XPUT 'http://localhost:9200/my_index/my_type/1' -d '{
 "field1" : "value1",
 "field2" : 2
}'

 

Check out the tips!

I’ve just added a ‘Logstash Tips’ menu section which will appear at the top of the page.  The tips don’t appear in the regular blog article area.  This section will replace pastebin as a repository for reusable tips.

I will be converting more logstash tips over to this section, and will also add sections for Elasticsearch, python, and grok{} patterns.

Using conditionals in your filter{} blocks

Wrapping your filter logic in conditional expressions can be very important.

If your configuration is split up into many files, logstash will combine and run all of the stanzas.  Also, using conditionals to limit the amount of processing performed will make this step faster.

To tell if an event contains a given tag:

if "value" in [tags] {
}

For string fields:

if [FIELD] =~ /.+/ {
     # exists
}
 
if [FIELD] !~ /.+/ {
     # doesn't exist
}

For numeric fields:

if [FIELD] {
     # exists
}

Processing common event information with grok{}

If you’re lucky, most of your log messages in a given input will arrive in a standard format, typically with a set of common fields at the front (date, time, server, etc).

Rather than multiple grok{} patterns that are looking across the entire message, like these:

grok {
    match => ["message", "%{SYSLOGTIMESTAMP:syslogtime} %{HOSTNAME:sysloghost} Save this %{WORD:word1}"]
    tag_on_failure => ["_grokparsefailure_match1"]
}

grok {
    match => ["message", "%{SYSLOGTIMESTAMP:syslogtime} %{HOSTNAME:sysloghost} Save this other %{WORD:word2}"]
    tag_on_failure => ["_grokparsefailure_match2"]
}

I like to split off the common stuff:

grok {
    match => ["message", "%{SYSLOGTIMESTAMP:syslogtime} %{HOSTNAME:sysloghost} %{GREEDYDATA:message}"]
    overwrite => [ "message" ]
    tag_on_failure => ["_grokparsefailure_syslog"]
}

Note that the last pattern puts the results into the field “message”.  Since that field already exists, we have to use the “overwrite” setting to update it.

Then use smaller patterns against this smaller “message” for your application specific info:

grok {
    match => ["message", "Save this %{WORD:word1}"]
    tag_on_failure => ["_grokparsefailure_match1"]
}

This is easier to read, and the later grok{}s will be running smaller regexps
against smaller input, which should be faster.

Handling exceptions in the ruby{} filter

If you need to drop into ruby for your processing, be sure to handle any exceptions.  If you don’t, the filter worker will exit, possibly halting your processing.

The following code will allow the worker to continue, and will add a field to the event so you can track them down later:

    ruby {
        code => "
          begin
            # your great code goes here
          rescue Exception => e
            event['ruby_exception'] = 'YOUR_FILTER_NAME: ' + e.message
          end
       "
    }

 

I add a panel for this field to my cluster health dashboard in kibana.

Casting variables in the ruby{} filter

Note that the mutate{} filter contains a convert{} operation, which is very useful.

If you find yourself in ruby for another purpose, you might want to cast the variables while your there.  Here are some examples:

      ruby {
        code => "
          begin
            event['foo'] = event['foo'].to_f
            event['bar'] = event['bar'].to_i
          rescue Exception;
            event['ruby_exception'] = 'cast'
          end
        "
      }

Combining lines with the multiline{} filter

The multiline filter is designed to combine messages that span lines into a single event that can be easily processed with other logstash filters.  Systems that throw large exceptions (e.g. Java) are the standard use-case for this filter.

At the most basic, you need to provide three pieces of information to the filter:

  • ‘pattern’: the regular expression that signals the start of a new event.
  • ‘what’: the action to take with a line that does or doesn’t match the pattern.
  • ‘negate’: how the does/doesn’t for ‘what’ is decided.

When ‘negate’ is set to true, read it as “when my PATTERN doesn’t match, do WHAT”; when false, read it as “when my PATTERN does match, do WHAT”.

In this example, ‘negate’ is true, so we read it as “when my timestamp pattern doesn’t match, keep the line with the previous entry”:

filter {
    multiline {
      negate => 'true'
      pattern => "^%{TIMESTAMP_ISO8601} "
      what => 'previous'
    }
}

This filter should be used first, so that other filters will see the single event.

Until a new line matches the pattern, logstash is expecting more lines to join, so it won’t release the combined event.  There is an enable_flush option, but it should not be used in production.  In logstash version 1.5, the flush will be “production ready”.

When using multiline, you cannot use multiple filter workers, as each worker would be reading a different line.  If you attempt this configuration, logstash will not start.

If your application writes log entries in a way where they can overlap with each other, the basic filter can’t help you.  However, if your system prints a common string in each message (a UUID, etc), you can use that to combine messages.  See the ‘stream_identity’ option.

You should also consider using the multiline{} codec, so that messages are combined in the input{} phase.  Note that the codec doesn’t offer the ‘stream_identity’ option.

 

Changing @timestamp with the date{} filter

By default, elasticsearch sets the @timestamp field to the time that the document was written into elasticsearch.  For log file data, one of the first things you’ll want to do with logstash is to set @timestamp to be the value from the log event you’re processing.

To keep this example simple, we’ll assume that you’ve already grok’ed the event and have a field called “my_timestamp” that contains the correct information from the log event, e.g. “14/Mar/2015:09:26:53 -0500”.

filter {
  date {
    match => [ 'my_timestamp', "dd/MMM/yyyy:HH:mm:ss Z" ]
    remove_field => [ 'my_timestamp' ]
  }
}

The match{} takes the “my_timestamp” field, applies it against the specified pattern, and puts the resulting date object into the @timestamp field.

Once @timestamp has been populated, we no longer need “my_timestamp”, so it is removed.