Better Logging Approach For Microservices

The logging concern is one of the most complicated parts of our microservices. Microservices should stay as pure as possible. So, we shouldn’t use any library if we can(like logging, monitoring, resilience library dependencies). I mean, every dependency can change any time and then usually, we must do that change for the other microservices. There is a lot of work here. Instead of that, we need to handle these dependencies with a more generic way. For logging, the way is the stdout logging. For most of the programming languages, logging to stdout is the default way and probably no additional change required at the beginning.

Generally, the log libraries push your logs to monitoring tools for every period you specified or every group of log collected.

This is the most commonly used way. Simple and effective for monolith applications. No additional effort required. Logs stay structural on application memory. So doesn’t need any step to make them structural.

What if we have too many microservices that need to implement logging without any change of code? Think about you have to modify and deploy every service when you need to change the logging library. What if your team working on polyglot architecture? That means you need to find a new log library to implement logging for every programming language you use.

In short, the microservice architectural style is an approach to developing a single application as a suite of small services, each running in its own process and communicating with lightweight mechanisms, often an HTTP resource API. There is a bare minimum of centralized management of these services, which may be written in different programming languages. #Martin Fowler

For these reasons, we will let the logs to console(actually a file) and forgot it. Then the collector will collect the logs at specific time intervals.

There are two problems here. How to collect the logs from stdout and how to provide more fields to logs like headers cookies timespan etc.?

How to Collect the Logs From Stdout

There are various tools to do that. The most popular ones are Logstash and Fluentd. For example, if you orchestrate your microservices with containers by using k8s, both of them have an implementation(Filebeat/Fluentbit) to collect logs from the containers. We will handle the scenario with Filebeat. Filebeat ships your logs from log files to Logstash.

Logging to stdout means logging to file for Docker containers. If you work with non-Docker environments maybe you need to rotate your logs to files to let them collect by Filebeat.

The problem of reading log lines from the console is finding which lines belong to one log from multiple log lines. For example, exception logs.

Default golang log result from simple go api after panic called.

Multiline Patterns to Reading Log Lines

The solution is simple. Use the multiline pattern provided by Filebeat. The pattern tells, when the new log line starts and when it ends. Here is the multiline pattern for Filebeat to read the multiple log lines above.

multiline.pattern: '^([12]\d{3}\/(0[1-9]|1[0-2])\/(0[1-9]|[12]\d|3[01]))'
multiline.negate: true
multiline.match: after

Filebeat takes all the lines that do not start with(negate:true) that date format(yyyy/mm/dd) and combines them with the previous line(match:after) that does.

More detail about the Filebeat multiline pattern options:

Manage multiline messages | Filebeat Reference [7.3] | Elastic

The next step is making log details structured. So, we collected them as a string and then time to know which part is the message and which parts are the exception details.

Make Your Logs Structured

Now we have simple text belong one log after the collect it from the console(actually file.). Making your logs structured(extract them into fields.) is important to searching and visualizing. So, making them more accessible and easy to find.

Meet the grok filters! Grok works with text pattern and it helps to extract string data into fields.

Logstash has grok filter plugin.

Here is the example text and the grok pattern to fetch fields from the text data.

Example text:

2019/08/12 21:01:27 http: panic serving [::1]:50206: Something went wrong :/
goroutine 5 [running]:
net/http.(*conn).serve.func1(0xc00008c8c0)
 /usr/local/Cellar/go/1.11.1/libexec/src/net/http/server.go:1746 +0xd0
panic(0x1245ea0, 0x12eb9a0)

Grok pattern:

%{DATESTAMP:log_date} %{GREEDYDATA:message}(\n(?m)%{GREEDYDATA:exception})

Result:

{
  "log_date": [
    [
      "19/08/12 21:01:27"
    ]
  ],
  "message": [
    [
      "http: panic serving [::1]:50206: Something went wrong :/"
    ]
  ],
  "exception": [
    [
      "goroutine 5 [running]:\nnet/http.(*conn).serve.func1(0xc00008c8c0)\n /usr/local/Cellar/go/1.11.1/libexec/src/net/http/server.go:1746 +0xd0\npanic(0x1245ea0, 0x12eb9a0)"
    ]
  ]
}

After that, logs are extracted to fields and ready to send to Elasticsearch or somewhere you want to store them. Logstash can ship your logs if you specify the output on your Logstash configuration. The next step is visualizing them but it is not the case for now.

If you will visualize your logs on Kibana, you need to know the nested fields are not supported.

How to Provide More Fields to Logs Like Headers, Cookies, Timespan, etc.?

The default approach for common programming languages the stdout logs do not contain any additional fields except log message and exception call stack. To providing more fields, we need to override the default logger.

Let's implement a simple logger that contain request relevant fields for golang web api. Here is the code:

The code snippet, responsible to write the error logs to stdout by given format. During the process, x-request-idadding the log. Also, for the errors, the logs start with error: prefix. Thus, this making it easier to reading the log and making it structural by grok. In short, we created the log with this format:

level: timestamp request_id "message" \nstack_trace

Let's make a simple request to the index that only calls the panic method. Then see the results.

curl -H "x-request-id:a56bc-99hx0" localhost:8000

The multiline pattern:

multiline.pattern: '^error:|^info:'
multiline.negate: true
multiline.match: after

The grok filter should be like that for the right match of fields.

%{WORD:log_level}: %{TIMESTAMP_ISO8601:log_date} %{DATA:request_id} %{DATA:msg}(\n(?m)%{GREEDYDATA:exception})

Bonus: log results on Kibana:

@ timestamp and log_date fields can be different. log_date is the application level date and time. timestamp is the date and time that provided by Logstash. @ version _id _index _score and _type are default fields.

Links:

https://cloud.docker.com/repository/docker/turgayozgur/goexample
https://martinfowler.com/articles/microservices.html
https://www.elastic.co/products/beats/filebeat
https://www.elastic.co/products/logstash
https://www.elastic.co/products/elasticsearch
https://www.elastic.co/products/kibana
https://grokdebug.herokuapp.com/
https://fluentbit.io/