DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

mark_ — Wed, 15 Feb 2012 07:37:23 GMT

We are still using nuxeo 5.3 but we've got a use case where we are creating 200 documents and calling followTransition to a particular state. This works on between 193-198 of the documents, but for the remaining 2-7 documents they are unchanged and still in the original lifeCycleState. All the other changes that are being made are persisted to the document.

Is there anything special about the followTransition() method call that would be persisted differently to any other DocumentModel.setProperty() call?

This is the method that is being called :

private boolean followTransition(DocumentModel doc, String transition)
{
    try
    {
        LOG.info("Trying to follow a transition for ad (" + getAdvertNumber(doc) + ") with transition : " + transition);

        if (doc.getAllowedStateTransitions().contains(transition))
        {
            LOG.info("Processing state change for ad (" + getAdvertNumber(doc) + ") with transition : " + transition);
            doc.followTransition(transition);
            return true;
        }
    }
    catch (ClientException e)
    {
        LOG.error("Failed to transition private ad : " + doc.getId() + " with transition : " + transition);
    }

    return false;
}

Here is a log excerpt from the "Processing state change...." log message :

2012-02-16 11:37:43,941 INFO  [com.base2.ecm.just.ws.PrivateAdServiceBean] Processing state change for ad (ATF2721953) with transition : to_valid
2012-02-16 11:37:43,941 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Initializing session for repository: default
2012-02-16 11:37:43,941 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@2fa56884
2012-02-16 11:37:43,941 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@505d7d2e
2012-02-16 11:37:43,942 INFO  [com.base2.ecm.just.search.solr.DelayedIndexOperation] Set the index operation for id : 87c03427-1bde-4abb-a917-fcd6ff0d7584 to be requested at : 1329352663942.  toString() : 87c03427-1bde-4abb-a917-fcd6ff0d7584 due in 2000ms but will wait another 2000
2012-02-16 11:37:43,942 INFO  [com.base2.ecm.just.search.solr.IndexingQueue] Indexing already scheduled for 87c03427-1bde-4abb-a917-fcd6ff0d7584 current queue : [2afd86ae-7e5b-4431-bed1-5bdefbb41d29 due in 248ms, 87c03427-1bde-4abb-a917-fcd6ff0d7584 due in 1966ms]
2012-02-16 11:37:43,942 INFO  [com.base2.ecm.just.processors.PostCommitDocumentEventListener] Triggered an index for event : lifecycle_transition_event
2012-02-16 11:37:43,942 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2012-02-16 11:37:43,943 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2012-02-16 11:37:43,943 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@2fa56884
2012-02-16 11:37:43,943 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@505d7d2e
2012-02-16 11:37:43,988 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@5bfb2122
2012-02-16 11:37:43,988 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] NXLoginModule initialized
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] UserIdentificationInfoCallback is not supported
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] createIdentity: Guest
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] getRoleSets
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Getting roles for user=Guest
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Found role=regular
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Initializing session for repository: default
2012-02-16 11:37:43,990 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@5bfb2122
2012-02-16 11:37:43,990 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@2396ba1b
2012-02-16 11:37:43,990 DEBUG [org.nuxeo.ecm.platform.versioning.listeners.DocVersioningEventListener] req: BasicVersionChangeRequest {source=RequestSource: Auto, initial state=null, final state=null}
2012-02-16 11:37:43,992 INFO  [com.base2.ecm.just.search.solr.IndexingQueue] Indexing scheduled for e58485c0-680b-4507-9215-e649b65acaeb
2012-02-16 11:37:43,992 INFO  [com.base2.ecm.just.processors.PostCommitDocumentEventListener] Triggered an index for event : beforeDocumentModification
2012-02-16 11:37:43,993 INFO  [com.base2.ecm.just.search.solr.DelayedIndexOperation] Set the index operation for id : e58485c0-680b-4507-9215-e649b65acaeb to be requested at : 1329352663993.  toString() : e58485c0-680b-4507-9215-e649b65acaeb due in 1000ms but will wait another 1000
2012-02-16 11:37:43,993 INFO  [com.base2.ecm.just.search.solr.IndexingQueue] Indexing already scheduled for e58485c0-680b-4507-9215-e649b65acaeb current queue : [2afd86ae-7e5b-4431-bed1-5bdefbb41d29 due in 197ms, 87c03427-1bde-4abb-a917-fcd6ff0d7584 due in 1915ms, e58485c0-680b-4507-9215-e649b65acaeb due in 999ms]
2012-02-16 11:37:43,993 INFO  [com.base2.ecm.just.processors.PostCommitDocumentEventListener] Triggered an index for event : documentModified
2012-02-16 11:37:43,993 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2012-02-16 11:37:43,995 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2012-02-16 11:37:43,995 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2012-02-16 11:37:43,995 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@30a24357
2012-02-16 11:37:43,995 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@15e093ce
2012-02-16 11:37:43,999 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2012-02-16 11:37:43,999 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@5bfb2122
2012-02-16 11:37:43,999 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@2396ba1b
2012-02-16 11:37:44,047 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@ad62822
2012-02-16 11:37:44,047 DEBUG [org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed, commited tx
2012-02-16 11:37:44,047 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] @Remove
2012-02-16 11:37:44,047 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] @PreDestroy
2012-02-16 11:37:44,047 DEBUG [org.nuxeo.ecm.core.api.CoreSession] Destroying core session ...
2012-02-16 11:37:44,049 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] URI: default
2012-02-16 11:37:44,049 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Add caller principal to the session context....
2012-02-16 11:37:44,049 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Initializing session for repository: default
2012-02-16 11:37:44,049 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@ad62822
2012-02-16 11:37:44,049 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@25168fea
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@ad62822
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@25168fea
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@ad62822
2012-02-16 11:37:44,050 DEBUG [org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed, commited tx
2012-02-16 11:37:44,051 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] @Remove
2012-02-16 11:37:44,051 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] @PreDestroy
2012-02-16 11:37:44,051 DEBUG [org.nuxeo.ecm.core.api.CoreSession] Destroying core session ...
2012-02-16 11:37:44,053 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] URI: default
2012-02-16 11:37:44,053 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Add caller principal to the session context....
2012-02-16 11:37:44,053 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Initializing session for repository: default
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@2fa56884
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@ad62822
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@29a33f76
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] NXLoginModule initialized
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] UserIdentificationInfoCallback is not supported
2012-02-16 11:37:44,054 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] createIdentity: Guest
2012-02-16 11:37:44,055 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] getRoleSets
2012-02-16 11:37:44,055 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Getting roles for user=Guest
2012-02-16 11:37:44,055 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Found role=regular
2012-02-16 11:37:44,056 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean] Initializing session for repository: default
2012-02-16 11:37:44,056 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@2fa56884
2012-02-16 11:37:44,056 DEBUG [org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@5bab0fcf
2012-02-16 11:37:44,056 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2012-02-16 11:37:44,056 DEBUG [org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save

I've noticed that this snippet seems to fire after the lifecycle_transition_event when it fails :

2012-02-16 11:37:43,988 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] NXLoginModule initialized
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] UserIdentificationInfoCallback is not supported
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] createIdentity: Guest
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] getRoleSets
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Getting roles for user=Guest
2012-02-16 11:37:43,989 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule] Found role=regular

If I look at the history tab of this document then there are 2 records that says 'Document lifecycle update', but the State field has not changed.

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Benjamin_Jalon1 — Wed, 15 Feb 2012 09:32:28 GMT

Do you have any trace in your logs ? All is transactional so if you request a follow transition action for your 200 documents, this must be done or if any trouble occurred, you must have trace in your logs.

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Benjamin_Jalon1 — Thu, 16 Feb 2012 10:25:53 GMT

Did you do a

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Benjamin_Jalon1 — Mon, 27 Feb 2012 09:09:33 GMT

No answers to my remark ??

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

mark_ — Mon, 05 Mar 2012 05:45:15 GMT

Sorry, took me a while to reply. Performing a saveDocument() and a save() reduced the occurence the bug to roughly 1 in 400. So an improvement, but still happening.

topic Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState in Nuxeo Forum

DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState

Re: DocumentModel.followTransition() intermittently not persisting to misc.lifeCycleState