So, I'm deploying a web app which use Hibernate 4.3.6. and Tomcat 7. I'm trying to use SLF4J as logging abstract layer to log. However, I have many issues and doubts. First of all, both Hibernate and Tomcat come yet with different logging frameworks, jboss-logging and juli respectively (even if I can't find juli on the libraries) So, I think I have to install the bridge from these frameworks to SLF4J. For Hibernate, from this answer, a solution could be to use a SystemProperty. However, if I don't set this,
it tries jboss, then log4j, then slf4j (only if logback used) and fallback to jdk. So, maybe this is what I want: don't set the SystemProperty and leaves it choose slf4j.
For Tomcat, I think I have to simply add the jul-to-slf4j and tomcat-juli jars to the build path. So, at this moment, I have this jars on the build path:
- slf4j-api-1.7.7
- logback-classic-1.1.2
- logback-core-1.1.2
- tomcat-juli-7.0.42
- jul-to-slf4j-1.7.7
(I've deleted jboss-logging and the default and old slf4j coming with hibernate, but not tomcat-logging) Also, I've added this xml file inside a package in my project.
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug = "true">
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>/var/lib/tomcat7/MyApp/MyLog.log</file>
<encoder>
<Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
</Pattern>
</encoder>
</appender>
<root level="trace">
<appender-ref ref="FILE" />
</root>
</configuration>
but I haven't linked it to any resource at all. Have I to declare this log configuration somewhere in web.xml? To call SLF4J inside one of my resources, I simply put these lines
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
private final static Logger LOG = LoggerFactory.getLogger(MyServlet.class);
...
LOG.debug("I'm logging");
However, nothing works. I continue to have messages from Tomcat logger, while Hibernate complains that it doesn't have a logger; at the same time, I can't see any log coming from slf4j/logback.
SEVERE: Exception sending context initialized event to listener instance of class pervasive.com.gmail.tigerjack89.forum.server.controller.servlet.ContainerContext
java.lang.NoClassDefFoundError: org/jboss/logging/BasicLogger
at java.lang.ClassLoader.defineClass1(Native Method)
at java.lang.ClassLoader.defineClass(ClassLoader.java:800)
at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:2944)
at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:1208)
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1688)
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1569)
at org.hibernate.cfg.Configuration.<clinit>(Configuration.java:192)
...
Caused by: java.lang.ClassNotFoundException: org.jboss.logging.BasicLogger
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1718)
at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1569)
The error message stay the same even if I add "-Dorg.jboss.logging.provider=slf4j" to the VM arguments. So, how can I solve the problem?
EDIT
Adding back jboss-logging to classpath the error disappeared. Problem is that now I have a lot of messages coming from logback, jboss-logging and juli. Also, no file is created until now, even if I specified one in logback.xml; instead, it continues to write to the console using the default pattern (indeed, it doesn't print the day as specified in logback.xml). This is an example of log output, where you can easily identify messages coming from the different loggers (logback start with the hour, jboss-logging start with Hibernate: and juli start with the debug level)
16:50:01.331 [localhost-startStop-1] DEBUG org.hibernate.SQL -
select
subforums0_.parent_sub_forum as parent_s3_1_0_,
subforums0_.id as id1_1_0_,
subforums0_.id as id1_1_1_,
subforums0_.parent_sub_forum as parent_s3_1_1_,
subforums0_.title as title2_1_1_
from
subforum subforums0_
where
subforums0_.parent_sub_forum=?
Hibernate:
select
subforums0_.parent_sub_forum as parent_s3_1_0_,
subforums0_.id as id1_1_0_,
subforums0_.id as id1_1_1_,
subforums0_.parent_sub_forum as parent_s3_1_1_,
subforums0_.title as title2_1_1_
from
subforum subforums0_
where
subforums0_.parent_sub_forum=?
16:50:01.332 [localhost-startStop-1] DEBUG o.h.l.p.e.p.i.ResultSetProcessorImpl - Preparing collection intializer : [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums#11]
16:50:01.337 [localhost-startStop-1] DEBUG o.h.e.l.i.CollectionLoadContext - 1 collections were found in result set for role: pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums
16:50:01.337 [localhost-startStop-1] DEBUG o.h.e.l.i.CollectionLoadContext - Collection fully initialized: [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums#11]
16:50:01.337 [localhost-startStop-1] DEBUG o.h.e.l.i.CollectionLoadContext - 1 collections initialized for role: pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums
16:50:01.338 [localhost-startStop-1] DEBUG o.h.l.c.p.AbstractLoadPlanBasedCollectionInitializer - Done loading collection
16:50:01.338 [localhost-startStop-1] DEBUG o.h.e.t.spi.AbstractTransactionImpl - committing
16:50:01.339 [localhost-startStop-1] DEBUG o.h.e.i.AbstractFlushingEventListener - Processing flush-time cascades
16:50:01.346 [localhost-startStop-1] DEBUG o.h.e.i.AbstractFlushingEventListener - Dirty checking collections
16:50:01.361 [localhost-startStop-1] DEBUG o.h.engine.internal.Collections - Collection found: [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforumThreads#11], was: [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforumThreads#11] (uninitialized)
16:50:01.361 [localhost-startStop-1] DEBUG o.h.engine.internal.Collections - Collection found: [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums#11], was: [pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum.subforums#11] (initialized)
16:50:01.362 [localhost-startStop-1] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
16:50:01.362 [localhost-startStop-1] DEBUG o.h.e.i.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
16:50:01.364 [localhost-startStop-1] DEBUG o.h.internal.util.EntityPrinter - Listing entities:
16:50:01.366 [localhost-startStop-1] DEBUG o.h.internal.util.EntityPrinter - pervasive.com.gmail.tigerjack89.forum.shared.model.entities.Subforum{subforumThreads=<uninitialized>, subforums=[], subforumParent=null, subforumId=11, subforumTitle=Main}
16:50:01.367 [localhost-startStop-1] DEBUG o.h.e.t.i.jdbc.JdbcTransaction - committed JDBC Connection
16:50:01.373 [localhost-startStop-1] DEBUG o.h.e.j.i.LogicalConnectionImpl - Releasing JDBC connection
16:50:01.373 [localhost-startStop-1] DEBUG o.h.e.j.i.LogicalConnectionImpl - Released JDBC connection
Dec 06, 2014 4:50:01 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 06, 2014 4:50:01 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 5850 ms
EDIT 2
Deploying the app on the system installation folder of Tomcat (instead of the one used by Eclipse), all the juli files are written into catalina.[date].log, while the logs coming from jboss-logging and logback are written into catalina.out. It seems that the logback.xml file isn't recognized at all.
EDIT 3 Well, one of the problems seems to be with the position of logback.xml. I had put it in a subfolder, while it should be directly under WEB-INF/classes. Now it logs to the right directories. However, both Hibernate and Tomcat still continues to write their log messages to System.out (and as a result to catalina.out).
EDIT 4
Ok, I disabled Hibernate outputs to stdout deleting <property name="show_sql">true</property> from hibernate.cfg.xml.
Now, my question is: is it ok/desiderable that tomcat continues to print messages like
Dec 07, 2014 7:46:59 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
on the console?
