[jboss-jira] [JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
Scott Marlow (Jira)
issues at jboss.org
Thu Oct 18 11:48:00 EDT 2018
[ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13650101#comment-13650101 ]
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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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)
More information about the jboss-jira
mailing list