Revision as of 23:08, 11 January 2009

Bug Analysis Document: 256277: Endless loop on @PrePersist using a nested Persist

• Bugzilla Bug 256277
• EclipseLink Users Newsgroup posting

Document History

Overview

This bug describes the behavior and fix for the issue of nested flush() calls when using the @PrePersist annotation callback method on an unmanaged entity containing a read query method that causes a flush() when the entity is the target of a relationship from a managed entity that has pending changes.

This bug is also encountered when a secondary persist is executed inside of a @PrePersist callback method on the Entity being itself persisted. Soo there are two use cases here - we will concentrate on the read query causing a secondary flush to sync changes before the read - causing an infinite loop or double persist which causes a PK conflict.

Concepts

See p.139 of Pro EJB 3.0 "Some providers will flush the persistence context to ensure that the query incorporates all pending changes" - EclipseLink is one of these providers.

JPA Specification Notes

Here is what the JPA specification says about performing persists inside the @PrePersist method. Essentially it states that we should not be performing persists inside a @PrePersist callback - however it may be the responsibility of the container to handle any that may be done depending on the nature of the persistence.

JPA 1.0 Specification

• P58 Section 3.5
  • "In general, portable applications should not invoke EntityManager or Query operations, access other entity instances, or modify relationships in a lifecycle callback method.[19]"
  • "[19] The semantics of such operations may be standardized in a future release of this specification."

JPA 2.0 Specification

• P82 Section 3.5.1
  • "In general, portable applications should not invoke EntityManager or Query operations, access other entity instances, or modify relationships within the same persistence context.[34] A lifecycle callback method may modify the non-relationship state of the entity on which it is invoked."
  • "[34] The semantics of such operations may be standardized in a future release of this specification."

Reproduction

Prerequisites

• Run tests out of container on an SE persistence unit (EE can also be used)
• At least two entities must be persisted to avoid performance optimization code for a single entity
• Two different entity classes are required
  • One must be managed, the other one containing the @PrePersist must be unmanaged/detached but referenced by the first
• Test must commit more than one object so that the non-performance else clause in CommitManager.commitAllObjectsWithChangeSet() is used
• Test must perform a change on an existing object that is already persisted
• cascade must be set to CascadeType.ALL
• fetch must be set to FetchType.EAGER
• Set FlushMode to AUTO
  • entityManager.setFlushMode(FlushModeType.AUTO);

Data Model

This matches the data model used in Chapter 5 of Pro EJB 3.0.

@Entity
public class Employee implements Serializable {
    @Id
    private BigInteger id;
 
    @OneToOne(fetch=FetchType.EAGER, cascade=CascadeType.PERSIST)
    ParkingSpace parkingSpace;
 
    @OneToMany(fetch=FetchType.EAGER, mappedBy="employee", cascade=CascadeType.PERSIST)
    Collection<Phone> phones;
 
    @ManyToOne(fetch=FetchType.EAGER, cascade=CascadeType.PERSIST)
    Address address;
}
 
@Entity
public class Address implements Serializable {
 
    @Id
    private BigInteger id;
 
    @OneToMany(fetch=FetchType.EAGER, mappedBy="address",cascade=CascadeType.PERSIST)
    Collection<Employee> employees;
 
    @PrePersist
    // 256277: test prePersist with a nested persist
    public void prePersist() {
        name = "name"; 
        // get a reference to the entityManager and perform a persist inside this prePersist
        EntityManager entityManager = TestClient.staticEntityManager;
        processQuery(entityManager);
    }
}
 
@Entity
public class ParkingSpace implements Serializable {
    @Id
    private BigInteger id;
}
 
@Entity
public class Phone implements Serializable {
    @Id
    private BigInteger id;
 
    @ManyToOne
    Employee employee;
}
 
