Null Pointer Exception with p:value-available() #152

Closed
alexmilowski opened this Issue May 1, 2014 · 5 comments

Comments

Projects
None yet
3 participants
@alexmilowski

I am using version 1.0.16-95.

I have a p:value-available in a p:choose:

<p:when test="/app:collection">
<p:choose name="generate-name">
<p:when test="p:value-available('slug')">
...

Not sure what is happening but I get this:

java.lang.NullPointerException
at com.xmlcalabash.functions.ValueAvailable$ValueAvailableCall.call(Unknown Source)
at net.sf.saxon.lib.ExtensionFunctionCall.effectiveBooleanValue(ExtensionFunctionCall.java:217)
at net.sf.saxon.functions.IntegratedFunctionCall.effectiveBooleanValue(IntegratedFunctionCall.java:324)
at net.sf.saxon.functions.BooleanFn.effectiveBooleanValue(BooleanFn.java:161)
at net.sf.saxon.functions.BooleanFn.evaluateItem(BooleanFn.java:152)
at net.sf.saxon.functions.BooleanFn.evaluateItem(BooleanFn.java:31)
at net.sf.saxon.expr.Expression.iterate(Expression.java:466)
at net.sf.saxon.sxpath.XPathExpression.iterate(XPathExpression.java:163)
at net.sf.saxon.s9api.XPathSelector.iterator(XPathSelector.java:208)
at com.xmlcalabash.runtime.XAtomicStep.evaluateXPath(Unknown Source)
at com.xmlcalabash.runtime.XWhen.shouldRun(Unknown Source)
at com.xmlcalabash.runtime.XChoose.run(Unknown Source)
at com.xmlcalabash.runtime.XCompoundStep.run(Unknown Source)
at com.xmlcalabash.runtime.XChoose.run(Unknown Source)
at com.xmlcalabash.runtime.XPipeline.doRun(Unknown Source)
at com.xmlcalabash.runtime.XPipeline.run(Unknown Source)
at org.atomojo.server.xproc.XProcHelper.handle(XProcHelper.java:751)
at org.atomojo.server.xproc.XProcRestlet.handle(XProcRestlet.java:31)

@jwcranford

This comment has been minimized.

Show comment
Hide comment
@jwcranford

jwcranford May 5, 2014

I think this is the same error I ran into using Piperack, a restlet application bundled with Calabash. I also get a NullPointerException (stack trace below), and it seems related to the use of a thread-local variable in XProcExtensionFunctionDefinition, which both ValueAvailableCall and SystemPropertyCall extend. My guess is that the way that restlet uses threads doesn't work with the thread-local variable, but more on that later.

Stack trace first, then steps on how to reproduce. Note that the stack trace below is from the latest commit on the saxon95 branch (commit eb361d9), built with debug symbols.

com.xmlcalabash.core.XProcException: java.lang.NullPointerException
at com.xmlcalabash.piperack.BaseResource.runPipeline(BaseResource.java:267)
at com.xmlcalabash.piperack.Run.post(Run.java:34)
at org.restlet.resource.ServerResource.doHandle(ServerResource.java:592)
...
at org.restlet.engine.connector.BaseHelper$2.run(BaseHelper.java:593)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.NullPointerException
at com.xmlcalabash.functions.SystemProperty$SystemPropertyCall.call(SystemProperty.java:71)
at net.sf.saxon.functions.IntegratedFunctionCall.iterate(IntegratedFunctionCall.java:268)
at net.sf.saxon.sxpath.XPathExpression.iterate(XPathExpression.java:163)
at net.sf.saxon.s9api.XPathSelector.iterator(XPathSelector.java:208)
at com.xmlcalabash.runtime.XAtomicStep.evaluateXPath(XAtomicStep.java:843)
at com.xmlcalabash.runtime.XAtomicStep.computeValue(XAtomicStep.java:693)
at com.xmlcalabash.runtime.XAtomicStep.computeParameters(XAtomicStep.java:229)
at com.xmlcalabash.runtime.XAtomicStep.run(XAtomicStep.java:367)
at com.xmlcalabash.runtime.XPipeline.doRun(XPipeline.java:235)
at com.xmlcalabash.runtime.XPipeline.run(XPipeline.java:135)
at com.xmlcalabash.piperack.BaseResource.runPipeline(BaseResource.java:255)
... 44 more

