Ask Question
« General Questions on Nuxeo

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

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.

mark
Member (77)   1   2   2 		02/15/2012 ( History)
0 votes
0 answers
1773 views
ANSWER
Benjamin Jalon
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.

How do you do your update.

Can you answer with editing your question.

Thanks.

02/15/2012
Benjamin Jalon
Did you do a:

session.saveDocument(yourDoc);

and at least at the end of the treatment:

session.save();

?

02/16/2012
Benjamin Jalon
No answers to my remark ??
02/27/2012
mark
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.
03/05/2012
Follow
Tags
Linked Questions
Related Questions
What can mean the following error : unknown connection org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl
I am getting unknown connection org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@37a6bcc6 in org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@32b806ea after updating platform, any know why I am getting this error
I am getting unknown connection
Trouble with Nuxeo 5.5 and MSSQL
Can't save search due to "Unknown type: faceted_search_default_cv"
Start nuxeo fails when constrained by the pool
Error while Nuxeo 5.9.4 start up db schema setup
Can't generate picture thumbnails
Nuxeo-5.9.4 and MS SQL 2005 error