Transaction management fails when using AspectJ and load-time weaving [SPR-6392]

[spring-projects-issues]

Thomas Risberg opened SPR-6392 and commented

Having issues running the 2.5.6 sample application using AspectJ and load-time weaving for the transaction support. This showed up during testing of JPA on JBoss but it also happens on Tomcat 6.0.

Steps to reproduce:

download and extract:
spring-framework-2.5.6.SEC01-with-dependencies.zip
apache-tomcat-6.0.20.tar.gz

set up and configure the HSQL db

modify:
war/WEB-INF/web.xml - change to use /WEB-INF/application-context-jpa.xml instead of the jdbc one
war/META-INF/context.xml - un-comment the class loader entry

copy:
spring-tomcat-weaver.jar to ~/apache-tomcat-6.0.20/lib

run:
ant warfile

copy:
dist/petclinic.war to ~/apache-tomcat-6.0.20/webapps

open a browser ant point to http://localhost:8080/petclinic
go to "Find owner" screen and click [FIND OWNERS]
from the list click on one and on the edit screen click [EDIT OWNER]
then click [UPDATE OWNER]

Sometimes it works on the first deploy but I usually see the following error on subsequent deploys:

Data access failure: Exception Description: No transaction is currently active; nested exception is javax.persistence.TransactionRequiredException: Exception Description: No transaction is currently active

org.springframework.dao.InvalidDataAccessApiUsageException: Exception Description: No transaction is currently active; nested exception is javax.persistence.TransactionRequiredException: Exception Description: No transaction is currently active at org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:291) at org.springframework.orm.jpa.DefaultJpaDialect.translateExceptionIfPossible(DefaultJpaDialect.java:120) at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:352) at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:62) at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:212) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:146) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy19.storeOwner(Unknown Source) at org.springframework.samples.petclinic.web.EditOwnerForm.processSubmit(EditOwnerForm.java:56) 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.web.bind.annotation.support.HandlerMethodInvoker.doInvokeMethod(HandlerMethodInvoker.java:421) at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:136) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:326) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:313) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:875) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454) at java.lang.Thread.run(Thread.java:619) Caused by: javax.persistence.TransactionRequiredException: Exception Description: No transaction is currently active at oracle.toplink.essentials.internal.ejb.cmp3.transaction.EntityTransactionWrapper.throwCheckTransactionFailedException(EntityTransactionWrapper.java:70) at oracle.toplink.essentials.internal.ejb.cmp3.transaction.base.EntityTransactionWrapper.checkForTransaction(EntityTransactionWrapper.java:62) at oracle.toplink.essentials.internal.ejb.cmp3.base.EntityManagerImpl.checkForTransaction(EntityManagerImpl.java:616) at oracle.toplink.essentials.internal.ejb.cmp3.base.EntityManagerImpl.flush(EntityManagerImpl.java:335) 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.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:358) at $Proxy16.flush(Unknown Source) 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.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:198) at $Proxy16.flush(Unknown Source) at org.springframework.samples.petclinic.jpa.EntityManagerClinic.storeOwner(EntityManagerClinic.java:70) 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.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:138) ... 30 more

---

Affects: 2.5.6, 3.0 RC2

Attachments:

• spr-6392-test.zip (1.98 kB)

Issue Links:

• TransactionSynchronizationUtils.unwrapResourceIfNecessary() overwrites InfrastructureProxy.getWrappedObject() results [SPR-6625] #11291 TransactionSynchronizationUtils.unwrapResourceIfNecessary() overwrites InfrastructureProxy.getWrappedObject() results
• Investigate issues around local resource transaction management in JBoss 5.1 [SPR-6318] #10984 Investigate issues around local resource transaction management in JBoss 5.1

4 votes, 5 watchers

[spring-projects-issues]

Costin Leau commented

The same problem occurs on Spring 3.0 as well.

[spring-projects-issues]

Michael Pilquist commented

I'm seeing the same problem after upgrading from Spring 3.0.0.RC1 to 3.0.0.RELEASE. Here's some trace logging from o.sfw.{transaction, orm} packages -- note the log from Hibernate indicating that there's no active transaction:

DEBUG [on.annotation.AnnotationTransactionAttributeSource] - Adding transactional method [persistTest] with attribute [PROPAGATION_REQUIRED,ISOLATION_DEFAULT]
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Creating new transaction with name [foo.persistTest]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@2069a6cb] for JPA transaction
DEBUG [ org.hibernate.impl.SessionImpl] - opened session at timestamp: 12610691887
DEBUG [ org.hibernate.transaction.JDBCTransaction] - begin
DEBUG [ org.hibernate.jdbc.ConnectionManager] - opening JDBC connection
DEBUG [ org.hibernate.transaction.JDBCTransaction] - current autocommit status: true
DEBUG [ org.hibernate.transaction.JDBCTransaction] - disabling autocommit
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mchange.v2.c3p0.impl.NewProxyConnection@65cc892e]
DEBUG [on.annotation.AnnotationTransactionAttributeSource] - Adding transactional method [persist] with attribute [PROPAGATION_REQUIRED,ISOLATION_DEFAULT]
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl@2069a6cb] for JPA transaction
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Participating in existing transaction
DEBUG [.springframework.orm.jpa.EntityManagerFactoryUtils] - Opening JPA EntityManager
DEBUG [.springframework.orm.jpa.EntityManagerFactoryUtils] - Registering transaction synchronization for JPA EntityManager
DEBUG [ org.hibernate.impl.SessionImpl] - opened session at timestamp: 12610691888
DEBUG [ org.hibernate.event.def.AbstractSaveEventListener] - delaying identity-insert due to no transaction in progress
DEBUG [.springframework.orm.jpa.EntityManagerFactoryUtils] - Closing JPA EntityManager
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Initiating transaction commit
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@2069a6cb]
DEBUG [ org.hibernate.transaction.JDBCTransaction] - commit
DEBUG [ org.hibernate.transaction.JDBCTransaction] - re-enabling autocommit
DEBUG [ org.hibernate.transaction.JDBCTransaction] - committed JDBC Connection
DEBUG [ org.hibernate.jdbc.ConnectionManager] - aggressively releasing JDBC connection
DEBUG [ org.hibernate.jdbc.ConnectionManager] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG [ org.springframework.orm.jpa.JpaTransactionManager] - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@2069a6cb] after transaction
DEBUG [.springframework.orm.jpa.EntityManagerFactoryUtils] - Closing JPA EntityManager

[spring-projects-issues]

Michael Pilquist commented

I should have mentioned that I'm experiencing this issue with compile-time weaving via ajc.

[spring-projects-issues]

Costin Leau commented

Hi Michael,

Did things work for you in 3.0.0.RC1 as opposed to RELEASE?

[spring-projects-issues]

Michael Pilquist commented

Yep, worked with 3.0.0.RC1. After further debugging of this issue, it looks like my issue was caused by #11291. Each bundle imports the transaction manager but due to the missing unwrapping, I ended up with multiple entity managers opened in the same transaction, and only one of those getting flushed.

[spring-projects-issues]

Costin Leau commented

Michael, could you try testing against AspectJ 1.6.8? I can reproduce the issue against Spring 3.0.0 with AspectJ 1.6.5 but upgrading to 1.6.8 solves the issue. I'm using load-time weaving but I don't think this impacts the tx aspect in any way.

[spring-projects-issues]

Michael Pilquist commented

In my case, I traced the execution in the debugger and verified the aspect was applied successfully. But due to the resourceRef unwrapping issue, the thread local map of entity managers had an entry for each bundle.

Here's a project that shows the aspect application using AspectJ 1.6.5. I get the same results with AspectJ 1.6.8.

After building attached project, run javap to see the transaction aspect application:

spr-6392-test$ javap -classpath target/classes -c test.App
Compiled from "App.java"
public class test.App extends java.lang.Object{
public test.App();
  Code:
   0:	aload_0
   1:	invokespecial	#8; //Method java/lang/Object."<init>":()V
   4:	return

public static void main(java.lang.String[]);
  Code:
   0:	getstatic	#17; //Field java/lang/System.out:Ljava/io/PrintStream;
   3:	ldc	#23; //String Hello World!
   5:	invokevirtual	#25; //Method java/io/PrintStream.println:(Ljava/lang/String;)V
   8:	return

public void txMethod();
  Code:
   0:	invokestatic	#46; //Method org/springframework/transaction/aspectj/AnnotationTransactionAspect.aspectOf:()Lorg/springframework/transaction/aspectj/AnnotationTransactionAspect;
   3:	aload_0
   4:	getstatic	#48; //Field ajc$tjp_0:Lorg/aspectj/lang/JoinPoint$StaticPart;
   7:	invokevirtual	#54; //Method org/springframework/transaction/aspectj/AbstractTransactionAspect.ajc$before$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96c:(Ljava/lang/Object;Lorg/aspectj/lang/JoinPoint$StaticPart;)V
   10:	goto	24
   13:	astore_1
   14:	invokestatic	#46; //Method org/springframework/transaction/aspectj/AnnotationTransactionAspect.aspectOf:()Lorg/springframework/transaction/aspectj/AnnotationTransactionAspect;
   17:	aload_0
   18:	aload_1
   19:	invokevirtual	#58; //Method org/springframework/transaction/aspectj/AbstractTransactionAspect.ajc$afterThrowing$org_springframework_transaction_aspectj_AbstractTransactionAspect$2$2a73e96c:(Ljava/lang/Object;Ljava/lang/Throwable;)V
   22:	aload_1
   23:	athrow
   24:	invokestatic	#46; //Method org/springframework/transaction/aspectj/AnnotationTransactionAspect.aspectOf:()Lorg/springframework/transaction/aspectj/AnnotationTransactionAspect;
   27:	aload_0
   28:	invokevirtual	#62; //Method org/springframework/transaction/aspectj/AbstractTransactionAspect.ajc$afterReturning$org_springframework_transaction_aspectj_AbstractTransactionAspect$3$2a73e96c:(Ljava/lang/Object;)V
   31:	goto	44
   34:	astore_2
   35:	invokestatic	#46; //Method org/springframework/transaction/aspectj/AnnotationTransactionAspect.aspectOf:()Lorg/springframework/transaction/aspectj/AnnotationTransactionAspect;
   38:	aload_0
   39:	invokevirtual	#65; //Method org/springframework/transaction/aspectj/AbstractTransactionAspect.ajc$after$org_springframework_transaction_aspectj_AbstractTransactionAspect$4$2a73e96c:(Ljava/lang/Object;)V
   42:	aload_2
   43:	athrow
   44:	invokestatic	#46; //Method org/springframework/transaction/aspectj/AnnotationTransactionAspect.aspectOf:()Lorg/springframework/transaction/aspectj/AnnotationTransactionAspect;
   47:	aload_0
   48:	invokevirtual	#65; //Method org/springframework/transaction/aspectj/AbstractTransactionAspect.ajc$after$org_springframework_transaction_aspectj_AbstractTransactionAspect$4$2a73e96c:(Ljava/lang/Object;)V
   51:	return
  Exception table:
   from   to  target type
     0    13    13   Class java/lang/Throwable

     0    34    34   Class java/lang/Throwable


static {};
  Code:
   0:	new	#69; //class org/aspectj/runtime/reflect/Factory
   3:	dup
   4:	ldc	#70; //String App.java
   6:	ldc	#72; //String test.App
   8:	invokestatic	#78; //Method java/lang/Class.forName:(Ljava/lang/String;)Ljava/lang/Class;
   11:	invokespecial	#81; //Method org/aspectj/runtime/reflect/Factory."<init>":(Ljava/lang/String;Ljava/lang/Class;)V
   14:	astore_0
   15:	aload_0
   16:	ldc	#83; //String method-execution
   18:	aload_0
   19:	ldc	#85; //String 1
   21:	ldc	#86; //String txMethod
   23:	ldc	#72; //String test.App
   25:	ldc	#88; //String 
   27:	ldc	#88; //String 
   29:	ldc	#88; //String 
   31:	ldc	#90; //String void
   33:	invokevirtual	#94; //Method org/aspectj/runtime/reflect/Factory.makeMethodSig:(Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Lorg/aspectj/lang/reflect/MethodSignature;
   36:	bipush	17
   38:	invokevirtual	#98; //Method org/aspectj/runtime/reflect/Factory.makeSJP:(Ljava/lang/String;Lorg/aspectj/lang/Signature;I)Lorg/aspectj/lang/JoinPoint$StaticPart;
   41:	putstatic	#48; //Field ajc$tjp_0:Lorg/aspectj/lang/JoinPoint$StaticPart;
   44:	return

}

[spring-projects-issues]

Costin Leau commented

I think we are looking at different issues - one regarding proxy unwrapping (which shows up in OSGi I presume) and one that occurs in traditional environments (as mentioned in the initial description). I'll try the latest Spring snapshot and see whether I can reproduce the AJ 1.6.5 vs 1.6.8 issue.

[spring-projects-issues]

Thomas Risberg commented

I tried PetClinic with AspectJ 1.6.8 and I can no longer reproduce the error, so it looks like whatever issue got triggered is no longer there when using AspectJ 1.6.8.

[spring-projects-issues]

Costin Leau commented

After several debugging sessions, it seems that the aspect is not applied for some reason on storeOwner method. At this point, I don't know why this happens, as Thomas pointed out sometimes the method is ignored from the first deployment, sometimes after redeploy. I've tried AJ 1.6.2 to 1.6.5 and they all exposed the same behaviour.
AJ 1.6.8 however did not.
The only reliable fix I can suggest for now thus is to use AJ 1.6.8 - it might be that other versions, such as 1.6..6 and 1.6.7 but I haven't tested them.

[spring-projects-issues]

Costin Leau commented

After talking with Andy Clement we got to the bottom of this. Upgrading to AspectJ 1.6.6 or 1.6.8 solves the problem as there was a weaving bug that got fixed since 1.6.6 (see https://bugs.eclipse.org/bugs/show_bug.cgi?id=285172 for more details).