Logar é preciso, debugar não é preciso?

Muitas vezes você percebe que está debugando o mesmo trecho de código incessantemente: horas são gastas tentando procurar o erro, checando variáveis, adicionando e removendo break points e até adicionando complexos alarmes condicionais. Ferramentas como o Netbeans e o Eclipse facilitam muito esse trabalho, mesmo quando ele é feito remotamente, o que é ainda mais complexo.

O tempo gasto com debug é relevante, e devemos tentar minimizá-lo. Não é a toa que Brian Kernighan, considerado um dos co-autores do C, é frequentemente citado em relação a este assunto, dizendo que:

Como escolha pessoal, nós tendemos a não usar debuggers a não ser para tirar uma stracktrace ou o valor de uma ou outra variável. A razão é que é fácil de se perder em tantos detalhes de estruturas de dados e controle de fluxo complicados. Nós achamos que ir passo a passo no programa é menos produtivo que adicionar logs e asserções em lugares estratégicos. Ficar clicando em linhas de código toma mais tempo que olhar o log. Toma menos tempo decidir onde colocar as invocações ao log que fazer o passo a passo até a seção crítica do código, mesmo assumindo que saibamos onde ela está. Mais importante, debug por logging fica no programa, já o processo de debug é transiente.“.

Como já estamos bastante acostumados a usar logging, vamos aproveitar pra ver que nem sempre é tão trivial: às vezes, temos de tomar cuidado ao colocar inúmeras invocações à API de log sem muito critério. Para ilustrar o caso, vamos imaginar uma situação bastante comum: estamos querendo descobrir por que os emails que deveriam chegar pro cliente não estão sendo enviados. Considere o seguinte código que usa o Apache Commons Mail:

class EnviadorEmail {
  public void enviaEmailDeCadastro(String to) {
    try {
      SimpleEmail email = new SimpleEmail();
      email.setHostName("mail.myserver.com");
      email.addTo(to, "nome do cliente");
      email.send();
    } catch(EmailException e) {
    }
  }
}

O erro aqui é a péssima prática de engolir exceptions, que costuma aparecer em diversos códigos por aí. Ao debugar rapidamente, iremos perceber que devemos corrigir esse codigo. Como? Uma sugestão seria colocar um logging aí.

Então vamos nos aventurar a usar um sistema de logging para o Java. Existem vários, sendo o mais clássico o Log4J, mas ainda há a própria API de logging do Java (desde 1.4) e temos tambem wrappers, como o commons logging ou o SL4J – simple logging, este último adotado pelo Hibernate. Vamos utilizar o Log4J dada a sua grande adoção. Baixe o Log4J e coloque o JAR no build path do seu projeto.

Agora, podemos criar um logger especifico para a nossa classe e, dentro do catch, mostrar uma mensagem:

class EnviadorEmail {
  private static final Logger LOG = 
      Logger.getLogger(EnviadorEmail.class);
  public void enviaEmailDeCadastro(String to) {
    try {
      SimpleEmail email = new SimpleEmail();
      email.setHostName("mail.myserver.com");
      email.addTo(to, "nome do cliente");
     email.send();
     log.info("E-mail enviado para  " + to);
    } catch (EmailException e) {
      log.error("problemas enviando email", e);
    }
  }
}

Ao rodar o programa, se o sistema não conseguir enviar um email, a exception sera capturada e logada. Mas não configuramos onde esse log deve aparecer, então o Log4J nos alertará sobre isso. É bastante comum esse alerta aparecer quando usamos, por exemplo, o Hibernate sem configurar o log:

log4j:WARN No appenders could be found for
				logger (org.hibernate.cfg.annotations.Version).
log4j:WARN Please initialize 
				the log4j system properly.

Então, além de uma configuração básica de log4j.xml para o seu sistema, você precisa configurar para que o log do Hibernate use um appender, no caso chamado sysout que vai jogar pra saída padrão:

	<category name="org.hibernate">
		<priority value="info" />
		<appender-ref ref="sysout" />
	</category>

