[
https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin...
]
Scott Marlow commented on WFLY-11213:
-------------------------------------
I'm trying your app on WildFly master, which is currently using Hibernate ORM
5.3.7.Final. I also enabled TRACE logging for org.jboss.as.jpa, as I like to see what is
going on, with regard to JTA + JPA. TRACE log output from pressing the execute button
once is:
{code}
10:53:02,061 INFO [stdout] (default task-1) Executing
10:53:02,163 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: created entity manager session Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffff0a0000b0:-4f2abb39:5bc89e39:10
status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA
transaction provider)
10:53:02,169 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
10:53:02,205 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 1
for default task-1:transaction scoped EntityManager [demo.war#primary]:
10:53:02,205 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
10:53:02,207 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 1
for default task-1:transaction scoped EntityManager [demo.war#primary]:
10:53:02,217 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.EventLog' took 126ms
10:53:02,218 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: reuse entity manager session already in tx Local
transaction (delegate=TransactionImple < ac, BasicAction:
0:ffff0a0000b0:-4f2abb39:5bc89e39:10 status: ActionStatus.RUNNING >, owner=Local
transaction context for provider JBoss JTA transaction provider)
10:53:02,218 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.EventLog' took 0ms
10:53:02,219 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: reuse entity manager session already in tx Local
transaction (delegate=TransactionImple < ac, BasicAction:
0:ffff0a0000b0:-4f2abb39:5bc89e39:10 status: ActionStatus.RUNNING >, owner=Local
transaction context for provider JBoss JTA transaction provider)
10:53:02,252 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default
task-1) HHH000010: On release of batch it still contained JDBC statements
10:53:02,252 ERROR [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default
task-1) HHH000352: Unable to release batch statement...
10:53:02,260 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.Comment' took 41ms
10:53:02,261 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
10:53:02,264 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: closing entity managersession
{code}
From the above logging output, it looks like WildFly is associating
the entity manager with the JTA transaction, so I think that the JPA container is doing
the integration correctly.
I then enabled TRACE logging for org.hibernate as well, so we have a bit more information
about what happened the second time that I pressed "execute":
{code}
11:12:06,389 INFO [stdout] (default task-1) Executing
11:12:06,423 TRACE [org.hibernate.internal.SessionFactoryImpl$SessionBuilderImpl] (default
task-1) Opening Hibernate Session. tenant=null, owner=null
11:12:06,463 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl]
(default task-1) Hibernate RegisteredSynchronization successfully registered with JTA
platform
11:12:06,477 TRACE [org.hibernate.service.internal.AbstractServiceRegistryImpl] (default
task-1) Initializing service [role=org.hibernate.stat.spi.StatisticsImplementor]
11:12:06,480 DEBUG [org.hibernate.stat.internal.StatisticsInitiator] (default task-1)
Statistics initialized [enabled=false]
11:12:06,485 TRACE [org.hibernate.internal.SessionImpl] (default task-1) Opened Session
[18610f50-983f-4d05-b2fc-c3b915129a98] at timestamp: 1539875526463
11:12:06,486 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: created entity manager session Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffff0a0000b0:38e96acf:5bc8a29e:11
status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA
transaction provider)
11:12:06,487 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Transient instance of: demo.EventLog
11:12:06,488 TRACE [org.hibernate.event.internal.DefaultPersistEventListener] (default
task-1) Saving transient instance
11:12:06,490 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
11:12:06,490 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate] (default
task-1) Surrounding JTA transaction suspended [Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffff0a0000b0:38e96acf:5bc8a29e:11
status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA
transaction provider)]
11:12:06,501 DEBUG [org.hibernate.SQL] (default task-1) select tbl.next_val from
primaryKeyPools tbl where tbl.sequence_name=? for update
11:12:06,511 DEBUG [org.hibernate.SQL] (default task-1) update primaryKeyPools set
next_val=? where next_val=? and sequence_name=?
11:12:06,512 TRACE [org.hibernate.id.IdentifierGeneratorHelper] (default task-1) binding
parameter [1] - [500]
11:12:06,513 TRACE [org.hibernate.id.IdentifierGeneratorHelper] (default task-1) binding
parameter [2] - [0]
11:12:06,518 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 1
for default task-1:transaction scoped EntityManager [demo.war#primary]:
11:12:06,518 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate] (default
task-1) Surrounding JTA transaction resumed [Local transaction (delegate=TransactionImple
< ac, BasicAction: 0:ffff0a0000b0:38e96acf:5bc8a29e:11 status: ActionStatus.RUNNING
>, owner=Local transaction context for provider JBoss JTA transaction provider)]
11:12:06,518 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
11:12:06,518 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate] (default
task-1) Surrounding JTA transaction suspended [Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffff0a0000b0:38e96acf:5bc8a29e:11
status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA
transaction provider)]
11:12:06,519 DEBUG [org.hibernate.SQL] (default task-1) select tbl.next_val from
primaryKeyPools tbl where tbl.sequence_name=? for update
11:12:06,519 DEBUG [org.hibernate.SQL] (default task-1) update primaryKeyPools set
next_val=? where next_val=? and sequence_name=?
11:12:06,519 TRACE [org.hibernate.id.IdentifierGeneratorHelper] (default task-1) binding
parameter [1] - [1000]
11:12:06,520 TRACE [org.hibernate.id.IdentifierGeneratorHelper] (default task-1) binding
parameter [2] - [500]
11:12:06,520 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 1
for default task-1:transaction scoped EntityManager [demo.war#primary]:
11:12:06,520 DEBUG
[org.hibernate.resource.transaction.backend.jta.internal.JtaIsolationDelegate] (default
task-1) Surrounding JTA transaction resumed [Local transaction (delegate=TransactionImple
< ac, BasicAction: 0:ffff0a0000b0:38e96acf:5bc8a29e:11 status: ActionStatus.RUNNING
>, owner=Local transaction context for provider JBoss JTA transaction provider)]
11:12:06,521 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Generated identifier: 1, using strategy: org.hibernate.id.enhanced.TableGenerator
11:12:06,522 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Saving [demo.EventLog#1]
11:12:06,529 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding an
EntityInsertAction for [demo.EventLog] object
11:12:06,530 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding insert
with no non-nullable, transient entities: [EntityInsertAction[demo.EventLog#1]]
11:12:06,530 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding resolved
non-early insert action.
11:12:06,533 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.EventLog' took 114ms
11:12:06,533 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: reuse entity manager session already in tx Local
transaction (delegate=TransactionImple < ac, BasicAction:
0:ffff0a0000b0:38e96acf:5bc8a29e:11 status: ActionStatus.RUNNING >, owner=Local
transaction context for provider JBoss JTA transaction provider)
11:12:06,533 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Transient instance of: demo.EventLog
11:12:06,534 TRACE [org.hibernate.event.internal.DefaultPersistEventListener] (default
task-1) Saving transient instance
11:12:06,534 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Generated identifier: 2, using strategy: org.hibernate.id.enhanced.TableGenerator
11:12:06,534 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Saving [demo.EventLog#2]
11:12:06,534 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding an
EntityInsertAction for [demo.EventLog] object
11:12:06,534 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding insert
with no non-nullable, transient entities: [EntityInsertAction[demo.EventLog#2]]
11:12:06,534 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding resolved
non-early insert action.
11:12:06,534 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.EventLog' took 1ms
11:12:06,534 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: reuse entity manager session already in tx Local
transaction (delegate=TransactionImple < ac, BasicAction:
0:ffff0a0000b0:38e96acf:5bc8a29e:11 status: ActionStatus.RUNNING >, owner=Local
transaction context for provider JBoss JTA transaction provider)
11:12:06,535 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Transient instance of: demo.Comment
11:12:06,535 TRACE [org.hibernate.event.internal.DefaultPersistEventListener] (default
task-1) Saving transient instance
11:12:06,535 TRACE [org.hibernate.event.internal.AbstractSaveEventListener] (default
task-1) Saving [demo.Comment#<null>]
11:12:06,535 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding an
EntityIdentityInsertAction for [demo.Comment] object
11:12:06,535 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Executing
inserts before finding non-nullable transient entities for early insert:
[EntityIdentityInsertAction[demo.Comment#<null>]]
11:12:06,537 DEBUG [org.hibernate.validator.internal.engine.resolver.TraversableResolvers]
(default task-1) Found javax.persistence.Persistence on classpath containing
'getPersistenceUtil'. Assuming JPA 2 environment. Trying to instantiate JPA aware
TraversableResolver
11:12:06,537 DEBUG [org.hibernate.validator.internal.engine.resolver.TraversableResolvers]
(default task-1) Instantiated JPA aware TraversableResolver of type
org.hibernate.validator.internal.engine.resolver.JPATraversableResolver.
11:12:06,537 DEBUG [org.hibernate.validator.internal.xml.config.ValidationXmlParser]
(default task-1) Trying to load META-INF/validation.xml for XML based Validator
configuration.
11:12:06,537 DEBUG [org.hibernate.validator.internal.xml.config.ResourceLoaderHelper]
(default task-1) Trying to load META-INF/validation.xml via TCCL
11:12:06,537 DEBUG [org.hibernate.validator.internal.xml.config.ResourceLoaderHelper]
(default task-1) Trying to load META-INF/validation.xml via Hibernate Validator's
class loader
11:12:06,537 DEBUG [org.hibernate.validator.internal.xml.config.ValidationXmlParser]
(default task-1) No META-INF/validation.xml found. Using annotation based configuration
only.
11:12:06,540 DEBUG [org.hibernate.validator.internal.engine.ConfigurationImpl] (default
task-1) Setting custom ConstraintValidatorFactory of type
org.hibernate.validator.cdi.internal.InjectingConstraintValidatorFactory
11:12:06,540 DEBUG
[org.hibernate.validator.messageinterpolation.ResourceBundleMessageInterpolator] (default
task-1) Loaded expression factory via original TCCL
11:12:06,540 DEBUG [org.hibernate.validator.internal.engine.ConfigurationImpl] (default
task-1) Setting custom MessageInterpolator of type
org.hibernate.validator.messageinterpolation.ResourceBundleMessageInterpolator
11:12:06,540 DEBUG [org.hibernate.validator.internal.engine.ConfigurationImpl] (default
task-1) Setting custom TraversableResolver of type
org.hibernate.validator.internal.engine.resolver.JPATraversableResolver
11:12:06,540 DEBUG [org.hibernate.validator.internal.engine.ConfigurationImpl] (default
task-1) Setting custom ParameterNameProvider of type
org.hibernate.validator.internal.engine.DefaultParameterNameProvider
11:12:06,540 DEBUG [org.hibernate.validator.internal.engine.ConfigurationImpl] (default
task-1) Setting custom ClockProvider of type
org.hibernate.validator.internal.engine.DefaultClockProvider
11:12:06,546 DEBUG [org.hibernate.validator.internal.engine.ValidatorFactoryImpl] (default
task-1) HV000234: Using
org.hibernate.validator.messageinterpolation.ResourceBundleMessageInterpolator as
ValidatorFactory-scoped message interpolator.
11:12:06,546 DEBUG [org.hibernate.validator.internal.engine.ValidatorFactoryImpl] (default
task-1) HV000234: Using
org.hibernate.validator.internal.engine.resolver.JPATraversableResolver as
ValidatorFactory-scoped traversable resolver.
11:12:06,546 DEBUG [org.hibernate.validator.internal.engine.ValidatorFactoryImpl] (default
task-1) HV000234: Using
org.hibernate.validator.internal.util.ExecutableParameterNameProvider as
ValidatorFactory-scoped parameter name provider.
11:12:06,546 DEBUG [org.hibernate.validator.internal.engine.ValidatorFactoryImpl] (default
task-1) HV000234: Using org.hibernate.validator.internal.engine.DefaultClockProvider as
ValidatorFactory-scoped clock provider.
11:12:06,546 DEBUG [org.hibernate.validator.internal.engine.ValidatorFactoryImpl] (default
task-1) HV000234: Using
org.hibernate.validator.internal.engine.scripting.DefaultScriptEvaluatorFactory as
ValidatorFactory-scoped script evaluator factory.
11:12:06,554 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Inserting entity: [demo.EventLog#1]
11:12:06,556 TRACE [org.hibernate.service.internal.AbstractServiceRegistryImpl] (default
task-1) Initializing service [role=org.hibernate.engine.jdbc.batch.spi.BatchBuilder]
11:12:06,557 TRACE [org.hibernate.service.internal.AbstractServiceRegistryImpl] (default
task-1) Initializing service [role=org.hibernate.jmx.spi.JmxService]
11:12:06,560 DEBUG [org.hibernate.SQL] (default task-1) insert into EventLog (message, id)
values (?, ?)
11:12:06,561 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Registering statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@1909c5ad]
11:12:06,561 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Dehydrating entity: [demo.EventLog#1]
11:12:06,563 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1)
binding parameter [1] as [VARCHAR] - [Foo]
11:12:06,563 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1)
binding parameter [2] as [BIGINT] - [1]
11:12:06,564 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Inserting entity: [demo.EventLog#2]
11:12:06,564 DEBUG [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default
task-1) Reusing batch statement
11:12:06,564 DEBUG [org.hibernate.SQL] (default task-1) insert into EventLog (message, id)
values (?, ?)
11:12:06,564 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Dehydrating entity: [demo.EventLog#2]
11:12:06,564 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1)
binding parameter [1] as [VARCHAR] - [Bar]
11:12:06,564 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1)
binding parameter [2] as [BIGINT] - [2]
11:12:06,565 DEBUG [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] (default
task-1) Executing batch size: 2
11:12:06,566 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@1909c5ad]
11:12:06,566 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Closing prepared statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@1909c5ad]
11:12:06,567 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) Starting after statement execution processing [AFTER_STATEMENT]
11:12:06,567 TRACE
[org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor] (default
task-1) LogicalConnection#afterStatement
11:12:06,567 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Initiating JDBC connection release from afterStatement
11:12:06,567 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing JDBC resources
11:12:06,568 INFO [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default
task-1) HHH000010: On release of batch it still contained JDBC statements
11:12:06,568 ERROR [org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl] (default
task-1) HHH000352: Unable to release batch statement...
11:12:06,568 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@1909c5ad]
11:12:06,568 DEBUG [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) HHH000387: ResultSet's statement was not registered
11:12:06,568 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Closing prepared statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@1909c5ad]
11:12:06,568 DEBUG [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Exception clearing maxRows/queryTimeout [IJ031040: Connection is not
associated with a managed connection:
org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@42780d9a]
11:12:06,568 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) Starting after statement execution processing [AFTER_STATEMENT]
11:12:06,568 TRACE
[org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor] (default
task-1) LogicalConnection#afterStatement
11:12:06,568 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Initiating JDBC connection release from afterStatement
11:12:06,568 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Adding insert
with no non-nullable, transient entities:
[EntityIdentityInsertAction[demo.Comment#<null>]]
11:12:06,568 TRACE [org.hibernate.engine.spi.ActionQueue] (default task-1) Executing
insertions before resolved early-insert
11:12:06,568 DEBUG [org.hibernate.engine.spi.ActionQueue] (default task-1) Executing
identity-insert immediately
11:12:06,570 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Inserting entity: demo.Comment (native id)
11:12:06,571 DEBUG [org.hibernate.SQL] (default task-1) insert into Comment (id, message)
values (null, ?)
11:12:06,571 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Registering statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@22cfab5e]
11:12:06,571 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (default
task-1) Dehydrating entity: [demo.Comment#<null>]
11:12:06,571 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-1)
binding parameter [1] as [VARCHAR] - [Foo]
11:12:06,575 DEBUG [org.hibernate.id.IdentifierGeneratorHelper] (default task-1) Natively
generated identity: 1
11:12:06,575 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing result set [rs12: org.h2.result.LocalResult@2d71b25c columns: 1
rows: 1 pos: 0]
11:12:06,575 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Closing result set [rs12: org.h2.result.LocalResult@2d71b25c columns: 1
rows: 1 pos: 0]
11:12:06,575 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@22cfab5e]
11:12:06,575 DEBUG [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) HHH000387: ResultSet's statement was not registered
11:12:06,575 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Closing prepared statement
[org.jboss.jca.adapters.jdbc.jdk8.WrappedPreparedStatementJDK8@22cfab5e]
11:12:06,575 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) Starting after statement execution processing [AFTER_STATEMENT]
11:12:06,576 TRACE
[org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor] (default
task-1) LogicalConnection#afterStatement
11:12:06,576 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Initiating JDBC connection release from afterStatement
11:12:06,576 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing JDBC resources
11:12:06,576 TRACE [org.jboss.as.jpa] (default task-1) persist entityClass
'demo.Comment' took 42ms
11:12:06,576 TRACE [org.jboss.as.jpa] (default task-1) transaction association counter = 0
for default task-1:transaction scoped EntityManager [demo.war#primary]:
11:12:06,576 TRACE
[org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization]
(default task-1) Registered JTA Synchronization : beforeCompletion()
11:12:06,576 TRACE
[org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl]
(default task-1) Synchronization coordinator: beforeCompletion()
11:12:06,576 TRACE [org.hibernate.internal.SessionImpl] (default task-1)
SessionImpl#beforeTransactionCompletion()
11:12:06,576 TRACE [org.hibernate.internal.SessionImpl] (default task-1) Automatically
flushing session
11:12:06,576 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Flushing session
11:12:06,577 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Processing flush-time cascades
11:12:06,577 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Processing
cascade ACTION_PERSIST_ON_FLUSH for: demo.EventLog
11:12:06,577 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Done
processing cascade ACTION_PERSIST_ON_FLUSH for: demo.EventLog
11:12:06,577 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Processing
cascade ACTION_PERSIST_ON_FLUSH for: demo.EventLog
11:12:06,577 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Done
processing cascade ACTION_PERSIST_ON_FLUSH for: demo.EventLog
11:12:06,578 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Processing
cascade ACTION_PERSIST_ON_FLUSH for: demo.Comment
11:12:06,578 TRACE [org.hibernate.engine.internal.Cascade] (default task-1) Done
processing cascade ACTION_PERSIST_ON_FLUSH for: demo.Comment
11:12:06,578 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Dirty checking collections
11:12:06,578 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Flushing entities and processing referenced collections
11:12:06,579 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Processing unreferenced collections
11:12:06,579 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Scheduling collection removes/(re)creates/updates
11:12:06,579 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
11:12:06,579 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
11:12:06,580 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) Listing
entities:
11:12:06,580 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1)
demo.EventLog{id=1, message=Foo}
11:12:06,580 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1)
demo.EventLog{id=2, message=Bar}
11:12:06,580 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1)
demo.Comment{id=1, message=Foo}
11:12:06,580 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Executing flush
11:12:06,580 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) Starting after statement execution processing [AFTER_STATEMENT]
11:12:06,580 TRACE
[org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor] (default
task-1) LogicalConnection#afterStatement
11:12:06,580 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Initiating JDBC connection release from afterStatement
11:12:06,581 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (default
task-1) Post flush
11:12:06,582 TRACE
[org.hibernate.resource.transaction.internal.SynchronizationRegistryStandardImpl] (default
task-1)
SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
11:12:06,582 DEBUG [org.jboss.as.jpa] (default task-1) default task-1:transaction scoped
EntityManager [demo.war#primary]: closing entity managersession
11:12:06,582 TRACE [org.hibernate.internal.SessionImpl] (default task-1) Closing session
[18610f50-983f-4d05-b2fc-c3b915129a98]
11:12:06,583 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) Closing JDBC container
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl@5f794ef2]
11:12:06,583 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (default
task-1) HHH000420: Closing un-released batch
11:12:06,583 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing JDBC resources
11:12:06,583 TRACE [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Closing logical connection
11:12:06,583 TRACE [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Logical connection closed
11:12:06,584 TRACE
[org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization]
(default task-1) Registered JTA Synchronization : afterCompletion(3)
11:12:06,584 TRACE
[org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl]
(default task-1) Synchronization coordinator: afterCompletion(status=3)
11:12:06,584 TRACE
[org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl]
(default task-1) Synchronization coordinator: doAfterCompletion(successful=true,
delayed=false)
11:12:06,584 TRACE
[org.hibernate.resource.transaction.internal.SynchronizationRegistryStandardImpl] (default
task-1)
SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
11:12:06,584 TRACE
[org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor] (default
task-1) LogicalConnection#afterTransaction
11:12:06,584 TRACE [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl]
(default task-1) Releasing JDBC resources
11:12:06,584 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl]
(default task-1) Initiating JDBC connection release from afterTransaction
11:12:06,584 TRACE [org.hibernate.internal.SessionImpl] (default task-1)
SessionImpl#afterTransactionCompletion(successful=true, delayed=false)
{code}
I will need to reject this bug, as there isn't anything to fix in WildFly, instead a
[
HHH|https://hibernate.atlassian.net/browse/HHH] jira for Hibernate ORM is needed, that
references this jira. Please create the Hibernate ORM
[
HHH|https://hibernate.atlassian.net/browse/HHH] jira and update WFLY-11213 with a link to
the HHH jira.
I set a breakpoint in the Hibernate ORM code that logs "On release of batch it still
contained JDBC statements...". The call stack below shows when the breakpoint is
hit, it should be helpful to whomever works on the HHH bug that you create for this (sorry
that you have to go through yet another step).
:
{code}
"default task-1@18441" prio=5 tid=0x9d nid=NA runnable
java.lang.Thread.State: RUNNABLE
at
org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.release(AbstractBatchImpl.java:193)
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:359)
at
org.hibernate.event.internal.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:292)
at
org.hibernate.event.internal.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:200)
at
org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:131)
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:800)
at org.hibernate.internal.SessionImpl.persist(SessionImpl.java:785)
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:285)
at com.sun.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:304)
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:107)
at
javax.faces.component.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:87)
at
com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:102)
at javax.faces.component.UICommand.broadcast(UICommand.java:330)
at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:870)
at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:1418)
at
com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:82)
at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100)
at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:201)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:670)
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$806.28060389.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$807.2125395911.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$807.2125395911.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$807.2125395911.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$807.2125395911.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$807.2125395911.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:360)
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:1985)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487)
at
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378)
at java.lang.Thread.run(Thread.java:748)
{code}
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)