Structured Logging with Rsyslog and Elasticsearch

As more and more organizations are starting to use our Performance Monitoring and Search Analytics services, we have more and more logs from various components that make up these applications.  So what do we do?  Do we just keep logging everything to files, rotating them, and grepping them when we need to troubleshoot something?  There must be something better we can do!  And indeed, there is – so much so, that we’ll soon be launching Logsene – a Log Analytics service to complement SPM.  When your applications generate a lot of logs, you’d probably want to make some sense of them by searching and/or statistics. Here’s when structured logging comes in handy, and I would like to share some thoughts and configuration examples of how you could use a popular syslog daemon like rsyslog to handle both structured and unstructured logs. Then I’m going to look at how you can take those logs, format them in JSON, and index them with Elasticsearch – for some fast and easy searching and statistics.  If you are going to Berlin Buzzwords this year and you are into logging, Logstash, ElasticSearch, or Kibana, I’ll be talking about them in my JSON logging with ElasticSearch presentation.

On structured logging

If we take an unstructured log message, like:

Joe bought 2 apples

And compare it with a similar one in JSON, like:

{"name": "Joe", "action": "bought", "item": "apples", "quantity": 2}

We can immediately spot a couple of advantages and disadvantages of structured logging:
if we index these logs, it will be faster and more precise to search for “apples” in the “item” field, rather than in the whole document. At the same time, the structured log will take up more space than the unstructured one.

But in most use-cases there will be more applications that would log the same subset of fields. So if you want to search for the same user across those applications, it’s nice to be able to pinpoint the “name” field everywhere. And when you add statistics, like who’s the user buying most of our apples, that’s when structured logging really becomes useful.

Finally, it helps to have a structure when it comes to maintenance. If a new version of the application adds a new field, and your log becomes:

Joe bought 2 red apples

it might break some log-parsing, while structured logs rarely suffer from the same problem.

Enter CEE and Lumberjack: structured logging within syslog

With syslog, as defined by RFC3164, there is already a structure in the sense that there’s a priority value (severity*8 + facility), a header (timestamp and hostname) and a message. But this usually isn’t the structure we’re looking for.

CEE and Lumberjack are efforts to introduce structured logging to syslog in a backwards-compatible way. The process is quite simple: in the message part of the log, one would start with a cookie string “@cee:”, followed by an optional space and then a JSON or XML. From this point on I will talk about JSON, since it’s the format that both rsyslog and Elasticsearch prefer. Here’s a sample CEE-enhanced syslog message:

@cee: {"foo": "bar"}

This makes it quite easy to use CEE-enhanced syslog with existing syslog libraries, although there are specific libraries like liblumberlog, which make it even easier. They’ve also defined a list of standard fields, and applications should use those fields where they’re applicable – so that you get the same field names for all applications. But the schema is free, so you can add custom fields at will.

CEE-enhanced syslog with rsyslog

rsyslog has a module named mmjsonparse for handling CEE-enhanced syslog messages. It checks for the “CEE cookie” at the beginning of the message, and then tries to parse the following JSON. If all is well, the fields from that JSON are loaded and you can then use them in templates to extract whatever information seems important. Fields from your JSON can be accessed like this: $!field-name. An example of how they can be used is shown here.

To get started, you need to have at least rsyslog version 6.6.0, and I’d recommend using version 7 or higher. If you don’t already have that, check out Adiscon’s repositories for RHEL/CentOS and Ubuntu.

Also, mmjsonparse is not enabled by default. If you use the repositories, install the rsyslog-mmjsonparse package. If you compile rsyslog from sources, specify –enable-mmjsonparse when you run the configure script. In order for that to work you’d probably have to install libjson and liblognorm first, depending on your operating system.

For a proof of concept, we can take this config:

#load needed modules
module(load="imuxsock") # provides support for local system logging
module(load="imklog") # provides kernel logging support
module(load="mmjsonparse") #for parsing CEE-enhanced syslog messages

#try to parse structured logs
action(type="mmjsonparse")

#define a template to print field "foo"
template(name="justFoo" type="list") {
    property(name="$!foo")
    constant(value="n") #we'll separate logs with a newline
}

