Level up logs and ELK - Contract first log generator - HTML and Java generation from descriptor file.

Articles index:

1. Introduction (Everyone)
2. JSON as logs format (Everyone)
3. Logging best practices with Logback (Targetting Java DEVs)
4. Logging cutting-edge practices (Targetting Java DEVs) 
5. Contract first log generator (Targetting Java DEVs)
6. ElasticSearch VRR Estimation Strategy (Targetting OPS)
7. VRR Java + Logback configuration (Targetting OPS)
8. VRR FileBeat configuration (Targetting OPS)
9. VRR Logstash configuration and Index templates (Targetting OPS)
10. VRR Curator configuration (Targetting OPS)
11. Logstash Grok, JSON Filter and JSON Input performance comparison (Targetting OPS) 

 Contract first log generator - HTML and Java generation from descriptor file.

 As a result of my previous article,Logging best practices with Logback and Logging cutting-edge practices, I came to the conclusion that we were putting to much weight into developers alone to generate top quality logs.

Nowadays it wouldn't be acceptable by many people to live with code full of hard-coded keys that need to be kept in mind, types to relate and never mistake, and explain all this to other colleagues not only from development teams, but from support, pre-sales, etc...

I see no better alternative than creating a description file that relates domain, type and explanation, something I could convert to HTML and code alike:

version: 1

project-name: coins-jdk8-example

mappings:
  - name: amount
    type: java.lang.Integer
    description: Amount of money to match, in minimum representation (no decimals).
  - name: combinations
    type: java.lang.Integer
    description: Total number of combinations of change.
  - name: coins
    type: int
    description: Number of coins in a combination.

Generated code:

package com.navid.codegen;

import static net.logstash.logback.argument.StructuredArguments.keyValue;

import java.lang.Integer;
import java.lang.Iterable;
import net.logstash.logback.argument.StructuredArgument;

public final class LoggerUtils {
  public static StructuredArgument kvAmount(Integer amount) {
    return keyValue("amount",amount);
  }

  public static StructuredArgument aAmount(Iterable amount) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("amount",amount);
  }

  public static StructuredArgument aAmount(Integer... amount) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("amount",amount);
  }

  public static StructuredArgument kvCombinations(Integer combinations) {
    return keyValue("combinations",combinations);
  }

  public static StructuredArgument aCombinations(Iterable combinations) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("combinations",combinations);
  }

  public static StructuredArgument aCombinations(Integer... combinations) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("combinations",combinations);
  }

  public static StructuredArgument kvCoins(int coins) {
    return keyValue("coins",coins);
  }

  public static StructuredArgument aCoins(Iterable coins) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("coins",coins);
  }

  public static StructuredArgument aCoins(int... coins) {
    return new net.logstash.logback.marker.ObjectAppendingMarker("coins",coins);
  }
}

And HTML description code

After a second evolution, talking with my colleagues while I was presenting this idea, they feed back with the idea of adding complete log sentences instead of just key-type-description triplets.

This would be specially useful for non-coders and other teams, as they would know what to look for in the logs without needing to read it all.

version: 1
project-name: coins-jdk8-example
mappings:
  - name: amount
    type: java.lang.Integer
    description: Amount of money to match, in minimum representation (no decimals).
  - name: combinations
    type: java.lang.Integer
    description: Total number of combinations of change.
  - name: coins
    type: int
    description: Number of coins in a combination.
  - name: iid
    type: java.util.UUID
    description: Interaction id, basically like a request id.
sentences:
  - code: ResultCombinations
    message: "Number of combinations of getting change"
    variables:
      - amount
      - combinations
    extradata: {}
    defaultLevel: info
  - code: ResultMinimum
    message: "Minimum number of coins required"
    variables:
      - amount
      - coins
    extradata: {}
    defaultLevel: info
context:
  - iid

Generated code (removing repeated code from above)

