Spring DM + OpenEntityManagerInView pattern LazyInitialization exception

[jmclaughlin]

Hi,

I'm trying to implement the OEMIV pattern but am running into problems. I've spent a few days trawling forum posts, but am not much the wiser. Essentially the transaction manager doesn't seem to be aware of the opened session.

I'm using Hibernate as the JPA implementation, and have separate bundles implementing the data model, and the actual vendor specific DAO. I've configured the entitymanager and transaction manager in the Hibernate DAO bundle and exposed them as services thus (only posting relevant bits):

Bean declaration

	<bean id="testEMF" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
		<property name="dataSource" ref="testDS"/>
		<property name="persistenceUnitName" value="TestPU"/>
		<property name="jpaVendorAdapter">
			<bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter">
				 <property name="databasePlatform" value="org.hibernate.dialect.HSQLDialect"/> 
				 <property name="generateDdl" value="false"/>
				 <property name="showSql" value="true"/>
			</bean>
		</property>
	</bean>

	<bean id="testTM" class="org.springframework.orm.jpa.JpaTransactionManager">
		<property name="entityManagerFactory" ref="testEMF"/>
	</bean>

Service export

	<service ref="testTM" interface="org.springframework.transaction.PlatformTransactionManager"/>
	<service ref="testEMF" interface="javax.persistence.EntityManagerFactory"/>

I've defined my webapp application context in applicationContext.xml and test-console-servlet.xml with contents as follows (omitting namespace declarations):

applicationContext.xml

	<osgi:reference id="componentSvc"
		interface="org.tssg.test.dataaccess.service.ComponentService" />
		
	<osgi:reference id="testEMF"
		interface="javax.persistence.EntityManagerFactory" />

test-console-servlet.xml

	<context:component-scan base-package="org.tssg.test.web.dashboard.web" />
	
	<bean
		class="org.springframework.web.servlet.view.InternalResourceViewResolver"
		p:prefix="/WEB-INF/jsp/" p:suffix=".jsp" />

web.xml (relevant bits)

	<filter>
		<filter-name>openEntityManagerInViewFilter</filter-name>
		<filter-class>org.springframework.orm.jpa.support.OpenEntityManagerInViewFilter</filter-class>
		<init-param>
			<param-name>entityManagerFactoryBeanName</param-name>
			<param-value>testEMF</param-value>
		</init-param>
	</filter>

	<filter-mapping>
		<filter-name>openEntityManagerInViewFilter</filter-name>
		<url-pattern>*.do</url-pattern>
	</filter-mapping>

	<context-param>
		<param-name>contextClass</param-name>
		<param-value>com.springsource.server.web.dm.ServerOsgiBundleXmlWebApplicationContext</param-value>
	</context-param>

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

	<servlet>
		<servlet-name>test-console</servlet-name>
		<servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>
		<load-on-startup>2</load-on-startup>
	</servlet>

	<servlet-mapping>
		<servlet-name>test-console</servlet-name>
		<url-pattern>*.do</url-pattern>
	</servlet-mapping>

I'll post the log output in a reply, as if I include it here, I run into the 10k limit, so I'll comment on that there.

I've also attached a stripped down Maven project that should hopefully import cleanly if anybody wants to try it. I'm deploying to DM Server btw

(to be continued)

John McLaughlin

[jmclaughlin]

The logs extract below shows an attempt to access the page. OEMIV opens the EntityManager at the start, but when the transaction starts at 16:49:04.859, a new EntityManager is opened, then closed after the transaction, thus leading to the LIE.

Something that looks odd to me happens also at 16:49:08.390 where another raw Hibernate session is opened after the OEMIV filter exits. Should this be happening?

The clues I've picked up from other threads (I can't find them to link to at the moment unfortunately) lead me to suspect it's a class visibility issue, and that the transaction manager may not be seeing the same EntityManagerFactory as the filter. I've tried the Interceptor as well, with the same result.

stacktrace (most of stack dumps removed for size reasons)

[2010-05-11 16:49:04.796] http-8080-1 o.springframework.orm.jpa.support.OpenEntityManagerInViewFilter Using EntityManagerFactory 'testEMF' for OpenEntityManagerInViewFilter 
[2010-05-11 16:49:04.812] http-8080-1 o.springframework.orm.jpa.support.OpenEntityManagerInViewFilter Opening JPA EntityManager in OpenEntityManagerInViewFilter 
[2010-05-11 16:49:04.828] http-8080-1 org.springframework.web.servlet.DispatcherServlet DispatcherServlet with name 'test-console' determining Last-Modified value for [/test/test.do] 
[2010-05-11 16:49:04.843] http-8080-1 o.s.web.servlet.mvc.annotation.DefaultAnnotationHandlerMapping Mapping [/test.do] to handler 'org.tssg.test.web.dashboard.web.DashboardController@19bcf14' 
[2010-05-11 16:49:04.843] http-8080-1 org.springframework.web.servlet.DispatcherServlet Last-Modified value for [/test/test.do] is: -1 
[2010-05-11 16:49:04.843] http-8080-1 org.springframework.web.servlet.DispatcherServlet DispatcherServlet with name 'test-console' processing GET request for [/test/test.do] 
[2010-05-11 16:49:04.859] http-8080-1 o.s.web.bind.annotation.support.HandlerMethodInvoker Invoking request handler method: public void org.tssg.test.web.dashboard.web.DashboardController.dashboardHandler(org.springframework.ui.Model) 
[2010-05-11 16:49:04.859] http-8080-1 org.tssg.test.web.dashboard.web.DashboardController DashboardController::dashboardHandler() 
[2010-05-11 16:49:04.859] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Creating new transaction with name [org.tssg.test.dataaccess.service.ComponentService.getComponent]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly 
[2010-05-11 16:49:04.859] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@1b25799] for JPA transaction 
[2010-05-11 16:49:04.890] http-8080-1 org.hibernate.impl.SessionImpl opened session at timestamp: 12735929448 
[2010-05-11 16:49:04.890] http-8080-1 org.hibernate.transaction.JDBCTransaction begin 
[2010-05-11 16:49:04.890] http-8080-1 org.hibernate.jdbc.ConnectionManager opening JDBC connection 
[2010-05-11 16:49:04.890] http-8080-1 org.hibernate.transaction.JDBCTransaction current autocommit status: true 
[2010-05-11 16:49:04.890] http-8080-1 org.hibernate.transaction.JDBCTransaction disabling autocommit 
[2010-05-11 16:49:04.921] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: jdbc:hsqldb:hsql://localhost:9001, UserName=SA, HSQL Database Engine Driver] 
[2010-05-11 16:49:04.937] http-8080-1 org.hibernate.jdbc.AbstractBatcher about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 
[2010-05-11 16:49:04.937] http-8080-1 org.hibernate.SQL select top ? component0_.id as id0_, component0_.class_id as class3_0_, component0_.name as name0_ from component component0_ where component0_.name=? 
[2010-05-11 16:49:04.953] http-8080-1 org.hibernate.jdbc.AbstractBatcher about to open ResultSet (open ResultSets: 0, globally: 0) 
[2010-05-11 16:49:04.953] http-8080-1 org.hibernate.loader.Loader result row: EntityKey[org.tssg.test.dataaccess.domain.model.Component#1] 
[2010-05-11 16:49:04.953] http-8080-1 org.hibernate.jdbc.AbstractBatcher about to close ResultSet (open ResultSets: 1, globally: 1) 
[2010-05-11 16:49:04.953] http-8080-1 org.hibernate.jdbc.AbstractBatcher about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.engine.TwoPhaseLoad resolving associations for [org.tssg.test.dataaccess.domain.model.Component#1] 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.engine.TwoPhaseLoad done materializing entity [org.tssg.test.dataaccess.domain.model.Component#1] 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.engine.StatefulPersistenceContext initializing non-lazy collections 
[2010-05-11 16:49:04.968] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Initiating transaction commit 
[2010-05-11 16:49:04.968] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@1b25799] 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.transaction.JDBCTransaction commit 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.transaction.JDBCTransaction re-enabling autocommit 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.transaction.JDBCTransaction committed JDBC Connection 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.jdbc.ConnectionManager aggressively releasing JDBC connection 
[2010-05-11 16:49:04.968] http-8080-1 org.hibernate.jdbc.ConnectionManager releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 
[2010-05-11 16:49:04.968] http-8080-1 org.springframework.orm.jpa.JpaTransactionManager Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@1b25799] after transaction 
[2010-05-11 16:49:04.968] http-8080-1 org.springframework.orm.jpa.EntityManagerFactoryUtils Closing JPA EntityManager 
[2010-05-11 16:49:04.984] http-8080-1 org.springframework.web.servlet.DispatcherServlet Rendering view [org.springframework.web.servlet.view.JstlView: name 'test'; URL [/WEB-INF/jsp/test.jsp]] in DispatcherServlet with name 'test-console' 
[2010-05-11 16:49:04.984] http-8080-1 org.springframework.web.servlet.view.JstlView Added model object 'c' of type [org.tssg.test.dataaccess.domain.model.Component] to request in view with name 'test' 
[2010-05-11 16:49:04.984] http-8080-1 org.springframework.web.servlet.view.JstlView Added model object 'org.springframework.validation.BindingResult.c' of type [org.springframework.validation.BeanPropertyBindingResult] to request in view with name 'test' 
[2010-05-11 16:49:05.000] http-8080-1 org.springframework.web.servlet.view.JstlView Forwarding to resource [/WEB-INF/jsp/test.jsp] in InternalResourceView 'test' 
[2010-05-11 16:49:08.359] http-8080-1 org.hibernate.LazyInitializationException could not initialize proxy - no Session org.hibernate.LazyInitializationException: could not initialize proxy - no Session
	at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:132)
	at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:174)
	at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:190)
	at org.tssg.test.dataaccess.domain.model.ComponentClass_$$_javassist_1.getName(ComponentClass_$$_javassist_1.java)
    :

