Dynamic module import / function call causes too many brokers / threads

[wshager]

Since upgrading to Ubuntu 16.04 LTS a warning appears on every HTTP request to eXist:

WARN  (TransactionManager.java [close]:257) - Transaction was not committed or aborted, auto aborting!

Also, the broker pool is flooded, and transactions don't get handled anymore.

This might be unrelated to the Ubuntu upgrade, but there's not much else that has changed.

[wshager]

When setting logging in root level to debug, I see a warning just before that says there's a possible lock problem. Not much else unfortunately.

[adamretter]

@wshager Almost certainly not related to updating your Ubuntu issue. Tell us which version of eXist-db, how you installed and how to reproduce...

[wshager]

@adamretter it occurs with both latest release and my branch around 3.0RC.

[wshager]

@adamretter both build from source, nothing too special. The app just uses the controller, don't know anything more specific right now, since the same code on a different machine (Ubuntu 14.04 LTS) doesn't have this issue.

[adamretter]

@wshager Hmm I really don't think it can be the machine. The transaction code in eXist hasn't changed in some time and it is completely OS/machine agnostic. When you know how to reproduce just let me know...

[wshager]

@adamretter I spotted a difference with the controller on the other machine. In it I make a call to xmldb:collection-available on a non-existent collection. Had the collection existed, there wouldn't have been a warning.

However... that doesn't explain the high number of brokers and threads that don't complete, so I'll have to rename this issue...

[wshager]

There's a lot of requests to a controller that don't finish. There's a large number of active threads, the stack trace in Monex look like this:

java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.fillInStackTrace(Throwable.java:783)
java.lang.Throwable.(Throwable.java:265)
java.lang.Exception.(Exception.java:66)
antlr.ANTLRException.(ANTLRException.java:17)
antlr.RecognitionException.(RecognitionException.java:43)
antlr.NoViableAltException.(NoViableAltException.java:22)
org.exist.xquery.parser.XQueryParser.stepExpr(XQueryParser.java:7753)
org.exist.xquery.parser.XQueryParser.relativePathExpr(XQueryParser.java:7573)
org.exist.xquery.parser.XQueryParser.pathExpr(XQueryParser.java:7366)

[wshager]

It seems this was due to a dynamic module-import in the controller. The code below causes each request to be handled by a dynamic module import and a dynamic function call. The reason I did this is to be able to switch modules on some condition. I don't understand why this causes the number of brokers / threads to increase, but I'd call it a bug.

xquery version "3.0";

(:~ -------------------------------------------------------
    Main controller: handles all requests not matched by
    sub-controllers.
    ------------------------------------------------------- :)
declare namespace output="http://www.w3.org/2010/xslt-xquery-serialization";

declare variable $exist:path external;
declare variable $exist:resource external;
declare variable $exist:controller external;
declare variable $exist:prefix external;
declare variable $exist:root external;

let $imports := 
    util:import-module(xs:anyURI("http://benjamins.com/app"), "app", xs:anyURI("/db/modules/benjamins.com/app.xqm"))

return function-lookup(xs:QName("app:controller"), 3)($exist:path,$exist:resource,$exist:controller)

[dizzzz]

Just to check: there is no 'java' module involved that is developed by you?

[wshager]

@dizzzz honestly I prefer to not develop java, so no.

[joewiz]

@wshager Interesting! Can you develop this into a reproducible example? Then you'll be ready to fill in the template.

[adamretter]

@wshager I think there are two different things happening here. Certainly the warning itself is harmless:

WARN  (TransactionManager.java [close]:257) - Transaction was not committed or aborted, auto aborting!

However, to avoid that scaring people I have fixed it for the code path you are exploring, i.e. when there is a non-existent Collection: https://github.com/eXist-db/exist/pull/1524

The more serious issue of "high number of brokers and threads that don't complete" will need a reproducible test case from you so we can investigate. Also/Alternatively if you could get a jstack when the problem is visible, that might help us shed some light on it...

[wshager]

@adamretter I'll send a stack dump via email. Test below is a bit silly, but it should rule out application logic.

xquery version "3.0";

(:~ -------------------------------------------------------
    Test application module
    ------------------------------------------------------- :)

module namespace app="http://test.com/app";

import module namespace login="http://exist-db.org/xquery/login" at "resource:org/exist/xquery/modules/persistentlogin/login.xql";

declare function app:controller($path,$resource, $controller){
    if ($resource = 'login') then
            let $loggedIn := login:set-user("org.exist.login", (), false())
            return
                try {
                    util:declare-option("exist:serialize", "method=json"),
                    if (request:get-attribute("org.exist.login.user")) then
                        let $isAdmin := xmldb:is-admin-user(request:get-attribute("org.exist.login.user"))
                        return
                        <status>
                            <user>{request:get-attribute("org.exist.login.user")}</user>
                            <isAdmin json:literal="true">{$isAdmin}</isAdmin>
                        </status>
                    else (
                        response:set-status-code(401),
                        <status>fail</status>
                    )
                } catch * {
                    response:set-status-code(401),
                    <status>{$err:description}</status>
                }
    else if(matches($path,"/doc")) then
        (: Serve something real :)
    else
            <ignore xmlns="http://exist.sourceforge.net/NS/exist">
            <cache-control cache="yes"/>
        </ignore>
};

xquery version "3.0";

(:~ -------------------------------------------------------
    Main controller: handles all requests not matched by
    sub-controllers.
    ------------------------------------------------------- :)
declare namespace output="http://www.w3.org/2010/xslt-xquery-serialization";

declare variable $exist:path external;
declare variable $exist:resource external;
declare variable $exist:controller external;
declare variable $exist:prefix external;
declare variable $exist:root external;

let $imports := 
    util:import-module(xs:anyURI("http://test.com/app"), "app", xs:anyURI("/db/modules/test/app.xqm"))

return function-lookup(xs:QName("app:controller"), 3)($exist:path,$exist:resource,$exist:controller)

[adamretter]

@wshager I looked through your stack traces. The first set of traces seem to show an issue with Jetty, so I have updated to the latest one here: https://github.com/eXist-db/exist/pull/1527

The second set might show a deadlock in eXist-db, I would need to reproduce, but it would help me if you could check using 3.4.1 + https://github.com/eXist-db/exist/pull/1524 and https://github.com/eXist-db/exist/pull/1527

[wshager]

@adamretter thanks, but the issue persists (stack dump attached dump.txt) . Could you please use the test I provided? Even with this simple test the isue really is reproducable.

[adamretter]

@wshager I can't run the code that you provided.

I saved the first file as /db/modules/test/app.xqm. I save the second file as /db/modules/test/controller.xql. How am I meant to execute this?

If I directly hit http://localhost:8080/exist/rest/db/modules/test/controller.xql` then I get:

<exception>
  <path>/db/main.xq</path>
  <message>
    err:XPDY0002 undefined value for variable '$exist:path' [at line 18, column 56, source: /db/main.xq] In function: app:controller(item()*, item()*, item()*) [18:56:/db/app.xqm]
  </message>
</exception>

I would love to reproduce the problem in time to fix it for the upcoming 3.6.0 release.

[wshager]

@dizzzz the controller should probably go into an app, say /db/apps/test/controller.xql.

[wshager]

Oh sorry @adamretter

[wshager]

@adamretter I guess you don't use the controller much anymore, right?

[duncdrum]

@adamretter did you get to reproduce this with the provided controller.xql?

[adamretter]

@duncdrum nope.