Stability problems with hibernate.

[Knut-Håvard Aksnes]

We are deploying a single ear server on Wildfly 36.0.1.Final  and Java 21. The problem being that the application sometimes doesn't start up as it should.

The problem is related to JPA and second level caches, we do have a largish jpa mapping to our application db. We have been trying to be using second level caches for a few entity classes. We do get an indication of the underlying cause of the problem under startup even when it succeeds as we do get some warnings even then. The problem is that the application logs warnings during startup that infinispan caches already have been initialized, this even on a clean setup. For each cache and there are more than one of them for each cached entity class we do get one warning from hibernate. To me this looks like there are two threads doing cache initialization the second one emitting the warning.

What happens when startup fails is that we for one of the caches get an error message from Infinispan about attempt to reinitializing an already existing cache. To me this looks like a race condition where both threads try to initialize the same cache due to missing thread synchronization during infinispan cache initialization. 

Our deployed ear is built using skinny wars where we have several wars, one ejb and some support jars (including the jpa one) as part of it. The jpa jar is deployed inside the ear and then used (using a provided relationship) from client wars and ejbs.

The main problem is the missing thread synchronization for the init threads in hibernate thus making it possible to get into a bad state in infinispan. 

A second problem is that this deployment failure reports as a readiness failure, not as a liveness failure by health checks. This is a situation where the application won't be able to self heal it is stuck in a bad state. We are deploying this in kubernetes, a workaround might be to set up a startup probe probing /health/ready but it still not right.

Currently we are building a single jar packaged using wildfly-jar-maven-plugin then in a separate project we install this into a temurin base image with some customization related to fonts and java agents.

[Knut-Håvard Aksnes]

The kind of messages we get during working startup are:

WARN 2025-08-19T14:54:11.57+02:00 HHH025031: Configuration for pending-puts cache 'org.xxx.SystemLanguage-pending-puts' is already defined - another instance of SessionFactory was not closed properly.
WARN 2025-08-19T14:54:11.57+02:00 HHH025031: Configuration for pending-puts cache 'org.xxx.Sector-pending-puts' is already defined - another instance of SessionFactory was not closed properly.
WARN 2025-08-19T14:54:11.57+02:00 HHH025031: Configuration for pending-puts cache 'org.xxx.SystemConfiguration-pending-puts' is already defined - another instance of SessionFactory was not closed properly.
WARN 2025-08-19T14:54:11.57+02:00 HHH025031: Configuration for pending-puts cache 'org.xxx.TimeZone-pending-puts' is already defined - another instance of SessionFactory was not closed properly.

[Scott Marlow]

Could you show us one of the persistence unit definitions from one of your persistence.xml files that has the second level cache enabled?  I don't need to see any specific values for any properties set in the persistence units but would like to see which property names are set that could cause problems like this.  

Do you have access to your WildFly server log or console output?  By default there is some information shown during deployment which shows some information about each persistence unit deploying.  From a recent WildFly unit test run that I ran locally, I see the following output when I search for a persistence unit named "mypc":

"

grep mypc testsuite/integration/basic/target/wildfly/standalone/log/server.log

2025-08-15 11:21:02,676 INFO  [org.jboss.as.jpa] (MSC service thread 1-7) WFLYJPA0002: Read persistence.xml for mypc
2025-08-15 11:21:02,707 INFO  [org.jipijapa] (MSC service thread 1-8) JIPIORMV6020260: Second level cache enabled for jpa_transaction.jar#mypc
2025-08-15 11:21:03,103 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 84) WFLYJPA0010: Starting Persistence Unit (phase 1 of 2) Service 'jpa_transaction.jar#mypc'
2025-08-15 11:21:03,114 INFO  [org.hibernate.jpa.internal.util.LogHelper] (ServerService Thread Pool -- 84) HHH000204: Processing PersistenceUnitInfo [name: mypc]
2025-08-15 11:21:03,702 INFO  [org.jipijapa] (MSC service thread 1-5) JIPIORMV6020260: Second level cache enabled for jpa_transaction.jar#mypc
2025-08-15 11:21:03,821 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 32) WFLYJPA0010: Starting Persistence Unit (phase 2 of 2) Service 'jpa_transaction.jar#mypc'
2025-08-15 11:21:05,347 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 5) WFLYJPA0011: Stopping Persistence Unit (phase 2 of 2) Service 'jpa_transaction.jar#mypc'
2025-08-15 11:21:05,477 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 17) WFLYJPA0011: Stopping Persistence Unit (phase 1 of 2) Service 'jpa_transaction.jar#mypc'
"

What do you see if you search in your server.log for all references to one of the persistence units that have the cache enabled?  

Do you see the "Starting Persistence Unit (phase 1 of 2) Service" output exactly once for each persistence unit?  Or more than once?

[Knut-Håvard Aksnes]

We doesn't, do anything special for these classes exception annotating them with @jakarta.inject.Cacheable

In persistence.xml we do set the property hibernate.cache.use_second_level_cache to true.

We also include <shared-cache-mode>ENABLE_SELECTIVE</shared-cache-mode>

