HttpClient timeout (proxy firewall) -> locked database

[dizzzz]

often exist-db shuts slowely down because of hanging locks:

2014-08-12 16:17:37,554 [eXistThread-385] ERROR (BaseHTTPClientFunction.java [doRequest]:211) - Connection timed out 
java.net.ConnectException: Connection timed out
    at java.net.PlainSocketImpl.socketConnect(Native Method)
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
    at java.net.Socket.connect(Socket.java:579)
    at java.net.Socket.connect(Socket.java:528)
    at java.net.Socket.<init>(Socket.java:425)
    at java.net.Socket.<init>(Socket.java:280)
    at org.apache.commons.httpclient.protocol.DefaultProtocolSocketFactory.createSocket(DefaultProtocolSocketFactory.java:80)
    at org.apache.commons.httpclient.protocol.DefaultProtocolSocketFactory.createSocket(DefaultProtocolSocketFactory.java:122)
    at org.apache.commons.httpclient.HttpConnection.open(HttpConnection.java:707)
    at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:387)
    at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
    at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
    at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
    at org.exist.xquery.modules.httpclient.BaseHTTPClientFunction.doRequest(BaseHTTPClientFunction.java:202)
    at org.exist.xquery.modules.httpclient.GETFunction.eval(GETFunction.java:119)
    at org.exist.xquery.BasicFunction.eval(BasicFunction.java:70)
    at org.exist.xquery.InternalFunctionCall.eval(InternalFunctionCall.java:56)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:142)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:187)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.TryCatchExpression.eval(TryCatchExpression.java:127)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.ConditionalExpression.eval(ConditionalExpression.java:102)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:142)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:187)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.value.FunctionReference.eval(FunctionReference.java:80)
    at org.exist.xquery.DynamicFunctionCall.eval(DynamicFunctionCall.java:75)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.SwitchExpression.eval(SwitchExpression.java:104)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.SequenceConstructor.eval(SequenceConstructor.java:84)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:65)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:189)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.value.FunctionReference.eval(FunctionReference.java:80)
    at org.exist.xquery.DynamicFunctionCall.eval(DynamicFunctionCall.java:75)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:65)
    at org.exist.xquery.ForExpr.eval(ForExpr.java:307)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:187)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.ConditionalExpression.eval(ConditionalExpression.java:102)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:65)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:189)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:65)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:189)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:187)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.UserDefinedFunction.eval(UserDefinedFunction.java:153)
    at org.exist.xquery.FunctionCall.evalFunction(FunctionCall.java:328)
    at org.exist.xquery.FunctionCall.eval(FunctionCall.java:232)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.SequenceConstructor.eval(SequenceConstructor.java:84)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:65)
    at org.exist.xquery.LetExpr.eval(LetExpr.java:189)
    at org.exist.xquery.BindingExpression.eval(BindingExpression.java:164)
    at org.exist.xquery.ConditionalExpression.eval(ConditionalExpression.java:100)
    at org.exist.xquery.DebuggableExpression.eval(DebuggableExpression.java:58)
    at org.exist.xquery.ConditionalExpression.eval(ConditionalExpression.java:102)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.SequenceConstructor.eval(SequenceConstructor.java:84)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.PathExpr.eval(PathExpr.java:264)
    at org.exist.xquery.AbstractExpression.eval(AbstractExpression.java:71)
    at org.exist.xquery.XQuery.execute(XQuery.java:297)
    at org.exist.xquery.XQuery.execute(XQuery.java:217)
    at org.exist.http.urlrewrite.XQueryURLRewrite.runQuery(XQueryURLRewrite.java:719)
    at org.exist.http.urlrewrite.XQueryURLRewrite.service(XQueryURLRewrite.java:259)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1448)
    at de.betterform.agent.web.filter.XFormsFilter.doFilter(XFormsFilter.java:163)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:533)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
    at org.eclipse.jetty.server.Server.handle(Server.java:368)
    at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:488)
    at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:932)
    at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:994)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
    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:628)
    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:744)

[adamretter]

@dizzzz Is this still a problem?

[dizzzz]

yes ; during startup still 'something' makes a HTTP request....

[dizzzz]

actually... it is during database start... not shutdown ; I am wondering why I wrote this...

[adamretter]

So we could easily trace this with Wireshark, no?

[dizzzz]

yes, that should be rather easy. somehow i never did it :-/

[dizzzz]

here it is:

Hypertext Transfer Protocol
    GET /xquery/console HTTP/1.1\r\n
    User-Agent: Java/1.8.0_162\r\n
    Host: exist-db.org\r\n
    Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2\r\n
    Connection: keep-alive\r\n
    \r\n
    [Full request URI: http://exist-db.org/xquery/console]
    [HTTP request 1/1]
    [Response in frame: 92]

response

Hypertext Transfer Protocol
    HTTP/1.1 404 Not Found\r\n
    Date: Sat, 17 Feb 2018 18:14:03 GMT\r\n
    Server: Jetty(9.4.6.v20170531)\r\n
    Cache-Control: must-revalidate,no-cache,no-store\r\n
    Content-Type: text/html;charset=iso-8859-1\r\n
    Content-Length: 336\r\n
    Set-Cookie: JSESSIONID=node01do3dpruj5q3q1f3ozp325gnxq1423628.node0;Path=/exist\r\n
    Keep-Alive: timeout=15, max=100\r\n
    Connection: Keep-Alive\r\n
    \r\n
    [HTTP response 1/1]
    [Time since request: 0.040570000 seconds]
    [Request in frame: 90]
    File Data: 336 bytes

I fear that one of these try to resolve the external URL instead of resolving it locally:

monex

webapp/WEB-INF/data/expathrepo/monex-0.9.12/exist.xml:4:        <namespace>http://exist-db.org/xquery/console</namespace>
webapp/WEB-INF/data/expathrepo/monex-0.9.12/console.html:66:                <pre data-language="xquery">import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/test-app.xql:6:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/test-timeline-prof.xql:9:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/app.xql:12:(: import module namespace console="http://exist-db.org/xquery/console" at "java:org.exist.console.xquery.ConsoleModule"; :)
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/app.xql:28:        util:import-module(xs:anyURI("http://exist-db.org/xquery/console"), "console", xs:anyURI("java:org.exist.console.xquery.ConsoleModule")),
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/indexes.xqm:15:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/job.xql:5:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/test-timeline.xql:9:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/suite.xql:3:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/notification.xql:7:import module namespace console="http://exist-db.org/xquery/console" at "java:org.exist.console.xquery.ConsoleModule";
webapp/WEB-INF/data/expathrepo/monex-0.9.12/modules/hipchat.xql:8:import module namespace console="http://exist-db.org/xquery/console";

webapp/WEB-INF/data/fs/db/apps/monex/modules/test-app.xql:6:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/test-timeline-prof.xql:9:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/app.xql:12:(: import module namespace console="http://exist-db.org/xquery/console" at "java:org.exist.console.xquery.ConsoleModule"; :)
webapp/WEB-INF/data/fs/db/apps/monex/modules/app.xql:28:        util:import-module(xs:anyURI("http://exist-db.org/xquery/console"), "console", xs:anyURI("java:org.exist.console.xquery.ConsoleModule")),
webapp/WEB-INF/data/fs/db/apps/monex/modules/indexes.xqm:15:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/job.xql:5:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/test-timeline.xql:9:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/suite.xql:3:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/monex/modules/notification.xql:7:import module namespace console="http://exist-db.org/xquery/console" at "java:org.exist.console.xquery.ConsoleModule";
webapp/WEB-INF/data/fs/db/apps/monex/modules/hipchat.xql:8:import module namespace console="http://exist-db.org/xquery/console";

usermanager

webapp/WEB-INF/data/expathrepo/usermanager-0.15.1/controller.xql:41:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/expathrepo/usermanager-0.15.1/modules/userManager.xqm:36:import module namespace console="http://exist-db.org/xquery/console";

webapp/WEB-INF/data/fs/db/apps/usermanager/controller.xql:41:import module namespace console="http://exist-db.org/xquery/console";
webapp/WEB-INF/data/fs/db/apps/usermanager/modules/userManager.xqm:36:import module namespace console="http://exist-db.org/xquery/console";

exide

webapp/WEB-INF/data/expathrepo/eXide-2.4.3/templates/namespaces.json:17:    "console": "http://exist-db.org/xquery/console"

webapp/WEB-INF/data/fs/db/apps/eXide/templates/namespaces.json:17:    "console": "http://exist-db.org/xquery/console"

in the logs:

webapp/WEB-INF/logs/expath-repo.log:27:2018-02-17 19:14:03,435 [main] DEBUG (Logger.java [fine]:38) - Package 'http://exist-db.org/apps/shared', resolve in XQUERY: 'http://exist-db.org/xquery/console' (true) 
webapp/WEB-INF/logs/expath-repo.log:28:2018-02-17 19:14:03,435 [main] DEBUG (Logger.java [fine]:38) - Package 'http://exist-db.org/apps/shared', not in XQUERY: 'http://exist-db.org/xquery/console' 
webapp/WEB-INF/logs/expath-repo.log:29:2018-02-17 19:14:03,436 [main] DEBUG (Logger.java [fine]:38) - Package 'http://exist-db.org/apps/usermanager', resolve in XQUERY: 'http://exist-db.org/xquery/console' (true) 
webapp/WEB-INF/logs/exist.log:72:2018-02-17 19:14:03,669 [main] ERROR (DocumentTriggers.java [afterCreateDocument]:238) - Invalid URI: xmldb URI scheme does not start with xmldb:: http://exist-db.org/xquery/console 
webapp/WEB-INF/logs/exist.log:73:java.lang.IllegalArgumentException: Invalid URI: xmldb URI scheme does not start with xmldb:: http://exist-db.org/xquery/console

[adamretter]

@dizzzz Okay, so er... it is a problem with an App?

[dizzzz]

Looks like it....

[dizzzz]

Removing the <trigger class="org.exist.extensions.exquery.restxq.impl.RestXqTrigger"/> from collection.xconf.init solves the problem.

[adamretter]

Okay but that isn't the cause

[dizzzz]

sure ; there is an ordering issue, where the console extension is not yet available when the RestXQtrigger is being initialised. Potential solution: move the console-extension into the exist-db core. @wolfgangmm agree?