I am currently developping a small webapplication wich i deploy on JBoss EAP 6.3.0.GA (version 7.4.0.Final-redhat-19).
This application use hibernate as its JPA provider (hibernate version 4.2.14.SP1-redhat-1) and it also use an EJB between the webapp and the data layer).
I have succesfully configured my application to log its processes through log4j in a specific file.
I have also succesfully configure hibernate to log the statement's parameters to the same file.
THe log4j version used is 1.2.16.
My problem is that the SQL statements generated by hibernate are never log to the file when i call my DAO through the webapp and those statements are logged to the server.log file if a remotely call to the business EJB through a main method.
I need this logs because the log provided by the spy on the datasource is not suitable for my case (i must log the hibernate stuff on a application basis rather than for the whole server).
Can you say me what i have misconfigured in my application ? Here is a link to github where my application is currently stored : https://github.com/lionelh/jboss-testing
Thank you for your help.
Here is also the log4j.properties wich is deployed with my application :
#
# ROOT LOGGER
#
log4j.rootLogger=DEBUG
log4j.appender.applog=org.apache.log4j.DailyRollingFileAppender
log4j.appender.applog.File=../standalone/log/jbosstesting.log
log4j.appender.applog.DatePattern='-'yyyy-MM-dd
log4j.appender.applog.layout=org.apache.log4j.PatternLayout
log4j.appender.applog.layout.ConversionPattern=%5p *** %d{dd/MM/yyyy HH:mm:ss,SSS} *** (%C:%L) *** %m%n
#
# LOGGERS
#
log4j.logger.be.lionelh.jbosstesting=DEBUG, applog
log4j.logger.org.hibernate.SQL=DEBUG, applog
log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=trace, applog
log4j.logger.org.hibernate.type.descriptor.sql.BasicEXtractor=trace, applog
Here is the content of the log file produced during JUnit test (this is what i want when the webapp is deployed) :
DEBUG *** 14/03/2015 16:30:36,996 *** [main] (UserDaoImpl.java:41) *** In findById
DEBUG *** 14/03/2015 16:30:36,999 *** [main] (SqlStatementLogger.java:104) *** select user0_.US_ID as US_ID1_0_0_, user0_.US_CREATION_DATE as US_CREAT2_0_0_, user0_.US_LANGUAGE as US_LANGU3_0_0_, user0_.US_LAST_UPDATE_DATE as US_LAST_4_0_0_, user0_.US_LOGIN as US_LOGIN5_0_0_ from phone_user user0_ where user0_.US_ID=?
TRACE *** 14/03/2015 16:30:37,003 *** [main] (BasicBinder.java:84) *** binding parameter [1] as [BIGINT] - 1
TRACE *** 14/03/2015 16:30:37,005 *** [main] (BasicExtractor.java:74) *** Found [2015-02-14 21:22:55.0] as column [US_CREAT2_0_0_]
TRACE *** 14/03/2015 16:30:37,005 *** [main] (BasicExtractor.java:74) *** Found [F] as column [US_LANGU3_0_0_]
TRACE *** 14/03/2015 16:30:37,006 *** [main] (BasicExtractor.java:74) *** Found [2015-02-14 21:22:55.0] as column [US_LAST_4_0_0_]
TRACE *** 14/03/2015 16:30:37,006 *** [main] (BasicExtractor.java:74) *** Found [lh] as column [US_LOGIN5_0_0_]
Here is the content of the log when the application is deploy to JBoss (the SQL staement are missing :
DEBUG *** 14/03/2015 19:54:30,827 *** (be.lionelh.jbosstesting.web.UserBean:69) *** In login()
DEBUG *** 14/03/2015 19:54:30,923 *** (be.lionelh.jbosstesting.data.ejb.JBossTestingBean:35) *** In createUser(UserDto)
DEBUG *** 14/03/2015 19:54:30,924 *** (be.lionelh.jbosstesting.data.domain.dao.impl.UserDaoImpl:28) *** In create(User)
TRACE *** 14/03/2015 19:54:31,146 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [1] as [TIMESTAMP] - Sat Mar 14 19:54:31 CET 2015
TRACE *** 14/03/2015 19:54:31,161 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [2] as [VARCHAR] - F
TRACE *** 14/03/2015 19:54:31,164 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [3] as [TIMESTAMP] - Sat Mar 14 19:54:31 CET 2015
TRACE *** 14/03/2015 19:54:31,165 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [4] as [VARCHAR] - vp
DEBUG *** 14/03/2015 19:54:31,286 *** (be.lionelh.jbosstesting.data.ejb.JBossTestingBean:42) *** In findAllUsers()
DEBUG *** 14/03/2015 19:54:31,287 *** (be.lionelh.jbosstesting.data.domain.dao.impl.UserDaoImpl:35) *** In findAll()
The issue is that Hibernate will use the log configuration from the server not your application. Given your example configuration though it would be quite easy to configure the logging subsystem to do this.
You can place the following CLI commands into a file and run them via $JBOSS_HOME/bin/jboss-cli.sh -c --file="path/to/file.cli"
batch
/subsystem=logging/pattern-formatter=applog-formatter:add(pattern="%5p *** %d{dd/MM/yyyy HH:mm:ss,SSS} *** (%C:%L) *** %m%n")
/subsystem=logging/periodic-rotating-file-handler=applog:add(append=true,autoflush=true,named-formatter=applog-formatter,suffix="'-'yyyy-MM-dd",file={relative-to="jboss.server.log.dir",path="jbosstesting.log"})
/subsystem=logging/logger=be.lionelh.jbosstesting:add(level=DEBUG,handlers=[applog])
/subsystem=logging/logger=org.hibernate.SQL:add(level=DEBUG,handlers=[applog],use-parent-handlers=false)
/subsystem=logging/logger=org.hibernate.type.descriptor.sql.BasicBinder:add(level=TRACE,handlers=[applog],use-parent-handlers=false)
/subsystem=logging/logger=org.hibernate.type.descriptor.sql.BasicEXtractor:add(level=TRACE,handlers=[applog],use-parent-handlers=false)
run-batch
You'll also need to remove the log4j.properties so the server does not attempt to configure a log manager based on those settings.
You could also use the script with the the jboss-as-maven-plugin as well.