[
https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin...
]
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)