Ou, no caso do nosso sistema, o name da nossa categoria deve refletir o nome do nosso pacote. Nosso sistema agora loga corretamente a falha, mas ainda há um problema maior: quem pediu para executar a acao de enviar o email, mesmo que ele nao seja enviado, tem a impressão de que tudo ocorreu normalmente. Isto é:

cadastra(usuario);
EnviadorEmail ee = new EnviadorEmail();
ee.enviaEmailDeCadastro(usuario.getEmail());
System.out.println("sucesso no cadastro");

O codigo acima executará normalmente, mesmo que haja uma falha no envio do e-mail. É isso que gostaríamos? Em alguns casos, talvez seja interessante não falhar mesmo que um e-mail não seja enviado, mas esse tipo de decisão deve ser tomada pela lógica de negócio, e não pela classe que escrevemos. Deveríamos então ter propagado a exception, que era checked. Podemos fazer isso atraves da mesma exception ou “envelopando-a” numa unchecked que você considere, tal como:

    try {
      SimpleEmail email = new SimpleEmail();
      email.setHostName("mail.myserver.com");
      email.addTo(to, "nome do cliente");
      email.send();
      log.info("E-mail enviado para  " + to);
    } catch (EmailException e) {
      log.error("problemas enviando email", e);
      throw new IllegalStateException("falha ao enviar email para " + to, e);
    }
 

Pronto. Agora, além de falhar, vai logar pra gente o motivo da falha. Será que agora temos um logging bom que vai evitar que debuguemos nosso código? Ainda precisamos ajustar diversos detalhes. Um deles é que, nesse mesmo codigo, estamos aplicado o log and throw antipattern, que, no caso de existir alguém, em algum nivel acima, fazendo o try catch, vai provavelmente logar a exception, e ela será logada duas vezes. Devemos logar exceptions apenas quando não a relançamos (wrapped ou não).

Também precisaríamos colocar muito mais logging, acertar os níveis (info, error, warn, debug) e tomar cuidado até mesmo com a performance: apesar das APIs de logging serem incrivelmente rápidas, muitas vezes elas vão acabar invocando métodos seus, como o toString:

log.debug("cadastrando usuario " + usuario);

Aqui, usuario.toString() será invocado ao concatenar a mensagem, mesmo se o log não estiver definido em debug no seu arquivo de configuração, podendo gastar um tempo precioso se for invocado inúmeras vezes. É por esse motivo que as vezes aparece o seguinte idiomismo evitando chamadas desnecessárias:

if (log.isDebugEnable()) {
  log.debug("cadastrando usuario " + usuario);
}

As APIs de log mais modernas, como o SL4J, vão utilizar de varios argumentos ou de varargs, para que não tenha de cair nesse tipo de código, fazendo essas chamadas de toString apenas se aquele nível de log estiver habilitado.

Concluindo: debugar é sim preciso, mas devemos, através de boas práticas e um forte e criterioso logging, diminuir ao máximo a sua necessidade. E siga as boas práticas e faça boas logadas.

