[JBoss JIRA] (WFLY-11214) Periodic recovery does not recover XAResource after jvm crash when agroal subsystem is used
by James Perkins (Jira)
[ https://issues.jboss.org/browse/WFLY-11214?page=com.atlassian.jira.plugin... ]
James Perkins moved JBEAP-15686 to WFLY-11214:
----------------------------------------------
Project: WildFly (was: JBoss Enterprise Application Platform)
Key: WFLY-11214 (was: JBEAP-15686)
Workflow: GIT Pull Request workflow (was: CDW with loose statuses v1)
Component/s: Agroal
Transactions
(was: Agroal)
(was: Transactions)
Affects Version/s: (was: 7.2.0.CD14)
> Periodic recovery does not recover XAResource after jvm crash when agroal subsystem is used
> -------------------------------------------------------------------------------------------
>
> Key: WFLY-11214
> URL: https://issues.jboss.org/browse/WFLY-11214
> Project: WildFly
> Issue Type: Bug
> Components: Agroal, Transactions
> Reporter: Ivan Straka
> Assignee: Luis Barreiro
> Priority: Blocker
> Attachments: JPACrashRecoveryTestCase_commitHaltSecond_jta_server.log, JPACrashRecoveryTestCase_commitHaltSecond_jts_server.log
>
>
> Scenario:
> Halts server at commit phase ...
> # enlist TestXA resource
> # enlist XA resource
> # prepare TestXA resource
> # prepare XA resource
> # commit Test XA resource
> # JVM crash
> # recovery started
> # commit XA resource
> Periodic recovery does not recover xa resource. It looks like agroal subsystem does not register xa resource to xa recovery module.
> Test outcome:
> {code:java}
> Running org.jboss.as.test.jbossts.crashrec.test.JPACrashRecoveryTestCase
> Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 109.002 sec <<< FAILURE! - in org.jboss.as.test.jbossts.crashrec.test.JPACrashRecoveryTestCase
> commitHaltSecond(org.jboss.as.test.jbossts.crashrec.test.JPACrashRecoveryTestCase) Time elapsed: 102.976 sec <<< FAILURE!
> java.lang.AssertionError: Incorrect data in database after crash recovery. expected:<2> but was:<1>
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.failNotEquals(Assert.java:834)
> at org.junit.Assert.assertEquals(Assert.java:645)
> at org.jboss.as.test.jbossts.crashrec.test.JPABaseCrashRecoveryTestCase.checkAfterTestExecution(JPABaseCrashRecoveryTestCase.java:150)
> at org.jboss.as.test.jbossts.crashrec.test.TestBaseCrashRecovery.commitHaltTest(TestBaseCrashRecovery.java:485)
> at org.jboss.as.test.jbossts.crashrec.test.TestBaseCrashRecovery.commitHaltSecond(TestBaseCrashRecovery.java:418)
> at org.jboss.as.test.jbossts.crashrec.test.JPACrashRecoveryTestCase.commitHaltSecond(JPACrashRecoveryTestCase.java:76)
> {code}
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
7 years, 9 months
[JBoss JIRA] (DROOLS-3054) Highlight in expression builder previous selection in Scenario right panel
by Daniele Zonca (Jira)
[ https://issues.jboss.org/browse/DROOLS-3054?page=com.atlassian.jira.plugi... ]
Daniele Zonca commented on DROOLS-3054:
---------------------------------------
[~srambach]
Hi, thanks for the updates.
I think there is a bug:
!Screenshot from 2018-10-18 17-58-35.png|thumbnail!
My mouse was on "This [This stuff]" element but the "hover" effect is on its parent "More stuff" and on the top level parent "applicant". Is it correct?
> Highlight in expression builder previous selection in Scenario right panel
> --------------------------------------------------------------------------
>
> Key: DROOLS-3054
> URL: https://issues.jboss.org/browse/DROOLS-3054
> Project: Drools
> Issue Type: Task
> Components: Scenario Simulation and Testing
> Reporter: Daniele Zonca
> Assignee: Gabriele Cardosi
> Priority: Minor
> Labels: UX, UX-CSS, UXTeam
> Attachments: Screen Shot 2018-09-28 at 3.45.25 PM.png, Screen Shot 2018-10-15 at 1.38.30 PM.png, Screenshot from 2018-10-12 15-53-50.png, Screenshot from 2018-10-18 17-58-35.png, tree-issues.png
>
>
> When the user edits the type of a column, the expression builder into the right panel should highlight the existing mapped type.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
7 years, 9 months
[JBoss JIRA] (DROOLS-3154) Minor UI improvements/bugfixes for Scenario
by Sarah Rambacher (Jira)
[ https://issues.jboss.org/browse/DROOLS-3154?page=com.atlassian.jira.plugi... ]
Sarah Rambacher commented on DROOLS-3154:
-----------------------------------------
Regarding bullets 3 and 6, space around the tabs and the right panel. I'd suggest some padding on the .uf-scroll-panel or on the #right-panel if possible (one or the other). This would take care of the spacing around everything inside the panel. Probably just left and right padding is sufficient.
{{<div style="overflow: auto;position: absolute;zoom: 1;left: 0px;top: 0px;right: 0px;bottom: 0px;"><div class="{color:#FFAB00}uf-scroll-panel{color}" style="position: relative;zoom: 1;{color:#FFAB00}/* padding: 1em; */{color}"><div {color:#FFAB00}id="right-panel"{color} class="tab-pane kie-dock active" data-i18n-prefix="RightPanelViewImpl." style="
/* {color:#FFAB00}padding: 1em;{color}*/
">}}
> Minor UI improvements/bugfixes for Scenario
> -------------------------------------------
>
> Key: DROOLS-3154
> URL: https://issues.jboss.org/browse/DROOLS-3154
> Project: Drools
> Issue Type: Bug
> Components: Scenario Simulation and Testing
> Reporter: Daniele Zonca
> Assignee: Toni Rikkola
> Priority: Critical
> Labels: UX-CSS
>
> This item contains a list of general UI bugs to be fixed:
> - Use grey borders for all the grid and not only for the header
> - Add some padding to the cells of the grid
> - Add some padding to right panel the tab titles
> - Remove scrolling bar from right panel
> - Review expression editor component HTML/CSS (paddings, indents, etc)
> - Review right panel padding (now it is hardcoded)
> - Use text area inputs instead of text box for inline editing
> - Reduce the width of Index column
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
7 years, 9 months
[JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
by Cody Lerum (Jira)
[ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin... ]
Cody Lerum commented on WFLY-11213:
-----------------------------------
[~guillaume.smet] I did create a test case https://github.com/codylerum/hibernate-test-case-templates/tree/batch_sta... but I was unable to get the log message to fire.
I suspected it has something to do with the integration of the JTA Tx or something. Maybe someone who knows more about hibernate test cases can look at the demo project and the test case and modify it to trigger.
> 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)
7 years, 9 months
[JBoss JIRA] (DROOLS-3054) Highlight in expression builder previous selection in Scenario right panel
by Daniele Zonca (Jira)
[ https://issues.jboss.org/browse/DROOLS-3054?page=com.atlassian.jira.plugi... ]
Daniele Zonca updated DROOLS-3054:
----------------------------------
Attachment: Screenshot from 2018-10-18 17-58-35.png
> Highlight in expression builder previous selection in Scenario right panel
> --------------------------------------------------------------------------
>
> Key: DROOLS-3054
> URL: https://issues.jboss.org/browse/DROOLS-3054
> Project: Drools
> Issue Type: Task
> Components: Scenario Simulation and Testing
> Reporter: Daniele Zonca
> Assignee: Gabriele Cardosi
> Priority: Minor
> Labels: UX, UX-CSS, UXTeam
> Attachments: Screen Shot 2018-09-28 at 3.45.25 PM.png, Screen Shot 2018-10-15 at 1.38.30 PM.png, Screenshot from 2018-10-12 15-53-50.png, Screenshot from 2018-10-18 17-58-35.png, tree-issues.png
>
>
> When the user edits the type of a column, the expression builder into the right panel should highlight the existing mapped type.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
7 years, 9 months
[JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
by Guillaume Smet (Jira)
[ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin... ]
Guillaume Smet commented on WFLY-11213:
---------------------------------------
[~clerum] we have a test case template here (https://github.com/hibernate/hibernate-test-case-templates/tree/master/or...) that might help.
> 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)
7 years, 9 months
[JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
by Scott Marlow (Jira)
[ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin... ]
Scott Marlow closed WFLY-11213.
-------------------------------
Resolution: Rejected
As mentioned above, this bug needs to be reported against Hibernate ORM via [https://hibernate.atlassian.net/browse/HHH]. Please link back to this jira, so that the information that you provided and I added in my comment, can be referenced. If needed, we can always reopen this jira. Thanks for reporting this!
CC [~gbadner] [~guillaume.smet]
> 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)
7 years, 9 months
[JBoss JIRA] (DROOLS-3054) Highlight in expression builder previous selection in Scenario right panel
by Liz Clayton (Jira)
[ https://issues.jboss.org/browse/DROOLS-3054?page=com.atlassian.jira.plugi... ]
Liz Clayton commented on DROOLS-3054:
-------------------------------------
[~srambach] Thanks for getting the indenting and selection working! Would it be difficult to bold the parent node label, I think that might help distinguish it as top level, wdyt?
> Highlight in expression builder previous selection in Scenario right panel
> --------------------------------------------------------------------------
>
> Key: DROOLS-3054
> URL: https://issues.jboss.org/browse/DROOLS-3054
> Project: Drools
> Issue Type: Task
> Components: Scenario Simulation and Testing
> Reporter: Daniele Zonca
> Assignee: Gabriele Cardosi
> Priority: Minor
> Labels: UX, UX-CSS, UXTeam
> Attachments: Screen Shot 2018-09-28 at 3.45.25 PM.png, Screen Shot 2018-10-15 at 1.38.30 PM.png, Screenshot from 2018-10-12 15-53-50.png, tree-issues.png
>
>
> When the user edits the type of a column, the expression builder into the right panel should highlight the existing mapped type.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
7 years, 9 months
[JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
by Cody Lerum (Jira)
[ https://issues.jboss.org/browse/WFLY-11213?page=com.atlassian.jira.plugin... ]
Cody Lerum commented on WFLY-11213:
-----------------------------------
Thanks Scott I'll get one filed with HHH
> 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)
7 years, 9 months
[JBoss JIRA] (WFLY-11213) On release of batch it still contained JDBC statements logged
by Scott Marlow (Jira)
[ 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)
7 years, 9 months