STEPS TO REPRODUCE

$ java -cp calabash.jar:lib/* com.xmlcalabash.drivers.Piperack \
-c test-piperack-config.xml
<!-- test-piperack-config.xml -->
<xproc-config xmlns="http://xmlcalabash.com/ns/configuration">
   <piperack-load-pipeline name="gv">general-values-example.xpl</piperack-load-pipeline>
</xproc-config>

general-values-example.xpl is copied from http://xmlcalabash.com/docs/reference/langext.html#ext.general-values and is copied here for convenience:

<!-- general-values-example.xpl -->
<p:declare-step xmlns:p="http://www.w3.org/ns/xproc" version="1.0">
    <p:input port="parameters" kind="parameter"/>
    <p:output port="result"/>
    <p:serialization port="result" indent="true"/>

    <p:identity>
        <p:input port="source">
            <p:inline>
                <doc>
                    <para>Some <emph>text</emph> in a paragraph.</para>
                </doc>
            </p:inline>
        </p:input>
    </p:identity>

    <p:xslt template-name="root">
        <p:input port="stylesheet">
            <p:inline>
                <xsl:stylesheet xmlns:xsl="http://www.w3.org/1999/XSL/Transform" 
                        version="2.0">

                    <xsl:param name="text" required="yes"/>
                    <xsl:param name="gv" required="yes"/>

                    <xsl:template name="root">
                        <root general-values="{$gv}">
                            <xsl:sequence select="$text"/>
                        </root>
                    </xsl:template>
                </xsl:stylesheet>
            </p:inline>
        </p:input>
        <p:with-param name="text" select="/doc/para"/>
        <p:with-param name="gv" select="p:system-property('cx:general-values')"
            xmlns:cx="http://xmlcalabash.com/ns/extensions"/>
    </p:xslt>

</p:declare-step>
$ curl -X POST http://localhost:8088/pipelines/gv/run

And voila! You get the stack trace above in the Piperack output.

ANALYSIS
Now for the juicy parts: here are lines 70-71 of SystemProperty.java:

70             XProcRuntime runtime = tl_runtime.get();
71             XStep step = runtime.getXProcData().getStep();

tl_runtime.get() is returning a null, which turns into a NPE on line 71.

tl_runtime is declared in XProcExtensionFunctionDefinition, which both ValueAvailableCall and SystemPropertyCall extend.

public abstract class XProcExtensionFunctionDefinition extends ExtensionFunctionDefinition {
    protected ThreadLocal<XProcRuntime> tl_runtime = new ThreadLocal<XProcRuntime>() {
        protected synchronized XProcRuntime initialValue() {
            return null;
        }
    };

Both ValueAvailable and SystemProperty set tl_runtime in the constructor, and both read it from ValueAvailableCall and SystemPropertyCall, respectively, which are inner classes. tl_runtime isn't set anywhere else.

So here's what I think is happening. ValueAvailable and SystemProperty are created in the XProcRuntime constructor, which gets called in the main thread. However, ValueAvailableCall and SystemPropertyCall are called in a different thread via a ThreadPoolExecutor used by restlet (see stack trace above). Because they're called in a different thread, tl_runtime.get() returns the value of initialValue(), which is null.

Thus, it seems like an inherent assumption in the code that XProcRuntime is created in the same thread that executes the pipeline. That works fine for a command-line app, but doesn't seem to work well in restlet.

The same pattern seems to be used by the other extension XPath functions, so I imagine they could suffer from the same problem.

Not sure how to fix this, but I hope this information helps in diagnosing and designing a fix to the problem.

I think this is the same error I ran into using Piperack, a restlet application bundled with Calabash. I also get a NullPointerException (stack trace below), and it seems related to the use of a thread-local variable in XProcExtensionFunctionDefinition, which both ValueAvailableCall and SystemPropertyCall extend. My guess is that the way that restlet uses threads doesn't work with the thread-local variable, but more on that later.

Stack trace first, then steps on how to reproduce. Note that the stack trace below is from the latest commit on the saxon95 branch (commit eb361d9), built with debug symbols.

com.xmlcalabash.core.XProcException: java.lang.NullPointerException
at com.xmlcalabash.piperack.BaseResource.runPipeline(BaseResource.java:267)
at com.xmlcalabash.piperack.Run.post(Run.java:34)
at org.restlet.resource.ServerResource.doHandle(ServerResource.java:592)
...
at org.restlet.engine.connector.BaseHelper$2.run(BaseHelper.java:593)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.NullPointerException
at com.xmlcalabash.functions.SystemProperty$SystemPropertyCall.call(SystemProperty.java:71)
at net.sf.saxon.functions.IntegratedFunctionCall.iterate(IntegratedFunctionCall.java:268)
at net.sf.saxon.sxpath.XPathExpression.iterate(XPathExpression.java:163)
at net.sf.saxon.s9api.XPathSelector.iterator(XPathSelector.java:208)
at com.xmlcalabash.runtime.XAtomicStep.evaluateXPath(XAtomicStep.java:843)
at com.xmlcalabash.runtime.XAtomicStep.computeValue(XAtomicStep.java:693)
at com.xmlcalabash.runtime.XAtomicStep.computeParameters(XAtomicStep.java:229)
at com.xmlcalabash.runtime.XAtomicStep.run(XAtomicStep.java:367)
at com.xmlcalabash.runtime.XPipeline.doRun(XPipeline.java:235)
at com.xmlcalabash.runtime.XPipeline.run(XPipeline.java:135)
at com.xmlcalabash.piperack.BaseResource.runPipeline(BaseResource.java:255)
... 44 more

STEPS TO REPRODUCE

$ java -cp calabash.jar:lib/* com.xmlcalabash.drivers.Piperack \
-c test-piperack-config.xml
<!-- test-piperack-config.xml -->
<xproc-config xmlns="http://xmlcalabash.com/ns/configuration">
   <piperack-load-pipeline name="gv">general-values-example.xpl</piperack-load-pipeline>
</xproc-config>

general-values-example.xpl is copied from http://xmlcalabash.com/docs/reference/langext.html#ext.general-values and is copied here for convenience:

<!-- general-values-example.xpl -->
<p:declare-step xmlns:p="http://www.w3.org/ns/xproc" version="1.0">
    <p:input port="parameters" kind="parameter"/>
    <p:output port="result"/>
    <p:serialization port="result" indent="true"/>

    <p:identity>
        <p:input port="source">
            <p:inline>
                <doc>
                    <para>Some <emph>text</emph> in a paragraph.</para>
                </doc>
            </p:inline>
        </p:input>
    </p:identity>

    <p:xslt template-name="root">
        <p:input port="stylesheet">
            <p:inline>
                <xsl:stylesheet xmlns:xsl="http://www.w3.org/1999/XSL/Transform" 
                        version="2.0">

                    <xsl:param name="text" required="yes"/>
                    <xsl:param name="gv" required="yes"/>

                    <xsl:template name="root">
                        <root general-values="{$gv}">
                            <xsl:sequence select="$text"/>
                        </root>
                    </xsl:template>
                </xsl:stylesheet>
            </p:inline>
        </p:input>
        <p:with-param name="text" select="/doc/para"/>
        <p:with-param name="gv" select="p:system-property('cx:general-values')"
            xmlns:cx="http://xmlcalabash.com/ns/extensions"/>
    </p:xslt>

</p:declare-step>
$ curl -X POST http://localhost:8088/pipelines/gv/run

And voila! You get the stack trace above in the Piperack output.

ANALYSIS
Now for the juicy parts: here are lines 70-71 of SystemProperty.java:

70             XProcRuntime runtime = tl_runtime.get();
71             XStep step = runtime.getXProcData().getStep();

tl_runtime.get() is returning a null, which turns into a NPE on line 71.

tl_runtime is declared in XProcExtensionFunctionDefinition, which both ValueAvailableCall and SystemPropertyCall extend.

public abstract class XProcExtensionFunctionDefinition extends ExtensionFunctionDefinition {
    protected ThreadLocal<XProcRuntime> tl_runtime = new ThreadLocal<XProcRuntime>() {
        protected synchronized XProcRuntime initialValue() {
            return null;
        }
    };

Both ValueAvailable and SystemProperty set tl_runtime in the constructor, and both read it from ValueAvailableCall and SystemPropertyCall, respectively, which are inner classes. tl_runtime isn't set anywhere else.

So here's what I think is happening. ValueAvailable and SystemProperty are created in the XProcRuntime constructor, which gets called in the main thread. However, ValueAvailableCall and SystemPropertyCall are called in a different thread via a ThreadPoolExecutor used by restlet (see stack trace above). Because they're called in a different thread, tl_runtime.get() returns the value of initialValue(), which is null.

Thus, it seems like an inherent assumption in the code that XProcRuntime is created in the same thread that executes the pipeline. That works fine for a command-line app, but doesn't seem to work well in restlet.

The same pattern seems to be used by the other extension XPath functions, so I imagine they could suffer from the same problem.

Not sure how to fix this, but I hope this information helps in diagnosing and designing a fix to the problem.

@jwcranford

This comment has been minimized.

Show comment
Hide comment
@jwcranford

jwcranford May 5, 2014

After some more digging, this issue seems related to issue 153 in the old Google project (https://code.google.com/p/xmlcalabash/issues/detail?id=153), which is still open.

The thread-local variables were introduced in commit db9ad9b, in response to google issue 153.

After some more digging, this issue seems related to issue 153 in the old Google project (https://code.google.com/p/xmlcalabash/issues/detail?id=153), which is still open.

The thread-local variables were introduced in commit db9ad9b, in response to google issue 153.

@ndw

This comment has been minimized.

Show comment
Hide comment
@ndw

ndw May 5, 2014

Owner

That's a very useful analysis. Thank you, Jonathan.

So now I need to figure out some other mechanism for passing information through to the functions...

Owner

ndw commented May 5, 2014

That's a very useful analysis. Thank you, Jonathan.

So now I need to figure out some other mechanism for passing information through to the functions...

@ndw

This comment has been minimized.

Show comment
Hide comment
@ndw

ndw May 7, 2014

Owner

Ok. I think I've cracked this one. Instead of a thread local variable, I've created a singleton class to serve as a registry for XProcRuntimes. Seems to work.

Owner

ndw commented May 7, 2014

Ok. I think I've cracked this one. Instead of a thread local variable, I've created a singleton class to serve as a registry for XProcRuntimes. Seems to work.

ndw added a commit that referenced this issue May 8, 2014

@ndw ndw closed this May 8, 2014

@jwcranford

This comment has been minimized.

Show comment
Hide comment
@jwcranford

jwcranford Jun 20, 2014

This fixes the problem with NullPointerExceptions, so I have no objection to this particular issue being closed.

However, it seems like it's a step backwards to where the code was before the old google issue 153 was addressed. Is there really a difference between a singleton registry for XProcRuntimes (what the code has now) and simply storing a reference to XProcRuntime in each extension function (the way the code was before commit db9ad9b? (You can follow the link to commit db9ad9b to see the way the code used to be.) If there isn't any real difference, then we may just be back to where we were when google issue 153 was first raised.

In case it helps, comment 3 on the old google issue 153 by Romain Deltour seems to still be relevant and potentially useful, and not addressed in the codebase. https://code.google.com/p/xmlcalabash/issues/detail?id=153#c3

HTH....

This fixes the problem with NullPointerExceptions, so I have no objection to this particular issue being closed.

However, it seems like it's a step backwards to where the code was before the old google issue 153 was addressed. Is there really a difference between a singleton registry for XProcRuntimes (what the code has now) and simply storing a reference to XProcRuntime in each extension function (the way the code was before commit db9ad9b? (You can follow the link to commit db9ad9b to see the way the code used to be.) If there isn't any real difference, then we may just be back to where we were when google issue 153 was first raised.

In case it helps, comment 3 on the old google issue 153 by Romain Deltour seems to still be relevant and potentially useful, and not addressed in the codebase. https://code.google.com/p/xmlcalabash/issues/detail?id=153#c3

HTH....

@bertfrees bertfrees referenced this issue in daisy/pipeline-tasks Mar 29, 2017

Open

Identify performance bottlenecks #71

2 of 3 tasks complete
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment