A funny thing happened on the way to creating a logger

[toddblackwell]

Okay, so I had this great idea to inject a static logger instance into a Spring bean object that was to become an RPC DMI object. The logger instance is an SLF4J logger instance, and the reason I wanted to inject it is because another team on our project came up with the bright idea to put a wrapper around the SLF4J framework to provide application-specific functionality for the logger instances that were to be created and used by our application. I know, I know, why on Earth did they decide to do it that way instead of just implementing their own Appender object or something? Great question. I asked the same thing at their design review, and their answer was, “It’s too late to change things now”. I still have a red mark on my head from banging it against the wall.

Anyway, back to the reason I’m posting. To get around this requirement of using this so-called SLF4J wrapper, I thought I’d be clever and dependency-inject all loggers into all server-side classes that needed them. I could then put any project-specific code for the creation of the logger instance into the Spring configuration file, and keep it out of my code. Sounds great, right? WRONG!! One of the objects I tried to statically dependency-inject a logger instance into was an RPC DMI object, which itself was loaded into my SmartGWT application via the bean/lookupStyle combination in my app.xml file:

<Application>
   <rpcBindings>
      <ServerObject ID=”dmiObjectId” bean=”dmiBeanId” lookupStyle=”spring”>
         <visibleMethods>
            <method name=”aMethodName”/>
         </visibleMethods>
      </ServerObject>
   </rpcBindings>
</Application>

Over in my Spring file, I had this:

<bean id=”dmiObjectLogger class=”org.slf4j.LoggerFactory” factory-method=”getLogger>
   <constructor-arg type=”java.lang.Class” value=”com.company.MyDmiClass”/>
</bean>

<bean id=”setMyDmiClassLogger” class=”org.springframework.beans.factory.config.MethodInvokingFactoryBean”>
   <property name=”targetClass”><value>com.company.MyDmiClass</value></property>
   <property name=”targetMethod”><value>setLogger</value></property>
   <property name=”arguments”>
      <list>
         <ref bean=”dmiObjectLogger”/>
      </list>
   </property>
</bean>

<bean id=”dmiBeanId” class=”com.company.MyDmiClass”/>

And my classes basically had this type of layout:

public class MyDmiClass
{
   private static Logger theLogger;

   public static void setLogger(Logger aLogger)
   {
      theLogger = aLogger;
   }
}

When I started my application, I got the following exception:

=== 2011-10-27 14:51:31,040 [main] INFO  ISCInit - Isomorphic SmartClient Framework (SC_SNAPSHOT-2011-08-02/PowerEdition Deployment 2011-08-02) - Initialization Complete
=== 2011-10-27 14:51:31,041 [main] INFO  ISCInit - No ServletContext available yet - using container IO for now
Problem loading builtinTypes.xml
Exception when loading from __USE_CONTAINER__/productanalysisinterface/sc/system/schema/builtinTypes.xml:
java.io.IOException: Configured for containerIO, but servletContext not available!  You need to install the Init servlet
	at com.isomorphic.io.ISCFile.<init>(ISCFile.java:139)
	at com.isomorphic.store.ProcessedFileCache.getObjectFromFile(ProcessedFileCache.java:138)
	at com.isomorphic.xml.XML.getXMLDocument(XML.java:254)
	at com.isomorphic.xml.XML.toDSRecords(XML.java:262)
	at com.isomorphic.xml.XML.toDSRecords(XML.java:265)
	at com.isomorphic.datasource.DataSource.<clinit>(DataSource.java:544)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
	at org.springframework.beans.factory.config.MethodInvokingFactoryBean.doInvoke(MethodInvokingFactoryBean.java:162)
	at org.springframework.beans.factory.config.MethodInvokingFactoryBean.afterPropertiesSet(MethodInvokingFactoryBean.java:152)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1477)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:563)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
	at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:276)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:197)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:47)
	at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:543)
	at org.mortbay.jetty.servlet.Context.startContext(Context.java:136)
	at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1220)
	at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:513)
	at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:448)
	at com.google.gwt.dev.shell.jetty.JettyLauncher$WebAppContextWithReload.doStart(JettyLauncher.java:463)
	at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
	at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
	at org.mortbay.jetty.handler.RequestLogHandler.doStart(RequestLogHandler.java:115)
	at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
	at org.mortbay.jetty.handler.HandlerWrapper.doStart(HandlerWrapper.java:130)
	at org.mortbay.jetty.Server.doStart(Server.java:222)
	at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:39)
	at com.google.gwt.dev.shell.jetty.JettyLauncher.start(JettyLauncher.java:667)
	at com.google.gwt.dev.DevMode.doStartUpServer(DevMode.java:500)
	at com.google.gwt.dev.DevModeBase.startUp(DevModeBase.java:1055)
	at com.google.gwt.dev.DevModeBase.run(DevModeBase.java:804)
	at com.google.gwt.dev.DevMode.main(DevMode.java:309)

