[SLING-4222] WebDAV and many javax.jcr.RepositoryException: not a token for an open-scoped JCR lock: opaquelocktoken exceptions

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: Launchpad Builder 8
• Component/s: JCR
• Labels: jcr webdav

Environment

linux
Webdav mounted with davfs using:
{{
mount -t davfs -o gid=sling,rw,uid=sling,username=admin http://localhost:8090 /mnt/jcr

%> mount | grep 8090
http://localhost:8090 on /mnt/jcr type davfs (rw,nosuid,nodev,_netdev,gid=999,uid=1009)
}}

• Assignee: Unassigned
• Reporter: Bruce Edge
• Created: 05/Dec/14 23:08
• Updated: 11/Dec/14 19:46
• Resolved: 11/Dec/14 19:46

Description

I'm importing content into the JCR default workspace using a combination of sling:folder node creation in a JobConsumer from a bundle thread, then extracting a zip at that target location through webdav from the same thread.
Re-running the same data import drops different files each time. There are several thousand files in the zip. Each import differs by several dozen files. It's not even close to reliable.

I’m seeing this RepositoryException in the logs for each file that’s dropped in the final output.

I'm creating the node from a sling job consumer, then calling a method to unpack into the webdav folder:

adminResolver = resolverFactory.getAdministrativeResourceResolver(null);
adminSession = adminResolver.adaptTo(Session.class);
Workspace workspace = adminSession.getWorkspace();
Node destinationNode = JcrUtils.getOrCreateByPath(destination, JcrResourceConstants.NT_SLING_FOLDER, adminSession);
adminSession.save();
File destinationFile = new File(NimJcrConstants.WEBDAV_ROOT + destinationNode.getPath());
unpack(sourceFile, destinationFile);

Full trace with some log context.

05.12.2014 12:06:06.313 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.sling.servlets.resolver.internal.SlingServletResolver resolveServlet called for resource NonExistingResource, path=/content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml
05.12.2014 12:06:06.313 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.sling.servlets.resolver.internal.SlingServletResolver Using cached servlet org.apache.sling.jcr.webdav.impl.servlets.SimpleWebDavServlet
05.12.2014 12:06:06.313 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.sling.servlets.resolver.internal.SlingServletResolver getServletInternal returns servlet org.apache.sling.jcr.webdav.impl.servlets.SimpleWebDavServlet
05.12.2014 12:06:06.313 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.sling.servlets.resolver.internal.SlingServletResolver Servlet org.apache.sling.jcr.webdav.impl.servlets.SimpleWebDavServlet found for resource=NonExistingResource, path=/content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml
05.12.2014 12:06:06.313 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.sling.engine.impl.request.RequestData Servlet call counter : 0
05.12.2014 12:06:06.314 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.jackrabbit.webdav.header.IfHeader IfHeader: No If header in request
05.12.2014 12:06:06.314 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.jackrabbit.webdav.simple.DavSessionProviderImpl Attaching session 'org.apache.jackrabbit.webdav.simple.DavSessionImpl@123f907b' to request 'org.apache.jackrabbit.webdav.WebdavRequestImpl@b268499'
05.12.2014 12:06:06.315 DEBUG [127.0.0.1 [1417809966281] UNLOCK /content/ZP/2013/2013_01_03/IPAD/1024x76815/Folio.xml HTTP/1.1] org.apache.jackrabbit.webdav.jcr.JcrDavSession trying to add lock token opaquelocktoken:f1816b43-97d1-481e-b77b-cc96572d3ef8 to session
javax.jcr.RepositoryException: not a token for an open-scoped JCR lock: opaquelocktoken:f1816b43-97d1-481e-b77b-cc96572d3ef8
at org.apache.jackrabbit.webdav.jcr.lock.LockTokenMapper.getJcrLockToken(LockTokenMapper.java:67)
at org.apache.jackrabbit.webdav.jcr.JcrDavSession.addLockToken(JcrDavSession.java:104)
at org.apache.jackrabbit.webdav.simple.DavSessionImpl.addLockToken(DavSessionImpl.java:61)
at org.apache.jackrabbit.webdav.WebdavRequestImpl.setDavSession(WebdavRequestImpl.java:137)
at org.apache.jackrabbit.webdav.simple.DavSessionProviderImpl.attachSession(DavSessionProviderImpl.java:92)
at org.apache.jackrabbit.webdav.server.AbstractWebdavServlet.service(AbstractWebdavServlet.java:275)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
at org.apache.sling.engine.impl.request.RequestData.service(RequestData.java:533)
at org.apache.sling.engine.impl.filter.SlingComponentFilterChain.render(SlingComponentFilterChain.java:45)
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:64)
at org.apache.sling.engine.impl.SlingRequestProcessorImpl.processComponent(SlingRequestProcessorImpl.java:282)
at org.apache.sling.engine.impl.filter.RequestSlingFilterChain.render(RequestSlingFilterChain.java:49)
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:64)
at org.apache.sling.i18n.impl.I18NFilter.doFilter(I18NFilter.java:129)
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
at org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter.doFilter(RequestProgressTrackerLogFilter.java:95)
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
at org.apache.sling.engine.impl.SlingRequestProcessorImpl.doProcessRequest(SlingRequestProcessorImpl.java:151)
at org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:217)
at org.apache.felix.http.base.internal.handler.ServletHandler.doHandle(ServletHandler.java:339)
at org.apache.felix.http.base.internal.handler.ServletHandler.handle(ServletHandler.java:300)
at org.apache.felix.http.base.internal.dispatch.ServletPipeline.handle(ServletPipeline.java:93)
at org.apache.felix.http.base.internal.dispatch.InvocationFilterChain.doFilter(InvocationFilterChain.java:50)
at org.apache.felix.http.base.internal.dispatch.HttpFilterChain.doFilter(HttpFilterChain.java:31)
at org.apache.sling.i18n.impl.I18NFilter.doFilter(I18NFilter.java:129)
at org.apache.felix.http.base.internal.handler.FilterHandler.doHandle(FilterHandler.java:108)
at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:80)
at org.apache.felix.http.base.internal.dispatch.InvocationFilterChain.doFilter(InvocationFilterChain.java:46)
at org.apache.felix.http.base.internal.dispatch.HttpFilterChain.doFilter(HttpFilterChain.java:31)
at org.apache.sling.engine.impl.log.RequestLoggerFilter.doFilter(RequestLoggerFilter.java:75)
at org.apache.felix.http.base.internal.handler.FilterHandler.doHandle(FilterHandler.java:108)
at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:80)
at org.apache.felix.http.base.internal.dispatch.InvocationFilterChain.doFilter(InvocationFilterChain.java:46)
at org.apache.felix.http.base.internal.dispatch.HttpFilterChain.doFilter(HttpFilterChain.java:31)
at org.apache.felix.http.base.internal.dispatch.FilterPipeline.dispatch(FilterPipeline.java:76)
at org.apache.felix.http.base.internal.dispatch.Dispatcher.dispatch(Dispatcher.java:49)
at org.apache.felix.http.base.internal.DispatcherServlet.service(DispatcherServlet.java:67)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:366)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:667)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
at java.lang.Thread.run(Thread.java:745)