Archive

Posts Tagged ‘elk’
  • Structuring data with Logstash

    Logstash old logo

    Given the trend around microservices, it has become mandatory to be able to follow a transaction across multiple microservices. Spring Cloud Sleuth is such a distributed tracing system fully integrated into the Spring Boot ecosystem. By adding the spring-cloud-starter-sleuth into a project’s POM, it instantly becomes Sleuth-enabled and every standard log call automatically adds additional data, such as spanId and traceId to the usual data.

    2016-11-25 19:05:53.221  INFO [demo-app,b4d33156bc6a49ec,432b43172c958450,false] 25305 ---\n
    [nio-8080-exec-1] ch.frankel.blog.SleuthDemoApplication      : this is an example message
    

    (broken on 2 lines for better readability)

    Now, instead of sending the data to Zipkin, let’s say I need to store it into Elasticsearch instead. A product is as good as the way it’s used. Indexing unstructured log messages is not very useful. Logstash configuration allows to pre-parse unstructured data and send structured data instead.

    Grok

    Grokking data is the usual way to structure data with pattern matching.

    Last week, I wrote about some hints for the configuration. Unfortunately, the hard part comes in writing the matching pattern itself, and those hints don’t help. While it might be possible to write a perfect Grok pattern on the first draft, the above log is complicated enough that it’s far from a certainty, and chances are high to stumble upon such message when starting Logstash with an unfit Grok filter:

    "tags" => [
        [0] "_grokparsefailure"
    ]
    

    However, there’s “an app for that” (sounds familiar?). It offers three fields:

    1. The first field accepts one (or more) log line(s)
    2. The second the grok pattern
    3. The 3rd is the result of filtering the 1st by the 2nd

    The process is now to match fields one by one, from left to right. The first data field .e.g. 2016-11-25 19:05:53.221 is obviously a timestamp. Among common grok patterns, it looks as if the TIMESTAMP_ISO8601 pattern would be the best fit.

    Enter %{TIMESTAMP_ISO8601:timestamp} into the Pattern field. The result is:

    {
      "timestamp": [
        [
          "2016-11-25 17:05:53.221"
        ]
      ]
    }
    

    The next field to handle looks like the log level. Among the patterns, there’s one LOGLEVEL. The Pattern now becomes %{TIMESTAMP_ISO8601:timestamp} *%{LOGLEVEL:level} and the result:

    {
      "timestamp": [
        [
          "2016-11-25 17:05:53.221"
        ]
      ],
      "level": [
        [
          "INFO"
        ]
      ]
    }
    

    Rinse and repeat until all fields have been structured. Given the initial log line, the final pattern should look something along those lines:

    %{TIMESTAMP_ISO8601:timestamp} *%{LOGLEVEL:level} \[%{DATA:application},%{DATA:traceId},%{DATA:spanId},%{DATA:zipkin}]\n
    %{DATA:pid} --- *\[%{DATA:thread}] %{JAVACLASS:class} *: %{GREEDYDATA:log}
    

    (broken on 2 lines for better readability)

    And the associated result:

    {
            "traceId" => "b4d33156bc6a49ec",
             "zipkin" => "false",
              "level" => "INFO",
                "log" => "this is an example message",
                "pid" => "25305",
             "thread" => "nio-8080-exec-1",
               "tags" => [],
             "spanId" => "432b43172c958450",
               "path" => "/tmp/logstash.log",
         "@timestamp" => 2016-11-26T13:41:07.599Z,
        "application" => "demo-app",
           "@version" => "1",
               "host" => "LSNM33795267A",
              "class" => "ch.frankel.blog.SleuthDemoApplication",
          "timestamp" => "2016-11-25 17:05:53.221"
    }
    

    Dissect

    The Grok filter gets the job done. But it seems to suffer from performance issues, especially if the pattern doesn’t match. An alternative is to use the dissect filter instead, which is based on separators.

    Unfortunately, there’s no app for that - but it’s much easier to write a separator-based filter than a regex-based one. The mapping equivalent to the above is:

    %{timestamp} %{+timestamp} %{level}[%{application},%{traceId},%{spanId},%{zipkin}]\n
    %{pid} %{}[%{thread}] %{class}:%{log}
    

    (broken on 2 lines for better readability)

    This outputs the following:

    {
            "traceId" => "b4d33156bc6a49ec",
             "zipkin" => "false",
                "log" => " this is an example message",
              "level" => "INFO ",
                "pid" => "25305",
             "thread" => "nio-8080-exec-1",
               "tags" => [],
             "spanId" => "432b43172c958450",
               "path" => "/tmp/logstash.log",
         "@timestamp" => 2016-11-26T13:36:47.165Z,
        "application" => "demo-app",
           "@version" => "1",
               "host" => "LSNM33795267A",
              "class" => "ch.frankel.blog.SleuthDemoApplication      ",
          "timestamp" => "2016-11-25 17:05:53.221"
    }
    

    Notice the slight differences: by moving from a regex-based filter to a separator-based one, some strings end up padded with spaces. There are 2 ways to handle that:

    • change the logging pattern in the application - which might make direct log reading harder
    • strip additional spaces with Logstash

    With the second option, the final filter configuration snippet is:

    filter {
      dissect {
    	mapping => { "message" => ... }
      }
      mutate {
        strip => [ "log", "class" ]
      }
    }
    

    Conclusion

    In order to structure data, the grok filter is powerful and used by many. However, depending on the specific log format to parse, writing the filter expression might be quite complex a task. The dissect filter, based on separators, is an alternative that makes it much easier - at the price of some additional handling. It also is an option to consider in case of performance issues.

    Categories: Development Tags: elklogstashelasticparsingdata
  • Debugging hints for Logstash

    Logstash old logo

    As a Java developer, when you are first shown how to run the JVM in debug mode, attach to it and then set a breakpoint, you really feel like you’ve reached a step on your developer journey. Well, at least I did. Now the world is going full microservice and knowing that trick means less and less in it everyday.

    This week, I was playing with Logstash to see how I could send all of an application exceptions to an Elasticsearch instance, so I could display them on a Kibana dashboard for analytics purpose. Of course, nothing was seen in Elasticsearch at first. This post describes helped me toward making it work in the end.

    The setup

    Components are the following:

    • The application. Since a lot of exceptions were necessary, I made use of the Java Bullshifier. The only adaptation was to wire in some code to log exceptions in a log file. {% highlight java %} public class ExceptionHandlerExecutor extends ThreadPoolExecutor { private static final Logger LOGGER = LoggerFactory.getLogger(ExceptionHandlerExecutor.class); public ExceptionHandlerExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue workQueue) { super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue); } @Override protected void afterExecute(Runnable r, Throwable t) { if (r instanceof FutureTask) { FutureTask futureTask = (FutureTask) r; if (futureTask.isDone()) { try { futureTask.get(); } catch (InterruptedException | ExecutionException e) { LOGGER.error("Uncaught error", e); } } } } } {% endhighlight %} </li>
    • Logstash
    • Elasticsearch
    • Kibana
    • </ul> ## The first bump Before being launched, Logstash needs to be configured - especially its input and its output. There's no out-of-the-box input focused on exception stack traces. Those are multi-lines messages: hence, only lines starting with a timestamp mark the beginning of a new message. Logstash achieves that with a specific `codec` including a `regex` pattern.
      Some people, when confronted with a problem, think "I know, I'll use regular expressions."
      Now they have two problems.
      -- Jamie Zawinski
      Some are better than others at regular expressions but nobody learned it as his/her mother tongue. Hence, it's not rare to have errors. In that case, one should use one of the many available online regex validators. They are just priceless for understanding why some pattern doesn't match. The relevant Logstash configuration snippet becomes: ```javascript input { file { path => "/tmp/logback.log" start_position => "beginning" codec => multiline { pattern => "^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}" negate => true what => "previous" } } } ``` ## The second bump Now, data found its way into Elasticsearch, but message were not in the expected format. In order to analyze where this problem came from, messages can be printed on the console instead of indexed in Elasticsearch. That's quite easy with the following snippet: ```javascript output { stdout { codec => rubydebug } } ``` With messages printed on the console, it's possible to understand where the issue occurs. In that case, I was able to tweak the `input` configuration (and add the forgotten `negate => true` bit). Finally, I got the expected result: ## Conclusion With more and more tools with every passing day, the toolbelt of the modern developer needs to increase as well. Unfortunately, there's no one-size-fits-all solution: in order to know a tool's every nook and cranny, one needs to use and re-use it, be creative, and search on Google... a lot.
    Categories: Development Tags: elklogstashelasticdebugging