From: ch.g <chr...@e-...> - 2012-10-08 14:12:25
|
Hi all, I tried to dig a bit more into this and discovered some strange behaviors when urlRewrite + templating + circular module dependencies are involved, that eventually lead to the lock problem described above (and to the fact that xquery modules take quite a long time - 10sec + - to be commited to the database), and sometimes to database corruption. One test case not too cumbersome to reproduce is to : 0- backup your data (in my case the following steps lead to a corrupted db !) 1- load the demo package to the database 2- modify demo/modules/templates.xql - > demo/modules/templates.xqm 3- modify the ref of import modules in config.xqm and view.xql from templates/xql to templates.xqm 4- try to save the modifications Under my current configuration (Linux Mint - latest trunk version of eXist), this lead to : a message box in oxygen : Cannot save the file. Failed to invoke method storeBinary in class org.exist.xmlrpc.RpcConnection: java.lang.NullPointerException >From now on, db fails to re-start and to recover... in exist.log: 2012-10-08 15:58:35,762 [eXistThread-37] DEBUG (TransactionManager.java [execute]:153) - Starting new transaction: 15 2012-10-08 15:58:35,762 [eXistThread-37] DEBUG (RpcConnection.java [storeBinary]:2411) - Storing binary resource to collection /db/demo/modules 2012-10-08 15:58:35,763 [eXistThread-37] DEBUG (Collection.java [checkPermissionsForAddDocument]:1756) - Found old doc 11255 2012-10-08 15:58:35,765 [eXistThread-37] DEBUG (Collection.java [addBinaryResource]:1862) - removing old document config.xqm 2012-10-08 15:58:35,765 [eXistThread-37] DEBUG (NativeBroker.java [removeBinaryResource]:2718) - removing binary resource 11255... 2012-10-08 15:58:35,765 [eXistThread-37] DEBUG (RenameBinaryLoggable.java [<init>]:39) - Rename binary created /home/christophe/eXist-db/webapp/WEB-INF/data/fs/db/demo/modules/config.xqm -> /home/christophe/eXist-db/webapp/WEB-INF/data/fs.journal/txn.15/db/demo/modules/config.xqm 2012-10-08 15:58:35,766 [eXistThread-37] DEBUG (NativeBroker.java [removeResourceMetadata]:2761) - Removing resource metadata for 11255 2012-10-08 15:58:35,766 [eXistThread-37] DEBUG (CreateBinaryLoggable.java [<init>]:36) - CreateBinaryLoggable created 2012-10-08 15:58:35,779 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from templates.xqm 2012-10-08 15:58:35,850 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from config.xqm 2012-10-08 15:58:35,863 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:35,874 [eXistThread-37] DEBUG (XQuery.java [compile]:173) - Query diagnostics: [skipped: more than 150 expressions] 2012-10-08 15:58:35,875 [eXistThread-37] DEBUG (XQuery.java [compile]:178) - Compilation took 107 ms 2012-10-08 15:58:35,879 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from templates.xqm 2012-10-08 15:58:35,950 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from config.xqm 2012-10-08 15:58:35,963 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:35,973 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from ../examples/web/shakespeare.xql 2012-10-08 15:58:35,987 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:35,987 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:35,988 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from resource:org/exist/xquery/lib/kwic.xql 2012-10-08 15:58:36,022 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from i18n-templates.xql 2012-10-08 15:58:36,027 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from xmldb:exist:///db/demo/modules/i18n.xql 2012-10-08 15:58:36,065 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:36,065 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:36,066 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:36,067 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from demo.xql 2012-10-08 15:58:36,072 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from xmldb:exist:///db/demo/examples/tests/shakespeare-tests.xql 2012-10-08 15:58:36,076 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from resource:org/exist/xquery/lib/xqsuite/xqsuite.xql 2012-10-08 15:58:36,214 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/apps/demo/shakespeare already present. 2012-10-08 15:58:36,215 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/xqsuite already present. 2012-10-08 15:58:36,217 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from ../examples/web/guess-templates.xql 2012-10-08 15:58:36,225 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:36,227 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from cex.xql 2012-10-08 15:58:36,238 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:36,238 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/kwic already present. 2012-10-08 15:58:36,244 [eXistThread-37] DEBUG (XQuery.java [compile]:171) - Query diagnostics: let <15> $lookup := function(xs:string*, xs:int*) item()*, let <22> $content := request:get-data() return templates:apply($content, untyped-value-check[function, $lookup], untyped-value-check[map, ]) 2012-10-08 15:58:36,245 [eXistThread-37] DEBUG (XQuery.java [compile]:178) - Compilation took 368 ms 2012-10-08 15:58:36,250 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from xmldb:exist:///db/demo/modules/i18n.xql 2012-10-08 15:58:36,297 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from config.xqm 2012-10-08 15:58:36,310 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from templates.xqm 2012-10-08 15:58:36,383 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:36,392 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from resource:org/exist/xquery/lib/kwic.xql 2012-10-08 15:58:36,425 [eXistThread-37] DEBUG (XQuery.java [compile]:173) - Query diagnostics: [skipped: more than 150 expressions] 2012-10-08 15:58:36,426 [eXistThread-37] DEBUG (XQuery.java [compile]:178) - Compilation took 137 ms 2012-10-08 15:58:36,442 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from ../../modules/config.xqm 2012-10-08 15:58:36,455 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from templates.xqm 2012-10-08 15:58:36,529 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/apps/config already present. 2012-10-08 15:58:36,540 [eXistThread-37] DEBUG (XQueryContext.java [importModule]:2685) - Module http://exist-db.org/xquery/templates already present. 2012-10-08 15:58:36,540 [eXistThread-37] DEBUG (XQueryContext.java [compileModule]:2855) - Loading module from resource:org/exist/xquery/lib/kwic.xql 2012-10-08 15:58:36,573 [eXistThread-37] DEBUG (XQuery.java [compile]:173) - Query diagnostics: [skipped: more than 150 expressions] 2012-10-08 15:58:36,574 [eXistThread-37] DEBUG (XQuery.java [compile]:178) - Compilation took 144 ms 2012-10-08 15:58:36,574 [eXistThread-37] DEBUG (Collection.java [getDocument]:734) - Document templates.xql not found! 2012-10-08 15:58:36,575 [eXistThread-37] DEBUG (NativeBroker.java [getResource]:2173) - document '/db/demo/modules/templates.xql' not found! 2012-10-08 15:58:36,576 [eXistThread-37] DEBUG (RpcConnection.java [handleException]:120) - java.lang.NullPointerException at org.exist.extensions.exquery.restxq.impl.XQueryCompiler.compile(XQueryCompiler.java:88) at org.exist.extensions.exquery.restxq.impl.RestXqTrigger.findServices(RestXqTrigger.java:217) at org.exist.extensions.exquery.restxq.impl.RestXqTrigger.reexamineModulesWithResolvedDependencies(RestXqTrigger.java:286) at org.exist.extensions.exquery.restxq.impl.RestXqTrigger.findServices(RestXqTrigger.java:230) at org.exist.extensions.exquery.restxq.impl.RestXqTrigger.after(RestXqTrigger.java:155) at org.exist.extensions.exquery.restxq.impl.RestXqTrigger.afterUpdateDocument(RestXqTrigger.java:105) at org.exist.collections.triggers.DocumentTriggersVisitor.afterUpdateDocument(DocumentTriggersVisitor.java:98) at org.exist.collections.Collection.addBinaryResource(Collection.java:1887) at org.exist.collections.Collection.addBinaryResource(Collection.java:1806) at org.exist.collections.Collection.addBinaryResource(Collection.java:1794) at org.exist.collections.Collection.addBinaryResource(Collection.java:1788) at org.exist.xmlrpc.RpcConnection.storeBinary(RpcConnection.java:2413) at org.exist.xmlrpc.RpcConnection.storeBinary(RpcConnection.java:2376) at org.exist.xmlrpc.RpcConnection.storeBinary(RpcConnection.java:5061) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.xmlrpc.server.ReflectiveXmlRpcHandler.invoke(ReflectiveXmlRpcHandler.java:115) at org.apache.xmlrpc.server.ReflectiveXmlRpcHandler.execute(ReflectiveXmlRpcHandler.java:106) at org.apache.xmlrpc.server.XmlRpcServerWorker.execute(XmlRpcServerWorker.java:46) at org.apache.xmlrpc.server.XmlRpcServer.execute(XmlRpcServer.java:86) at org.apache.xmlrpc.server.XmlRpcStreamServer.execute(XmlRpcStreamServer.java:200) at org.apache.xmlrpc.webserver.XmlRpcServletServer.execute(XmlRpcServletServer.java:112) at org.apache.xmlrpc.webserver.XmlRpcServlet.doPost(XmlRpcServlet.java:196) at org.exist.xmlrpc.RpcServlet.doPost(RpcServlet.java:68) at javax.servlet.http.HttpServlet.service(HttpServlet.java:755) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:598) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:486) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:542) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:233) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1065) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:413) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:192) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:999) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117) at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:224) at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:98) at org.exist.http.urlrewrite.Forward.doRewrite(Forward.java:47) at org.exist.http.urlrewrite.XQueryURLRewrite.service(XQueryURLRewrite.java:211) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:598) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:486) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:499) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:233) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1065) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:413) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:192) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:999) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117) at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:111) at org.eclipse.jetty.server.Server.handle(Server.java:350) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:454) at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:900) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:954) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:851) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:77) at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:606) at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:46) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:603) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:538) at java.lang.Thread.run(Thread.java:662) 2012-10-08 15:58:36,620 [eXistThread-30] DEBUG (SecurityManagerImpl.java [authenticate]:399) - Authentication try for 'admin'. 2012-10-08 15:58:36,621 [eXistThread-30] DEBUG (SecurityManagerImpl.java [authenticate]:442) - Authenticated by 'exist' as '[auth] <account name="admin" id="1048574"><group name="dba" id="1048575"></group></user>'. 2012-10-08 15:58:37,621 [eXistThread-37] DEBUG (SecurityManagerImpl.java [authenticate]:399) - Authentication try for 'admin'. 2012-10-08 15:58:37,622 [eXistThread-37] DEBUG (SecurityManagerImpl.java [authenticate]:442) - Authenticated by 'exist' as '[auth] <account name="admin" id="1048574"><group name="dba" id="1048575"></group></user>'. -- View this message in context: http://exist.2174344.n4.nabble.com/possible-lock-problems-with-oXygen-tp4656554p4656629.html Sent from the exist-open mailing list archive at Nabble.com. |