public static void auditResultCombinations(Logger logger, Integer amount, Integer combinations) {
    logger.info("Number of combinations of getting change {} {}",kvAmount(amount),kvCombinations(combinations));
  }

  public static void auditResultCombinations(TriConsumer logger, Integer amount,
      Integer combinations) {
    logger.accept("Number of combinations of getting change {} {}",kvAmount(amount),kvCombinations(combinations));
  }

  public static void auditResultMinimum(Logger logger, Integer amount, int coins) {
    logger.info("Minimum number of coins required {} {}",kvAmount(amount),kvCoins(coins));
  }

  public static void auditResultMinimum(TriConsumer logger, Integer amount, int coins) {
    logger.accept("Minimum number of coins required {} {}",kvAmount(amount),kvCoins(coins));
  }

  public static void setContextIid(UUID iid) {
    org.slf4j.MDC.put("ctx.iid",String.valueOf(iid));
  }

  public static void removeContextIid() {
    org.slf4j.MDC.remove("iid");
  }

  public static void resetContext() {
    org.slf4j.MDC.clear();
  }

  public interface MonoConsumer {
    void accept(String var1);
  }

  public interface BiConsumer {
    void accept(String var1, Object var2);
  }

  public interface TriConsumer {
    void accept(String var1, Object var2, Object var3);
  }

  public interface ManyConsumer {
    void accept(String var1, Object... var2);
  }

Generated code follows all the principles I have been elaborating before:

1. As developers are not typing the name of the Structured Argument, they won't make typos, upper-lower case mistakes, etc. Same concept won't be reused alongside code. Same concept will always have same name, perfectly written each time.
2. As generated code is strongly typed, we are removing another danger from the road. At the same time, generated code allows single, collection and arrays of the same type, trying to make it comfortable for the developer at the same time.
3. Compatible with the idea of forbidding developers to use their own StructuredArguments key-value pairs on the code.
4. Generates HTML code to share with other teams, explaining mappings and sentences to search for.

Final HTML Documentation (including MDC and Sentences)

Role responsibilities are now as follows:

Business / Product Owner / Product Manager / B.I. Analyst
- Ask for introduction of main KPIs that they could later on map in charts or dashboards in order to measure whether the system is doing that it is suppose to do in business words.
This value is usually offered from developers to business, this time they would know they have a tool to ask for this information themselves.

Developers:
- Introduce information related to performance, audit of actions, transactions, etc...
- Introduce those sentences asked by other teams to make their life easier.

Maintainers/ On Callers/ Supports
- Introduce or ask for introduction for some specific well known errors in logs, being them documented first in the descriptor files. We could be aiming for a collection of error codes.
- They can elaborate log based alerts using descriptor file to know what's available.

Missing or future features:

• Maven plugin (currently only Gradle is supported)
• Support for more JDK versions (currently 1.7 and 1.8 supported).
• Improve HTML aspect.
• Redo the tool, it's my first time in Kotlin and I am a bit ashamed to be honest.
• Support for other languages, even not JVM based.
• Support for other Java logging framework.
• Create Elastalert configuration for error messages, maybe for other products as well.
• Suport for varargs and collections in sentences part.
• Extradata field to do something really.
• MDC Closeable function

To be honest, the more I work with this approach, the more I like it. I cannot but invite you to try:
Gradle plugin with working examples: https://github.com/albertonavarro/loggergenerator-gradle-plugin
Standalone tool: https://github.com/albertonavarro/loggergenerator


Next: 6 - ElasticSearch VRR Estimation Strategy

Level up logs and ELK - JSON logs

Articles index:

1. Introduction (Everyone)
2. JSON as logs format (Everyone)
3. Logging best practices with Logback (Targetting Java DEVs)
4. Logging cutting-edge practices (Targetting Java DEVs) 
5. Contract first log generator (Targetting Java DEVs)
6. ElasticSearch VRR Estimation Strategy (Targetting OPS)
7. VRR Java + Logback configuration (Targetting OPS)
8. VRR FileBeat configuration (Targetting OPS)
9. VRR Logstash configuration and Index templates (Targetting OPS)
10. VRR Curator configuration (Targetting OPS)
11. Logstash Grok, JSON Filter and JSON Input performance comparison (Targetting OPS)

JSON as logs format

 

JSON Logs

JSON is not the only solution, but it's one of them, and the one I am advocating for until I find something better.

