How to enable Hibernate logging

And why your custom logging settings may refuse to apply

Enabling Hibernate logs is usually as simple as setting org.hibernate logging level to TRACE or ALL using your logging framework configuration of choice. Unfortunately, these may just not apply for some reason under certain circumstances. This post aims to clarify at least one of the problems leading to such annoying behavior.

Note that this is not only about logging SQL statements Hibernate prepares, but about enabling any internal Hibernate logging. Which, essentially, includes SQL logging, too.

This will be partly a story of some deep debugging results and partly a description of how what you should do to make it work as expected. In case you’re not interested in the former, you can jump straight to “The solution” paragraph. Nevertheless, I guess my story can be useful for a lot of occasional searchers. Also, it’s pretty short, so I won’t take much of your time.

The problem

The main issue with enabling the log for Hibernate (at least this is what I stumbled into and thought it’s far from obvious) is its algorithm for choosing the logging implementation (e.g. slf4j, log4j etc.). Probably it wouldn’t be the case if our project hadn’t multiple dependencies of dependencies which occasionally included more than a single implementation, but I believe our case is not really unique considering that no one really cares about managing dependencies until they cause problems.

We use slf4j interface and logback implementation generally. Thus, we have a proper config, in which I initially added a line to enable logging for Hibernate, too:

<logger name="org.hibernate" level="ALL"/>

If you ever looked into Hibernate sources, you’d mention that it writes really a lot of logs. So naturally I was expecting that my Terminal will be flooded, making me happy to dive in and tweak the config to filter only what I needed. But.. that did not happen.

OK, I googled a bit more and tried to put log4j.properties configuration file along the already existing logback config — just in case. And it worked. And that’s where it became annoying and… challenging.

The investigation

Since Hibernate uses jboss-logging module for logging purposes, the starting point where the initialization happens is org.jboss.logging.LoggerProviders class — this is where the logging framework is chosen. By the way, the whole jboss-logging module is pretty small and consists only of one package with about 30–40 classes, so if you’re interested you may inspect it from GitHub. But for this post we only need one method — findProvider, which is responsible to find an appropriate LoggerProvider implementation.

Having inspected the code, we can now conclude that the following is the order in which jboss-logging decides which implementation it should try to load and use:

1. Use the one defined in system property org.jboss.logging.provider
2. Load proper implementation via java.util.ServiceLoader
3. Try JBoss log manager
4. Try Log4j2
5. Try Log4j
6. Try Slf4j
7. Try JDK Log Manager

The explanation

Finally I could see what was the cause of that weird situation when log4j was used instead of slf4j: it’s just hard coded that it is tried to be loaded earlier. And because there is log4j library dangling somewhere in dependencies, it was used as a logging implementation as a result. Not pretty straight-forward, but totally legit.

The solution

Long story short, here is how you can force Hibernate to use exactly the logger implementation, and thus configuration, you want. And from there you should be familiar to how to enable either global “org.hibernate” logging or some specific one like “org.hibernate.engine.spi.ActionLogger”.

• Add -Dorg.jboss.logging.provider=slf4j when launching the java process. Or run System.setProperty("org.jboss.logging.provider", “slf4j") somewhere in the beginning of your code. Possible alternatives for sql4j are: jboss, jdk, log4j2 and log4j. If this system property is set, Hibernate will try to use the specified logging framework.
• Otherwise — if the appropriate system property is missing or the logging framework couldn’t be found or loaded by the specified value — Hibernate will try to load org.jboss.logging.LoggerProvider implementation using java.util.ServiceLoader. For more details on how this is performed I advice you to investigate the javadoc. In the simplest case, you can specify the implementing class in resources/META-INF/service/org.jboss.logging.LoggerProvider text file. But there is an important caveat — you cannot specify the implementations which already exist in jboss-logging package, like org.jboss.logging.Slf4jLoggerProvider, because these classes are not declared as public. There is an issue on jboss-logging tracker, but it’s closed literally as “works as designed”. Not sure whether they plan to share the default implementations somehow in the future, but apparently this option is currently only for custom implementations.
• In case the previous case also fails, the following implementations are searched on the classpath in the exact order: JBoss Log Manager, Log4j2, Log4j, Slf4j (only with Logback) and JDK Log Manager.

To conclude, I now can say that Hibernate does its best to fit your application’s logging needs. In case you do not explicitly define anything, it searches the classpath to find at least one appropriate implementation, and if it doesn’t — it falls back to default JDK Log Manager. It’s only when you have multiple implementations in dependencies Hibernate may not guess correctly which one will you want to be picked up. But hey, now you know where to look for.