Apresentação e considerações

Este artigo é um registro de como solucionei o caso de fazer a ingestão de logs do meu banco de dados com Filebeat, Grok, Elasticsearch e Kibana!

Como pra mim não foi uma tarefa nada fácil, resolvi documentar!

Lets’s go!

Entendendo a necessidade

O objetivo principal é coletar os logs do MariaDB para identificar as queries lentas, e dessa forma realizar um trabalho preventivo na otimizações das consultas.

Vi que o Filebeat tinha um módulo para isso já com um pipeline definido usando multiline, de forma a coletar os logs, processar, quebrar com grok e enviar para o Elasticsearch.

Porém como nem tudo são flores na vida de Joseph Climber, o módulo em si por padrão não estava preparado para o tipo de log que o meu DB estava gerando, me levando a estudar e testar incansavelmente combinações diversas de regex com grok que inclusive registrei algumas coisas do meu drama no grupo de discussão oficial da Elastic.

Esse artigo parte do princípio que você já tenha o Elasticsearch e o Kibana instalado e devidamente configurado!

Versões utilizadas:

  • Elasticsearch version: 6.3.0
  • MariaDB Versions: 5.5.56-MariaDB and 10.1.21-MariaDB
  • Filebeat version: 6.3.0
  • Kibana version: 6.3.0

Logs do MariaDB

Por padrão o MariaDB e o MySQL vem com os logs de Slow Queries desativados, para ativá-los podemos editar o arquivo /etc/my.cnf inserindo os seguintes valores abaixo:

vim /etc/my.cnf

[mysqld]

## 1 habilita, 0 desabilita
log_slow_queries = 1

## Tempo em segundos que voce considera que uma query é lenta, o valor de 1 é somente para testes, basicamente vai logar tudo, portanto entenda o seu ambiente para colocar um valor que indique que uma query está lenta de fato.
long_query_time = 1

## Caminho do arquivo de log que sera utilizado por padrão.
log-slow-queries = /var/log/mariadb/slow_query.log

Padrão de Log a ser analisado

Path de exemplo: /var/log/mariadb/mariadb-slow.log

Como podemos ver abaixo cada evento gera múltiplas linhas no log começando em # Time: XXX e finalizando com select XXXXX;, podemos ver que esse log segue sempre o mesmo padrão a medida que ele é alimentado.

# Time: 180613 11:04:36
# User@Host: root[root] @ localhost []
# Thread_id: 5  Schema: TESTE  QC_hit: No
# Query_time: 2.000652  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1528898676;
select sleep(2);
# Time: 180618 11:10:30
# User@Host: root[root] @ localhost []
# Thread_id: 6  Schema: TESTE  QC_hit: No
# Query_time: 3.000652  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1528898453;
select sleep(2);

Grok e Grok Debugger

Quando queremos adotar uma solução de centralização e análise de logs, fazer o armazenamento exatamente da forma com que os logs são gerados não é a melhor opção para se extrair o devido valor dos dados. É ai que o GROK entra!

O Filebeat fica “escutando” o arquivo, quando há um evento no arquivo o Filebeat captura esse evento e se existe um pipeline definido o arquivo começa a ser tratado, com o GROK podemos fazer digamos que um processo de ETL em nossos logs, ou seja, através de alguns padrões (patterns) que definimos utilizando expressões regulares ReGex podemos e dar nomes para cada item do log quebrando em linhas, e com isso analisar de uma forma mais precisa.

Já temos um exemplo de como o nosso arquivo de log é escrito, agora precisa criar uma regex utilizando o grok para parsear os nossos logs, para isso podemos utilizar o Grok Debug para testar!

Log Pattern

# Time: 180617 20:35:45\n# User@Host: root[root] @ localhost [192.168.10.1]\n# Thread_id: 4  Schema:   QC_hit: No\n# Query_time: 3.007507  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0\nSET timestamp=1529278545;\nSELECT sleep(3);

Grok filter

Abaixo segue a expressão que eu montei para parsear o log:

^# Time: (?<mysql_slowlog_time>%{NUMBER}%{SPACE}%{TIME})(.|\r|\n)*# User@Host: %{USER:mysql_slowlog_user}\[%{USER:mysql_slowlog_current_user}\] @ %{HOSTNAME:mysql_slowlog_client_host}? \[%{IP:mysql_slowlog_client_ip}?\](.|\r|\n)*# Thread_id:%{SPACE}%{NUMBER:mysql_slowlog_id} Schema: %{WORD:mysql_slowlog_schema}? QC_hit: %{WORD:mysql_slowlog_qc_hit}(.|\r|\n)*# Query_time: %{NUMBER:mysql_slowlog_query_time_sec} Lock_time: %{NUMBER:mysql_slowlog_lock_time} Rows_sent: %{NUMBER:mysql_slowlog_rows_sent} Rows_examined: %{NUMBER:mysql_slowlog_rows_examined}(.|\r|\n)*SET timestamp=%{NUMBER:mysql_slowlog_timestamp};(.|\n)%{GREEDYDATA:mysql_slowlog_query}

 

grok-debbuger

Instalando e configurando o Filebeat

Para instalar:
https://www.elastic.co/downloads/past-releases

Apontando o output do filebeat para o Elasticsearch

Path: /etc/filebeat/filebeat.yml

Localize o bloco de configuração abaixo no arquivo e ajuste conforme os dados de acesso do seu Elasticsearch.

output.elasticsearch:
  # Array of hosts to connect to.
  hosts: ["localhost:9200"]

  # Optional protocol and basic auth credentials.
  #iprotocol: "http"
  #username: ""
  #password: ""

Habilitando o módulo MySQL

filebeat modules enable mysql

Preparando as configurações

Arquivo: mysql.yml