Based on my personal experience across almost a dozen companies, Logs lifecycle looks like this a lot:

Bad log lifecycle:

1. Logs are created as plain text, using natural language, unstructured.
2. Lines are batched together if they belong to an exception stacktrace, otherwise treated as individual messages (regex work).
3. Parsed using Grok, message and timestamp are extracted from parts of the parsing (more regex).
4. If logs are structured, or unstructured fixed-format, some useful information can be extracted by using Grok (e.g. Apache or Nginx logs, they are always the same, easy).
5. OPS team see how Grok consumes all CPU it can find and reject to add more regex to the expression.
6. Developers want to get information from logs to index and plot, they ask OPS to please add some lines to Grok. Three OPS suicide and other two quit the company. Developers finally get what they want.
7. DEV team changes the logs without telling OPS, so previously useful information stops flowing in, dashboards are now empty and nobody cares.

It doesn't really matter if your company doesn't match all previous bullet points. As long as you are using Grok, you will struggle to squeeze 50+ different regex in a single or series of Grok Regex expressions in order to extract all the information you want, and, as long as your log writing team is not your Logstash maintaining team, your Grok configuration will get outdated for good and it will happen soon.

However, if your application produced JSON, that's it, all fields go through Logstash and end up in ElasticSearch without OPS intervention at all.

Alternative steps using JSON + Logback + Logstash + ElasticSearch:

1. Logs are created in JSON, it's developer responsibility to choose what extra metrics needs to be extracted from the code itself. Even exceptions with stacktrace are single liners JSON documents in the log file.
2. Log files are taken by FileBeat and sent to Logstash line by line. This configuration is written once and won't change much after that.
3. Logstash takes these lines and send it to its index in ElasticSearch without any other processing, again, write once (for all applications, not even once per application).
4. ElasticSearch take this information, index per application, day and priority, it will keep the extra fields that developers put in the logs in first place.
5. When developers want to expose more fields, they don't need to bother anyone, if it's in the logs, they will be in ElasticSearch. (Maybe asking for a reindexing in ES every now and then, not too much).

Using JSON as your log format is, by all means, part of the solution I am presenting here.

I haven't yet explored other topologies, like using Fluentd instead of Logstash, or FileBeat sending to ElasticSearch directly, yet to explore.


Next: 3 - Logging best practices with Logback

Level up logs and ELK - Introduction

Articles index:

1. Introduction (Everyone)
2. JSON as logs format (Everyone)
3. Logging best practices with Logback (Targetting Java DEVs)
4. Logging cutting-edge practices (Targetting Java DEVs) 
5. Contract first log generator (Targetting Java DEVs)
6. ElasticSearch VRR Estimation Strategy (Targetting OPS)
7. VRR Java + Logback configuration (Targetting OPS)
8. VRR FileBeat configuration (Targetting OPS)
9. VRR Logstash configuration and Index templates (Targetting OPS)
10. VRR Curator configuration (Targetting OPS)
11. Logstash Grok, JSON Filter and JSON Input performance comparison (Targetting OPS)

 

Introduction

 

Why this? Why now?

This is the result of many years as a developer knowing that there was something called "logs":

A log is something super important that you cannot change because someone reads them, you cannot read them either because you don't have ssh access to the boxes they are generated in. Write them, but not too much, disk may fill.

Then learned how to write them, then suffered how to read them (grep) until I knew there was a superexpensive tool that could collect, sort, query and present them for you.
Then I love them, always thought of them like the ultimate audit tool but still too many colleagues preferred to use database for that sort of functionality.

I got better at logging like it was a nice story happening in my application, learned also how to correlate logs across multiple services, but I barely managed to create good dashboards.It happened that Splunk was too expensive to buy, and ElasticSearch too expensive to maintain. Infamous years without managing logs happened again.

