Gerenciamento de LOG com ELK

Published in

Dev Cave

7 min readMar 23, 2018

Por que eu me importaria com log?

Bom, acredito que todos consideramos logs algo muito importante, mas para os que não tem essa visão vamos pensar em um cenário:

Sexta feira 17:48, você recebe uma mensagem dizendo que deu um problema na funcionalidade X. Como podemos fazer para ver o que aconteceu com essa funcionalidade? Se seus métodos não estão com o mínimo de log como podemos saber qual foi a combinação de parâmetros que originou o problema?

Se tivermos em um ambiente com micro serviço fica ainda pior, imaginando que o micro serviço A chamou o B que por fim chamou o C, onde aconteceu o problema? teríamos que ver o log dessas 3 aplicações cada uma em sua máquina, o que torna ainda pior se tivermos em um cluster que não garantimos em que máquina exatamente essas aplicações estão rodando.

Bom acho que já convenci vocês que log é algo MUITO importante, então por onde começamos?

ELK

ELK é um conjunto de três projetos OpenSource (ElasticSearch, LogStash e Kibana) que formam uma conhecida stack para agregação indexação e busca de logs.

ElasticSearch

Baseado no Apache Lucene o ElasticSearch serve dentro na nossa stack como o banco de dados, ele irá guardar e indexar os dados.

LogStash

É o nosso processador de dados que irá consumir manipular e enviar os dados para nosso repositório de dados.

Kibana

Kibana será a ferramenta que iremos utilizar para a visualização dos dados, ele será o responsável por ler os dados do ElasticSearch e até formar uns gráficos bonitinhos.

Instalação ELK

Bom esse é um passo bem simples podemos baixar as três ferramentas nos links a seguir:

O ElasticSearch e o Kibana não precisam de configurações especificas para começarmos você pode simplesmente baixar o Zip/Tar descompactar e executar o script de start dentro da pasta bin de cada um dos dois.

lferreira@mint ~/workspace/elk/elasticsearch $ ./bin/elasticsearch
lferreira@mint ~/workspace/elk/kibana $ ./bin/kibana

