Configure Hibernate Logging with SLF4j + Logback

This tutorial shows how to configure hibernate with SLF4j and Logback. Logging is an important tool for each developer. So it’s worth setting up right the first time. We configure Logback with a ConsoleAppender for logging to the console and a RollingFileAppender for logging to a file for archival. If you stick around, we’ll also show you how to remove the annoying c3p0 logging.

Maven Dependencies

We are using Apache Maven to manage the projects dependencies. Add the following dependencies to your projects pom.xml file.

<dependency>
    <groupId>mysql</groupId>
    <artifactId>mysql-connector-java</artifactId>
    <version>6.0.4</version>
</dependency>
<dependency>
    <groupId>org.hibernate</groupId>
    <artifactId>hibernate-core</artifactId>
    <version>5.2.3.Final</version>
</dependency>
<dependency>
    <groupId>org.hibernate</groupId>
    <artifactId>hibernate-c3p0</artifactId>
    <version>5.2.3.Final</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.1.7</version>
</dependency>

Project Structure

Make sure the configuration files like logback.xml and mchange-log.properties resides on the classpath in the src/main/resources folder.

src
|    +--main
|        +--java
|            +--com
|                +--memorynotfound
|                    +--hibernate
|                        |--App.java
|                        |--Book.java
|                        |--HibernateUtil.java
|        +--resources
|            |--Hibernate.cfg.xml
|            |--logback.xml
|            |--mchange-log.properties
pom.xml

Logback Configuration

In the logback.xml file, we can configure Logback. In this example we define two loggers. The first ch.qos.logback.core.ConsoleAppender will write the output to the console. The second ch.qos.logback.core.rolling.RollingFileAppender will write the output to a file for archival reasons. We can specify the log level using the logger element. In this element we can provide a package name to manage the log level of that specific package.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%d{yyyy-MM-dd_HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</Pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>mylog.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>

        <encoder>
            <pattern>%d{yyyy-MM-dd_HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="org.hibernate" level="INFO" />
    <logger name="com.memorynotfound" level="DEBUG" />

    <root level="WARN">
        <appender-ref ref="FILE" />
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

Disabling c3p0 Info Logging

When you don’t want the c3p0 info logging information, you can disable this by creating a mchange-log.properties file in the src/main/resources folder. In this file you can specify the following properties. These will disable the info logging and only log WARNING messages.

com.mchange.v2.log.MLog=com.mchange.v2.log.FallbackMLog
com.mchange.v2.log.FallbackMLog.DEFAULT_CUTOFF_LEVEL=WARNING

Output

The following output is an example of the log, created by logback.

2016-10-12_09:49:38.185 INFO  org.hibernate.Version - HHH000412: Hibernate Core {5.2.3.Final}
2016-10-12_09:49:38.189 INFO  org.hibernate.cfg.Environment - HHH000206: hibernate.properties not found
2016-10-12_09:49:38.191 INFO  org.hibernate.cfg.Environment - HHH000021: Bytecode provider name : javassist
2016-10-12_09:49:38.384 INFO  o.h.annotations.common.Version - HCANN000001: Hibernate Commons Annotations {5.0.1.Final}
2016-10-12_09:49:38.501 INFO  o.h.c.i.C3P0ConnectionProvider - HHH010002: C3P0 using driver: com.mysql.cj.jdbc.Driver at URL: jdbc:mysql://localhost:3306/bookstore?serverTimezone=Europe/Brussels
2016-10-12_09:49:38.501 INFO  o.h.c.i.C3P0ConnectionProvider - HHH10001001: Connection properties: {user=root, password=****}
2016-10-12_09:49:38.501 INFO  o.h.c.i.C3P0ConnectionProvider - HHH10001003: Autocommit mode: false
2016-10-12_09:49:38.643 INFO  o.h.c.i.C3P0ConnectionProvider - HHH10001007: JDBC isolation level: 
2016-10-12_09:49:38.930 INFO  org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
2016-10-12_09:49:38.977 INFO  o.h.e.j.e.i.LobCreatorBuilderImpl - HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
2016-10-12_09:49:39.446 INFO  org.hibernate.orm.connections.access - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.[email protected]6ea04618] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
2016-10-12_09:49:39.459 INFO  org.hibernate.orm.connections.access - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.[email protected]eb507b9] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
2016-10-12_09:49:39.474 INFO  o.h.t.s.internal.SchemaCreatorImpl - HHH000476: Executing import script 'org.hiber[email protected]624a24f6'
2016-10-12_09:49:39.554 DEBUG com.memorynotfound.hibernate.App - creating new book
2016-10-12_09:49:39.555 DEBUG com.memorynotfound.hibernate.App - saving new book
2016-10-12_09:49:39.587 DEBUG com.memorynotfound.hibernate.App - committing transaction
2016-10-12_09:49:39.591 DEBUG com.memorynotfound.hibernate.App - closing session
2016-10-12_09:49:39.592 DEBUG com.memorynotfound.hibernate.App - shutting down
2016-10-12_09:49:39.593 INFO  o.h.t.s.i.SchemaDropperImpl$DelayedDropActionImpl - HHH000477: Starting delayed drop of schema as part of SessionFactory shut-down'
2016-10-12_09:49:39.593 INFO  org.hibernate.orm.connections.access - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.[email protected]481e91b6] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.

Download