Yuck!! So what the heck happened? I definitely had the Init servlet correctly installed, and I had the __AUTO_DETECT__ value set in my server.properties file, so it shouldn’t have been trying to use the __USE_CONTAINER__ value. After MUCH digging around and testing this is what I think is going on. From what I found out about Spring, it uses two different classloaders when creating its container: one to parse and load classes found within the configuration file, and one to create instances from that file. When the application starts up, the Spring container is created via the entries I have in the web.xml:

<context-param>
   <param-name>contextConfigLocation</param-name>
   <param-value>/WEB-INF/classes/spring-config.xml</param-value>
</context-param>

<listener>
   <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>

Using its first classloader. After that, the SmartGWT framework attempts to create the DMI object using the app.xml file to access the Spring container to get the target bean object. This is where the problem occurs. The DMI loading is done via the Init servlet, and when it attempts to get an instance from the Spring container, that Class object has already been loaded and accessed by another classloader (the one doing the static logger setting), and gets confused, causing the error above.

To get around this, I simply changed my logger instance from a static attribute to an instance attribute, and adjusted the Spring configuration accordingly:

<bean id=”setMyDmiClassLogger” class=”org.springframework.beans.factory.config.MethodInvokingFactoryBean”>
   <property name=”targetObject”><ref local=”dmiBeanId”/></property>
   <property name=”targetMethod”><value>setLogger</value></property>
   <property name=”arguments”>
      <list>
         <ref bean=”dmiObjectLogger”/>
      </list>
   </property>
</bean>

When I restarted my application, the error disappeared. So, the moral of the story is that if you use Spring from within SmartGWT for the creation of SmartGWT objects for any reason (DMI object creation, static method calls on a custom datasource class), don’t call any static methods on them using the technique I’ve outlined above, or you’ll get the same error I did.

If anybody has a workaround for this, PLEASE let me know as I’d like to be able to call static methods on my classes if I need to.

Thanks

[RubenS]

I had a similar problem, maybe this can help:

In web.xml I try to delay spring loading until Init loaded

<!-- standard spring configuration -->
	<context-param>
		<param-name>contextConfigLocation</param-name>
		<param-value>/WEB-INF/spring-service.xml</param-value>
	</context-param>


	<!-- ISC init: initializes ISC framework -->
	<servlet>
		<servlet-name>Init</servlet-name>
		<servlet-class>com.isomorphic.base.Init</servlet-class>
		<load-on-startup>1</load-on-startup>
	</servlet>
	
	<!-- Delay the spring initialization -->
	<servlet>
		  <servlet-name>context</servlet-name>
		  <servlet-class>
				org.springframework.web.context.ContextLoaderServlet
		  </servlet-class>
		  <load-on-startup>5</load-on-startup>
	</servlet>

[toddblackwell]

Interesting. So the fact that you switched to the ContextLoaderServlet, and put it after the Init servlet definition delayed the Spring initialization? Hmmm. I'll have to try that.

Thanks!!!