[BUG] Attempt to copy temporary document throws NPE, possibly corrupts structural index

[IanDavey]

We have been dealing with the following intermittent NPE being thrown after updating nodes in a document repeatedly:

ERROR (XQueryURLRewrite.java [service]:365) - Error while processing /exist/rest/db/etc/Locks.xml: An unknown error occurred: null 
javax.servlet.ServletException: An unknown error occurred: null
	at org.exist.http.servlets.EXistServlet.doPost(EXistServlet.java:572) ~[exist.uber.jar:6.2.0]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) ~[exist.uber.jar:6.2.0]
	at org.exist.http.servlets.EXistServlet.service(EXistServlet.java:588) ~[exist.uber.jar:6.2.0]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1459) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:552) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:618) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:167) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:81) ~[exist.uber.jar:6.2.0]
	at org.exist.http.urlrewrite.Forward.doRewrite(Forward.java:50) ~[exist.uber.jar:6.2.0]
	at org.exist.http.urlrewrite.XQueryURLRewrite.service(XQueryURLRewrite.java:203) ~[exist.uber.jar:6.2.0]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1450) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:292) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:552) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:571) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[exist.uber.jar:6.2.0]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[exist.uber.jar:6.2.0]
	at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_332]
Caused by: java.lang.NullPointerException
	at org.exist.dom.persistent.DocumentImpl.<init>(DocumentImpl.java:205) ~[exist.uber.jar:6.2.0]
	at org.exist.storage.NativeBroker.defragXMLResource(NativeBroker.java:3036) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.update.Modification.checkFragmentation(Modification.java:284) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.update.Modification.checkFragmentation(Modification.java:260) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.XQueryContext.reset(XQueryContext.java:1452) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.XQueryContext.reset(XQueryContext.java:1428) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.XQuery.execute(XQuery.java:469) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.XQuery.execute(XQuery.java:348) ~[exist.uber.jar:6.2.0]
	at org.exist.xquery.XQuery.execute(XQuery.java:335) ~[exist.uber.jar:6.2.0]
	at org.exist.http.RESTServer.search(RESTServer.java:1371) ~[exist.uber.jar:6.2.0]
	at org.exist.http.RESTServer.doPost(RESTServer.java:860) ~[exist.uber.jar:6.2.0]
	at org.exist.http.servlets.EXistServlet.doPost(EXistServlet.java:538) ~[exist.uber.jar:6.2.0]
	... 65 more

From there, any queries into the document return no results until we reindex the document.

Looking at NativeBroker.java:3036, it appears null is being passed as pool into the DocumentImpl constructor, which then calls pool.getSecurityManager(), guaranteeing an NPE.

We are uncertain about the context that leads up to this execution path (given the difficulty in reliably reproducing the error), as well as the implications of simply wrapping in a ternary that checks for nulls, although we are currently testing a recompiled JAR with DocumentImpl.java:205 like so:

pool != null ? PermissionFactory.getDefaultResourcePermission(pool.getSecurityManager()) : collection.getPermissions(), 0, null,

This is using the existdb:6.2.0 Docker container.

[line-o]

Thanks for your thorough issue report. From the stack trace it is clear that this is a duplicate of #5273
Although the original issue is closed the fix has not landed in develop-6.x.x yet as we discovered that additional work has to be done to allow update expressions to work in all use cases (related are these two open PRs #5311 and #5296).

[line-o]

fixed in exist-db v6.3.0