The unusual part of our setup is our usage of skinny wars and the fact that the jpa jar is shared within the jar. Multiple threads doing initialization isn't necessarily a problem here the problem is that the initialization isn't thread safe. The check for cache being uninitialized and the initialization of it must be done as an atomic operation, if infinispan doesn't provide such functionality, then hibernate should at least protect its own state.

--
You received this message because you are subscribed to the Google Groups "WildFly" group.
To unsubscribe from this group and stop receiving emails from it, send an email to wildfly+u...@googlegroups.com.
To view this discussion visit https://groups.google.com/d/msgid/wildfly/19d05ed6-0b7b-4be6-a209-734ea6b572abn%40googlegroups.com.

[Scott Marlow]

On 8/21/25 8:19 AM, Knut-Håvard Aksnes wrote:

We doesn't, do anything special for these classes exception annotating them with @jakarta.inject.Cacheable

In persistence.xml we do set the property hibernate.cache.use_second_level_cache to true.

We also include <shared-cache-mode>ENABLE_SELECTIVE</shared-cache-mode>

The unusual part of our setup is our usage of skinny wars and the fact that the jpa jar is shared within the jar. Multiple threads doing initialization isn't necessarily a problem here the problem is that the initialization isn't thread safe. The check for cache being uninitialized and the initialization of it must be done as an atomic operation, if infinispan doesn't provide such functionality, then hibernate should at least protect its own state.

Can you hack together a reproducer that I could run?  Perhaps you can build the ear without any classes and see if the problem still occurs. 

[Knut-Håvard Aksnes]

I do have access to logs when running locally (ranger desktop) The main problem is that the start failure isn't consistently reproducible. Our datamodel contains ~700 entity classes, due to the nature of the problem producing a consistent small reproducer might be hard. The full EAR is big. We suspect there are two entity manager factories being initialized in parallel for some reason which might explain there being two intializers running. 

The next time I get a local startup failure due to this problem I will store the logs.

[Scott Marlow]

The information in the logs should help me to understand more.  Even though the persistence unit properties do not seem special, if you set the session factory name or certain other properties that could cause a problem.

> We suspect there are two entity manager factories being initialized in parallel for some reason which might explain there being two intializers running. 

The entity manager factories are started/initialized in parallel.  Each persistence unit definition has a unique (scoped) name that consists of the containing deployment file name + the persistence unit name.  The unique name is typically used when setting up the second level cache to ensure that each entity manager factory has its own cache.

If you obtain your persistence.xml file and show me the persistence unit property names being passed in, that might be enough of a clue until you get the logs to share.   The property names shouldn't contain any confidential information.  Mostly, you would look at something like the following (very old) persistence.xml:

<?xml version="1.0" encoding="UTF-8"?>
<persistence xmlns="http://java.sun.com/xml/ns/persistence" version="1.0">
    <persistence-unit name="TEST_PU">
    <provider>org.hibernate.ogm.jpa.HibernateOgmPersistence</provider>
    <jta-data-source>java:jboss/datasources/ExampleDS</jta-data-source>
    <properties>
         <property name="jboss.as.jpa.classtransformer" value="false" />      
         <property name="jboss.as.jpa.adapterModule" value="org.jboss.as.jpa.hibernate:4"/>
    </properties>
  </persistence-unit>
</persistence>

And just show me:

property name="jboss.as.jpa.classtransformer" 

property name="jboss.as.jpa.adapterModule" 

Scott

[Knut-Håvard Aksnes]

Trimmed persistence.xml file under our package names have been changed the entire class list is around 700 classes we also use one attributeconverter named BooleanXConverter:

<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_2.xsd"

version="2.2">

<persistence-unit name="ptsmc" transaction-type="RESOURCE_LOCAL">

<provider>org.hibernate.jpa.HibernatePersistenceProvider</provider>

<non-jta-data-source>java:jboss/example</non-jta-data-source>

<!-- START GENERATED BLOCK. DO NOT EDIT INSIDE -->

<class>org.example.CtrlProperty</class>

<class>org.example.CtrlPropertyMeta</class>

<!-- END GENERATED BLOCK. DO NOT EDIT INSIDE -->

<class>org.example.BooleanXConverter</class>

<exclude-unlisted-classes>true</exclude-unlisted-classes>

<shared-cache-mode>ENABLE_SELECTIVE</shared-cache-mode>

<properties>

<property name="hibernate.dialect" value="org.hibernate.dialect.OracleDialect"/>

<property name="hibernate.show_sql" value="false"/>

<property name="hibernate.transaction.jta.platform" value="org.hibernate.service.jta.platform.internal.JBossAppServerJtaPlatform"/>

<property name="hibernate.archive.scanner" value="org.hibernate.boot.archive.scan.internal.DisabledScanner"/>

<property name="hibernate.connection.autocommit" value="false"/>

<property name="hibernate.cache.use_second_level_cache" value="true"/>

</properties>

</persistence-unit>

</persistence>

[Knut-Håvard Aksnes]

A colleague of me has identified and fixed the underlying cause of this, more than one EntityManagerFactory was created for the same database. We now don't get warnings during normal startup.