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 - Logging Cutting-Edge Practices - Documenting and sharing your most important logged information

 

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)

Logging cutting-edge practices: Sharing your log strategy with other teams and departments

Once you have your ELK cluster in place, and your team is making an application (or several) logging into it, you still have a problem to solve.

Given either of the following scenarios:

• A team newcomer is asked to investigate something that involves logs.
• CTO has granted Support access to ELK so they can have some insights to application activity or problems.
• Another team is investigating a cross-application problem.

Assuming they know the service, host and other common OPS-depending attributes...

• What attributes can they query in ELK?
• What to they mean?
• What text does come with the data they need?
• How do they know what data is correlated?

Bonus question

• How do you enforce that same attribute has same name in all your logs? Moreover, how do you enforce it's always the same type?

I'll be proposing a number of different solutions in a iterative evolution, pick the one you prefer.

Baseline:

You are using  latest log format and best practices from Level up logs and ELK - Logging best practices with Logback

logger.info("New Market Status {} {}", kv("marketId", 1234), kv("newStatus", "ready"));

Cons:

• Name or case could differ for same concept in different names.
• Type mismatch is possible, same name, different type.
• Enforcing usage as policy.
• Not documentation available for sharing with other teams or for your own reference.

 

Iteration #1: Constant names

First problem to solve is ensuring we are not using different keys for the same concept.
Initially there's nothing that avoided this to happen:

logger.info("New Market Status {} {}", kv("marketId", 1234), kv("newStatus", "ready"));

[...] 

logger.info("Editing Market Status {} {}", kv("id", 1234), kv("newstatus", "ready"));

On one hand, no developer is going to manually check all the names for any variable to enforce consistency of names. On the other, even lower/upper case mismatch could ruin your queries as they are stored in case sensitive fields.

First iteration would make us think of a set of constant Strings or Enums to help us to deal with variety of names. Documentation about meaning, usage, required type and description could be explicit in comments.

public class LoggerUtils {
    public static final String MK_ID = "marketId"; //String - Market Id
    public static final String MK_NEW_STATUS = "newStatus"; //MarketStatus.java enum - New Market Status
}

Finally code would look like this (Enforced by code review and good will only)

logger.info("New Market Status {} {}", kv(MK_ID, 1234), kv(MK_NEW_STATUS, "ready"));

[...] 

logger.info("Editing Market Status {} {}", kv(MK_ID, 1234), kv(MK_NEW_STATUS, "ready"));

Cons:

• Name or case could differ for same concept in different names.
• Type mismatch is possible: same name, different type.
• Enforce usage as policy.
• Not documentation available for sharing with other teams or for your own reference.

Iteration #2: Enforcing types

This problem comes from accidentally reusing same name for different kinds of items, being "id" a paradigmatic example.

logger.info("New Market Status {} {}", kv("id", 1234), kv("newStatus", "ready"));

[...] 

logger.info("User has signed up {}", kv("id", "email@forexample.com"));

Unless forced, first occurrence of a type defines the type for that index. Therefore you will find an error as following in Logstash logs/output:

logstash_1       | [2018-11-15T22:08:29,392][WARN ][logstash.outputs.elasticsearch] 

Could not index event to Elasticsearch. {

:status=>400, 

:action=>[

  "index", {

    :_id=>nil, 

    :_index=>"vrr-leveluplogging-low-2018-11-15", 

    :_type=>"doc", 

    :_routing=>nil

  }, 

  #<LogStash::Event:0x9b41f3e>

], 

:response=>{

  "index"=>{

    "_index"=>

    "vrr-leveluplogging-low-2018-11-15", 

    "_type"=>"doc", 

    "_id"=>"hJZrGWcBSDbbRtN6HHw3", 

    "status"=>400, 

    "error"=>{

      "type"=>"illegal_argument_exception", 

      "reason"=>"mapper [id] of different type, current_type [long], merged_type [text]"

}}}}

If you check Kibana's Management -> Index Patterns -> vrr-* (in our example)


Field "id" has been defined as "number", therefore when Logstash tries to put a "string" it fails.

Once introduced the problem, let's try the solution.

import net.logstash.logback.argument.StructuredArgument;
import static net.logstash.logback.argument.StructuredArguments.kv;

public class LoggerUtils {

