Kibana-mother or Why do you need logs at all? / UKit Group Blog

You can say that “sometimes it is necessary ...” But in fact, you want to always see what is in your logs through the graphical interface. This allows:

• Make life easier for developers and system administrators, whose time is simply a pity and expensive to spend writing grep pipelines and parsers for each individual case.
  
• Provide access to information contained in the logs to moderately advanced users - managers and technical support.
  
• And see the dynamics and trends of the occurrence of secured events (for example, errors).

So today let's talk again about the ELK stack (Elasticsearch + Logstash + Kibana).
But this time - in the conditions of json-logs !

Such a use case promises to fill your life with completely new colors and will make you experience the full gamut of feelings.

Prologue:

"Understand, on Habrahabr only and talk that about Kibana and Elasticsearch. About how damn cool it is to observe how a huge text log turns into beautiful graphics, and a barely visible load on the CPU burns somewhere deep in the top. And you? .. What will you tell them? ”

Materiel

In the life of every normal kid, a moment arises when he decided to put an ELK bunch on his project.

The average pipeline layout looks something like this:


We send 2 types of logs to Kibana:

1. “Almost normal” nginx log. Its only highlight is request-id. We will generate them, as is now fashionable, using Lua-in-config ™.
2. “Unusual” logs of the application on node.js. That is, the error log and the “prolog”, where “normal” events fly - for example, “the user created a new site”.
   
   The peculiarity of this type of logs is that it:
   
   • Serialized json (logs events to the bunyan npm module)
   • Formless. The set of fields for messages is different, in addition, in the same fields, different messages can have different data types (this is important!).
   • Very greasy. The length of some messages exceeds 3Mb.

These, respectively, are the front- and back-end-s of our entire system ... Let's get started!

filebeat


logstash

Binding events in front and back logs

Setting:

“We had 2 types of logs, 5 services in the stack, half a terabyte of data in ES, and also an uncountable set of fields in the application logs. It’s not that it was a necessary set for realtime analysis of the status of the service, but when you start to think about binding events of nginx and the application, it becomes difficult to stop.

The only thing that worried me was Lua. There is nothing more helpless, irresponsible and vicious than Lua in Nginx configs. I knew that sooner or later we will go to this rubbish. "

To generate request-id on Nginx, we will use the Lua-library, which generates uuid-s. She, in general, copes with her task, but I had to modify it a bit with a file - for in its original form it (ta-dam!) Duplicates uuid-s.

http {
...
# Либа для генерации идентификаторов запросов
lua_package_path '/etc/nginx/lua/uuid4.lua';
init_worker_by_lua '
    uuid4 = require "uuid4"
    math = require "math"
';
...
# Объявляем переменную request_id, 
# обычный способ (set $var) не будет работать в контексте http
map $host $request_uuid { default ''; }
# Описываем формат лога
log_format ukit  '$remote_addr - [$time_local] $host "$request" '
                    '$status $body_bytes_sent "$http_referer" '
                    '"$http_user_agent" $request_time '
                    '$upstream_response_time $request_uuid';
# Путь к файлу и формат лога
access_log    /home/appuser/app/log/nginx.log ukit;
}
server { 
...
	# Генерируем id запроса
set_by_lua $request_uuid '
        if ngx.var.http_x_request_id == nil then
            return uuid4.getUUID()
        else
            return ngx.var.http_x_request_id
        end
';
	# Отправляем его в бекэнд в виде заголовка, чтобы он у себя тоже его залогировал.
	location @backend {
            proxy_pass       http://127.0.0.1:$app_port;
            proxy_redirect   http://127.0.0.1:$app_port http://$host;
            proxy_http_version 1.1;
            proxy_set_header Connection "";
            proxy_set_header X-Real-IP $remote_addr;
            proxy_set_header X-Nginx-Request-ID $request_uuid; #id запроса
            proxy_set_header Host $host;
            ...
        }
...
}

At the output, we get the opportunity by an event in the application log to find the request that triggered it, arriving at Nginx. And vice versa.

It quickly became apparent that our “ecumenically unique” identifiers are not so unique. The fact is that the randomseed library takes from the timestamp at the time of the start of the nginx worker. And we have as many workers as the cores of the processor, and they start at the same time ... It doesn’t matter! Mix the pid of the worker there and we will be happy:

...
local M = {}
local pid = ngx.worker.pid()
-----
math.randomseed( pid + os.time() )
math.random()
...

PS There is a ready-made nginx-extras package in the Debian repository. There immediately there is Lua and a bunch of useful modules. I recommend that instead of compiling the Lua module by hand (openresty still happens, but I have not tried it).

Group errors by frequency of occurrence.

Kibana allows you to group (build ratings) events based on the same field values.

We have stack traces in the error log, they are almost ideally suited as a grouping key, but the catch is that in Kiban it is impossible to group by keys longer than 256 characters, and stacks are certainly longer. Therefore, we make md5 hashes of stackraces in bunyan and group them by them already. Beauty!

This is what the top 20 errors look like:


And a single type of error on the graph and a list of episodes:


Now we know which bug in the system can be fixed sometime later, because he is too rare. You must admit that this approach is much more scientific than “there have been many similar support tickets in this week”.

And now - the breakdown: it works, but badly

Climax:

