[jboss-jira] [JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged

Scott Marlow (Jira) issues at jboss.org
Wed Apr 17 13:45:00 EDT 2019 

    [ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13723986#comment-13723986 ] 

Scott Marlow commented on WFLY-11213:
-------------------------------------

I recreated locally with the attached test case, call stack showing when the "HHH000010: On release of batch it still contained JDBC statements" is logged is below:

{code}
	  at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.release(AbstractBatchImpl.java:201)
	  at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.abortBatch(JdbcCoordinatorImpl.java:221)
	  at org.hibernate.internal.JdbcObserverImpl.jdbcReleaseRegistryResourcesStart(JdbcObserverImpl.java:89)
	  at org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl.releaseResources(ResourceRegistryStandardImpl.java:305)
	  at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:204)
	  at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.afterStatement(LogicalConnectionManagedImpl.java:149)
	  at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterStatementExecution(JdbcCoordinatorImpl.java:279)
	  at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.releaseStatements(AbstractBatchImpl.java:158)
	  at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:150)
	  at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:212)
	  at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633)
	  at org.hibernate.engine.spi.ActionQueue.executeInserts(ActionQueue.java:461)
	  at org.hibernate.engine.spi.ActionQueue.addInsertAction(ActionQueue.java:258)
	  at org.hibernate.engine.spi.ActionQueue.addAction(ActionQueue.java:317)
	  at org.hibernate.event.internal.AbstractSaveEventListener.addInsertAction(AbstractSaveEventListener.java:332)
	  at org.hibernate.event.internal.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:289)
	  at org.hibernate.event.internal.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:196)
	  at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:127)
	  at org.hibernate.event.internal.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:192)
	  at org.hibernate.event.internal.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:135)
	  at org.hibernate.event.internal.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:62)
	  at org.hibernate.internal.SessionImpl.firePersist(SessionImpl.java:799)
	  at org.hibernate.internal.SessionImpl.persist(SessionImpl.java:784)
	  at org.jboss.as.jpa.container.AbstractEntityManager.persist(AbstractEntityManager.java:580)
	  at demo.CommentActions.create(CommentActions.java:19)
	  at demo.CommentActions$Proxy$_$$_WeldSubclass.create$$super(Unknown Source:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51)
	  at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:186)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorMandatory.doIntercept(TransactionalInterceptorMandatory.java:59)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:88)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorMandatory.intercept(TransactionalInterceptorMandatory.java:51)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
	  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
	  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
	  at demo.CommentActions$Proxy$_$$_WeldSubclass.create(Unknown Source:-1)
	  at demo.CommentActions$Proxy$_$$_WeldClientProxy.create(Unknown Source:-1)
	  at demo.DemoActions.execute(DemoActions.java:19)
	  at demo.DemoActions$Proxy$_$$_WeldSubclass.execute$$super(Unknown Source:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51)
	  at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:174)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:53)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:88)
	  at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:47)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
	  at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
	  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
	  at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
	  at demo.DemoActions$Proxy$_$$_WeldSubclass.execute(Unknown Source:-1)
	  at demo.DemoActions$Proxy$_$$_WeldClientProxy.execute(Unknown Source:-1)
	  at demo.Demo.execute(Demo.java:16)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at javax.el.ELUtil.invokeMethod(ELUtil.java:311)
	  at javax.el.BeanELResolver.invoke(BeanELResolver.java:415)
	  at javax.el.CompositeELResolver.invoke(CompositeELResolver.java:256)
	  at com.sun.el.parser.AstValue.invoke(AstValue.java:261)
	  at com.sun.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:280)
	  at org.jboss.weld.module.web.util.el.ForwardingMethodExpression.invoke(ForwardingMethodExpression.java:40)
	  at org.jboss.weld.module.web.el.WeldMethodExpression.invoke(WeldMethodExpression.java:50)
	  at org.jboss.weld.module.web.util.el.ForwardingMethodExpression.invoke(ForwardingMethodExpression.java:40)
	  at org.jboss.weld.module.web.el.WeldMethodExpression.invoke(WeldMethodExpression.java:50)
	  at com.sun.faces.facelets.el.TagMethodExpression.invoke(TagMethodExpression.java:65)
	  at com.sun.faces.application.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:66)
	  at com.sun.faces.application.ActionListenerImpl.getNavigationOutcome(ActionListenerImpl.java:82)
	  at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:71)
	  at javax.faces.component.UICommand.broadcast(UICommand.java:222)
	  at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:847)
	  at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:1395)
	  at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:58)
	  at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:76)
	  at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:177)
	  at javax.faces.webapp.FacesServlet.executeLifecyle(FacesServlet.java:707)
	  at javax.faces.webapp.FacesServlet.service(FacesServlet.java:451)
	  at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
	  at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
	  at io.opentracing.contrib.jaxrs2.server.SpanFinishingFilter.doFilter(SpanFinishingFilter.java:55)
	  at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	  at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	  at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
	  at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
	  at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
	  at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
	  at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
	  at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	  at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
	  at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
	  at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	  at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
	  at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
	  at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
	  at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
	  at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
	  at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
	  at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	  at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
	  at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	  at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68)
	  at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	  at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
	  at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
	  at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
	  at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
	  at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
	  at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	  at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
	  at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$838.947810661.call(Unknown Source:-1)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$839.457346356.call(Unknown Source:-1)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$839.457346356.call(Unknown Source:-1)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$839.457346356.call(Unknown Source:-1)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$839.457346356.call(Unknown Source:-1)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
	  at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$839.457346356.call(Unknown Source:-1)
	  at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
	  at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
	  at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
	  at io.undertow.server.Connectors.executeRootHandler(Connectors.java:364)
	  at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
	  at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	  at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
	  at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	  at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	  at java.lang.Thread.run(Thread.java:748)
{code}

