Spring-boot: Hibernate 5.1.x(and 5.2.x) + weblogic transaction management broken

[apixandru]

Using spring boot 1.4.2.RELEASE and weblogic 12c

I have a sample project here
https://github.com/apixandru/case-study/tree/master/spring-hibernate-transactional

The link contains a project that uses spring boot and what i consider the spring-webmvc equivalent.

When using spring boot, it appears that transaction management is broken (inside weblogic) using hibernate 5.1.x or 5.2.x. However, this doesn't appear to be a problem in plain spring-webmvc

When downgrading to 5.0.x, it works perfectly fine with both

[apixandru]

The stacktrace for hibernate 5.1.x or hibernate 5.2.x in spring boot is

org.springframework.transaction.support.DefaultTransactionStatus@7fa5e611
2016-11-23 08:46:56.400 DEBUG 7691 --- [ (self-tuning)'] org.hibernate.SQL                        : select 1 from dual
2016-11-23 08:46:56.400  WARN 7691 --- [ (self-tuning)'] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2016-11-23 08:46:56.400 ERROR 7691 --- [ (self-tuning)'] o.h.engine.jdbc.spi.SqlExceptionHelper   : The transaction is no longer active - status: 'Rolled back. [Reason=weblogic.transaction.internal.AppSetRollbackOnlyException: setRollbackOnly called on transaction]'. No further JDBC access is allowed within this transaction.
2016-11-23 08:46:56.418 ERROR 7691 --- [ (self-tuning)'] o.s.boot.web.support.ErrorPageFilter     : Forwarding to error page from request [/combo] due to exception [org.hibernate.exception.GenericJDBCException: could not prepare statement]

javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not prepare statement
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) ~[hibernate-entitymanager-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) ~[hibernate-entitymanager-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:560) ~[hibernate-entitymanager-5.1.2.Final.jar:5.1.2.Final]
    at com.apixandru.casestudy.ExampleServiceImpl.executeOkQuery(ExampleServiceImpl.java:33) ~[spring-hibernate-transactional-common-1.0-SNAPSHOT.jar:na]
    at com.apixandru.casestudy.ExampleServiceImpl$$FastClassBySpringCGLIB$$5026cc7f.invoke(<generated>) ~[spring-hibernate-transactional-common-1.0-SNAPSHOT.jar:na]
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:720) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at com.apixandru.casestudy.ExampleServiceImpl$$EnhancerBySpringCGLIB$$48016fc5.executeOkQuery(<generated>) ~[spring-hibernate-transactional-common-1.0-SNAPSHOT.jar:na]
    at com.apixandru.casestudy.CaseStudyController.ok(CaseStudyController.java:20) ~[spring-hibernate-transactional-common-1.0-SNAPSHOT.jar:na]
    at com.apixandru.casestudy.CaseStudyController.combo(CaseStudyController.java:34) ~[spring-hibernate-transactional-common-1.0-SNAPSHOT.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_102]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_102]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_102]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_102]
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:844) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:280) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:254) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:136) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:346) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:25) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) [spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
    at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:61) [spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
    at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:92) [spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:110) [spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3436) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3402) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120) [com.oracle.css.weblogic.security.wls_7.1.0.0.jar:CSS 7.1 0.0]
    at weblogic.servlet.provider.WlsSubjectHandle.run(WlsSubjectHandle.java:57) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.WebAppServletContext.doSecuredExecute(WebAppServletContext.java:2285) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2201) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2179) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1572) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.servlet.provider.ContainerSupportProviderImpl$WlsRequestExecutor.run(ContainerSupportProviderImpl.java:255) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311) [weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.work.ExecuteThread.run(ExecuteThread.java:263) [weblogic.server.merged.jar:12.1.3.0.0]
Caused by: org.hibernate.exception.GenericJDBCException: could not prepare statement
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1934) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1903) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.doQuery(Loader.java:925) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.doList(Loader.java:2622) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.doList(Loader.java:2605) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.Loader.list(Loader.java:2429) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:336) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:1980) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.internal.AbstractSessionImpl.list(AbstractSessionImpl.java:322) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.internal.SQLQueryImpl.list(SQLQueryImpl.java:125) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606) ~[hibernate-entitymanager-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:529) ~[hibernate-entitymanager-5.1.2.Final.jar:5.1.2.Final]
    ... 66 common frames omitted
