Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-25419

Default WorkManager in memory cannot disable queue processing

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 7.10, 8.10, 9.10, 10.1, 10.2
    • Fix Version/s: 10.3
    • Component/s: Events / Works
    • Backlog priority:
      900
    • Sprint:
      nxcore 10.3.3, nxcore 10.3.4
    • Story Points:
      3

      Description

      1. install Nuxeo
      2. add the following contribution :
          <extension target="org.nuxeo.ecm.core.work.service" point="queues">
            <queue id="*" processing="false" />
          </extension>
        
      3. add the following logger in $NUXEO_HOME/lib/log4j.xml
      4. start Nuxeo server
      5. observe the following in the logs:
        2018-07-17 09:53:39,268 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue escalation WorkQueueDescriptor[id=escalation categories=[routingEscalation]]
        2018-07-17 09:53:43,559 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Setting on all work queues: processing=false
        2018-07-17 09:53:43,559 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue blobs WorkQueueDescriptor[id=blobs categories=[blobListZip] processing=false maxThreads=2]
        2018-07-17 09:53:43,559 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue default WorkQueueDescriptor[id=default categories=[] processing=false maxThreads=4]
        2018-07-17 09:53:43,559 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue permissionsPurge WorkQueueDescriptor[id=permissionsPurge categories=[permissionsPurge] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue updateACEStatus WorkQueueDescriptor[id=updateACEStatus categories=[updateACEStatus] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue fulltextUpdater WorkQueueDescriptor[id=fulltextUpdater categories=[fulltextUpdater] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue collections WorkQueueDescriptor[id=collections categories=[duplicateCollectionMember, removeFromCollection, removedCollectionMember, removedCollection] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue videoConversion WorkQueueDescriptor[id=videoConversion categories=[videoConversion] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue escalation WorkQueueDescriptor[id=escalation categories=[routingEscalation] processing=false]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue pictureViewsGeneration WorkQueueDescriptor[id=pictureViewsGeneration categories=[pictureViewsGeneration] processing=false maxThreads=1]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue elasticSearchIndexing WorkQueueDescriptor[id=elasticSearchIndexing categories=[elasticSearchIndexing] processing=false maxThreads=4]
        2018-07-17 09:53:43,560 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Registered work queue renditionBuilder WorkQueueDescriptor[id=renditionBuilder categories=[renditionBuilder] processing=false maxThreads=1]
        2018-07-17 09:53:45,916 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue blobs WorkQueueDescriptor(id=blobs categories=[blobListZip] queuing=true processing=false maxThreads=2 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,917 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue default WorkQueueDescriptor(id=default categories=[] queuing=true processing=false maxThreads=4 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,917 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue permissionsPurge WorkQueueDescriptor(id=permissionsPurge categories=[permissionsPurge] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,917 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue updateACEStatus WorkQueueDescriptor(id=updateACEStatus categories=[updateACEStatus] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,918 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue fulltextUpdater WorkQueueDescriptor(id=fulltextUpdater categories=[fulltextUpdater] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,918 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue collections WorkQueueDescriptor(id=collections categories=[duplicateCollectionMember, removeFromCollection, removedCollectionMember, removedCollection] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,918 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue videoConversion WorkQueueDescriptor(id=videoConversion categories=[videoConversion] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,919 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue escalation WorkQueueDescriptor(id=escalation categories=[routingEscalation] queuing=true processing=false maxThreads=4 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,919 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue pictureViewsGeneration WorkQueueDescriptor(id=pictureViewsGeneration categories=[pictureViewsGeneration] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,920 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue elasticSearchIndexing WorkQueueDescriptor(id=elasticSearchIndexing categories=[elasticSearchIndexing] queuing=true processing=false maxThreads=4 capacity=-1 clearCompletedAfterSeconds=)
        2018-07-17 09:53:45,920 INFO  [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Initialized work queue renditionBuilder WorkQueueDescriptor(id=renditionBuilder categories=[renditionBuilder] queuing=true processing=false maxThreads=1 capacity=-1 clearCompletedAfterSeconds=)
        
      6. observe right after the queues intialization, some work is already running:
        2018-07-17 10:07:01,646 DEBUG [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Scheduling work after commit: FulltextUpdaterWork(f4af1adf-40bd-48d3-a370-0eb8645bb184, , Progress(?%, ?/0), null)
        2018-07-17 10:07:01,847 DEBUG [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Scheduling work after commit: FulltextUpdaterWork(d4f7c7a9-779a-4d2e-b8e4-0748e47f9593, , Progress(?%, ?/0), null)
        2018-07-17 10:07:02,042 DEBUG [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Scheduling work immediately: ListenerWork(Listener annotationsVersionEventListener [documentRemoved/a936182a-08d0-4638-b3ab-3423fe269a6d, documentRemoved/65877826-18f1-4701-b22d-aeb06fe2c5f0], Progress(?%, ?/0), null)
        2018-07-17 10:07:02,044 DEBUG [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Scheduling work immediately: ListenerWork(Listener docRemovedCommentListener [documentRemoved/a936182a-08d0-4638-b3ab-3423fe269a6d, documentRemoved/65877826-18f1-4701-b22d-aeb06fe2c5f0], Progress(?%, ?/0), null)
        2018-07-17 10:07:02,044 DEBUG [localhost-startStop-1] [org.nuxeo.ecm.core.work.WorkManagerImpl] Scheduling work immediately: ListenerWork(Listener notificationListener [documentCreated/f4af1adf-40bd-48d3-a370-0eb8645bb184, documentCreated/3842b94c-d603-43e1-987d-004948fb0348, documentCreated/d18e5ef8-c8f4-473e-a1fb-396e2b332b52, documentCreated/e4afdaa9-cd1a-422e-937f-8dbda2a9cb47, documentCreated/faa8347a-2dc7-49d4-b51a-fefa8960772d, documentCreated/c7560924-ac87-47d7-9ab2-82471839ee2d, documentCreated/4399989b-6d9b-4dca-b77a-2aadb33b0886, documentCreated/f7996f04-cd87-4a63-8997-5eb5832a6050, documentModified/f4af1adf-40bd-48d3-a370-0eb8645bb184, documentCreated/d4f7c7a9-779a-4d2e-b8e4-0748e47f9593, documentCreated/fceb1463-7fd0-4af4-9fd0-b60dfe1f811c, documentCreated/6b1aa66c-d82e-4bc6-8dfa-986b39201d9b, documentCreated/94dfa057-6414-4b91-aa06-71f335e3b289, documentCreated/037039bf-c97d-4194-80b8-5c3308e84a33, documentCreated/473e98eb-944f-4010-a194-32214d74e3b4, documentModified/d4f7c7a9-779a-4d2e-b8e4-0748e47f9593], Progress(?%, ?/0), null)
        
      7. try several actions like starting a test work, reindexing Elasticsearch, creating a document. They are all executed.

      Expected behavior: the works should not be processed according to the following documentation:
      https://doc.nuxeo.com/nxdoc/work-and-workmanager/#persistent-work-queues
      Impact: this prevents dedicated nodes for specific processing
      Note: the behavior can be reproduced from 6.0 to 10.1 (didn't try master but didn't find any open bug on the topic).
      Note 2: contribution files attached to this ticket and to be placed in $NUXEO_HOME/nxserver/config
      Note 3: while debugging, it seems there is no check on the queue activation status before starting a Work. For instance awaitCompletion is never called and thus noScheduledOrRunningWork is not called either, not checking here the queue processing status.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Time Spent - 3 days, 1 hour, 30 minutes Remaining Estimate - 3 hours
                  3h
                  Logged:
                  Time Spent - 3 days, 1 hour, 30 minutes Remaining Estimate - 3 hours
                  3d 1h 30m