    public static StructuredArgument logMarketId(Long id) {
        return kv("marketId", id);
    }

    public static StructuredArgument logCustId(String id) {
        return kv("custId", id);
    }

}

We could create a helper class that centralized the responsibility of not reusing names, and name-type relationship.

It would be used like this now (old and new version):
logger.info("User has signed up {}", kv("id", "email@forexample.com"));

logger.info("User has signed up {}", logCustId("email@forexample.com"));

Yet you need to enforce creating these functions and its usage.

Cons:

• Name or case could differ for same concept in different names
• Type mismatch is possible, same name, different type
• Enforce usage as policy
• Not documentation available for sharing with other teams or for your own reference

Please notice that a field accepting a type, e.g. "id" accepting "number", also implies that it can take an array of the same type (and not only a single value); it will be handled by ElasticSearch transparently. They will be indexed as searches will return the same document for a query of either of the values in the array.

Iteration #3: Enforcing usage

How to avoid that a random developer adds their own log lines, breaking all the rules above? Good and Rogue developer below:

import net.logstash.logback.argument.StructuredArgument;
import org.slf4j.Logger;import org.slf4j.LoggerFactory; 
import static example.LoggerUtils.logCustId;
import static net.logstash.logback.argument.StructuredArguments.kv; 

[...] 

logger.info("Good developer using custom LoggerUtils {}", logCustId("email@forexample.com")); 

[...] 

logger.info("Roge developer not using custom LoggerUtils {}", kv("custId",1234L));


Fortunately for us, Checkstyle already allows to control arbitrary imports, and also allows suppresion of this rule for a given class. Let's put it together.

Checkstyle configuration forbidding usage of kv import in the project:

<module name="Checker">
    <property name="charset" value="UTF-8">

    <module name="SuppressionFilter">
        <property name="file" value="${config_loc}/suppressions.xml">
    </property></module>
    
    <module name="TreeWalker">
        <module name="IllegalImport">
            <property name="illegalClasses" value="net\.logstash\.logback\.argument\.StructuredArguments.*">
            <property name="regexp" value="true">
        </property></property></module>
    </module>
</property></module>

Making an exception with LoggerUtils class:

<suppressions>
    <suppress checks="IllegalImport" files="LoggerUtils\.java"></suppress>

</suppressions>

You could argue that there are ways to avoid this prohibition, I agree, always are.
Goal here is not to avoid by all means that a Rogue developer logged anything he liked. Goal is to avoid mistakes, and programmatically bypass this checks should really shine in a code review.

As a result of applying above configuration in our favorite build tool (Maven, Gradle, etc..) you would find a broken build (if you configure it so, and so I recommend) and an explanation as follows (Gradle output):

:compileJava
:processResources UP-TO-DATE
:classes

[ant:checkstyle] [ERROR] /home/alberto/code/leveluplogging/leveluplogging/src/main/java/example/ErrorType.java:9:1: 

Illegal import - net.logstash.logback.argument.StructuredArguments.kv. [IllegalImport]
:checkstyleMain FAILED

FAILURE: Build failed with an exception.

Cons:

• Name or case could differ for same concept in different names.
• Type mismatch is possible: same name, different type.
• Enforce usage as policy.  
• Not documentation available for sharing with other teams or for your own reference.

 

Iteration #4: Contract-first LoggerUtils code generation

A solution that kept the goodness of the three previous iterations, but focused on a "documentation first" approach (analogy of contract-first for developers) would involve, in my opinion, the following elements:

1. A description file that explains in the closest to human language possible what are you logging that could be of any interest to anyone.
2. A code generator application that took the description file and made some equivalent to LoggerUtils in your favorite language. 
3. A documentation generator application that took the description file and made a full human readable documentation in your favorite markup / text format.
4. A plugin to attack previous two steps in your build chain (Gradle plugin, Maven plugin..)

This topic will take me long enough to deserve another article. See link below "Next"
 




Next: 5 - Contract first log generator

Level up logs and ELK - Logging best practices with Logback

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)

Logging best practices with Logback

 

Logs are the product of, so far, and in my experience only, very personal view of how software must be built and the amount of nights on call the developer has suffered.
In this chapter I am going to recommend some ways of logging information in order to make it more useful when it comes to Index, Search and Filter.

All examples expressed in Java + SLF4J.
Github repo: https://github.com/albertonavarro/leveluplogging/tree/master/leveluplogging

Simple Message:

Most of the free log information will come as message information. From "Application is ready to listen messages" to "Unknown error trying to upload file". These messages have a low information interest, I struggled to make these kind of messages without any parameter.

Example code in GitHub

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Main {
    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        logger.info("Starting main - without arguments");
    }
}

This could be the output for a simple Message in plain text:

20:15:52.106 [main] INFO  Main1 - Starting main - without arguments

You would still need some help to make that log line useful, like Grok or Splunk.
They could expect that your format to be constant and immutable, consisting of

input {
  beats {
    port => 5044
  }
}

filter {
    grok {
        match => [ "message" , "%{TIME:@timestamp} \[%{WORD:thread}\] 

%{LOGLEVEL:loglevel}\s+%{WORD:classname} - %{GREEDYDATA:message}" ]
        overwrite => ["message"]
    }
}

output {
    elasticsearch {
        hosts => "localhost:9200"
        index => "logstash-classic"
    }
}

Later on, these "messages" are translated to an identical message field in the ElasticSearch document that you may search by exact or partial match.

Notice than thanks to Grok, we have extracted "classname" and "loglevel" as long as that format never changes.

You might event count, compare, dashboard the number of events of a type VS the number of events of a different type, correlate by time, etc.

This would be the aspect of the same message in JSON:

{"@timestamp":"2018-09-06T20:15:52.106+02:00","message":"Starting main - without arguments",

"level":"INFO","level_value":20000}

Fields are already split and named, no need to do extra parsing to extract the same benefits.

Arguments: 

Example code in GitHub

At some point, we find it necessary to add dynamic information to our logs, flavor can go from free text to semi-structured format. This could be my own evolution:

Initially I wrote them like this:

logger.info("Market {} is ready", marketId)

Then I tried to give it some more structure:

logger.info("Market marketId={} is ready", marketId)

I ended like this in order to improve queries format:

logger.info("New Market Status marketId={} newStatus={}", marketId, "ready")

The reason for accumulating free text on the left and data on the right is simplifying the queries. In Kibana it would easier and more performing querying "Market is ready" than "Market" AND "is ready".

Output for this last test would look like:

23:26:52.164 [main] INFO  Main2 - New Market Status marketId=1234 newStatus=ready 

Reusing previous Grok expression, we could extract message="New Market Status marketId=1234 newStatus=ready", but we would need to run something else on top of it to get ElasticSearch to understand there is extra information there that it can index separately.

Logstash's KV plugin (Elastic KV plugin) will extract key/value pairs from a given input, so in this case, output would look like this (notice new fields marketId and newStatus)

Now ElasticSearch can filter by "marketId", by "status", and go deeper and wider in data analysis.

The only weak point for KV is that it could have "false positives" detecting key/value pairs. Until recently, only single character separators were supported. Now char sequences defined by regex are as well (finally). By default. separator is character "=", that you would easily find in base64 strings or URLs. That would dirt and damage your index performance rather quickly.

JSON output would have same output and problems, we would still need to separate information from within message text.

Structured Arguments

Example code in GitHub

The amazing library logstash-logback-encoder also provides another way of expressing arguments in a more structured way. Nicely wrapped in the StructuredArguments class, it offers a number of convenient methods to parameterize Key/Values, Lists and Maps.

Syntax is quite similar, just a little bit more verbose:

logger.info("New Market Status {} {}", kv("marketId", 1234), kv("newStatus", "ready"));

It leaves the following console output, as it automatically formats key value pairs. Likewise previous method, information can be extracted using KV plugin.

20:20:02.037 [main] INFO  Main3 - New Market Status marketId=1234 newStatus=ready

However this is way more valuable when the output is JSON instead of plain text, as it not only formats the message the same way, but it also introduces at root level the new pair of attributes, marketId and newStatus, as independent fields.

{"@timestamp":"2018-09-06T20:20:02.037+02:00","message":"New Market Status marketId=1234 

newStatus=ready","level":"INFO","level_value":20000,"marketId":1234,"newStatus":"ready"}

This is very important, because this document, either directly sent to ElasticSearch, or gone through Logstash, will be indexed by ElasticSearch taking "marketId" and "newStatus" as independently indexed information without extra effort at all (no need for Grok or KV).

Compare required Logstash configuration with previous one:

input {
  beats {
    port => 5044
    codec => json
  }
  
}

output {
    elasticsearch {
        hosts => "localhost:9200"
        index => "logstash-classic"
    }
}

Finally resulting in this output in ElasticSearch

Notice (again) that "marketId" and "newStatus" are recognized without Grok or KV plugins configured at all in Logstash. Moreover, there won't be false-positives (I talked about this in the KV section some lines above). Some more extra fields pop-up coming from logstash-logback-encoder.

MDC

Example code in GitHub

One of the most important and useful tools in modern log frameworks is the Mapped Diagnostic Context (MDC).

The most common scenario where MDC highlights is the log correlation within a service and across services; MDC uses a ThreadLocal to store a map of key/values per any thread that uses the logger.

If you created an aspect or a filter in your service that assigned in that map a well-known key (e.g. "rid" for "request id") with a new UUID value per request, all logs made by that request would have the same "rid". This value could be also taken by http/jms clients to propagate the "rid" to other services that we own, and keep the same id across all services.
This is an extended pattern to trace calls across distributed services in industry.

In any service that used multiple threads to execute a given code in parallel, this is as good as using the thread name to distinguish actions from one or other thread. However, thread name won't help you if task is started by one thread and finished by another, or you wanted to know what happened with that request in next service it invoked.

Simulating  such behavior with following code:

public static void main(String[] args) {
    MDC.put("rid", UUID.randomUUID().toString());
    logger.info("New Market Status {} {}", kv("marketId", 1234), kv("newStatus", "ready"));
    logger.info("Some more logging");
}

Console output for MDC requires some extra configuration per field, so don't get too excited with these fields.

<encoder>
    <pattern>%d{HH:mm:ss.SSS} %X{rid} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>

So now we are able to see it in the console/file

20:27:28.007 b5fab580-12f4-4266-8a97-927d03d1b01a [main] INFO  Main4 - New Market Status 

marketId=1234 newStatus=ready
20:27:28.043 b5fab580-12f4-4266-8a97-927d03d1b01a [main] INFO  Main4 - Some more logging

And given the strict format, to read it with grok as any other field (Notice extra configuration per new MDC field).

grok {
        match => [ "message" , "%{TIME:@timestamp} %{UUID:rid} \[%{WORD:thread}\] 

%{LOGLEVEL:loglevel}\s+%{WORD:classname} - %{GREEDYDATA:message}" ]
        overwrite => ["message"]

}

Once again, with the right Logstash configuration

input {
  beats {
    port => 5044
    codec => json
  }
  
}

output {
    elasticsearch {
        hosts => "localhost:9200"
        index => "logstash-classic"
    }
}

and the right Logback configuration (below) we can get MDC mapped in JSON with no effort for new fields at all:

{"@timestamp":"2018-09-06T20:27:28.007+02:00","thread_name":"main",

"rid":"b5fab580-12f4-4266-8a97-927d03d1b01a","logger_name":"Main4",

"message":"New Market Status marketId=1234 newStatus=ready","level":"INFO",

"marketId":1234,"newStatus":"ready"}

{"@timestamp":"2018-09-06T20:27:28.043+02:00","thread_name":"main",

"rid":"b5fab580-12f4-4266-8a97-927d03d1b01a","logger_name":"Main4",

"message":"Some more logging","level":"INFO"}

Once again, "rid" appears outside the message and as independent field, so it is automatically accepted by Logstash and indexed by ElasticSearch. No extra Logstash configuration either.

Logback Configuration for JSON using logstash-logback-encoder

It's not the purpose of the article to get deep into configuration details. Just mentioning this is the configuration that I'm using for this examples. Best guide to get this right is (GitHub) logstash-logback-encoder

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="stash" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logFile.json</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>file.log.%d{yyyy-MM-dd}</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <providers>
                <timestamp/>
                <threadName/>
                <mdc/>
                <loggerName/>
                <message/>
                <logLevel/>
                <arguments/>
                <stackTrace/>
                <stackHash/>
            </providers>
        </encoder>
    </appender>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    
    <root level="all">
        <appender-ref ref="stash" />
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

Next: 4 - Logging cutting-edge practices (experimental)