[2010-05-11 16:49:08.375] http-8080-1 o.a.c.core.ContainerBase.[Catalina].[localhost].[/test].[jsp] Servlet.service() for servlet jsp threw exception org.hibernate.LazyInitializationException: could not initialize proxy - no Session
    :

[2010-05-11 16:49:08.390] http-8080-1 org.springframework.web.servlet.DispatcherServlet Could not complete request org.apache.jasper.JasperException: An exception occurred processing JSP page /WEB-INF/jsp/test.jsp at line 21
18: 
19: Component ID : <c:out value="${c.id}"/><br/>
20: Component name : '<c:out value="${c.name}"/>'<br/>
21: Class : '<c:out value="${c.componentClass.name}"/>'<br/>
22: </div>	
23: 
24:   </div>
Stacktrace:
    :
[2010-05-11 16:49:08.390] http-8080-1 o.springframework.orm.jpa.support.OpenEntityManagerInViewFilter Closing JPA EntityManager in OpenEntityManagerInViewFilter 
[2010-05-11 16:49:08.390] http-8080-1 org.springframework.orm.jpa.EntityManagerFactoryUtils Closing JPA EntityManager 
[2010-05-11 16:49:08.390] http-8080-1 org.hibernate.impl.SessionImpl opened session at timestamp: 12735929483 
[2010-05-11 16:49:08.390] http-8080-1 o.a.c.c.C.[Catalina].[localhost].[/test].[test-console] Servlet.service() for servlet test-console threw exception org.hibernate.LazyInitializationException: could not initialize proxy - no Session

I'm guessing I've got some configuration issue, but can't for the life of me see what. Any help much appreciated, and if there's anything else I can provide in terms of extra logging output, manifests etc let me know!

I'm using DM Server 2.0.1 RELEASE, which in turn uses Spring framework 3.0.0.RELEASE.

Regards,

John

[jmclaughlin]

Hi all,

I've come back to this problem as I've got no further tinkering with configurations. I tried to externalise the EntityManagerFactory as suggest in this thread to no avail.

To try to get to the bottom of the problem, I've started to single step through the code for JpaTransactionManager, and OpenEntityManagerInViewFilter and have found what may be a bug.

Both EntityManagerInViewFilter and JpaTransactionManager make use of TransactionSynchronizationManager and use the EntityManagerFactory as a key. Both TransactionSynchronizationManager.bindResource() and TransactionSynchronizationManager.getResource() call TransactionSynchronizationUtils.unwrapResourceIfNe cessary() with the EMF bean (proxies in both cases). That method is shown here:

static Object unwrapResourceIfNecessary(Object resource) {
		Assert.notNull(resource, "Resource must not be null");
		Object resourceRef = resource;
		// unwrap infrastructure proxy
		if (resourceRef instanceof InfrastructureProxy) {
			resourceRef = ((InfrastructureProxy) resourceRef).getWrappedObject();
		}
		if (aopAvailable) {
			// now unwrap scoped proxy
			resourceRef = ScopedProxyUnwrapper.unwrapIfNecessary(resource);
		}
		return resourceRef;
	}

A sample of what happens is as follows. For OEMIVF, the resource is for example $Proxy283. After calling ((InfrastructureProxy) resourceRef).getWrappedObject() resourceRef is $Proxy270. For JpaTM resource is $Proxy269, and post unwrapping resourceRef is $Proxy270.

This would be wonderful if these were returned at this point, HOWEVER the method trundles on to

resourceRef = ScopedProxyUnwrapper.unwrapIfNecessary(resource)

which results in resourceRef being trampled by the original resource param, as the bean in question isn't and AOP proxy and thus not unwrapped in the SPU unwrap method.

Is this a bug or a "feature"? If the former, should I raise a JIRA, and if the latter (actually in either case), can anybody suggest a workaround?

DM Server version is 2.0.1-RELEASE implying Spring Framework 3.0.0-RELEASE and Spring DM 1.2.1

Regards,

John

[jmclaughlin]

Sigh. To answer my own question it's a bug. It's fixed as of version 3.0.1-RELEASE of the framework, but dm Server 2.0.1 uses 3.0.0-RELEASE, so this is an issue

I've verified by rebuilding 3.0.0-RELEASE with ScopedProxyUnwrapper.unwrapIfNecessary(resource) changed to ScopedProxyUnwrapper.unwrapIfNecessary(resourceRef ) and copying the transaction jar into dm Server repository. At this point OpenEntityManagerInViewFilter will work. I presume the interceptor will work as well, but I'll leave that as an exercise to somebody else.

I also presume the same will apply to anybody using the OpenSessionInView patterns

I'll raise a JIRA for dm Server, and update this post, which might help somebody

John