Log em Java do jeito certo – parte 1: frameworks

Logs são uma parte importante de qualquer aplicação. Usar log corretamente é uma tarefa aparentemente fácil, mas pode ser tornar algo complexo dependendo das características e necessidades do seu projeto. Nessa série de 3 artigos vamos acrescentar logs a uma pequena aplicação Java e lidar com diversas dificuldades ao longo do caminho.

Por que usar frameworks de log?

Você certamente já passou pela situação de encontrar um bug em sua aplicação, analisar a saída no console só para descobrir que ela não fornece as informações que você precisa. Para identificar o que aconteceu, você precisará: (1) imprimir mais mensagens no console; (2) talvez compilar em modo debug e colocar alguns breakpoints; (3) tentar reproduzir o bug, o que pode não ser muito fácil. Você vai descobrir que precisa adicionar mais informações às suas mensagens e aprender a logar as coisas certas.

Frameworks vão adicionar as seguintes informações às suas mensagens:

• A hora exata em que a mensagem foi impressa.
• A classe que chamou o log.
• A thread que estava executando.
• O nível de prioridade da mensagem (erro, alerta, debug…).
• A stacktrace completa, em caso de uma exceção.

Isso já é metade do caminho para tornar suas mensagens de log mais úteis. Sendo assim, nosso primeiro passo nessa jornada será escolher bem o framework de log.

Frameworks de log para Java

A linguagem Java tem uma quantidade muito maior de frameworks de log do que as outras linguagens. Isso por vezes causa uma bagunça em nosso software. Cada biblioteca usa um framework diferente, cada uma tenta gerenciar os logs da sua própria maneira e nós, desenvolvedores da aplicação, ficamos tentando colocar ordem nesse caos.

Vamos revisar os principais frameworks em ordem cronológica.

Log4j

Esse foi o primeiro grande framework de log para Java. A primeira versão pública do Log4j foi lançada em 1999 (versão 1.0 em 2001). Esse foi o framework mais popular durante mais de uma década. Hoje em dia usamos o Log4j2, a versão 1 não é mais mantida. Sendo assim, vamos pular a seção de como configurá-lo e deixar para falar do Log4j2 mais a frente (já que estamos seguindo a ordem cronológica).

Java Util Logging

Em 2002, a Sun Microsystems resolveu criar um pacote (java.util.logging, chamado abreviadamente de JUL) com classes de log embutidas no JDK 1.4. Essa opção nunca se tornou muito popular pelos seguintes motivos:

• Menos opções de configuração em comparação com o Log4j, que já era muito popular na época.
• JUL ignora silenciosamente erros de configuração.
• JUL tem desempenho muito inferior aos outros frameworks.

Sendo assim, não vamos nem perder tempo aprendendo a usá-lo.

Commons Logging

Inicialmente chamado de Jakarta Commons Logging (depois renomeado para Apache Commons Logging, mas ainda abreviado como JCL), esse foi o primeiro logging façade (lançado em 2002) que ficou famoso. A ideia era permitir usar qualquer implementação de log (Log4j, JUL e outros), mas ter uma API única para fazer chamadas de log e uma maneira de configurar o comportamento do log das bibliotecas usadas.

Embora tenha permanecido popular por algum tempo, o uso dessa biblioteca não é mais recomendado por causa dos 2 principais problemas que ele apresenta:

• API ruim: chata de usar (log.isDebugEnabled) e sem funcionalidades importantes (MDC).
• Problemas de classloader com JCL: devido ao mecanismo de carregar configurações dinamicamente.

É por isso que hoje em dia usa-se o SLF4J como façade.

SLF4J

Em 2005, o criado do Log4j (Ceki Gülcü), lançou o Simple Logging Facade for Java (SLF4J), que resolvia os problemas do JCL. Com esse façade, a implementação de log que será usada é decidida durante o build, dando total controle ao desenvolvedor da aplicação e removendo os problemas de decisão dinâmica do JCL. A sua API também é mais moderna, deixando poucos motivos para usar diretamente a API do framework subjacente.

Para usar o SLF4J, primeiro inclua a biblioteca que contém sua API como dependência do projeto (esse exemplo usa Maven, mas o procedimento é semelhante para qualquer outro gerenciador de dependências):

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
</dependency>

Depois, obtenha uma instância da classe Logger e use conforme exemplo abaixo.

public class Slf4jExample {

    public static final Logger logger = LoggerFactory.getLogger(Slf4jExample.class);

    public static void main(String[] args) {
        logger.info("Hello SLF4J!");
    }

Executando esse código, você obterá a seguinte saída no console:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

Veja que a mensagem não foi impressa. Além disso, durante a inicialização, o framework exibe uma mensagem de alerta dizendo que nenhuma implementação foi encontrada, por isso ele vai usar a implementação default, que é no-operation.

Embora esse comportamento possa parecer indesejado, na verdade, ele é um vantagem. Se você está implementando um biblioteca, tudo que você precisa fazer é incluir a dependência da API do SLF4J (não inclua nenhum implementação de log). Os desenvolvedores das aplicações que usam a sua biblioteca é que escolhem qual framework será usado como implementação de log na aplicações deles. Assim, no arquivo de configuração do framework escolhido, eles podem controlar o log de cada biblioteca que eles usam (veremos como fazer isso no segundo artigo da série).

Logback

Por muito tempo, o Log4j reinou sozinho como padrão de facto para logs em Java. Porém, o desenvolvimento “travou” na migração da versão 1.2 para 1.3. Ceki foi acusado de introduzir código que quebrava compatibilidade e depois abandonar o projeto. A essa altura, Ceki estava insatisfeito com a forma como projetos open source são conduzidos dentro da Apache Software Foundation e já tinha criado seu próprio framework de log do zero, o Logback (lançado em 2006). Segundo ele, o Logback continua de onde o Log4j parou.

Para usar o Logback, primeiro inclua sua dependência:

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

Depois use-o através da API do SLF4J, isso porque o Logback é uma implementação nativa do SFL4J.

public class LogbackExample {

    public static final Logger logger = LoggerFactory.getLogger(LogbackExample.class);

    public static void main(String[] args) {
        logger.info("Hello Logback!");
    }

Executando o código acima, obtemos essa saída no console:

20:06:41.742 [main] INFO com.aroliveira.java.log.intro.frameworks.logback.LogbackExample - Hello Logback!

Como não realizamos nenhuma configuração, o Logback carregou sua configuração padrão, que imprime suas mensagens no console juntamente com informações de hora, thread, prioridade e classe (tudo que dissemos no ínicio do artigo como sendo importante para tornar suas mensagens de log mais úteis).

Log4j2

O desenvolvimento do Log4j continuou estagnado por muitos anos. Os desenvolvedores decidiram que nunca haveria uma versão 1.3 e pulariam direto para a 2.0. Até que, em 2014, finalmente o Log4j 2.0 G.A foi lançado (só 8 anos atrasado em relação ao Logback).

Podemos dizer que esse é o framework mais moderno de todos. Como ele veio por último, incorporou quase tudo que o Logback. Além disso, acrescentou uma funcionalidade que eles consideram o grande trunfo dessa versão: Asynchronous Loggers (mais sobre isso abaixo).

Para usar o Log4j2, o procedimento é o mesmo de sempre: primeiro, inclua a dependência:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.8.2</version>
</dependency>

Depois obtenha uma instância da classe Logger e chame os métodos normalmente. Repare que o Log4j2 não implementa a API do SLF4J.

public class Log4j2Example {

    private static Logger logger = LogManager.getLogger(Log4j2Example.class);

    public static void main(String[] args) {
        logger.info("Hello Log4J2!");
    }

Executando esse código, você verá a saída abaixo.

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console. Set system property 'org.apache.logging.log4j.simplelog.StatusLogger.level' to TRACE to show Log4j2 internal initialization logging.

A configuração padrão do Log4j2 imprime apenas mensagens de prioridade ERROR. Para obter um comportamento parecido como o Logback, é necessário acrescentar o arquivo de configuração do Log4j2 no classpath. Crie o arquivo log4j2.xml no diretório src/main/resources (seguindo a estrutura de diretórios do Maven) com o conteúdo abaixo.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <Console name="STDOUT">
            <PatternLayout pattern="%d [%t] %p %c - %m%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="STDOUT" />
        </Root>
    </Loggers>
</Configuration>

Executando novamente, obtemos o resultado:

2017-06-30 10:24:32,476 [main] INFO com.aroliveira.java.log.intro.frameworks.log4j2.Log4j2Example - Hello Log4J2!

Escolha do framework

Dentre todos os framework vistos, apenas algumas opções valem a pena. Essas são as duas primeiras conclusões que já devem estar óbvias para você a essa altura:

• Para a API, use sempre o SLF4J.
• Para a implementação, use Logback ou Log4j2.

Como vimos, o uso do SLF4J como façade é ideal tanto para bibliotecas quanto para aplicações. Ele oferece uma excelente API e total controle sobre as diversas bibliotecas de log. Na minha opinião, não há motivos para usar diretamente a API de nenhuma implementação de log.

Já a escolha entre Logback e Log4j2 é mais complicada. A verdade é que ambos são ótimas escolhas. A principal diferença é que o Log4j2 é mais rápido para log assíncrono; desde que você use Asynchronous Loggers, inclua a dependência para o LMAX Disruptor e tenha um servidor multi-core (a própria página do Log4j2 admite que em máquinas single-core não há ganho de performance).

Existem vários benchmarks comparando Log4j2 com Logback por aí. Porém, considero que a maioria deles comete um erro ao assumir a premissa de que “atualmente, todos os servidores são multi-core” (os benchmarks na página do Log4j2 usam máquinas com 20 ou 30 cores). O erro está em ignorar que estamos na era da computação em núvem. Hoje em dia, quase ninguém compra servidores, aluga sala, instala ar-condicionado e fica tentando garantir o uptime “na mão”. Rodamos nossas aplicações na nuvem, onde a regra é “pague somente pelo que usar”. Dessa forma, usar múltiplos cores, sendo que sua aplicação não precisa deles 24h por dia, é desperdício de capacidade e de dinheiro. Faz mais sentido rodar em uma configuração mínima de hardware a maior parte do tempo, monitorar sua aplicação em tempo real e ajustar a capacidade dinamicamente de acordo com a demanda (isso é conhecido como “elasticidade”).

Ainda pretendo fazer meu próprio benchmark entre esses dois frameworks nas condições descritas acima. Até lá, use a seguinte regra simples para escolher entre eles:

• Se os requisitos mínimos de hardware da sua aplicação incluem um servidor multi-core, use Log4j2 (e use log assíncrono).
• Caso contrário, use Logback (pois ele é uma implementação nativa da API do SLF4J, economizando o overhead de mais uma camada para fazer a conversão).

Próximos passos

No próximo artigo da série vamos colocar a mão na massa e acrescentar mensagens de log a uma aplicação de exemplo.

Links:

• https://www.javacodegeeks.com/2011/09/java-logging-mess.html
• http://www.baeldung.com/java-logging-intro
• https://www.sitepoint.com/which-java-logging-framework-has-the-best-performance/