Path: /etc/filebeat/modules.d/mysql.yml


– module: mysql
# Error logs
error:
enabled: true
# Set custom paths for the log files. If left empty,
# Filebeat will choose the paths depending on your OS.
var.paths: ["/var/log/mariadb/mariadb.log"]
# Slow logs
slowlog:
enabled: true
# Set custom paths for the log files. If left empty,
# Filebeat will choose the paths depending on your OS.
var.paths: ["/var/log/mariadb/slow_query.log"]

view raw

filebeat-mysql-slowlog-mysql.yml

hosted with ❤ by GitHub

Arquivo: slowlog.yml

Path: /usr/share/filebeat/module/mysql/slowlog/config/slowlog.yml

Nesse arquivo declaramos que nosso log utiliza multiplas linhas para cada evento, com isso em pattern: '# Time: ' informamos qual a linha que ele deverá dar match para saber onde se inicia o log, em negate: true e match: after informamos que à partir do pattern definido as próximas linhas serão anexadas a anterior, e quando for localizado o pattern novamente e grok entenderá como um novo evento.


type: log
paths:
{{ range $i, $path := .paths }}
– {{$path}}
{{ end }}
exclude_files: ['.gz$']
multiline:
# pattern: '^# User@Host: '
pattern: '^# Time: '
negate: true
match: after
# exclude_lines: '^# Time: '
#exclude_lines: ['^[\/\w\.]+, Version: .* started with:.*'] # Exclude the header

view raw

filebeat-mysql-slowlog-slowlog.yml

hosted with ❤ by GitHub

Arquivo: pipeline.json

Path: /usr/share/filebeat/module/mysql/slowlog/ingest/pipeline.json

O GROK que testamos será adicionado logo no início do arquivo na seção patterns, lembrando que alguns caracteres precisam ser escapados para que o JSON seja reconhecido, na dúvida faça a validação adicionando o conteúdo do arquivo em: https://jsonlint.com/


{
"description": "Pipeline for parsing MySQL slow logs.",
"processors": [{
"grok": {
"field": "message",
"patterns":[
"^# Time: (?<mysql_slowlog_time>%{NUMBER}%{SPACE}%{TIME})(.|\r|\n)*# User@Host: %{USER:mysql_slowlog_user}\\[%{USER:mysql_slowlog_current_user}\\] @ %{HOSTNAME:mysql_slowlog_client_host}? \\[%{IP:mysql_slowlog_client_ip}?\\](.|\r|\n)*# Thread_id:%{SPACE}%{NUMBER:mysql_slowlog_id} Schema: %{WORD:mysql_slowlog_schema}? QC_hit: %{WORD:mysql_slowlog_qc_hit}(.|\r|\n)*# Query_time: %{NUMBER:mysql_slowlog_query_time_sec} Lock_time: %{NUMBER:mysql_slowlog_lock_time} Rows_sent: %{NUMBER:mysql_slowlog_rows_sent} Rows_examined: %{NUMBER:mysql_slowlog_rows_examined}(.|\r|\n)*SET timestamp=%{NUMBER:mysql_slowlog_timestamp};(.|\n)%{GREEDYDATA:mysql_slowlog_query}"
],
"pattern_definitions" : {
"GREEDYMULTILINE" : "(.|\n)*"
},
"ignore_missing": true
}
}, {
"remove":{
"field": "message"
}
}, {
"date": {
"field": "mysql.slowlog.timestamp",
"target_field": "@timestamp",
"formats": ["UNIX"],
"ignore_failure": true
}
}, {
"gsub": {
"field": "mysql.slowlog.query",
"pattern": "\n# Time: [0-9]+ [0-9][0-9]:[0-9][0-9]:[0-9][0-9](\\.[0-9]+)?$",
"replacement": "",
"ignore_failure": true
}
}],
"on_failure" : [{
"set" : {
"field" : "error.message",
"value" : "{{ _ingest.on_failure_message }}"
}
}]
}

view raw

filebeat-mysql-slowlog-pipeline.json

hosted with ❤ by GitHub

Arquivo: Filebeat-mysql.json

Esse arquivo é o responsável pela criação dos dashboard do MySQL no Kibana, basta ajustá-lo com os valores e carregar o dashboard para o Kibana.

Path: /usr/share/filebeat/kibana/6/dashboard/Filebeat-mysql.json

filebeat setup

Iniciando o serviço e habilitando na inicialização

systemctl start filebeat
systemctl enable filebeat

Acompanhe os logs em:

tailf /var/log/filebeat/filebeat

Visualizando o pipeline

Você pode usar Plugin Head do Chrome para conectar em seu Elasticsearch, na aba "Qualquer requisição" você pode realizar as consultas.

GET _ingest/pipeline/filebeat-6.3.0-mysql-slowlog-pipeline

Se já existir um pipeline carregado para esse propósito que não estiver funcionando, basta deletá-lo, e iniciar o filebeat para que faça o upload do novo.

DELETE _ingest/pipeline/filebeat-6.3.0-mysql-slowlog-pipeline

Visualizando os logs no Kibana

kibana-slowlog-lines

Ao visualizar os logs carregados pela primeira vez, você se depará com um triângulo amarelo que seria um sinal de alerta que diz:

No cached mapping for this field

kibana-slowlog-01

Para corrigir vá em:
Management -> Kibana – Index Patterns -> Escolha o pattern “filebeat-*” e clique em “Refresh field list”

kibana-filebeat-slowlog-3

Enjoy! … Agora é só configurar seus Dashboards!

Outras ISSUES que li sobre slow log

https://discuss.elastic.co/t/provided-grok-expressions-do-not-match-field-value/103502/3

https://discuss.elastic.co/t/filebeat-modules-problem-with-pipeline-json/103190

https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/3