Isso fará com que o ElasticSearch suba na porta 9200 e o Kibana na 5601, você pode tentar acessar para ver se está tudo ok mas ainda não terá nenhuma informação importante :(

Para o LogStash as coisas ficam um pouco mais complicada, precisamos especificar uma configuração que ele utilizará. Nesse arquivo de configuração precisamos essencialmente de 2 informações, o input e o output. Vamos criar um logstash.conf e colocar o seguinte conteúdo nele

input {
  tcp {
    port => 9090
    host => localhost
  }
}

output {
  elasticsearch { hosts => ["localhost:9200"] }
  stdout { codec => rubydebug }
}

Para iniciarmos o serviço do LogStash basta executar

lferreira@mint ~/workspace/elk/logstash $ ./bin/logstash -f log.conf

Com isso definimos que a entrada será por tcp e na porta 9090. Agora precisamos fazer com que nossa aplicação envie log para o logstash

Adicionamos a dependência:

compile "net.logstash.logback:logstash-logback-encoder:5.0"

E criamos um arquivo dentro de src/main/resources chamado logback.xml:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
    <appender name="stash" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
        <destination>localhost:9090</destination>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
    </appender>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="stash"/>
    </root>
</configuration>

Nesse arquivo definimos algumas configurações “default” e onde está nosso logstash.

Com isso já temos o básico do ELK disponível \o/

Vamos entrar no Kibana e dizer para ele o que queremos ver.

Se nossa aplicação não gerou nenhum log ao entrarmos em http://localhost:5601 o kibana dirá que não há dados no ElasticSearch (Couldn't find any Elasticsearch data), para resolver isso basta gerar algum log (suba aplicação ou entre em alguma tela que tenha log).

Após isso basta cadastrar um novo index pattern logstash-* com o “Time filter field name” = @timestamp. Com isso ao acessar novamente a tela “Discover” já é para estar sendo exibido um gráfico de “@timestamp per millisecond” e logo abaixo uma tabela com os logs gerados pela sua aplicação.

um gráfico de “@timestamp per millisecond” e logo abaixo uma tabela com os logs gerados pela sua aplicação.

A esquerda em “Available Fields” podemos selecionar apenas as colunas mais importantes para exibição

Mas como conseguimos fazer para “gerar” novos fields?

Filtros LogStash

O LogStash tem o seguinte fluxo Input > Filter > Output até agora nos trabalhamos apenas com o Input e o Output mas se quisermos indexar informações mais importantes teremos que entrar mais a fundo na configuração do LogStash.

Antes de mais nada vamos mudar a nossa entrada de dados, faremos com que o logstash fique lendo um arquivo de log.

Podemos remover a dependência inserida no projeto e remover o arquivo logback.xml só precisamos dizer para o Spring Boot gerar um arquivo externo de log, para isso vamos mudar o application.properties e adicionar o seguinte:

logging.file=application.log

Importante: o modo de entrada de dados não influencia no filtro (a não ser que sua entrada não envie alguma informação LÓGICO) apenas mudei para utilizar mais de um exemplo de entrada

Bom agora podemos alterar nosso log.conf

input {
  file {
    type => "java"
      path => "/path/to/application.log"
      codec => multiline {
        pattern => "^%{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME}.*"
        negate => "true"
        what => "previous"
      }
  }
}filter {
  if [message] =~ "\tat" {
    grok {
      match => ["message", "^(\tat)"]
      add_tag => ["stacktrace"]
    }
  }  grok {
    match => [ 
      "message",
      "(?<timestamp>%{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME})  %{LOGLEVEL:level} \[(?<app_name>[A-Za-z0-9-]+)\,(?<trace>[A-Za-z0-9-]+)\,(?<span>[A-Za-z0-9-]+)\,(?<sample>[A-Za-z0-9-]+)\] %{NUMBER:pid} --- \[(?<thread>[A-Za-z0-9-]+)\] [A-Za-z0-9.]*\.(?<class>[A-Za-z0-9#_]+)\s*:\s+(?<logmessage>.*)",
      "message",
      "(?<timestamp>%{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME})  %{LOGLEVEL:level} %{NUMBER:pid} --- .+? :\s+(?<logmessage>.*)"
    ]
  }
}output {
  elasticsearch { hosts => ["localhost:9200"] }
  stdout { codec => rubydebug }
}

O que mudamos na entrada foi que a entrada poderá ter mais de uma linha e o início de cada linha tem um pattern especificado. Já para o filtro nos definimos primeiramente que se o log for de exceção (começar com tab) nós adicionamos a tag “stacktrace”, e logo abaixo nos definimos alguns padrões, não vou explicar a fundo o funcionamento vou apenas deixar o link da documentação como referência, mas basicamente o que estamos definindo são os nossos index com algumas expressões regulares. O próprio logstash já possui algumas expressões regulares e utilizamos dela chamando pelo nome por exemplo %{LOGLEVEL:level}definimos que utilizaremos a expressão regular referente ao nível de log e vamos colocar ela no index chamado “level”, quando vamos utilizar uma expressão regular manualmente definimos do seguinte modo (?<index_name>EXPRESSAO). A documentação recomenda uma aplicação web que interpreta as expressões e exibe quais index serão gerados.

Definimos dois matchers para mensagem para que caso o primeiro não seja atendido o segundo guarda o log mesmo que sem os index esperados. Dessa mesma forma podemos definir quantos quisermos.

Agora ao acessar de novo o Kibana podemos ver em “Available Fields” que temos muitos outros index disponíveis

E com eles podemos montar as informações em um formato muito mais legível

Sleuth

Resolvemos o problema do log mas não da rastreabilidade, Sleuth é uma lib para promover essa rastreabilidade que precisamos através de tokens únicos que são passados de micro serviço a micro serviço. Na última imagem podemos ver que as colunas geradas pelo sleuth já estão lá indexadas (sample, trace e span) elas que serão utilizadas para o rastreio. A primeira referência é de um post que escrevi sobre o sleuth.

Docker

Hoje é comum termos um ambiente de produção ou até mesmo de desenvolvimento com docker, isso significa que não seria tão legal ficarmos gerando um arquivo e pedir para que o logstash ficasse olhando ele, também não seria uma tarefa tão simples mandarmos as informações por tcp e tirarmos por REGEX as informações que precisamos do log dos containers.

Felizmente o docker dá suporte a um protocolo que facilita bastante nosso lado.

GELF

GELF é um acrônimo para Graylog Extended Log Format, foi inicialmente projetado para o Graylog e hoje em dia outras plataformas também dão suporte a esse formato.

Para fazermos nosso containers enviarem log através desse protocolo apenas precisamos dizer que queremos o GELF como log driver e especificar onde está nosso logstash, Podemos fazer isso passando dois parâmetros em um docker run ou um docker service create.

--log-driver gelf --log-opt gelf-address=udp://localhost:12201

A partir disso todo log gerado pelo nosso container será enviado por UDP para localhost:12201, agora precisamos definir que o logstash ficará ouvindo udp nessa porta 12201. Para fazer isso basta mudar o input.

input {
  gelf {}
}

Assim quando iniciarmos o nosso logstash ele já subirá ouvindo UDP em localhost:12201.

Com isso nós perdemos nossa configuração de multiline e para vermos log de exception em linhas diferentes fica meio difícil. Para resolver isso vamos adicionar um plugin chamado logstash-filter-multiline com ele poderemos reconstruir nossa configuração de log multiline.

Para instalar o plugin basta executarmos

./bin/logstash-plugin install logstash-filter-multiline

E no nosso arquivo de configuração do logstash definimos o filtro assim:

filter {
  multiline {
      pattern => "^%{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME}.*"
      negate => true
      what => "previous"
      source => "message"
      stream_identity => "%{host}.%{container_id}"
  }  # outros filtros abaixo...
}

Também acabamos resolvendo um possível problema que teríamos caso muitas apps fizessem chamada ao nosso logstash, ele poderia acabar juntando logs de apps diferentes, isso significa que se duas apps estivessem enviando informações de múltiplas linhas o logstash misturaria as informações, isso porque ele estava apenas definindo múltiplas linhas por um pattern sem se importar quem enviava, resolvemos isso definindo o stream_identityque é dado pelo nome do host e do container que nossa aplicação está sendo executada.

Com isso já podemos ter uma boa visibilidade e rastreabilidade dos logs das nossa aplicações.