[PUBLISHING-88] Keep track of lock owners with session data Created: 28/Aug/20  Updated: 29/Mar/22  Resolved: 01/Sep/20

Status: Closed
Project: Publishing
Component/s: None
Affects Version/s: 1.1.5, 1.2.1
Fix Version/s: 1.1.6, 1.2.2

Type: Improvement Priority: Neutral
Reporter: Richard Gange Assignee: Federico Grilli
Resolution: Done Votes: 0
Labels: maintenance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: XML File scripts.lockNodeScript.xml    
Issue Links:
relation
is related to EEPUBLISH-28 Recurring Problem With Node Locking A... Closed
is related to EEPUBLISH-29 Add extra debug logging Closed
is related to PUBLISHING-86 Provide an app to clear activation locks Closed
Template:
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Date of First Response:
Sprint: Maintenance 22
Story Points: 1
Team: Nucleus

 Description   

When we lock an item for publication we should put some data into ownerInfo field so we can better track the locks.

Example using /travel/strories/story.

Successful publish:

2020-08-29 09:07:05,380 DEBUG ional.receiver.locking.TransactionalJcrLockManager: About to begin publish of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story
2020-08-29 09:07:05,381 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 373:1598684825376 Requesting XA lock
2020-08-29 09:07:05,384 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-29 09:07:05,421 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-267 DID locked website:/travel/stories
2020-08-29 09:07:05,423 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 373:1598684825376 Got clearance for JCR lock on parent node /travel/stories
2020-08-29 09:07:05,423 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
2020-08-29 09:07:05,423 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 373:1598684825376 Starting content publication
2020-08-29 09:07:05,423 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 373:1598684825376 Checking for existence of content website:a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-29 09:07:05,423 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 373:1598684825376 Content a096ec20-c190-4b2e-91a4-294c99b64049 was located under path website:/travel/stories/story
2020-08-29 09:07:05,513 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: Stored content website:/travel/stories/story:a096ec20-c190-4b2e-91a4-294c99b64049 for rollback later
2020-08-29 09:07:05,560 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 373:1598684825376 User superuser successfully published website:/travel/stories/story on dx-core-webapp.
2020-08-29 09:07:05,560 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Ordering story before main
2020-08-29 09:07:05,590 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-267 DID unlocked website:/travel/stories
2020-08-29 09:07:05,603 DEBUG ional.receiver.locking.TransactionalJcrLockManager: About to begin commit of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story
2020-08-29 09:07:05,603 DEBUG info.magnolia.publishing.locking.JcrLockManager   : node uuid:a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-29 09:07:05,620 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-269 DID locked website:/travel/stories/story
2020-08-29 09:07:05,620 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 370 Got clearance for JCR lock on parent node /travel/stories/story
2020-08-29 09:07:05,620 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 370 Proceeding with commit of content a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-29 09:07:05,637 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 370 Commited node a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-29 09:07:05,647 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-269 DID unlocked website:/travel/stories/story

Lock node on public using a groovy script. Provide ctx info about who locked the node.

import javax.jcr.Session
import info.magnolia.context.MgnlContext
 
session = MgnlContext.getJCRSession("website");
lockManager = session.getWorkspace().getLockManager();
lockManager.lock("/travel/stories", true, true, 15000, "groovy-lock-" + session);
session.save();

println lockManager.isLocked("/travel/stories")

Unsuccessful publish:

2020-08-31 15:01:28,198 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 340 About to begin publish of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story:session-admin-317
2020-08-31 15:01:28,198 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 340 Requesting XA lock for node:node /travel/stories/story, session:session-admin-317
2020-08-31 15:01:28,202 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:28,203 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 10 more times.
2020-08-31 15:01:30,206 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:30,206 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 9 more times.
2020-08-31 15:01:32,210 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:32,210 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 8 more times.
2020-08-31 15:01:34,210 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:34,211 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 7 more times.
2020-08-31 15:01:36,216 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:36,216 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 6 more times.
2020-08-31 15:01:38,221 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:38,221 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 5 more times.
2020-08-31 15:01:40,222 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:40,222 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 4 more times.
2020-08-31 15:01:42,227 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:42,227 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 3 more times.
2020-08-31 15:01:44,232 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:44,232 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 2 more times.
2020-08-31 15:01:46,236 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:01:46,237 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 1 more times.
2020-08-31 15:01:48,242 ERROR info.magnolia.publishing.locking.JcrLockManager   : Cannot acquire lock [owner: groovy-session-session-admin-293 expires: 241.17 mins]
2020-08-31 15:01:48,243 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 340 Cannot lock node node /travel/stories/story, another transaction using the node is still progress
2020-08-31 15:01:48,243 INFO  ional.receiver.locking.TransactionalJcrLockManager: 340 Node /travel/stories/story is locked by transaction. Will retry 10 more times.
2020-08-31 15:01:50,248 ERROR ional.receiver.locking.TransactionalJcrLockManager: Operation not permitted, /travel/stories is locked
2020-08-31 15:01:50,248 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
2020-08-31 15:01:50,248 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 340 Starting content publication
2020-08-31 15:01:50,248 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 340 Checking for existence of content website:a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-31 15:01:50,248 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 340 Content a096ec20-c190-4b2e-91a4-294c99b64049 was located under path website:/travel/stories/story
2020-08-31 15:01:50,339 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: Stored content website:/travel/stories/story:a096ec20-c190-4b2e-91a4-294c99b64049 for rollback later
2020-08-31 15:01:50,393 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 340 User superuser successfully published website:/travel/stories/story on dx-core-webapp.
2020-08-31 15:01:50,394 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Ordering story before main
2020-08-31 15:01:50,395 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Failed to order node
javax.jcr.lock.LockException: Node locked.
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:694) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:670) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:655) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.XALockManager.checkLock(XALockManager.java:174) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkLock(ItemValidator.java:367) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkCondition(ItemValidator.java:288) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkModify(ItemValidator.java:248) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.NodeImpl.orderBefore(NodeImpl.java:1470) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.NodeImpl.orderBefore(NodeImpl.java:1861) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.orderBefore(MgnlPropertySettingNodeWrapper.java:222) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.orderChildNodes(AbstractJcrReceiveOperation.java:390) ~[magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.orderImportedNode(AbstractJcrReceiveOperation.java:312) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.postExecute(AbstractJcrReceiveOperation.java:182) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.execute(AbstractJcrReceiveOperation.java:148) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.execute(JcrTransactionPublicationOperation.java:87) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.dispatcher.AbstractDispatcher.dispatch(AbstractDispatcher.java:105) [magnolia-publishing-core-1.2.2-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:57) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:1) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.receiver.filter.PublicationFilter.doFilter(PublicationFilter.java:61) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:127) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:79) [magnolia-module-enterprise-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:151) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:92) [magnolia-personalization-preview-app-2.0.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:155) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:110) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:96) [magnolia-core-6.2.2.jar:?]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:9.0.37]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:9.0.37]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [catalina.jar:9.0.37]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [catalina.jar:9.0.37]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:9.0.37]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_261]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_261]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.37]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_261]
2020-08-31 15:01:50,411 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Ordering story before footer
2020-08-31 15:01:50,411 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Failed to order node
javax.jcr.lock.LockException: Node locked.
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:694) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:670) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:655) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.XALockManager.checkLock(XALockManager.java:174) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkLock(ItemValidator.java:367) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkCondition(ItemValidator.java:288) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkModify(ItemValidator.java:248) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.NodeImpl.orderBefore(NodeImpl.java:1470) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.NodeImpl.orderBefore(NodeImpl.java:1861) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingNodeWrapper.orderBefore(MgnlPropertySettingNodeWrapper.java:222) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateNodeWrapper.orderBefore(DelegateNodeWrapper.java:339) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.orderChildNodes(AbstractJcrReceiveOperation.java:390) ~[magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.orderImportedNode(AbstractJcrReceiveOperation.java:312) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.postExecute(AbstractJcrReceiveOperation.java:182) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.execute(AbstractJcrReceiveOperation.java:148) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.execute(JcrTransactionPublicationOperation.java:87) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.dispatcher.AbstractDispatcher.dispatch(AbstractDispatcher.java:105) [magnolia-publishing-core-1.2.2-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:57) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:1) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.receiver.filter.PublicationFilter.doFilter(PublicationFilter.java:61) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:127) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:79) [magnolia-module-enterprise-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:151) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:92) [magnolia-personalization-preview-app-2.0.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:155) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:110) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:96) [magnolia-core-6.2.2.jar:?]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:9.0.37]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:9.0.37]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [catalina.jar:9.0.37]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [catalina.jar:9.0.37]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:9.0.37]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_261]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_261]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.37]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_261]
2020-08-31 15:01:50,413 WARN  info.magnolia.publishing.locking.JcrLockManager   : Node not locked by session: f8cbedd6-df91-4d7c-a952-2dc414d97704
2020-08-31 15:01:50,456 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 347 About to begin commit of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story:session-admin-319
2020-08-31 15:01:50,456 DEBUG info.magnolia.publishing.locking.JcrLockManager   : node uuid:a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-31 15:01:50,477 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-319 DID locked website:/travel/stories/story
2020-08-31 15:01:50,477 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 347 Got clearance for JCR lock on parent node /travel/stories/story
2020-08-31 15:01:50,477 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 347 Proceeding with commit of content a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-31 15:01:50,477 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 347 session:session-admin-320
2020-08-31 15:01:50,478 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 347 Removing node:node /story
2020-08-31 15:01:50,494 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 347 Committed node a096ec20-c190-4b2e-91a4-294c99b64049
2020-08-31 15:01:50,507 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-319 DID unlocked website:/travel/stories/story

Now we can see the node was locked by a groovy session:

2020-08-31 15:01:48,242 ERROR info.magnolia.publishing.locking.JcrLockManager   : Cannot acquire lock [owner: groovy-session-session-admin-293 expires: 241.17 mins]


 Comments   
Comment by Richard Gange [ 31/Aug/20 ]

Move operation

Successful

2020-08-31 15:06:24,750 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 339 About to begin publish of website:64cc52a3-326f-40b9-b021-c980f2959447:/sportstation/about:session-admin-330
2020-08-31 15:06:24,750 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 339 Requesting XA lock for node:node /sportstation/about, session:session-admin-330
2020-08-31 15:06:26,083 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/sportstation/tour
2020-08-31 15:06:26,109 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-330 DID locked website:/sportstation/tour
2020-08-31 15:06:26,110 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 339 Got clearance for JCR lock on parent node /sportstation/tour
2020-08-31 15:06:26,110 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
2020-08-31 15:06:26,110 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 339 Starting content publication
2020-08-31 15:06:26,110 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 339 Checking for existence of content website:64cc52a3-326f-40b9-b021-c980f2959447
2020-08-31 15:06:26,110 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 339 Content 64cc52a3-326f-40b9-b021-c980f2959447 was located under path website:/sportstation/about
2020-08-31 15:06:26,148 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: Stored content website:/sportstation/about:64cc52a3-326f-40b9-b021-c980f2959447 for rollback later
2020-08-31 15:06:26,148 INFO  receiver.operation.jcr.AbstractJcrReceiveOperation: Moving content from /sportstation/about to /sportstation/tour/about due to activation request.
2020-08-31 15:06:27,504 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Child removal [node /sportstation/tour/about] done in session: website:session-admin-330
2020-08-31 15:06:27,517 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Child removal [node /sportstation/tour/about] done in session: website:session-admin-330
2020-08-31 15:06:27,517 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing main into parent path /sportstation/tour/about
2020-08-31 15:06:27,519 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing 0 into parent path /sportstation/tour/about/main
2020-08-31 15:06:27,522 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer into parent path /sportstation/tour/about
2020-08-31 15:06:27,524 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer1 into parent path /sportstation/tour/about/footer
2020-08-31 15:06:27,525 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer2 into parent path /sportstation/tour/about/footer
2020-08-31 15:06:27,527 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer3 into parent path /sportstation/tour/about/footer
2020-08-31 15:06:27,530 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing footer4 into parent path /sportstation/tour/about/footer
2020-08-31 15:06:27,532 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Importing lastLinks into parent path /sportstation/tour/about/footer
2020-08-31 15:06:27,698 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 339 User superuser successfully published website:/sportstation/tour/about on dx-core-webapp.
2020-08-31 15:06:27,733 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-330 DID unlocked website:/sportstation/tour
2020-08-31 15:06:27,743 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 340 About to begin commit of website:64cc52a3-326f-40b9-b021-c980f2959447:/sportstation/tour/about:session-admin-339
2020-08-31 15:06:27,743 DEBUG info.magnolia.publishing.locking.JcrLockManager   : node uuid:64cc52a3-326f-40b9-b021-c980f2959447
2020-08-31 15:06:27,767 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-339 DID locked website:/sportstation/tour/about
2020-08-31 15:06:27,767 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 340 Got clearance for JCR lock on parent node /sportstation/tour/about
2020-08-31 15:06:27,767 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 340 Proceeding with commit of content 64cc52a3-326f-40b9-b021-c980f2959447
2020-08-31 15:06:27,768 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 340 session:session-admin-340
2020-08-31 15:06:27,768 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 340 Removing node:node /about
2020-08-31 15:06:27,787 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 340 Committed node 64cc52a3-326f-40b9-b021-c980f2959447
2020-08-31 15:06:27,799 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-339 DID unlocked website:/sportstation/tour/about

Unsuccessful

2020-08-31 15:09:24,708 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 343 About to begin publish of website:64cc52a3-326f-40b9-b021-c980f2959447:/sportstation/tour/about:session-admin-345
2020-08-31 15:09:24,708 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 343 Requesting XA lock for node:node /sportstation/tour/about, session:session-admin-345
2020-08-31 15:09:24,709 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:24,709 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 10 more times.
2020-08-31 15:09:26,712 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:26,713 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 9 more times.
2020-08-31 15:09:28,718 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:28,718 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 8 more times.
2020-08-31 15:09:30,723 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:30,723 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 7 more times.
2020-08-31 15:09:32,728 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:32,728 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 6 more times.
2020-08-31 15:09:34,733 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:34,733 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 5 more times.
2020-08-31 15:09:36,736 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:36,736 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 4 more times.
2020-08-31 15:09:38,739 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:38,739 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 3 more times.
2020-08-31 15:09:40,744 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:40,744 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 2 more times.
2020-08-31 15:09:42,748 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-08-31 15:09:42,749 INFO  info.magnolia.publishing.locking.JcrLockManager   : Node /travel/stories is locked. Will retry 1 more times.
2020-08-31 15:09:44,754 ERROR info.magnolia.publishing.locking.JcrLockManager   : Cannot acquire lock [owner: groovy-session-session-admin-293 expires: 233.22 mins]
2020-08-31 15:09:44,754 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 343 Cannot lock node node /sportstation/tour/about, another transaction using the node is still progress
2020-08-31 15:09:44,754 INFO  ional.receiver.locking.TransactionalJcrLockManager: 343 Node /sportstation/tour/about is locked by transaction. Will retry 10 more times.
2020-08-31 15:09:46,758 ERROR ional.receiver.locking.TransactionalJcrLockManager: Operation not permitted, /travel/stories is locked
2020-08-31 15:09:46,758 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
2020-08-31 15:09:46,759 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 343 Starting content publication
2020-08-31 15:09:46,759 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 343 Checking for existence of content website:64cc52a3-326f-40b9-b021-c980f2959447
2020-08-31 15:09:46,759 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 343 Content 64cc52a3-326f-40b9-b021-c980f2959447 was located under path website:/sportstation/tour/about
2020-08-31 15:09:46,834 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: Stored content website:/sportstation/tour/about:64cc52a3-326f-40b9-b021-c980f2959447 for rollback later
2020-08-31 15:09:46,834 INFO  receiver.operation.jcr.AbstractJcrReceiveOperation: Moving content from /sportstation/tour/about to /travel/stories/about due to activation request.
2020-08-31 15:09:46,835 ERROR receiver.operation.jcr.AbstractJcrReceiveOperation: Node locked.
info.magnolia.publishing.operation.ReceiveOperation$OperationExecutionException: Node locked.
	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.doExecute(JcrTransactionPublicationOperation.java:114) ~[magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.JcrPublicationOperation.doExecute(JcrPublicationOperation.java:78) ~[magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.execute(AbstractJcrReceiveOperation.java:147) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.execute(JcrTransactionPublicationOperation.java:87) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.dispatcher.AbstractDispatcher.dispatch(AbstractDispatcher.java:105) [magnolia-publishing-core-1.2.2-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:57) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.transactional.receiver.dispatcher.TransactionalHeadersDispatcher.dispatch(TransactionalHeadersDispatcher.java:1) [magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	at info.magnolia.publishing.receiver.filter.PublicationFilter.doFilter(PublicationFilter.java:61) [magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:127) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:79) [magnolia-module-enterprise-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:151) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:92) [magnolia-personalization-preview-app-2.0.2.jar:?]
	at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:155) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:110) [magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:96) [magnolia-core-6.2.2.jar:?]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:9.0.37]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:9.0.37]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [catalina.jar:9.0.37]
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690) [catalina.jar:9.0.37]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [catalina.jar:9.0.37]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [catalina.jar:9.0.37]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.37]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) [tomcat-coyote.jar:9.0.37]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:9.0.37]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_261]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_261]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.37]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_261]
Caused by: javax.jcr.lock.LockException: Node locked.
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:694) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:670) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:655) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.lock.XALockManager.checkLock(XALockManager.java:174) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkLock(ItemValidator.java:367) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkCondition(ItemValidator.java:288) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.ItemValidator.checkModify(ItemValidator.java:248) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.SessionMoveOperation.perform(SessionMoveOperation.java:141) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:216) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:363) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at org.apache.jackrabbit.core.SessionImpl.move(SessionImpl.java:909) ~[jackrabbit-core-2.20.0.jar:2.20.0]
	at info.magnolia.jcr.wrapper.DelegateSessionWrapper.move(DelegateSessionWrapper.java:267) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateSessionWrapper.move(DelegateSessionWrapper.java:267) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorSessionWrapper.move(ContentDecoratorSessionWrapper.java:164) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.cms.core.version.MgnlVersioningSession.move(MgnlVersioningSession.java:178) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateSessionWrapper.move(DelegateSessionWrapper.java:267) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorSessionWrapper.move(ContentDecoratorSessionWrapper.java:164) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.MgnlPropertySettingContentDecorator$MgnlPropertySettingSessionWrapper.move(MgnlPropertySettingContentDecorator.java:517) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateSessionWrapper.move(DelegateSessionWrapper.java:267) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorSessionWrapper.move(ContentDecoratorSessionWrapper.java:164) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.audit.MgnlAuditLoggingContentDecoratorSessionWrapper.move(MgnlAuditLoggingContentDecoratorSessionWrapper.java:67) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.DelegateSessionWrapper.move(DelegateSessionWrapper.java:267) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.decoration.ContentDecoratorSessionWrapper.move(ContentDecoratorSessionWrapper.java:164) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.jcr.wrapper.MagnoliaSessionWrapper.move(MagnoliaSessionWrapper.java:65) ~[magnolia-core-6.2.2.jar:?]
	at info.magnolia.publishing.receiver.operation.jcr.AbstractJcrReceiveOperation.handleMovedContent(AbstractJcrReceiveOperation.java:257) ~[magnolia-publishing-receiver-1.2.1.jar:?]
	at info.magnolia.publishing.transactional.receiver.operation.jcr.JcrTransactionPublicationOperation.doExecute(JcrTransactionPublicationOperation.java:106) ~[magnolia-publishing-transactional-receiver-1.0.7-SNAPSHOT.jar:?]
	... 59 more