===Use Case 1: Persist unmanaged entity (with @PrePersist query) referenced by managed entity===
 
 
===Use Case 2: Persist other Entity (with its own @PrePersist and persist) inside @PrePersist callback ===
[https://bugs.eclipse.org/bugs/attachment.cgi?id=121567 Source]
 
 
This use case currently causes an infinite loop on the following line up to build 20090105.
<source lang="java">
    EntityClassListener(EntityListener).prePersist(DescriptorEvent) line: 412

Use Case 3: Persist other Entity (with a @PrePersist without a persist) inside @PrePersist callback

Source

The @PrePersist of the first entity will cause a persist of the second entity that also has it's own @PrePersist (but without another persist).

Normal functionality with no infinite loop.

Use Case 4: Persist other Entity (without its own @PrePersist) inside @PrePersist

Normal functionality with no infinite loop.

===Use Case 5: @PrePersist calls another @PrePersist on a referenced entity

Analysis Constraints

Design / Functionality

Alternative 1: No flush() within a flush()

We will not perform nested flush() calls, a break will be required and a warning will printed if the entityManager is in FlushModeType.AUTO.

Implementation

• A new boolean field will be introduced on EntityManagerImpl.java

    /** Track whether we are already in a flush() */
    protected boolean withinFlush;

that will be set inside flush() just before writeChanges() to true and then reset to false on the finaly block. The use of this flag will be thread safe as far as the entityManager instance is used in a thread safe manner.

EJBQueryImpl when executing a read (possibly from a @PrePersist callback) will check that it is not already in a flush() before doing a pre-flush() - normally done so that any outstanding (uncommitted) changes are included in this query.

public class EJBQueryImpl implements org.eclipse.persistence.jpa.JpaQuery {
    protected Object executeReadQuery() {
...
        if (isFlushModeAUTO()) {
            // 256277: we do not allow nested flush() calls             
            if(!this.entityManager.withinFlush) {
                performPreQueryFlush();
            } else {
                AbstractSessionLog.getLog().log(SessionLog.WARNING,
                        "nested_entity_manager_flush_not_executed_pre_query_changes_may_be_pending", entityManager);
            }

Logging

The following log will not be used.

 this.entityManager.getServerSession().log(SessionLog.WARNING, 
     SessionLog.QUERY, "nested_entity_manager_flush_not_executed_pre_query_changes_may_be_pending");

The following log will be used.

 AbstractSessionLog.getLog().log(SessionLog.WARNING,
     "nested_entity_manager_flush_not_executed_pre_query_changes_may_be_pending", entityManager);

The output will be the following

[EL Warning]: 2009.01.11 21:36:21.786--Thread(Thread[main,5,main])--The em: org.eclipse.persistence.internal.jpa.EntityManagerImpl@1777b1 is already flushing. The query will be executed without further changes being written to the database. If the query is conditional upon changed data the changes may not be reflected in the results. Users should issue a flush() call upon completion of the dependent changes and prior to this flush() to ensure correct results.

Testing

Use Case 1: Output of nested flush()

The following logs and stacktrace illustrate the current nested flush() behavior when performing a @PrePersist containing a query that requires a flush() on uncommitted managed entity changes.

Client Code

Client code is persisting 2 Cell entities that themselves persist new Cell entities in their @PrePersist method.

    private void prePersistQuery() {
        EntityManagerFactory entityManagerFactory = Persistence.createEntityManagerFactory(PU_NAME_IN_USE);
        EntityManager em = entityManagerFactory.createEntityManager();
        staticEntityManager = em;
        try {
            // create 2 cells (to avoid performance optimization for 1 entity)  and link them
                em.getTransaction().begin();
 
                Employee left = new Employee();
                Employee right = new Employee();
 
                // Relationship: Employee --> 1-1 ParkingSpace
                ParkingSpace parkingSpace = new ParkingSpace();
 
                // Relationship: Employee <--> 1-n Phone
                List<Phone> phones = new ArrayList<Phone>();
                Phone phone1 = new Phone();
                Phone phone2 = new Phone();
                // Reverse relationship
                List<Employee> phoneEmployees = new ArrayList<Employee>();
                phoneEmployees.add(right);
 
                // Relationship: Employee <--> 1-1 Address                
                Address address = new Address();
                // Reverse relationship
                List<Employee> addressEmployees = new ArrayList<Employee>();
                addressEmployees.add(right);
 
                // Before merging objects, set any relationships
                right.setParkingSpace(parkingSpace);
 
                // persist the managed source
                em.persist(left);
                em.persist(right);            
 
                // modify the managed entity
                right.setName("xxxx");
                right.setParkingSpace(null);//parkingSpace);
                right.setAddress(address);
                // set reverse
                address.setEmployees(addressEmployees);
 
                phones.add(phone1);
                phones.add(phone2);
                right.setPhones(phones);
                // set reverse
                phone1.setEmployee(right);
                phone2.setEmployee(right);
                // Store objects
                // Note: a flush here will invoke a nested flush during the PrePersist without the changes for bug# 256277
                em.flush();
                em.getTransaction().commit();
        } catch (Exception e) {
            System.out.println("Exception " + e.getMessage());
            e.printStackTrace();
        } finally {
            em.close();
            entityManagerFactory.close();
        }
    }

Logs

[EL Finest]: 2009.01.11 21:36:21.483--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.Employee@18433730( id: null).
[EL Finest]: 2009.01.11 21:36:21.484--ClientSession(28524838)--Thread(Thread[main,5,main])--Execute query ValueReadQuery(sql="SELECT EL_EMPLOYEE_SEQ.NEXTVAL FROM DUAL")
[EL Fine]: 2009.01.11 21:36:21.484--ServerSession(12097592)--Connection(29752800)--Thread(Thread[main,5,main])--SELECT EL_EMPLOYEE_SEQ.NEXTVAL FROM DUAL
[EL Finest]: 2009.01.11 21:36:21.491--ServerSession(12097592)--Thread(Thread[main,5,main])--sequencing preallocation for EL_EMPLOYEE_SEQ: objects: 25 , first: 1, last: 25
[EL Finest]: 2009.01.11 21:36:21.491--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (1 -> org.eclipse.persistence.example.business.Employee@18433730( id: null))
[EL Finest]: 2009.01.11 21:36:21.495--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.Employee@21684929( id: null).
[EL Finest]: 2009.01.11 21:36:21.495--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (2 -> org.eclipse.persistence.example.business.Employee@21684929( id: null))
[EL Finest]: 2009.01.11 21:36:21.495--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.ParkingSpace@23930626( id: null).
[EL Finest]: 2009.01.11 21:36:21.495--ClientSession(28524838)--Thread(Thread[main,5,main])--Execute query ValueReadQuery(sql="SELECT EL_PARKINGSPACE_SEQ.NEXTVAL FROM DUAL")
[EL Fine]: 2009.01.11 21:36:21.496--ServerSession(12097592)--Connection(5324129)--Thread(Thread[main,5,main])--SELECT EL_PARKINGSPACE_SEQ.NEXTVAL FROM DUAL
[EL Finest]: 2009.01.11 21:36:21.498--ServerSession(12097592)--Thread(Thread[main,5,main])--sequencing preallocation for EL_PARKINGSPACE_SEQ: objects: 25 , first: 1, last: 25
[EL Finest]: 2009.01.11 21:36:21.499--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (1 -> org.eclipse.persistence.example.business.ParkingSpace@23930626( id: null))
[EL Finest]: 2009.01.11 21:36:21.501--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.Address@15594377( id: null).
[EL Finest]: 2009.01.11 21:36:21.502--ClientSession(28524838)--Thread(Thread[main,5,main])--Execute query ValueReadQuery(sql="SELECT EL_ADDRESS_SEQ.NEXTVAL FROM DUAL")
[EL Fine]: 2009.01.11 21:36:21.502--ServerSession(12097592)--Connection(29752800)--Thread(Thread[main,5,main])--SELECT EL_ADDRESS_SEQ.NEXTVAL FROM DUAL
[EL Finest]: 2009.01.11 21:36:21.504--ServerSession(12097592)--Thread(Thread[main,5,main])--sequencing preallocation for EL_ADDRESS_SEQ: objects: 25 , first: 1, last: 25
[EL Finest]: 2009.01.11 21:36:21.504--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (1 -> org.eclipse.persistence.example.business.Address@15594377( id: null))
[EL Warning]: 2009.01.11 21:36:21.786--Thread(Thread[main,5,main])--The em: org.eclipse.persistence.internal.jpa.EntityManagerImpl@1777b1 is already flushing. The query will be executed without further changes being written to the database.  If the query is conditional upon changed data the changes may not be reflected in the results.  Users should issue a flush() call upon completion of the dependent changes and prior to this flush() to ensure correct results.
[EL Finest]: 2009.01.11 21:36:21.787--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query ReadAllQuery(referenceClass=Employee sql="SELECT ID, NAME, ADDRESS_ID, PARKINGSPACE_ID FROM EL_EMPLOYEE")
[EL Fine]: 2009.01.11 21:36:21.789--ServerSession(12097592)--Connection(5324129)--Thread(Thread[main,5,main])--SELECT ID, NAME, ADDRESS_ID, PARKINGSPACE_ID FROM EL_EMPLOYEE
_Address.prePersist() complete: org.eclipse.persistence.example.business.Address@15594377( id: 1)
[EL Finest]: 2009.01.11 21:36:21.802--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.Phone@30008954( id: null).
[EL Finest]: 2009.01.11 21:36:21.802--ClientSession(28524838)--Thread(Thread[main,5,main])--Execute query ValueReadQuery(sql="SELECT EL_PHONE_SEQ.NEXTVAL FROM DUAL")
[EL Fine]: 2009.01.11 21:36:21.802--ServerSession(12097592)--Connection(29752800)--Thread(Thread[main,5,main])--SELECT EL_PHONE_SEQ.NEXTVAL FROM DUAL
[EL Finest]: 2009.01.11 21:36:21.805--ServerSession(12097592)--Thread(Thread[main,5,main])--sequencing preallocation for EL_PHONE_SEQ: objects: 25 , first: 1, last: 25
[EL Finest]: 2009.01.11 21:36:21.805--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (1 -> org.eclipse.persistence.example.business.Phone@30008954( id: null))
_Phone.prePersist() complete: org.eclipse.persistence.example.business.Phone@30008954( id: 1)
[EL Finest]: 2009.01.11 21:36:21.806--UnitOfWork(7634850)--Thread(Thread[main,5,main])--PERSIST operation called on: org.eclipse.persistence.example.business.Phone@3823508( id: null).
[EL Finest]: 2009.01.11 21:36:21.806--UnitOfWork(7634850)--Thread(Thread[main,5,main])--assign sequence to the object (2 -> org.eclipse.persistence.example.business.Phone@3823508( id: null))
_Phone.prePersist() complete: org.eclipse.persistence.example.business.Phone@3823508( id: 2)
[EL Finer]: 2009.01.11 21:36:21.807--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--begin transaction
[EL Finest]: 2009.01.11 21:36:21.808--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.Address@15594377( id: 1))
[EL Fine]: 2009.01.11 21:36:21.808--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_ADDRESS (ID, NAME) VALUES (?, ?)
	bind => [1, name]
[EL Finest]: 2009.01.11 21:36:21.862--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.ParkingSpace@23930626( id: 1))
[EL Fine]: 2009.01.11 21:36:21.863--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_PARKINGSPACE (ID, PARKINGNUMBER) VALUES (?, ?)
	bind => [1, null]
[EL Finest]: 2009.01.11 21:36:21.866--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.Employee@18433730( id: 1))
[EL Fine]: 2009.01.11 21:36:21.866--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_EMPLOYEE (ID, NAME, ADDRESS_ID, PARKINGSPACE_ID) VALUES (?, ?, ?, ?)
	bind => [1, null, null, null]
[EL Finest]: 2009.01.11 21:36:21.919--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.Employee@21684929( id: 2))
[EL Finest]: 2009.01.11 21:36:21.919--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query WriteObjectQuery(org.eclipse.persistence.example.business.Address@15594377( id: 1))
[EL Fine]: 2009.01.11 21:36:21.919--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_EMPLOYEE (ID, NAME, ADDRESS_ID, PARKINGSPACE_ID) VALUES (?, ?, ?, ?)
	bind => [2, xxxx, 1, null]
