Hibernate: log de instruções SQL no console

Para esse post inaugural vou falar de algo que me incomoda bastante, isto é, a maneira que a maioria dos desenvolvedores escolhe para exibir os comandos SQL do Hibernate no console para fins de debug, usando a propriedade “hibernate.show_sql” no persistence.xml.

Quando estamos desenvolvendo uma aplicação web qualquer, e estamos utilizando JPA, é muito cômodo usar a seguinte configuração no arquivo persistence.xml:

<property name="hibernate.show_sql" value="true" />

E de fato funciona. O problema dessa abordagem é que o uso dessa propriedade no persistence.xml faz com que seja impossível desliga-la um dia quando o sistema estiver em produção, o que é um comportamento desejável. Não faz sentido entregar um sistema para o cliente, e depois pedir para ele editar manualmente o arquivo persistence.xml para que os logs do seu servidor não seja inundado com comandos SQL que só deveriam aparecer em desenvolvimento. Sem contar que, após a alteração, ele teria que reiniciar o servidor 🙂

Uma das vantagens de um framework de logging, como o que usa o Hibernate e 99% dos frameworks de mercado, é exatamente a possibilidade de alterar tudo em tempo de execução e principalmente sem a necessidade de intervenção no código fonte. O que será exibido ou não no log do servidor, idealmente deve ser uma configuração de ambiente, externa ao código.

Sendo mais específico, vamos usar o JBoss 7 como exemplo. As configurações de logging do JBoss ficam por padrão em um dos dois arquivos abaixo, dependendo do modo no qual você está operando. A maioria dos mortais irá usar o modo “standalone”:

  1. %JBOSS_HOME%/standalone/configuration/standalone.xml
  2. %JBOSS_HOME%/domain/configuration/domain.xml

Abrindo o arquivo “standalone.xml” é só procurar o “logging subsystem”:

<subsystem xmlns="urn:jboss:domain:logging:1.1">
    <console-handler name="CONSOLE">
        <level name="INFO"/>
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
        </formatter>
    </console-handler>

    <periodic-rotating-file-handler name="FILE">
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
        </formatter>
        <file relative-to="jboss.server.log.dir" path="server.log"/>
        <suffix value=".yyyy-MM-dd"/>
        <append value="true"/>
    </periodic-rotating-file-handler>

    <logger category="com.arjuna">
       <level name="WARN"/>
    </logger>
    <logger category="org.apache.tomcat.util.modeler">
       <level name="WARN"/>
    </logger>
    <logger category="sun.rmi">
       <level name="WARN"/>
    </logger>
    <logger category="jacorb">
        <level name="WARN"/>
    </logger>
    <logger category="jacorb.config">
        <level name="ERROR"/>
    </logger>
    <root-logger>
        <level name="INFO"/>
        <handlers>
            <handler name="CONSOLE"/>
            <handler name="FILE"/>
        </handlers>
    </root-logger>
</subsystem>

Pra quem nunca usou “java.util.logging” ou similares, uma breve explicação: Temos ai dois tipos básicos de elementos, os “handlers” e os “loggers”. No log4j por exemplo, esses elementos seriam chamados de “appenders” e “categories”, respectivamente.

Os “handlers” definem ONDE o log será exibido: em um arquivo, no console, pode ser enviado por email, etc. Os “loggers” definem O QUE será exibido: consultas SQL feitas pelo hibernate, informações do ciclo de vida do JSF, etc.

Na configuração padrão do JBoss 7 exibida acima só temos dois “handlers”, ou seja, dois lugares onde os logs serão gravados. Um é no console (o seu console do eclipse), e o outro é em um arquivo (no server.log que fica no disco). Como já devem estar desconfiando, as informações de log que aparecem no seu console do eclipse/netbeans não é necessariamente igual ao que é gravado no arquivo server.log do JBoss. São dois “handlers” diferentes e podem ser configurados de forma diferente.

Agora voltando ao nosso tópico inicial, para que sejam exibidos os comandos SQL gerados pelo Hibernate, juntamente com os parâmetros, basta acrescentar os loggers “org.hibernate.SQL” e “org.hibernate.type”:

<!-- Esse exibe os comandos SQL -->
<logger category="org.hibernate.SQL">
    <level name="DEBUG"/>
</logger>

<!-- Esse aqui é para exibir os parâmetros -->
<logger category="org.hibernate.type">
    <level name="TRACE"/>
</logger>

Além dos dois loggers acima é preciso fazer uma pequena alteração no handler CONSOLE, para que você consiga ver todos os comandos no seu console do eclipse/netbeans. Se você prestar atenção existe um atributo “level” que está setado com o nível “INFO”. Como os dois loggers que configuramos são “DEBUG” e “TRACE”, temos que diminuir esse nível do console handler:

<console-handler name="CONSOLE">
    <level name="TRACE"/> <!-- Antes aqui tinha INFO -->
    <formatter>
        <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
    </formatter>
</console-handler>

No final das contas, o trecho com todas as alterações vai ficar assim:

<subsystem xmlns="urn:jboss:domain:logging:1.1">
    <console-handler name="CONSOLE"> <!-- Antes aqui tinha INFO -->
        <level name="TRACE"/>
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
        </formatter>
    </console-handler>

    <periodic-rotating-file-handler name="FILE">
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
        </formatter>
        <file relative-to="jboss.server.log.dir" path="server.log"/>
        <suffix value=".yyyy-MM-dd"/>
        <append value="true"/>
    </periodic-rotating-file-handler>

    <!-- Esse exibe os comandos SQL -->
    <logger category="org.hibernate.SQL">
        <level name="DEBUG"/>
    </logger>

    <!-- Esse aqui é para exibir os parâmetros -->
    <logger category="org.hibernate.type">
        <level name="TRACE"/>
    </logger>

    <logger category="com.arjuna">
       <level name="WARN"/>
    </logger>
    <logger category="org.apache.tomcat.util.modeler">
       <level name="WARN"/>
    </logger>
    <logger category="sun.rmi">
       <level name="WARN"/>
    </logger>
    <logger category="jacorb">
        <level name="WARN"/>
    </logger>
    <logger category="jacorb.config">
        <level name="ERROR"/>
    </logger>
    <root-logger>
        <level name="INFO"/>
        <handlers>
            <handler name="CONSOLE"/>
            <handler name="FILE"/>
        </handlers>
    </root-logger>
</subsystem>

Pronto. Agora você pode controlar o que cada um dos seus ambientes vai exibir como log, sem nenhuma intervenção em código. A configuração de logging será exclusiva do ambiente. No JBoss 7 também é possível fazer todas essas configurações via interface, pelo console de administração. Eu sou old school e prefiro a velha linha de comando 🙂

Dependendo de como o seu ambiente está configurado é possível que as configurações de logging do standalone.xml sejam ignoradas, por exemplo por conta da propriedade de sistema “org.jboss.as.logging.per-deployment”. Quando essa propriedade é true, o JBoss utiliza configurações dentro do próprio sistema, o que em alguns casos pode ser útil.

Não esqueçam de apagar o “hibernate.show_sql” do persistence.xml, senão os comandos SQL irão ser exibidos duplicados para cada operação.

2 thoughts on “Hibernate: log de instruções SQL no console

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s