2020-08-31 15:09:46,840 WARN  info.magnolia.publishing.locking.JcrLockManager   : Node not locked by session: f8cbedd6-df91-4d7c-a952-2dc414d97704
Comment by Richard Gange [ 01/Sep/20 ]

Using the new module v1.2.2 here is an example publish:

2020-09-01 19:39:29,896 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session website by thread http-nio-8080-exec-3
2020-09-01 19:39:29,897 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 334 About to begin publish of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story:session-admin-374
2020-09-01 19:39:29,897 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 334 Requesting XA lock for node:node /travel/stories/story, session:session-admin-374
2020-09-01 19:39:29,897 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session magnolia-mgnlSystem by thread http-nio-8080-exec-3
2020-09-01 19:39:32,566 DEBUG info.magnolia.publishing.locking.JcrLockManager   : parent path:/travel/stories
2020-09-01 19:39:33,979 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-374 DID lock website:/travel/stories
2020-09-01 19:39:33,979 DEBUG info.magnolia.publishing.locking.JcrLockManager   : Cannot acquire lock [owner: publishing-session-parentLock-session-admin-374 expires: infinite lock]
2020-09-01 19:39:33,979 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 334 Got clearance for JCR lock on parent node /travel/stories
2020-09-01 19:39:33,979 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Checking the timestamp of publication request
2020-09-01 19:39:33,979 TRACE receiver.operation.jcr.AbstractJcrReceiveOperation: Begin prexecution [parentPath:/travel/stories, existingNode:node /travel/stories/story, existingNodeSession:session-admin-374, session:session-admin-374]
2020-09-01 19:39:33,979 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 334 Starting content publication
2020-09-01 19:39:33,979 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 334 Checking for existence of content website:a096ec20-c190-4b2e-91a4-294c99b64049
2020-09-01 19:39:33,980 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: 334 Content a096ec20-c190-4b2e-91a4-294c99b64049 was located under path website:/travel/stories/story
2020-09-01 19:39:33,989 DEBUG r.operation.jcr.JcrTransactionPublicationOperation: Stored content website:/travel/stories/story:a096ec20-c190-4b2e-91a4-294c99b64049 for rollback later
2020-09-01 19:39:33,989 TRACE receiver.operation.jcr.AbstractJcrReceiveOperation: Moving content to it's position in session: session-admin-374
2020-09-01 19:39:34,056 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 334 User superuser successfully published website:/travel/stories/story on dx-core-webapp.
2020-09-01 19:39:34,056 DEBUG receiver.operation.jcr.AbstractJcrReceiveOperation: Ordering story before main
2020-09-01 19:39:34,066 TRACE receiver.operation.jcr.AbstractJcrReceiveOperation: Clean up multipart form data and release node locks after publish operation.
2020-09-01 19:39:34,077 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-374 DID unlock website:/travel/stories
2020-09-01 19:39:34,078 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,078 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,078 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-374 by thread http-nio-8080-exec-3
2020-09-01 19:39:34,078 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-375 by thread http-nio-8080-exec-3
2020-09-01 19:39:34,092 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session website by thread http-nio-8080-exec-6
2020-09-01 19:39:34,092 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 337 About to begin commit of website:a096ec20-c190-4b2e-91a4-294c99b64049:/travel/stories/story:session-admin-376
2020-09-01 19:39:34,092 DEBUG info.magnolia.publishing.locking.JcrLockManager   : node uuid:a096ec20-c190-4b2e-91a4-294c99b64049
2020-09-01 19:39:34,114 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-376 DID lock website:/travel/stories/story
2020-09-01 19:39:34,114 DEBUG info.magnolia.publishing.locking.JcrLockManager   : Cannot acquire lock [owner: publishing-session-parentLock-session-admin-376 expires: infinite lock]
2020-09-01 19:39:34,114 DEBUG ional.receiver.locking.TransactionalJcrLockManager: 337 Got clearance for JCR lock on parent node /travel/stories/story
2020-09-01 19:39:34,114 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 337 Proceeding with commit of content a096ec20-c190-4b2e-91a4-294c99b64049
2020-09-01 19:39:34,114 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session magnolia-mgnlSystem by thread http-nio-8080-exec-6
2020-09-01 19:39:34,115 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 337 session:session-admin-377
2020-09-01 19:39:34,115 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 337 Removing node:node /story
2020-09-01 19:39:34,129 DEBUG actional.receiver.operation.jcr.JcrCommitOperation: 337 Committed node a096ec20-c190-4b2e-91a4-294c99b64049
2020-09-01 19:39:34,129 TRACE receiver.operation.jcr.AbstractJcrReceiveOperation: Clean up multipart form data and release node locks after commit operation.
2020-09-01 19:39:34,139 DEBUG info.magnolia.publishing.locking.JcrLockManager   : session-admin-376 DID unlock website:/travel/stories/story
2020-09-01 19:39:34,140 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,140 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,140 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-376 by thread http-nio-8080-exec-6
2020-09-01 19:39:34,140 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-377 by thread http-nio-8080-exec-6
2020-09-01 19:39:34,343 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,343 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,344 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session website by thread Thread-19
2020-09-01 19:39:34,345 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,345 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,346 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-378 by thread Thread-19
2020-09-01 19:39:34,353 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,354 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,514 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session website by thread http-nio-8080-exec-9
2020-09-01 19:39:34,519 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session resources by thread http-nio-8080-exec-9
2020-09-01 19:39:34,540 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : creating jcr session tags by thread http-nio-8080-exec-9
2020-09-01 19:39:34,557 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,557 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-379 by thread http-nio-8080-exec-9
2020-09-01 19:39:34,558 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-381 by thread http-nio-8080-exec-9
2020-09-01 19:39:34,558 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:34,558 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : logged out jcr session: session-admin-380 by thread http-nio-8080-exec-9
2020-09-01 19:39:35,030 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:43,817 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions
2020-09-01 19:39:43,817 DEBUG info.magnolia.context.AbstractRepositoryStrategy  : releasing jcr sessions

It seems to me that there are two requests to try and lock the node at the beginning.

Generated at Mon Feb 12 10:35:17 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.