Desenvolvendo sua stack de log utilizando ELK com NLog

Publicado por fabricioveronez em

Na empresa que trabalho, surgiu uma nova demanda: Melhorar nossa maneira de armazenar nossos dados de log.

Atualmente cada aplicação armazena seus logs em pastas cheias de arquivos .TXT, não preciso comentar sobre o problema que é pra encontrar um log específico certo ?

Foi decido que adotaríamos a stack ELK com NLog para comunicar a aplicação com ela.

Sobre a Stack de Log

Navegando pelo site do meu amigo Luiz Carlos Faria, encontrei um post sobre o uso da stack utilizando RabbitMQ,  LogStash, ElasticSeach e Kibana. Detalhes mais profundos sobre o assunto, sugiro que confiram no post do Luiz (https://gago.io/blog/docker-de-z-15-rabbitmq-logstash-elsticseach-e-kibana-com-docker-compose/).

Criando um log estruturado

Vamos imaginar um cenário: Temos um sistema de emissão de pedidos. O sistema tem seus logs tradicionais, com a mensagem de erro e a stack de exceção. De repente ocorrem alguns erros e você não consegue reproduzir, os usuários não conseguem detalhar como o erro acontece e quais parâmetros foram inseridos.

Visando melhorar a investigação de erros, criaremos o nosso log em um formato chave/valor e com dados específicos da aplicação. Nesse exemplo, vamos inserir o nome do servidor que a aplicação está sendo executada.

Configurando o NLog

Novamente, o exemplo completo vocês encontram no meu github. Para configurar o ELK com NLog, criei um NLog target que se encontra no NuGet.

O exemplo será um projeto ASP.NET Core Web API, mas o arquivos nlog.config pode ser utilizado tranquilamente em um projeto .NET Full. Para começar, vamos instalar no nosso projeto os seguintes pacotes:

  • NLog
  • NLog.Web.AspNetCore
  • NLog.Extension.RabbitMQ.Target

 

Feito isso, é hora de criarmos o arquivo de configuração. O arquivo nlog.config deve estar na raiz do projeto e ser configurado como conteúdo e sempre ser copiado na compilação.

 

E o seu conteúdo será:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogLevel="info"
      internalLogFile="c:\temp\NLog.Extension.RabbitMQ.Examples.WebApi-Internal-NLog.txt">

  <extensions>
    <!-- Enable RabbitMQ Target -->
    <add assembly="NLog.Extension.RabbitMQ.Target" />
    <add assembly="NLog.Web.AspNetCore" />
    <add assembly="NLog.Extension.RabbitMQ.Examples.WebApi"/>
  </extensions>

  <!-- the targets to write to -->
  <targets>
    <target name="logstash"
            xsi:type="RabbitMQ"
            username="logUser"
            password="logPwd"
            routingkey="ApplicationLog"
            virtualhost="EnterpriseLog">

      <layout xsi:type="JsonLayout">
        <attribute name="date" layout="${longdate}" />
        <attribute name="eventId" layout="${event-properties:item=EventId_Id}"/>
        <attribute name="level" layout="${uppercase:${level}}" />
        <attribute name="orderId" layout="${event-properties:orderid}" />
        <attribute name="logger" layout="${logger}" />
        <attribute name="exception" layout="${exception:format=tostring}"/>
        <attribute name="message" layout="${message}" />
        <attribute name="url" layout="${aspnet-request-url}" />
        <attribute name="machineName" layout="${local-machine}" />
        <attribute name="action" layout="${aspnet-mvc-action}" />
      </layout>
    </target>
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <logger name="*" minlevel="Trace" writeTo=" logstash" />
  </rules>
</nlog>

No arquivo log.config devemos ter atenção a alguns detalhes:

  • Entre as linhas 10 e 12, importamos os assemblies que utilizaremos no log
  • Entre as linhas 24 e 35 inserimos os dados de log em formato chave/valor

Para mais detalhes sobre a configuração do NLog, pode ser encontrado na documentação do projeto

Criando meu próprio layout renderer

Para termos nossos dados customizados no log, é necessário criar um layout render específico para cada dado. Aqui vamos criar um para capturar o nome do servidor que está executando a aplicação.

using NLog.LayoutRenderers;
using System;
using System.Text;

namespace NLog.Extension.RabbitMQ.Examples.WebApi.Log
{
    [LayoutRenderer("local-machine")]
    public class MachineLogLayout : LayoutRenderer
    {
        protected override void Append(StringBuilder builder, LogEventInfo logEvent)
        {
            builder.Append(Environment.MachineName);
        }
    }
}

Com o MachineLogLayout conseguimos inserir mais um dado no nosso log. Atenção ao nome utilizado no atributo LayoutRenderer, pois deve ser o mesmo nome utilizado no log.config.

Inserindo Log

Agora iremos inserir dados de log. Para esse exemplo, teremos um controller que recebe uma chamada POST com uma mensagem e o nível de log.

using System;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;

namespace NLog.Extension.RabbitMQ.Examples.WebApi.Controllers
{
    [Route("api/log")]
    public class LogController : Controller
    {

        private ILogger<LogController> _log;

        public LogController(ILogger<LogController> log)
        {
            this._log = log;
        }

        [HttpPost]
        public IActionResult Post([FromBody] Model.Log log)
        {
            try
            {
                throw new Exception("This exception is a test.");
            }
            catch (Exception ex)
            {
                switch (log.LogLevel)
                {
                    case Model.LogLevel.Trace:
                        this._log.LogTrace(ex, log.Message);
                        break;
                    case Model.LogLevel.Debug:
                        this._log.LogDebug(ex, log.Message);
                        break;
                    case Model.LogLevel.Info:
                        this._log.LogInformation(ex, log.Message);
                        break;
                    case Model.LogLevel.Warn:
                        this._log.LogWarning(ex, log.Message);
                        break;
                    case Model.LogLevel.Error:
                        this._log.LogError(ex, log.Message);
                        break;
                    case Model.LogLevel.Fatal:
                        this._log.LogCritical(ex, log.Message);
                        break;
                }
            }

            return Ok();
        }
    }
}

Note que o objeto que insere o log é obtido por injeção de dependência.

Executando a aplicação

Para executar a aplicação, não se esqueça de ter o EnterpriseApplicationLog sendo executando na sua máquina.

Agora executamos o projeto WebApi e faço um post para a URL. No meu caso estou utilizando o Postman.

O resultado podemos ver no Kibana.

 

Nesse post vimos como melhorar a maneira que trabalhamos com logs, e que com a stack ELK com NLog pode funcionar muito bem, lembrando que esse exemplo foi feito em .NET Core, mas é possível alterar também em projetos legados, principalmente se já é utilizado o NLog.

Espero que tenham gostado e sintam-se à vontade para comentar e dar sugestões de novos assuntos !


9 comentários

Rodrigo Graúdo · 6 de junho de 2018 às 09:05

Dá uma olhada no Serilog depois. Uma abordagem mais simples também seria gerar os logs em JSON na pasta atual e usar o Filebeat da Elastic pra enviar pro Elasticsearch.

    fabricioveronez · 6 de junho de 2018 às 22:18

    O NLog em si eu utilizei por uma questão de aproveitamento do que já temos na empresa. Pois além do que estamos desenvolvendo, temos os projetos mais antigos, que em sua maioria utiliza o NLog.
    Gravar em arquivos, vai contra a nossa idéia de evitar IO em disco.

Luiz Carlos Faria · 6 de junho de 2018 às 14:01

Serilog ainda deixaria o log em disco por padrão, o que não é uma estratégia sábia, mas usando um outro provider, que enviasse para uma fila, pq não? A questão em si é a troca de latência. Não pode ser algo tão pesado quanto enviar para o Elastic, nem gravar no disco. O meio termo, foi usar o rabbitmq para isolar.

    Rodrigo Graúdo · 12 de junho de 2018 às 19:07

    Eu estava sugerindo uma outra abordagem baseado no começo do texto “Atualmente cada aplicação armazena seus logs em pastas cheias de arquivos .TXT, não preciso comentar sobre o problema que é pra encontrar um log específico certo ?”
    Se a ideia é só indexar os logs pra encontrar de maneira mais assertiva a abordagem do Filebeat é mais simples. Ainda sim o Serilog tem sinks pra jogar pra toda sorte de coisas inclusive direto pro elasticsearch ou pro rabbitmq conforme a sugestão do artigo.

      Luiz Carlos Faria · 12 de junho de 2018 às 20:22

      Eu já falei com Fabricio sobre isso, a questão é que Log não pode ser uma mera string, onde o único contexto está disperso em um bloco de texto. A proposta do stack vem junto com a proposta de abolir logs de uma string só, propondo um log que traga informações contextuais para que seja possível, entre outras coisas identificar um cenário mesmo que limitado, onde aquilo aconteceu, mas que sirva de caso de teste. Não é uma indexação de simples, é uma indexação baseada em diversos campos do seu contexto que podem ser desde parâmetros até dados do servidor, como hostname, ip e outros elementos que possam ajudar na identificação do contexto onde aquilo aconteceu. É muito mais que uma indexação simplista. Por isso essas soluções não atendem, pq são baseadas simplesmente em logs humanamente legíveis, e um log humanamente legível não é o que queremos persistir, apenas queremos exibir assim. Há uma diferença enorme de viés.

        Rodrigo Graúdo · 12 de junho de 2018 às 23:03

        Justamente por isso que sugeri olhar o Serilog. Não sei se você já utilizou, mas ele trabalha com um conceito de log estruturado por padrão e justamente muda esse mindset do log ser apenas uma string. Eu utilizo ele hoje gerando em JSON no Cloudwatch com todo o contexto que preciso (hostname, ip, etc) e informações a mais criadas graças ao modelo de template de mensagem dele. Recomendo fortemente!

          fabricioveronez · 13 de junho de 2018 às 08:01

          Eu vi o Serilog e gostei. Mas no meu caso aqui, foi premissa usar o NLog.

Construindo um diálogo com BotBuilder 4.0 – fabricioveronez.net · 20 de julho de 2018 às 15:43

[…] razão do meu post sobre NLog + Enterprise Application Log, fui convidado pelo meu amigo Rafael Cruz para participar de um hangout sobre o assunto no canal […]

Integração com o LUIS - fabricioveronez.net · 7 de agosto de 2018 às 00:06

[…] razão do meu post sobre NLog + Enterprise Application Log, fui convidado pelo meu amigo Rafael Cruz para participar de um hangout sobre o assunto no canal […]

Deixe uma resposta

O seu endereço de e-mail não será publicado. Campos obrigatórios são marcados com *