search

eXist-db / exist

eXist Native XML Database and Application Platform
https://exist-db.org
GNU Lesser General Public License v2.1
416 stars 179 forks source link

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

Closed IanDavey closed 1 week ago

IanDavey commented 2 weeks ago

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 commented 1 week ago

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).