Blogaro!

Proposta para um log melhor

Created by Thiago Guedes on 2015-09-26 06:11:52

Tags: #c++   #log   #programação  

O log é uma parte importante de qualquer sistema que precisa de análise em caso de falhas ou de monitoração de seja lá qual for o dado que é exposto lá.
Podemos usar como exemplo os seguintes cenários

  1. Um sistema de negociação gera um dado incorreto. Como descobrir isso se você não sabe o que gerou a falha ?

  2. Um sistema de restaurantes deu um erro, mas o restaurante fica num lugar ermo e de difícil acesso para que seja feita uma análise no local.

  3. Um sistema escreve no log informações de carga e tempo processamento dos dados.

Update: Número de parâmetros !

Com base nisso, podemos pensar em algumas características importantes em uma biblioteca de log, ou até melhor, quais são as características necessárias para uma biblioteca de log e quais são os problemas que me fariam não usar uma nova nos meus projetos ?

Como a minha linguagem de maior domínio, e também a que mais costuma estar em sistemas de alta performance é C++, vou manter tudo relacionado a ela somente.

Vamos falar um pouco sobre cada ponto.

Não pode causar falhas no sistema ou gerar exceções

Muitos geradores de logs são baseados em sprintf ou boost::format. Esse é um possível gerador de problemas. Vejamos o exemplo.

log.debug("[%d] Message received: %s") % msg->to_string();

A linha acima tem dois problemas.

  1. Ela vai gerar uma exceção pois tem dois parametros de formatação, mas só passa um.
  2. Ela está fazendo a resolução de to_string, mesmo que o log em debug não seja logado, pois o parâmetro é resolvido antes do método ser invocado. É um caso típico de eager evaluation

Uma solução para isso seria ter a chamada da forma abaixo:

log.debug("[", thread_id, "] Message received: ", msg->to_string());

Da forma mostrada agora, nunca será gerada uma exceção de formatação, mas ainda poderia gerar um crash se msg for null. Eu ainda continuo com o problema de resolução do to_string e gasto desnecessário de CPU.

Precisa ter o número de parâmetros variável

Um dos geradores de problemas nos logs é número de parâmetros variáveis. A forma padrão, vinda do C, é a formatação estilo printf

printf("%d - Message received: %s", thread_id, msg->to_string());

O problema disso é o mesmo do boost format. Se a quantidade de parâmetros não coincidir com a formatação, teremos problemas.
Para resolver isso, eu preciso usar variadic templates. Assim os parâmetros serão resolvidos em tempo de compilação, sem problemas de performance ou questões de formatação.

template <typename T>
void _log(StreamPolicy &st, T &t) {
    log_formatter<T, StreamPolicy>(st, t);
}
 
template <typename T, typename ...U>
void _log(StreamPolicy &ss, T &t, U&&... p) {
    log_formatter<T, StreamPolicy>(ss, t);
    _log(ss, p...);
}
 
template <typename ...T>
void log(log_level level, T&&... p) {
    if( !is_level_enabled(level) )
        return;
    StreamPolicy ss;
    _log(ss, p...);
    _log_callback((int)level, ss.str());
}

Aqui estamos recebendo uma quantidade variável de parâmetros em T&&… p e passando para o método _log.
Este agora irá descascar o template fazendo várias chamadas ao log_formatter, até que complete a linha e todos os parâmetros estejam concatenados. Isso garante que tenhamos tudo resolvido em tempo de compilação e não haja custo adicional em runtime.

Não pode resolver os parâmetros caso o log não seja gerado.

Nós podemos tratar o problema da mensagem nula usando uma técnica bem simples. O Lazy evaluation, e ainda de cara resolvemos o problema do parâmetro sendo resolvido desnecessariamente. Nós precisamos somente transformar em lazy evaluation a nossa formatação de mensagem

#define TP std::make_tuple
log.debug("[",thread_id,"] Message received: ", TP(msg,to_string));

Essa tupla será armazenada num parâmetro e resolvida somente depois, caso o nível de log esteja de acordo e o log seja gerado. Dentro do método to_string, eu posso fazer a validação que eu achar necessária.

std::string to_string(const Message *msg) {
    if( msg == nullptr ) return "null";
    return msg->to_string();
}

Isso pode gerar o mesmo

Não pode pode gastar mais tempo do que o realmente necessário

Aqui já temos um ponto resolvido. A resolução de parâmetros de forma lazy já tira uma parte do problema.
Outra parte se deve ser endereçada a uma policy para que eu tenha no meu sistema a implementação que eu achar melhor de um stream.

template<typename T, typename StreamPolicy>;
struct log_formatter {
    log_formatter(StreamPolicy &st, T &t) {
        st << t;
    }
};
log_formatter<std::string, MyInsanelyFastStream>(stream, date);
//ou
log_formatter<std::string, MyAsyncStream>(stream, date);

Eu consigo dessa forma fazer com que a implementação de stream seja flexível e rápida.

Precisa ser adaptável a sistemas de log já existentes

Aqui temos uma situação comum nas empresas. Eu tenho uma implementação de log que já é usada e eu não posso e nem quero trocar dos módulos já existentes. Os dois logs precisam coexistir e ninguém quer dois arquivos de log diferentes por causa disso.
Uma forma de fazer essa coexistência é o log gerar um callback para que eu use a implementação que eu quiser.

Logger::init(log_level::ALL, [](int level, const std::string &text) {
    Level l = to_legacy_level(level);
    LegacyLogger::log(l, text);
});

Precisa ser flexível a ponto de eu ter várias possibilidades de implementações

Na minha implementação atual, a forma de callback é obrigatória e ela está feita usando stream (com operador <<). Duas coisas interessantes que poderiam virar policies é o próprio callback ser uma Policy, podendo ser trocado por qualquer outra coisa e o uso de stream ser outra. Fico aberto a sugestões !

A implementação atual do log ainda é um draft e eu preciso fazer testes com ela e comparar com outros geradores. Sugestões e críticas são muito bem vindas.

Fonte: https://github.com/thiagomg/experiments