Finally I got a job that involved architecture-level monitoring decisions and got the opportunity to develop a logging strategy for ElasticSearch (Splunk and other managed platforms didn't require that much hard thinking as they were providing the know-how and setup time). The strategy I will be developing in the next few articles came as a solution to many common restrictions in all companies I've been around the last decade.

It is a long story, will try to make it concise, bear with me and, if you belong to that huge 95% of companies that uses ElasticSearch as a supergrep, you'll raise your game.

Objectives of this series of articles:

1. Save up to 90% disk space based on VRR (Variable Replication factor and Retention) estimations by playing with replication, retention and custom classification.
   • Differentiate important from redundant information and apply different policies to them.
2. Log useful information for once, that you will be able to filter, query, plot and alert on.
• We are covering parameters, structured arguments, and how to avoid grok to parse them.
3. Save tons of OPS time by using the right tools to empower DEVs to be responsible of their logs.
•  Let's avoid bothering our heroes with each change in a log line. Minimizing OPS time is paramount.

Some assumptions:

• All my examples will orbit around Java applications using SLF4J log framework, backed by Logback.

• Logs are dumped to files, read by FileBeat, sent to Logstash.

• Logstash receives the log lines and send them to ElasticSearch after some processing.

• Kibana as ElasticSearch UI.

Even if your stack is not 100% identical, I am sure you can apply some bits from here.


Next:  2 - JSON as logs format

Lombok, cleaning up your code

Much time without writing, ok, I have been working hard in company projects a bit, and the rest of the time trying to improve our tools and processes.

I want to introduce you to "Lombok", a nice tool that could bring light to the darkness of certain classes everyone has seen at least once.

The gain in this case is almost out of discussion, you annotate your code and magically it gets powers and kicks the ass to the bad guys. They are not dependencies and either aspects, because Lombok works in compilation time almost always. Indeed, inclusion of lombok.jar is not necessary in all cases, a few ones doesn't need it.


Some examples from their web:

@Getter and @Setter, it is like using Eclipse "generate getter and setter automatically" but Lombok does even easier and cleaner:

import lombok.AccessLevel;  import lombok.Getter;  import lombok.Setter;    public class GetterSetterExample {    @Getter @Setter private int age = 10;    @Setter(AccessLevel.PROTECTED) private String name;        @Override public String toString() {      return String.format("%s (age: %d)", name, age);    }  }

turns in

public class GetterSetterExample {    private int age = 10;    private String name;        @Override public String toString() {      return String.format("%s (age: %d)", name, age);    }        public int getAge() {      return age;    }        public void setAge(int age) {      this.age = age;    }        protected void setName(String name) {      this.name = name;    }  }

Those changes are made in compiled bytecode, although you can decompile this changes (delombok) and see them in Java.

Another example, let's avoid the tricky and ugly closing file even inside and exception catch.

import lombok.Cleanup;  import java.io.*;    public class CleanupExample {    public static void main(String[] args) throws IOException {      @Cleanup InputStream in = new FileInputStream(args[0]);      @Cleanup OutputStream out = new FileOutputStream(args[1]);      byte[] b = new byte[10000];      while (true) {        int r = in.read(b);        if (r == -1) break;        out.write(b, 0, r);      }    }  }

turns in

import java.io.*;    public class CleanupExample {    public static void main(String[] args) throws IOException {      InputStream in = new FileInputStream(args[0]);      try {        OutputStream out = new FileOutputStream(args[1]);        try {          byte[] b = new byte[10000];          while (true) {            int r = in.read(b);            if (r == -1) break;            out.write(b, 0, r);          }        } finally {          if (out != null) {            out.close();          }        }      } finally {        if (in != null) {          in.close();        }      }    }  }

More: automatic log declaration

import lombok.extern.slf4j.Log;    @Log  public class LogExample {        public static void main(String... args) {      log.error("Something's wrong here");    }  }    @Log(java.util.List.class)  public class LogExampleOther {        public static void main(String... args) {      log.warn("Something might be wrong here");    }  }

turns in

public class LogExample {    private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(LogExample.class);        public static void main(String... args) {      log.error("Something's wrong here");    }  }    public class LogExampleOther {    private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(java.util.List.class);        public static void main(String... args) {      log.warn("Something might be wrong here");    }  }

(Several implementations of log are provided).

And so on and on... check the features list

http://projectlombok.org/features/index.html

This tool is also integrated with Eclipse (through installation) and Eclipse (only by including it as a dependency). Use it wisely, but use it :)