exist icon indicating copy to clipboard operation
exist copied to clipboard

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

Open IanDavey opened this issue 7 months ago • 1 comments

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.

IanDavey avatar Jul 02 '24 19:07 IanDavey