#and now let's write the contents of field "foo" in a file
action(type="omfile"
    template="justFoo"
    file="/var/log/foo")

To see things, better, you can start rsyslog in foreground and in debug mode:

rsyslogd -dn

And in another terminal, you can send a structured log, then see the value in your file:

# logger '@cee: {"foo":"bar"}'
# cat /var/log/foo
bar

If we send an unstructured log, or an invalid JSON, nothing will be added

# logger 'test'
# logger '@cee: test2'
# cat /var/log/foo
bar

But you can see in the debug output of rsyslog why:

mmjsonparse: no JSON cookie: 'test'
[...]
mmjsonparse: toParse: ' test2'
mmjsonparse: Error parsing JSON ' test2': boolean expected

Indexing logs in Elasticsearch

To index our logs in Elasticsearch, we will use an output module of rsyslog called omelasticsearch. Like mmjsonparse, it’s not compiled by default, so you will have to add the –enable-elasticsearch parameter to the configure script to get it built when you run make. If you use the repositories, you can simply install the rsyslog-elasticsearch package.

omelasticsearch expects a valid JSON from your template, to send it via HTTP to Elasticsearch. You can select individual fields, like we did in the previous scenario, but you can also select the JSON part of the message via the $!all-json property. That would produce the message part of the log, without the “CEE cookie”.

The configuration below should be good for inserting the syslog message to an Elasticsearch instance running on localhost:9200, under the index “system” and type “events“. These are the default options, and you can take a look at this tutorial if you need some info on changing them.

#load needed modules
module(load="imuxsock") # provides support for local system logging
module(load="imklog") # provides kernel logging support
module(load="mmjsonparse") #for parsing CEE-enhanced syslog messages
module(load="omelasticsearch") #for indexing to Elasticsearch

#try to parse a structured log
action(type="mmjsonparse")

#define a template to print all fields of the message
template(name="messageToES" type="list") {
    property(name="$!all-json")
}

#write the JSON message to the local ES node
action(type="omelasticsearch"
    template="messageToES")

After restarting rsyslog, you can see your JSON will be indexed:

# logger '@cee: {"foo": "bar", "foo2": "bar2"}'
# curl -XPOST localhost:9200/system/events/_search?q=foo2:bar2 2>/dev/null | sed s/.*_source//
" : { "foo": "bar", "foo2": "bar2" }}]}}

As for unstructured logs, $!all-json will produce a JSON with a field named “msg”, having the message as a value:

# logger test
# curl -XPOST localhost:9200/system/events/_search?q=test 2>/dev/null | sed s/.*_source//
" : { "msg": "test" }}]}}

It’s “msg” because that’s rsyslog’s property name for the syslog message.

Including other properties

But the message isn’t the only interesting property. I would assume most would want to index other information, like the timestamp, severity, or host which generated that message.

To do that, one needs to play with templates and properties. In the future it might be made easier, but at the time of this writing (rsyslog 7.2.3), you need to manually craft a valid JSON to pass it to omelasticsearch. For example, if we want to add the timestamp and the syslogtag, a working template might look like this:

template(name="customTemplate" type="list") {
 #- open the curly brackets,
 #- add the timestamp field surrounded with quotes
 #- add the colon which separates field from value
 #- open the quotes for the timestamp itself
     constant(value="{"timestamp":"")
 #- add the timestamp from the log,
 # format it in RFC-3339, so that ES detects it by default
     property(name="timereported" dateFormat="rfc3339")
 #- close the quotes for timestamp,
 #- add a comma, then the syslogtag field in the same manner
     constant(value="","syslogtag":"")
 #- now the syslogtag field itself
 # and format="json" will ensure special characters
 # are escaped so they won't break our JSON
     property(name="syslogtag" format="json")
 #- close the quotes for syslogtag
 #- add a comma
 #- then add our JSON-formatted syslog message,
 # but start from the 2nd position to omit the left
 # curly bracket
     constant(value="",")
     property(name="$!all-json" position.from="2")
 }

Summary

If you’re interested in searching or analyzing lots of logs, structured logging might help. And you can do it with the existing syslog libraries, via CEE-enhanced syslog. If you use a newer version of rsyslog, you can parse these logs with mmjsonparse and index them in Elasticsearch with omelasticsearch.  If you want to use Logsene, it will consume your structured logs as described in this post.

25 thoughts on “Structured Logging with Rsyslog and Elasticsearch

  1. Hi Radu,

    Impressive write-up. You seem to have captured a lot of the nuances of rsyslog that took me a lot of documentation-searching to find.

    I currently have a strange situation. I’m not entirely sure what is going on with my JSON cookie. Here is what I see with rsyslogd -dn:

    2682.951216238:7f846138a700: msg parser: flags 30, from ‘redacted’, msg ‘@cee: {“message”:”testing”,”syslogtag”:”is:”,”hostname”:”thi’
    2682.951241224:7f846138a700: parse using parser list 0xb786f0 (the default list).
    2682.951251725:7f846138a700: Parser ‘rsyslog.rfc5424’ returned -2160
    2682.951260948:7f846138a700: Message will now be parsed by the legacy syslog parser (one size fits all… ;)).
    2682.951274021:7f846138a700: Parser ‘rsyslog.rfc3164’ returned 0

    2682.951415205:7f8460b89700: ACTION 0xb961a0 [mmjsonparse:action(type=”mmjsonparse” …)]
    2682.951431851:7f8460b89700: RRRR: execAct [mmjsonparse]: batch of 1 elements, active (nil)
    2682.951451339:7f8460b89700: Called action(NotAllMark), processing batch[0] via ‘mmjsonparse’
    2682.951458013:7f8460b89700: Called action(Batch), logging to mmjsonparse
    2682.951466803:7f846138a700: ——– calling select, active fds (max 9): 4 5 6 7 9
    2682.951518194:7f8460b89700: submitBatch: enter, nElem 1
    2682.951536278:7f8460b89700: tryDoAction 0xb961a0, pnElem 1, nElem 1
    2682.951546163:7f8460b89700: Action 0xb961a0 transitioned to state: itx
    2682.951554248:7f8460b89700: entering actionCalldoAction(), state: itx
    2682.951563307:7f8460b89700: mmjsonparse: no JSON cookie: ‘{“message”:”testing”,”syslogtag”:”is:”,”hostname”:”this”,”fromhost”:”redacted”,”fromhost-ip”:”redacted”,”facility”:”user”,”priority”:”notice”,”timereported”:”2015-01-06T20:04:42.936736-05:00″,”timegenerated”:”2015-01-06T20:04:42.936736-05:00″}’

    It sees the @cee: on the first line, but the last line says no JSON cookie. Is it somehow getting stripped? My config looks like this:

    action(type=”mmjsonparse”)
    if ($parsesuccess == “OK”) then {
    action(type=”omfile” dynaFile=”/data/syslog/%$!fromhost-ip%/%$year%/%$month%/%$!fromhost-ip%-%$year%-%$month%-%$day%.log” template=”%$!timereported% %$!fromhost-ip% %$!syslogtag%%$!message%n”)
    }

    1. This is interesting, I’ve never seen such issues and we’re using mmjsonparse extensively. Could you repost your question to the rsyslog mailing list and post your full config (I’d be interested where your logs are coming from, for example – socket, file, etc) and rsyslog version?

      1. Hi Radu,

        I think I may have found the issue, but I need to test it today. I believe that rsyslog requires that anything it receives will parse correctly via its $RulesetParser (http://www.rsyslog.com/doc/rsconf1_rulesetparser.html), which straight JSON does not. Therefore, we are going to attempt to format the output of our first level rsyslog infrastructure as RFC3164 and replace $msg with the “@cee: {…}” to see if that does it. Are you able to confirm this?

        To clarify – we have a cluster of front-end rsyslog aggregators which then forward in JSON to our analysis back-end rsyslog machine. We are using rsyslog 7.6.7 at the analysis level and a similar 7.x on the front-end.

        Thanks.

        1. Yes, I am able to confirm this. That’s why I’m using logger in the post, because it generates a RFC3164 message (filling up things like timestamp and hostname) with $msg set to whatever I provide (that ‘@cee: {…}’). So yes, you still have to send syslog-formatted messages via /dev/log. Other inputs may behave differently, for instance imfile takes every line as $msg if I understand correctly.

          1. Great! You’re welcome!

            I was just thinking – RFC3164 is sooo vague that rsyslog tries to parse pretty much anything. If I remember correctly, it would even parse something like “foo bar” by saying that “foo” is the hostname and “bar” is the message, then filling up the timestamp and some default priority. This would explain why “@cee: {…}” eats up exactly your “@cee:” cookie, because rsyslog takes it as a hostname. If you put the real hostname in the beginning (or even some junk like “bla @cee: {…}”) it should work as well.

          2. You are exactly right. I noticed that fact as well because I was sending syslog via netcat and at first when I sent “this is a test” “this” and “is” would get parsed out separate from “a test”, which ended up being the message.

  2. Great post!
    I have tried the following setup:

    template(name=”timereportedrfc3339″ type=”string” string=”%timereported:::date-rfc3339%”)
    set $!timereported = exec_template(“timereportedrfc3339″);

    set $!host = $hostname;
    set $!severity = $syslogseverity-text;
    set $!facility = $syslogfacility-text;
    set $!syslogtag = $syslogtag;
    set $!msg = $msg;

    if ( $!country_code == ” ) then
    {
    set $!country_code = “DE”;
    }

    template(name=”cee-syslog”
    type=”list”) {
    constant(value=”{“)
    constant(value=””@timestamp”:””) property(name=”$!timereported”)
    constant(value=””,”) property(name=”$!all-json” position.from=”2″)
    }

    But I have a performance issue with $!all-json property. With cee-syslog template only a few events per second can be forward into elasticsearch (I’am using rsyslog 8.2.2).

    Please have a lookup at foolowing rsyslog issue:
    https://github.com/rsyslog/rsyslog/issues/85

    Thanks in advance
    Joerg

    1. Hi Joerg,

      This is interesting, we have a similar configuration, with the same 8.2.2 rsyslog, and don’t have performance issues.

      Judging from the configuration in issue 85, it looks like you would benefit from the $jsonmesg property: https://github.com/rsyslog/rsyslog/issues/19

      Maybe using that one will also solve the performance issue you’re having? It should make your templates that much easier to use. But please beware of a leak that was fixed in 8.3.1 (http://www.rsyslog.com/changelog-for-8-3-1-v8-devel/) so I’d try with the latest devel (8.3.3) or wait a few days for 8.4.0: http://blog.gerhards.net/2014/06/upcoming-new-v8-stable.html

  3. FYI: the configuration given above uses bogus/fancy double quote characters (“) instead of (“) so it will not work if you copy and paste it. (Not sure why anyone uses these bogus double quote characters anyway…)

    1. Thanks, Evan, for your comment. I didn’t notice this, I copy-pasted the tested rsyslog.conf here, but didn’t try to paste it back 🙂

      I think the problem was due to formatting. It should be fixed now. But please let me know if it still doesn’t work for you.

  4. Given the recent announcement about funding for the CEE project ending (*just* before first release :(, what’s your take on using CEE for logging?

    1. Maybe I’m not entirely aware of the implications, but the “damage” has already been done. Both rsyslog and syslog-ng support parsing JSON messages if the CEE cookie is there. You can use that with any syslog library, or you can use CEE-specific ones that are already there. Whoever feels this is useful might push the effort forward, like Project Lumberjack seems to do:
      https://fedorahosted.org/lumberjack/

    1. That’s a good question, thanks! Indeed, the original, RFC 3164 syslog standard says that messages must be 1024 bytes or less.

      Modern syslog implementations don’t limit you as much, though. With rsyslog you can set $MaxMessageSize in the configuration, which defaults to 2k. If you’re using syslog-ng, you can configure log_msg_size(), which defaults to 8k.

      Sources:
      http://www.rsyslog.com/doc/rsyslog_conf_global.html
      http://www.syslog.org/syslog-ng/v2/

      So the only practical problem you’ll have with this limitation is when you have a chain of syslog daemons, forwarding logs from one to the other. You’ll need to make sure they’re all configured to accept the message size you need.

Leave a Reply