Statements.size = 1
Statements entry [0] = "insert into EventLog (message, id) values (?, ?)" -> 

>From a quick look at the call stack, I'm not suprised that org.hibernate.internal.JdbcObserverImpl.jdbcReleaseRegistryResourcesStart() is calling org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.abortBatch() which calls org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.release(), so this may be a case of incorrect logging.

[~gbadner] the test case for [https://hibernate.atlassian.net/browse/HHH-13307] is in the form of a WildFly test case, as described above in the description.  I just verified that the test case does reproduce the incorrect logging of message "On release of batch it still contained JDBC statements".  Please see call stack ^ for when this message is logged (while running the jpa-batch-release test case).



> On release of batch it still contained JDBC statements logged
> -------------------------------------------------------------
>
>                 Key: WFLY-11213
>                 URL: https://issues.jboss.org/browse/WFLY-11213
>             Project: WildFly
>          Issue Type: Bug
>          Components: JPA / Hibernate
>    Affects Versions: 14.0.1.Final
>         Environment: Java 8_181
> Wildfly 14.0.1.Final
>            Reporter: Cody Lerum
>            Assignee: Scott Marlow
>            Priority: Major
>
> After updating from Wildfly 11 (Hibernate 5.1.10) to Wildfly 14.0.1 (Hibernate 5.3.6) I've started seeing the following log messages
> I’m starting to see the log message
> {code:java}
> 2018-10-17 20:12:47,571 INFO  [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-54) HHH000010: On release of batch it still contained JDBC statements
> 2018-10-17 20:12:47,572 ERROR [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default task-54) HHH000352: Unable to release batch statement...
> {code}
> I’ve debugged where that is getting logged and all I can find is a single statement at the time.
> insert into EventLog (entityId, entityType, ipAddress, message, time, user, id) values (?, ?, ?, ?, ?, ?, ?)
> The only insert that is being created is actually being persisted to the database so this may be a spurious message.
> From my early debugging this appears to happen when 1 entity is persisted which does not need an immediate inset (due to having a generated pk) and then in another method of the same transaction an entity is persisted that does need an immediate insert because of a auto increment pk.



--
This message was sent by Atlassian Jira
(v7.12.1#712002)

More information about the jboss-jira mailing list