Sunday, August 12, 2012

Spring logging is not working in JRF/SOA enabled domain

Recently got an interesting SR which worth sharing.

An application which uses Spring and uses log4j to log debug information. log4j.properties is configured for both application code and Spring code:
log4j.logger.com.company.customerCode=DEBUG
log4j.logger.org.springframework.core=DEBUG  
The logging works perfectly on a base weblogic domain, which both application and spring debug messages are printed to specified log file. However, when the application is deployed to a JRF/SOA enabled domain, we see only application debug messages, not Spring ones. Why??

When diagnosing this problem, 2 debug flags helped:

1) -Dlog4j.debug

we can see the sample output here:
log4j: Using URL [zip:D:/bea/WLS1036/user_projects/domains/TestDevDomain/servers/AdminServer/tmp/_WL_user/_appsdir_aif-sm_ear_1.0.0-dev-b57/mpc1b8/war/WEB-INF/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL zip:D:/bea/WLS1036/user_projects/domains/TestDevDomain/servers/AdminServer/tmp/_WL_user/_appsdir_aif-sm_ear_1.0.0-dev-b57/mpc1b8/war/WEB-INF/log4j.properties
log4j: Parsing for [root] with value=[WARN, logfile].
log4j: Level token is [WARN].
log4j: Category root set to WARN
log4j: Parsing appender named "logfile".
log4j: Parsing layout options for "logfile".
log4j: Setting property [conversionPattern] to [%x %d %p [%c] - %m%n].
log4j: End of parsing for "logfile".
log4j: Setting property [file] to [aif-common.log].
log4j: setFile called: aif-common.log, true
log4j: setFile ended
log4j: Parsed "logfile" options.
log4j: Parsing for [com.company.customerCode] with value=[DEBUG].
log4j: Level token is [DEBUG].
log4j: Category com.company.customerCode set to DEBUG
log4j: Handling log4j.com.company.customerCode=[null]
log4j: Parsing for [org.springframework] with value=[DEBUG].
log4j: Level token is [DEBUG].
log4j: Category org.springframework set to DEBUG
log4j: Handling log4j.additivity.org.springframework=[null]
log4j: Finished configuring.
the output tells us that log4j configuration is correct. the log4j properties files are loaded and configurations are set.

2) -Dorg.apache.commons.logging.diagnostics.dest=d:\test\jcl.log

this output tells us how JCL loads it's configurations.

Here's sample output snippet from a base domain:
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] Trying to get log class from attribute 'org.apache.commons.logging.Log'
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] Trying to get log class from attribute 'org.apache.commons.logging.log'
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] Trying to get log class from system property 'org.apache.commons.logging.Log'
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] Trying to get log class from system property 'org.apache.commons.logging.log'
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] No user-specified Log implementation; performing discovery using the standard supported logging implementations...
[LogFactoryImpl@15531576 from weblogic.utils.classloaders.ChangeAwareClassLoader@14877755] Attempting to instantiate 'org.apache.commons.logging.impl.Log4JLogger'
here's sample output sinippet from a JRF/SOA enabled domain:
[LogFactoryImpl@8199388 from weblogic.utils.classloaders.ChangeAwareClassLoader@1666116] Trying to get log class from attribute 'org.apache.commons.logging.Log'
[LogFactoryImpl@8199388 from weblogic.utils.classloaders.ChangeAwareClassLoader@1666116] Trying to get log class from attribute 'org.apache.commons.logging.log'
[LogFactoryImpl@8199388 from weblogic.utils.classloaders.ChangeAwareClassLoader@1666116] Trying to get log class from system property 'org.apache.commons.logging.Log'
[LogFactoryImpl@8199388 from weblogic.utils.classloaders.ChangeAwareClassLoader@1666116] Attempting to load user-specified log class 'org.apache.commons.logging.impl.Jdk14Logger'...
Seems there is a system property set for org.apache.commons.logging.Log

I checked JRF domain, it indeed has that:
org.apache.commons.logging.Log = org.apache.commons.logging.impl.Jdk14Logger 
it's configured in setDomainEnv.cmd:
set EXTRA_JAVA_PROPERTIES=-Dcommon.components.home=%COMMON_COMPONENTS_HOME% -Djrf.version=11.1.1 -Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.Jdk14Logger -Ddomain.home=%DOMAIN_HOME% -Djrockit.optfile=%COMMON_COMPONENTS_HOME%\modules\oracle.jrf_11.1.1\jrocket_optfile.txt -Doracle.server.config.dir=%ORACLE_DOMAIN_CONFIG_DIR%\servers\%SERVER_NAME% -Doracle.domain.config.dir=%ORACLE_DOMAIN_CONFIG_DIR%  -Digf.arisidbeans.carmlloc=%ORACLE_DOMAIN_CONFIG_DIR%\carml  -Digf.arisidstack.home=%ORACLE_DOMAIN_CONFIG_DIR%\arisidprovider -Doracle.security.jps.config=%DOMAIN_HOME%\config\fmwconfig\jps-config.xml -Doracle.deployed.app.dir=%DOMAIN_HOME%\servers\%SERVER_NAME%\tmp\_WL_user -Doracle.deployed.app.ext=\- -Dweblogic.alternateTypesDirectory=%ALT_TYPES_DIR% -Djava.protocol.handler.pkgs=%PROTOCOL_HANDLERS%  %WLS_JDBC_REMOTE_ENABLED% %EXTRA_JAVA_PROPERTIES%
Then we found the problem. :)

There are 2 solutions for this problem:

1) modify the system level properties from
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.Jdk14Logger
to
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger
2) modify(or add one if not exist) the commons-logging.properties file under application's war file's WEB-INF\classes directory to contain the following content:

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger
priority=1