19 Comentários

  1. Tiago Peczenyj 27/05/2010 at 01:20 #

    Eu sempre vi o Logging como algo que pode ajudar a descrever um problema em produção. Prefiro usar BDD e descobrir que exceptions estão sumindo e logar só se for util.

  2. Paulo Silveira 27/05/2010 at 01:24 #

    Perfeito Tiago. Na edicao atual da mundojava escrevi junto com o Lucas esse exemplo de enviador de email, e como a gente pegaria esse tipo de problema desde o inicio.

    Daria ate pra brincar: “testar e’ preciso, logar nao e’ preciso” . O Log vai ser no caso de voce nao ter testado direito, e o debug no caso de voce nao ter logado direito.

    Sem duvida, Teste > Log > Debug. Mas log e debug vao se mostrar necessarios em alguns casos. Testes resolvem problemas antes de entrar em producao, log resolve problemas em producao, e debug quando a corda esta no pescoco :).

  3. Lucas Teixeira 27/05/2010 at 10:10 #

    Ter catch(Exception e) { } é aplicar o famoso pattern “silenciator”.

    Belo post 🙂

  4. André Silva 27/05/2010 at 11:22 #

    Concordo com o Paulo, o teste funcionará perfeitamente em “desenvolvimento”, mas em produção mtas vezes o erro pode acontecer.

    Usar try-catch é mto bom, qdo se usa! Conheço mtos sistemas q sempre que gera um erro em determinado lugar sobe o erro até uma classe “Genérica” onde loga a exceção. E mtas vezes chega apenas: “NullPointerException”. E ai temos que varrer todo o caminho do log até achar onde tudo começou, mas poderiamos já adiantar isso “especificando”na exception onde toda a brincadeira começou.

    Mto bom o post.

  5. Tiago Peczenyj 27/05/2010 at 11:38 #

    bom mesmo é catch Throwable

  6. Rafael de F. Ferreira 27/05/2010 at 11:52 #

    É legal lembrar que logging não é usado só para debugging, mas também para dar apoio ao pessoal de operações. Nesse caso, é útil envolver os sysadmins na definição de o que, e quanto, deve ser loggado; e o código de logging deve ser testado da mesma maneira que o resto do sistema.

  7. Valdemar Jr 27/05/2010 at 12:19 #

    Muito bom post. Gosto de logar os código “críticos” do sistema e alguns erros. Estou em um projeto atualmente que o cara não quer implementar log, por que um dos requisitos do sistema é performance e adicionado LOG, iria deixar o sistema mais lento =/

    Bom eu ainda estou “negociando” isso com o líder técnico 🙂

    Parabéns pelo post, ótima dica;

  8. Tiago Peczenyj 27/05/2010 at 14:05 #

    Valdemar, vc precisa logar TUDO?

    De repente vc pode logar as vezes e ter uma estatistica, ou escrever em um buffer e, então, mandar pro logger (se bem que um bom logger faria algo assim, eu mediria o impacto na performance com e sem log para ter uma ideia)

  9. Luís Carlos Moreira da Costa 27/05/2010 at 19:44 #

    Muito Bom post!

    Eu desenvolvo com OSGI-SL4J

    Eclipse RAP, RCP, eRCP, GMF, OSGI, Spring-DM and Pentaho Developer
    Regional Communities/Brazil
    http://wiki.eclipse.org/Regional_Communities/Brazil

  10. Breno Vitorino 27/05/2010 at 20:06 #

    Pessoal, ao escolherem a biblioteca de logging, prefiram SLF4J ao Commons Logging. Essa última possui erros de design que levam a vazamentos de memória. Veja o argumento completo em http://bit.ly/92VP1O.

  11. Alexandre Gazola 27/05/2010 at 21:15 #

    Ótimo, Paulo!

    A prática de engolir exceções e esse log-and-throw antipattern são muito usados mesmo. De fato, quanto mais testes escrevemos, menos tempo tendemos a despender com o debugger. E a parte de logging é sempre importante, por questões de instrumentação de código. O problema é só o ruído que o logging causa no código, o que a AOP tenta resolver (ou amenizar) tratando isso como um interesse transversal.

  12. Otávio Garcia 28/05/2010 at 01:41 #

    Paulo, como de praxe mais um excelente post seu. Logging é um dos meus assuntos preferidos, e muito mal compreendido por aí.

    Eu sou um fã do JDK Logging (JUL), uma pena que seja uma API tão mal compreendida, tanto pela Sun que até hoje mantém bugs abertos e também porque nunca obteve uma boa aceitação dos desenvolvedores.

    Obvio que o log4j é uma API dos jurássicos tempos pré JUL, mas acho que o tempo dele já passou. Não vejo um bom motivo de usar ele já que tudo que você faz no log4j você faz também no JUL. Sem contar com sua dependência com o commons-logging, que tinha um bonito propósito, pena que foi muito mal projetada e implementada.

    Sobre as exceptions é outro dos meus temas preferidos. Noto em muitos projetos por aí o pessoal fazendo um catch vazio, ou simplesmente exibindo algo no console mas sem tratar, e aí você já imagina a caca que dá no sistema todo. Infelizmente tem muito disso por aí.

    Sobre o debug, eu sempre digo que ele é um grande amigo dos desenvolvedores. Um exemplo que outro dia ví no GUJ um tópico onde um rapaz estava com um null-pointer. Foi complicado explicar pro rapaz que somente com um debug ele iria entender o que estava nulo. E que na base do “tentativa e erro” nunca chegariamos a uma solução.

    Abraços

  13. Emerson Macedo 30/05/2010 at 01:52 #

    Eu concordo plenamente com o que o Thiago disse no primeiro comment. Eu costumo dizer que quanto mais você faz TDD / BDD da forma certa você usa menos o debugger.

    Também concordo com que o Paulo disse. Teste > Logging > Debug. Esse último quase sempre precisamos por falha nossa mesmo.

    É lógico que dificilmente seremos perfeitos ao ponto de necessitar de zero debug, mas aplicando essas praticas corretamnete, isso diminui perceptivelmente.

    []s

  14. Paulo "JCranky" Siqueira 01/06/2010 at 23:23 #

    Acho que vale uma pergunta: se você fizer o tratamento do envio de e-mail desse jeito, a execução da lógica não está correndo o risco de ficar muito lenta? Sei que esse não é o objetivo do post, mas e-mail provavelmente seria melhor ser tratado de forma asincrona, ou estou viajando aqui?

    Tirando esse detalhe, concordo com 100% do post =)

  15. Paulo Silveira 01/06/2010 at 23:49 #

    Oi Paulo!

    Perfeito. Sem dúvida, em muitos casos é melhor enviar email assincronamente (fazemos assim no sistema da Caelum). Mas de qualquer maneira você vai ter um método (uma primitiva) que vai envia-lo sincronamente. Quem invoca esse método pode escolher se faz isso de maneira sincrona ou assincrona.

    abracos

  16. Arvin 16/06/2010 at 17:50 #

    Legal a idéia do post… mais legal ainda as considerações de cada um.

  17. Henrique S. 22/06/2010 at 23:36 #

    Post muito bom! Parabéns!

    Como já foi postado, o logging é muito importante p/ produção, principalmente quando é bem configurado e utilizado.

    Já passei por um caso complicado em que o sistema estava com erro e ao consultar o log estava: NullPointerException na linha e só! sequer o nome da classe e a linha da mesma estava no log. rsrs

    Já o debug, apesar de consumir um tempo considerável, acho muito importante quando utiliza-se corretamente também e quando a IDE fornece um bom debugger.

    Por exemplo, estou participando da customização de um certo portal onde o código fonte é disponibilizado, mas a princípio sem documentação do tipo: diagramas das classes, sequencia, atividade etc. Então p/ ajudar um pouco no entendimento de determinados processos, utilizo bastante o debug para fazer este ‘acompanhamento’.

    Então o debug é uma ferramenta bem interessante, não ficando com seu uso ‘restirto’ apenas p/ verificar erro no código.

    abçs

  18. Bruno Gonçales 22/08/2012 at 11:49 #

    E esse lance de misturar código de log com código de lógica, não é um problema? Eu poderia resolver isso com AspectJ, não é?

  19. Paulo Silveira 22/08/2012 at 13:06 #

    oi Bruno

    Ja perdi minhas ilusoes que tinha com AOP para segurança e logging. Fica impraticável colocar configuração de log para saber que parametros voce quer logar, em que nivel, em que situacao, fora do método em que ele deve ser feito. Além disso, depois que você refatora toda essa configuração quebra. Ou pior ainda: voce passa a utilizar kilos de anotações para configurar o log que deve ser produzido naquele método.

    Eu pessoalmente prefiro colocar no meio da lógica. O AOP tem ficado cada vez mais para o funcionamento interno de frameworks e containers.

Deixe uma resposta