Uploaded image for project: 'Magnolia Synchronization Module'
  1. Magnolia Synchronization Module
  2. MGNLSYNC-42

Synchronization manager does not complete normally

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Neutral
    • Resolution: Fixed
    • Affects Version/s: 1.8, 1.9
    • Fix Version/s: 1.8.3, 1.9
    • Component/s: Core, REST
    • Labels:
      None
    • Release notes required:
      Yes
    • Documentation update required:
      Yes
    • Sprint:
      Maintenance 10, HL & LD 5, HL & LD 6
    • Story Points:
      8
    • Magnolia Release:
      5.7.8, 6.2.2

      Description

      Using version 1.9-beta2 I find that synchronizations are not finishing normally. The log will claim the sync has been completed but the system workspace is still filled with nodes that have not been cleaned. I'm also getting part of the website sync'd.

      Public side log with info.magnolia.publishing set for DEBUG.

      2020-05-25 13:55:41,937 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 132:1590407741936 Requesting XA lock
      2020-05-25 13:55:41,939 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/
      2020-05-25 13:55:41,947 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-696 DID locked magnolia-mgnlSystem:/website-rootLock
      2020-05-25 13:55:41,947 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 132:1590407741936 Got clearance for JCR lock on parent node /
      2020-05-25 13:55:41,947 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
      2020-05-25 13:55:41,948 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 132:1590407741936 Starting content publication
      2020-05-25 13:55:41,948 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 132:1590407741936 Checking for existence of content website:b06b82a2-74b0-4994-8015-028c4fd60716
      2020-05-25 13:55:41,948 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 132:1590407741936 b06b82a2-74b0-4994-8015-028c4fd60716 doesn't exist in website and will be imported under parent path: /
      2020-05-25 13:55:41,948 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing travel into parent path /
      2020-05-25 13:55:41,959 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing main into parent path /travel
      ...
      ...
      2020-05-25 13:55:43,192 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 132:1590407741936 User superuser successfully published website:/travel on magnoliaPublic.
      2020-05-25 13:55:43,193 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Ordering travel before sportstation
      2020-05-25 13:55:43,260 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-696 DID unlocked magnolia-mgnlSystem:/website-rootLock
      2020-05-25 13:55:43,311 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 133:1590407743311 Requesting XA lock
      2020-05-25 13:55:43,311 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel
      2020-05-25 13:55:43,330 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-697 DID locked website:/travel
      2020-05-25 13:55:43,330 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 133:1590407743311 Got clearance for JCR lock on parent node /travel
      2020-05-25 13:55:43,331 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
      2020-05-25 13:55:43,331 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 133:1590407743311 Starting content publication
      2020-05-25 13:55:43,331 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 133:1590407743311 Checking for existence of content website:05872876-073e-40a3-a3c5-0d0a18c1d43d
      2020-05-25 13:55:43,331 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 133:1590407743311 05872876-073e-40a3-a3c5-0d0a18c1d43d doesn't exist in website and will be imported under parent path: /travel
      2020-05-25 13:55:43,331 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing tour-type into parent path /
      2020-05-25 13:55:43,339 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing main into parent path /tour-type
      ...
      ...
      2020-05-25 13:55:43,484 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 133:1590407743311 User superuser successfully published website:/travel/tour-type on magnoliaPublic.
      2020-05-25 13:55:43,520 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-697 DID unlocked website:/travel
      2020-05-25 13:55:43,608 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 129:1590407743608 Requesting XA lock
      2020-05-25 13:55:43,609 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel
      2020-05-25 13:55:43,627 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-699 DID locked website:/travel
      2020-05-25 13:55:43,627 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 129:1590407743608 Got clearance for JCR lock on parent node /travel
      2020-05-25 13:55:43,627 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
      2020-05-25 13:55:43,630 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 129:1590407743608 Starting content publication
      2020-05-25 13:55:43,630 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 129:1590407743608 Checking for existence of content website:028a4a92-35df-45a3-b6ff-58381db74eb5
      2020-05-25 13:55:43,630 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 129:1590407743608 028a4a92-35df-45a3-b6ff-58381db74eb5 doesn't exist in website and will be imported under parent path: /travel
      2020-05-25 13:55:43,630 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing destination into parent path /
      2020-05-25 13:55:43,636 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing main into parent path /destination
      2020-05-25 13:55:43,639 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing 0 into parent path /destination/main
      2020-05-25 13:55:43,642 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing 00 into parent path /destination/main
      2020-05-25 13:55:43,648 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing 02 into parent path /destination/main
      2020-05-25 13:55:43,656 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing 01 into parent path /destination/main
      2020-05-25 13:55:43,666 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer into parent path /destination
      ...
      ...
      2020-05-25 13:55:43,792 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 129:1590407743608 User superuser successfully published website:/travel/destination on magnoliaPublic.
      2020-05-25 13:55:43,813 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-699 DID unlocked website:/travel
      2020-05-25 13:55:43,877 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 127:1590407743877 Requesting XA lock
      2020-05-25 13:55:43,878 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel
      2020-05-25 13:55:43,894 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-701 DID locked website:/travel
      2020-05-25 13:55:43,894 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 127:1590407743877 Got clearance for JCR lock on parent node /travel
      2020-05-25 13:55:43,894 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
      2020-05-25 13:55:43,895 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 127:1590407743877 Starting content publication
      2020-05-25 13:55:43,895 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 127:1590407743877 Checking for existence of content website:af4cd608-2dda-4535-a5e0-703ef92fd45a
      2020-05-25 13:55:43,895 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 127:1590407743877 af4cd608-2dda-4535-a5e0-703ef92fd45a doesn't exist in website and will be imported under parent path: /travel
      2020-05-25 13:55:43,895 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing tour into parent path /
      ...
      ...
      2020-05-25 13:55:44,026 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 127:1590407743877 User superuser successfully published website:/travel/tour on magnoliaPublic.
      2020-05-25 13:55:44,053 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-701 DID unlocked website:/travel
      

      Trying to call sync again leads to:

      2020-05-25 13:57:14,623 DEBUG ional.receiver.locking.TransactionalJcrLockManager: About to begin publish of website:b06b82a2-74b0-4994-8015-028c4fd60716:/travel
      2020-05-25 13:57:14,624 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Requesting XA lock
      2020-05-25 13:57:14,625 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 10 more times.
      2020-05-25 13:57:16,628 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 9 more times.
      2020-05-25 13:57:18,630 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 8 more times.
      2020-05-25 13:57:20,635 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 7 more times.
      2020-05-25 13:57:22,639 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 6 more times.
      2020-05-25 13:57:24,639 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 5 more times.
      2020-05-25 13:57:26,644 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 4 more times.
      2020-05-25 13:57:28,645 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 3 more times.
      2020-05-25 13:57:30,646 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 2 more times.
      2020-05-25 13:57:32,646 INFO  ional.receiver.locking.TransactionalJcrLockManager: 129:1590407834622 Node /travel is locked by transaction. Will retry 1 more times.
      2020-05-25 13:57:34,649 ERROR receiver.operation.jcr.AbstractJcrReceiveOperation: Operation not permitted, /travel is locked by unfinished transaction.
      info.magnolia.publishing.locking.LockManager$LockException: Operation not permitted, /travel is locked by unfinished transaction.
      	at info.magnolia.publishing.transactional.receiver.locking.TransactionalJcrLockManager.applyLock(TransactionalJcrLockManager.java:128) ~[magnolia-publishing-transactional-receiver-1.0.5.jar:?]
      	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.preExecute(AbstractJcrReceiveOperation.java:174) ~[magnolia-publishing-receiver-1.2.jar:?]
      	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.execute(AbstractJcrReceiveOperation.java:146) [magnolia-publishing-receiver-1.2.jar:?]
      	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.execute(JcrTransactionPublicationOperation.java:87) [magnolia-publishing-transactional-receiver-1.0.5.jar:?]
      	at info.magnolia.publishing.dispatcher.AbstractDispatcher.dispatch(AbstractDispatcher.java:105) [magnolia-publishing-core-1.2.jar:?]
      	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:57) [magnolia-publishing-transactional-receiver-1.0.5.jar:?]
      	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:38) [magnolia-publishing-transactional-receiver-1.0.5.jar:?]
      	at info.magnolia.publishing.receiver.filter.PublicationFilter.doFilter(PublicationFilter.java:61) [magnolia-publishing-receiver-1.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:127) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:79) [magnolia-module-enterprise-6.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:151) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:92) [magnolia-personalization-preview-app-2.0.jar:?]
      	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:155) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:110) [magnolia-core-6.2.jar:?]
      	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:96) [magnolia-core-6.2.jar:?]
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:9.0.31]
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:9.0.31]
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) [catalina.jar:9.0.31]
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:9.0.31]
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [catalina.jar:9.0.31]
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [catalina.jar:9.0.31]
      	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [catalina.jar:9.0.31]
      	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:688) [catalina.jar:9.0.31]
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [catalina.jar:9.0.31]
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [catalina.jar:9.0.31]
      	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367) [tomcat-coyote.jar:9.0.31]
      	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.31]
      	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-coyote.jar:9.0.31]
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639) [tomcat-coyote.jar:9.0.31]
      	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:9.0.31]
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.31]
      	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
      

      Trying to call a sync on the entire travel site only published 4 pages.

        Attachments

        1. mgnl-system.png
          mgnl-system.png
          112 kB
        2. partial-sync.png
          partial-sync.png
          55 kB
        3. synchronization-5.7.pdf
          89 kB
        4. synchronization-tests.pdf
          122 kB
        5. travel-book-tour.png
          travel-book-tour.png
          71 kB
        6. unlock.png
          unlock.png
          101 kB

          Issue Links

            Activity

              People

              Assignee:
              canh.nguyen Canh Nguyen
              Reporter:
              rgange Richard Gange
              Votes:
              1 Vote for this issue
              Watchers:
              8 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0d
                  0d
                  Logged:
                  Time Spent - 5d 3h
                  5d 3h