[EL Finest]: 2009.01.11 21:36:21.924--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.Phone@30008954( id: 1))
[EL Finest]: 2009.01.11 21:36:21.924--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query WriteObjectQuery(org.eclipse.persistence.example.business.Employee@21684929( id: 2))
[EL Fine]: 2009.01.11 21:36:21.925--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_PHONE (ID, PHONENUMBER, EMPLOYEE_ID) VALUES (?, ?, ?)
	bind => [1, 0000000, 2]
[EL Finest]: 2009.01.11 21:36:21.949--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query InsertObjectQuery(org.eclipse.persistence.example.business.Phone@3823508( id: 2))
[EL Finest]: 2009.01.11 21:36:21.950--UnitOfWork(7634850)--Thread(Thread[main,5,main])--Execute query WriteObjectQuery(org.eclipse.persistence.example.business.Employee@21684929( id: 2))
[EL Fine]: 2009.01.11 21:36:21.950--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--INSERT INTO EL_PHONE (ID, PHONENUMBER, EMPLOYEE_ID) VALUES (?, ?, ?)
	bind => [2, 0000000, 2]
[EL Finer]: 2009.01.11 21:36:21.952--UnitOfWork(7634850)--Thread(Thread[main,5,main])--begin unit of work commit
[EL Finer]: 2009.01.11 21:36:21.961--ClientSession(28524838)--Connection(19432672)--Thread(Thread[main,5,main])--commit transaction

