logback <logger> level ignored when logs come from jboss-logging

3
votes

My web application (deployed on tomcat 7) is using hibernate 4.2 which logs using jboss-logging. Jboss logging is finding slf4j on the path and uses it. In turn, I have logback-classic to output the logs. Everything works nicely, but I cannot customize the root logging level, i.e. 

<logger name="o.h.cfg.annotations" level="info"/>
<logger name="rest.helpers" level="info"/>

<root level="debug">
    <appender-ref ref="STDOUT" />
</root>

Results in:

logback-test 16:47:03.689 [http-bio-8080-exec-5] DEBUG org.jboss.logging - Logging Provider: org.jboss.logging.Slf4jLoggerProvider

logback-test 16:47:04.244 [http-bio-8080-exec-5] DEBUG o.h.cfg.annotations.EntityBinder

logback-test 10:00:11.911 [localhost-startStop-1] INFO rest.helpers.MyApplication

For messages coming from jboss (o.h.cfg.annotations.*), level is set to info, but a debug message is printed. When I use slf4j directly (rest.helpers.*), it correctly filters out my debug messages, and prints my info messages.

Now, if root log level is set to "none", allowing some debug messages will print all of them:

<logger name="o.h.cfg.annotations" level="debug"/>
<logger name="rest.helpers" level="debug"/>
<root level="none"/>

logback-test 10:22:25.926 [localhost-startStop-1] DEBUG rest.helpers.MyApplication -dMyApplication() Aug 2, 2013 10:22:26 AM org.glassfish.jersey.server.ApplicationHandler initialize INFO: Initiating Jersey application

logback-test 10:22:26.253 [localhost-startStop-1] INFO rest.helpers.MyApplication

logback-test 10:22:42.995 [http-bio-8080-exec-5] DEBUG org.jboss.logging - Logging Provider: org.jboss.logging.Slf4jLoggerProvider

logback-test 10:22:43.025 [http-bio-8080-exec-5] DEBUG org.hibernate.type.BasicTypeRegistry

I have not allowed org.hibernate debug messages, why did they appear? i verified that the right config file is taken (by changing the log format)

Please help me make sense of this.

My classpath contains

  • slf4j-api 1.6.1
  • jul-to-slf4j 1.6.1
  • log4j-over-slf4j 1.6.1
  • logback-core 1.0.33
  • logback-classic 1.0.33
  • jboss-logging 3.1.0.GA.

Both logback.xml and logback-test.xml are in the classpath. logback.xml contains <root level="warn"> and no further specialization

3
hibernatelogginglogbackjboss-logging
Did you ever figure out a solution for this? I am seeing the same behavior on an application deployed to Websphere 8. – FGreg
Related: forum.hibernate.org/viewtopic.php?f=1&t=1032044&start=0 – FGreg

3 Answers

1
votes

I had the same problem with freemarker however in my case freemarker was not using the log4j-over-slf4j bridge but used log4j directly (i had it in my classpath without knowing (through a maven dependency)).

I discovered the problem when i told logback to log to a file and the freemarker logs still arrived on stdout.

The solution was to explicitly exclude the log4j dependency from a maven lib i used.

0
votes

To turn off unwanted logs just simply set root level to OFF and register logger for package/class you want to print in your logging destination.

<logger name="rest" level="INFO"/>
<root level="OFF">
    <appender-ref ref="STDOUT" />
</root>
0
votes

I had a similar problem with hibernate using HikariCP and logback within tomcat 8. I use JNDI to define the Hikari pool globally on tomcat.

So I ended with adding Hikari, logback and slf4j jars only under CATALINA_HOME/lib.

In such a case, it took me quite a while to discover that in such case, the logback.xml configuration file must also be under CATALINA_HOME/lib to be found by tomcat and not under CATALINA_HOME/conf where the rest of tomcat config is done.

Hope it can help someone.