Caused by: java.sql.SQLException: The transaction is no longer active - status: 'Rolled back. [Reason=weblogic.transaction.internal.AppSetRollbackOnlyException: setRollbackOnly called on transaction]'. No further JDBC access is allowed within this transaction.
    at weblogic.jdbc.wrapper.JTSConnection.checkIfRolledBack(JTSConnection.java:202) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.jdbc.wrapper.JTSConnection.checkConnection(JTSConnection.java:214) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at weblogic.jdbc.wrapper.JTSConnection.prepareStatement(JTSConnection.java:560) ~[weblogic.server.merged.jar:12.1.3.0.0]
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172) ~[hibernate-core-5.1.2.Final.jar:5.1.2.Final]
    ... 82 common frames omitted

[snicoll]

It looks like the boundary of the transaction are wider and the transaction is still active (in setRollbackOnly mode) when ok is invoked in the second case. Since it breaks only with recent versions of Hibernate, have you considered reporting that issue there?

Also, please add the actuator and invoke /beans to see the definition of the transactionManager. I'd like to make sure the auto-config created the same transaction manager.

Thanks!

[apixandru]

The transactionManager bean is of type org.springframework.transaction.jta.WebLogicJtaTransactionManager

The resource is JndiJtaConfiguration which owns a JtaTransactionManagerFactoryBean (that returns the WebLogicJtaTransactionManager)

I didn't report it to hibernate yet because it seems to be working with spring webmvc (also with spring boot when using the embedded tomcat)

I think that there is something dubious in the jta integration layer.

[apixandru]

One discrepancy is that with spring mvc i configure the hibernate.transaction.jta.platform as org.hibernate.engine.transaction.jta.platform.internal.WeblogicJtaPlatform
but spring boot auto configures a SpringJtaPlatform ( i just tried overriding the spring jta platform to WeblogicJtaPlatform in the spring boot application but i still get that exception)

[snicoll]

Thanks @apixandru for the sample and the feedback

[apixandru]

I wanted to simplify even further so that the jndi oracle connection in weblogic wouldn't be necessary but if i try to use an embedded hsqldb instead, the issue doesn't happen

the way i got a quick oracle database to test was using wnameless/docker-oracle-xe-11g

[snicoll]

I appreciate all the efforts @apixandru. I need some time to setup weblogic and Oracle to figure out what is going on. I might bug you to test a few things on your side if that's ok?

[apixandru]

Please do, I'm happy to help.

I tried simplifying it a bit further by using the embedded tomcat to provide the jndi connection and having atomikos and bitronix as the jta user transaction provider but it's not reproducible there unfortunately.

So having the complex oracle + weblogic setup seems to be the best that i could come up so far that still exhibits the issue.

[apixandru]

(assuming use of docker-oracle-xe-11g)

I can't reproduce this using a simple datasource, so far this only happens using the jndi connection

spring:
  datasource:
    url: jdbc:oracle:thin:@localhost:49161:xe
    username: system
    password: oracle
    driverClassName: oracle.jdbc.OracleDriver

[apixandru]

issue is not reproducible using wildfly-10.1.0.Final instead of weblogic

[snicoll]

@apixandru, I am looking at the code and I am confused. You can't have a WeblogicJtaTransactionManager with Spring Boot since we have no auto-configuration for it.

The only thing we do (besides Atomikos, Bitronix and Narayana) is looking in JNDI. And that exposes a plain JtaTransactionManager.

Could you please add the following to SpringBootWeblogicApplication please?

@Bean
public WebLogicJtaTransactionManager jtaTransactionManager() {
    return new WebLogicJtaTransactionManager();
}

And check via /beans that the PlatformTransactionManager is defined by your spring boot app class.

Also, if you could join us on gitter when you have some time that would help.

[apixandru]

Sorry, I wrote it wrong before, I accidentally said that JtaAutoConfiguration configures the WebLogicJtaTransactionManager but it was actually JndiJtaConfiguration

The full server logs with debug mode enabled are available here

The /beans endpoint output is available here

[apixandru]

I adapted the webmvc project to be more like what is autoconfigured by boot but i'm still unable to reproduce the bug

[apixandru]

found the culprit
It seems that OpenEntityManagerInViewFilter is what causes this behavior.
Spring boot automatically adds it. When I manually added it to the webmvc setup, the transaction management broke there as well.

[snicoll]

Oh wow, good catch. OK, now we have to figure out if that's a regression in our Hibernate support or in Hibernate itself. Let me move this to spring framework for further analysis. Thanks a lot for the debugging session!

[snicoll]

Duplicates https://jira.spring.io/browse/SPR-14957