StackTrace

This stacktrace is before changes were done to disallow nested flush() calls.

org.eclipse.persistence.example.TestClient at localhost:64236	
	Thread [main] (Suspended)	
		CommitManager.commitChangedObjectsForClassWithChangeSet(UnitOfWorkChangeSet, String) line: 236	
		CommitManager.commitAllObjectsForClassWithChangeSet(UnitOfWorkChangeSet, Class) line: 163	
		CommitManager.commitAllObjectsWithChangeSet(UnitOfWorkChangeSet) line: 116	
		RepeatableWriteUnitOfWork(AbstractSession).writeAllObjectsWithChangeSet(UnitOfWorkChangeSet) line: 3175	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).commitToDatabase(boolean) line: 1271	
		RepeatableWriteUnitOfWork.commitToDatabase(boolean) line: 445	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).commitToDatabaseWithPreBuiltChangeSet(UnitOfWorkChangeSet, boolean) line: 1407	
		RepeatableWriteUnitOfWork.writeChanges() line: 295	
		EntityManagerImpl.flush() line: 543	
		EJBQueryImpl.performPreQueryFlush() line: 1046	
		EJBQueryImpl.executeReadQuery() line: 351	
		EJBQueryImpl.getResultList() line: 600	
		Address.processQuery(EntityManager) line: 83	
		Address.prePersist() line: 73	
		NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]	
		NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39	
		DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25	
		Method.invoke(Object, Object...) line: 597	
		PrivilegedAccessHelper.invokeMethod(Method, Object, Object[]) line: 344	
		EntityClassListener(EntityListener).invokeMethod(Method, Object, Object[], DescriptorEvent) line: 297	
		EntityClassListener.invokeMethod(String, DescriptorEvent) line: 64	
		EntityClassListener(EntityListener).prePersist(DescriptorEvent) line: 412	
		DescriptorEventManager.notifyListener(DescriptorEventListener, DescriptorEvent) line: 650	
		DescriptorEventManager.notifyEJB30Listeners(DescriptorEvent) line: 593	
		DescriptorEventManager.executeEvent(DescriptorEvent) line: 187	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).registerNewObjectClone(Object, Object, ClassDescriptor) line: 3976	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).registerNotRegisteredNewObjectForPersist(Object, ClassDescriptor) line: 3955	
		RepeatableWriteUnitOfWork.registerNotRegisteredNewObjectForPersist(Object, ClassDescriptor) line: 336	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).discoverAndPersistUnregisteredNewObjects(Object, boolean, Map, Map, Map) line: 3857	
		OneToOneMapping(ObjectReferenceMapping).cascadeDiscoverAndPersistUnregisteredNewObjects(Object, Map, Map, Map, UnitOfWorkImpl) line: 713	
		ObjectBuilder.cascadeDiscoverAndPersistUnregisteredNewObjects(Object, Map, Map, Map, UnitOfWorkImpl) line: 1493	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).discoverAndPersistUnregisteredNewObjects(Object, boolean, Map, Map, Map) line: 3871	
		RepeatableWriteUnitOfWork.discoverUnregisteredNewObjects(Map, Map, Map, Map) line: 174	
		RepeatableWriteUnitOfWork(UnitOfWorkImpl).calculateChanges(Map, UnitOfWorkChangeSet, boolean) line: 613	
		RepeatableWriteUnitOfWork.writeChanges() line: 289	
		EntityManagerImpl.flush() line: 543	
		TestClient.prePersistQuery() line: 105	
		TestClient.main(String[]) line: 128	
	

API

GUI

Config files

Documentation

Open Issues

Decisions

Future Considerations

During the research for this bug, the following items were identified as out of scope but are captured here as potential future enhancements. If agreed upon during the review process these should be logged in the bug system.

References

• EclipseLink Fisheye Revision - pending