"I understand. You found paradise in NoSQL: you were developing quickly, because you kept everything in MongoDB and you didn’t need friends like me. And now, you come and say: I need a search. But you don’t ask with respect, you don’t even call me the Best Search Engine. No, you come to my house on Lucene’s birthday and ask me to index unstructured logs for free. ”

Surprises

Do all messages from the log go to Kibana?

Not. Not everyone gets in.

Mapping remembers the name of the field and its type (number, string, array, object, etc.). If we send a message to ES in which there is a field that already exists in the mapping, but the type does not match what was in this field before (for example, in mapping it is an array, but an object arrived), then such a message will not get into ES , and in his log there will be a not too obvious message:

{"error": "MapperParsingException [object mapping for [something] tried to parse as object, but got EOF, has a concrete value been provided to it?]"
Source

Field names in json logs

Elasticsearch v2.x does not accept messages that contain fields whose names contain periods. There was no such restriction in v1.x, and we cannot upgrade to the new version without redoing all the logs, as such fields have already “historically developed” in our country.
Source

In addition, Kibana does not support fields whose names begin with an underscore '_'.


Developer Comment

Automatically crawl data into neighboring ES instances

By default, the Zen Discovery option is enabled in ES. Thanks to her, if you run several ES instances on the same network (for example, several docker containers on the same host), they will find each other and share the data among themselves. A very convenient way to mix productive and test data and deal with it for a long time.

It falls and then rises for a long time. It's even more painful when docker

The stack of demons involved in our criminal scheme is quite numerous. In addition, some of them like to incomprehensibly fall and rise for a very long time (yes, those in Java). Most often the logstash-indexer hangs, in the logs there is silence or unsuccessful attempts to send data to the ES (it is clear that they were a long time ago, and not just that). The process is alive, if you send him kill - it dies for a very long time. You have to send kill -9 if you have no time to wait.

Less often, but it also happens that Elasticsearch falls. He does this “in English” (that is, silently).

To understand which of the two of them fell, we make an http-request in ES - if answered, then it is not he. In addition, when you have a relatively large amount of data (say, 500G), then your Elasticsearch after starting it will suck this data for about half an hour, and at that time it will be inaccessible. The data of Kibana itself is stored there, so it also does not work until its index is picked up. According to the law of meanness, it is usually the turn at the very end.

You have to monitor the queue length in rabbitmq by monitoring to quickly respond to incidents. Once a week they happen stably.

And when you have everything in docker, and the containers are linked to each other, then you need to restart all the containers that were linked to the ES container, except for itself.

Large memory dumps with OOM

By default, the option HeapDumpOnOutOfMemoryError is enabled in ES. This may cause you to run out of disk space unexpectedly due to one or more dumps of ~ 30GB in size. They are reset, of course, to the directory where the binaries are (and not to where the data is). This happens quickly, monitoring does not even have time to send SMS. You can disable this behavior in bin / elasticsearch.in.sh.

Performance

In Elasticsearch there is a so-called “Mapping” of indices. In essence, this is a table layout in which data is stored in the “field - type” format. It is created automatically based on the incoming data. This means that ES will remember the name and data type of the field, based on what type of data came in this field for the first time.

For example, we have 2 very different logs: access-log nginx and production-log nodejs applications. In one standard set of fields, it is short, data types never change. In the other, on the contrary, there are many fields, they are nested, they are different for each line of the log, the names can overlap, the data inside the fields can be of different types, the line length reaches 3 or more Mb. As a result, ES auto-mapping does this:

Mapping a healthy “nginx” rectangular log:
root @ localhost: /> du -h ./nginx.mapping
16K ./nginx.mapping

Mapping the smoker of the “shapeless” json-log of our application:
root @ localhost: /> du -h ./prodlog.mapping
2.1M ./ prodlog.mapping

In general, it greatly slows down both when indexing data and when searching through Kibana. Moreover, the more data has accumulated, the worse.

We tried to deal with this closing of old indexes using curator . There is certainly a positive effect, but still it is anesthesia, not a treatment.

Therefore, we came up with a more radical solution. All heavy nested-json in the production log will now be logged as a string in a dedicated onemessage field. Those. here directly JSON.stringify (). Due to this, the set of fields in messages becomes fixed and short, we come to the “easy” mapping like the nginx-log.

Of course, this is a kind of “amputation with further prosthetics”, but the option is working. It will be interesting to see in the comments how else could be done.

Subtotal

The ELK stack is a cool tool. For us, it has become simply indispensable. Managers monitor the bursts of errors on the frontend after the next release and come to complain to the developers already "not empty-handed." Those, in turn, find correlations with errors in the application, immediately see their stacks and other important data necessary for debugging. It is possible to instantly build various reports from the series “hits on site domains”, etc. In a word, it is not clear how we lived before. But on the other hand ...

“Robust, Reliable, Predictable” - all this is not about ELK. The system is very moody and rich in unpleasant surprises. Very often you have to delve into all this shaky, sorry, Jav-no. Personally, I can’t recall a technology that would so poorly follow the “tuned and forgot” principle.

Therefore, in the last 2 monthsWe completely redid the application logs. Both in terms of format (we get rid of dots in names to switch to ES v.2), and in terms of the approach to what to log and what not to do. By itself, this process, IMHO, is absolutely normal and logical for a project like ours - recently uKit celebrated its first birthday.

“At the beginning of the path, you dump as much information as possible into the logs, because it’s not known in advance what is needed, and then, starting to “grow up”, gradually remove the excess. ” (c. pavel_kudinov )