Bug #6348
closed
net.sf.saxon.expr.XPathContextMajor.getTargetComponent throws NullPointerException - race condition
0%
Description
I don't know if this bug deserves much attention since (a) the problem occurs only occasionally and (b) saxon:transform() will soon be replaced by fn:transform() with an extra parameter anyway (see #6339), but herewith the error message since this might help to improve the code:
2024-02-15 08:52:15 [INFO] Launching /micro/merge-split-and-purge-versions.xslt
2024-02-15 08:52:15 [INFO] parameter input-folder=C:/Data/Interfac/INT/intb/micro/8.2/tmp/
2024-02-15 08:52:15 [INFO] parameter latest-release-folder=C:/Data/Interfac/INT/intb/micro/8.2/latest-release/
2024-02-15 08:52:15 [INFO] parameter output-folder=C:/Data/Interfac/INT/intb/micro/8.2/
2024-02-15 08:52:15 [INFO] parameter purge-date=2024-02-05
2024-02-15 08:52:15 [INFO] parameter split-date=2024-02-05
2024-02-15 08:52:15 [INFO] parameter working-date=2024-02-25
2024-02-15 08:52:15 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/catenaryCase.xml
2024-02-15 08:52:16 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/gigBySerZone.xml
2024-02-15 08:52:16 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/graphicalCatenaryCase.xml
2024-02-15 08:52:18 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/graphicalEdge.xml
2024-02-15 08:52:19 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/graphicalLevelCrossing.xml
2024-02-15 08:52:21 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/graphicalNode.xml
2024-02-15 08:52:23 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/graphicalPlatform.xml
2024-02-15 08:52:23 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/gridInterGrid.xml
2024-02-15 08:52:23 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/levelCrossing.xml
2024-02-15 08:52:24 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/location.xml
2024-02-15 08:52:24 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/milestone.xml
2024-02-15 08:52:26 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/node.xml
java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
... 17 more
java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
... 17 more
2024-02-15 08:52:29 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/nodeByCatenaryCase.xml
2024-02-15 08:52:31 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/nodeByGig.xml
2024-02-15 08:52:34 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/nodeByLocation.xml
2024-02-15 08:52:53 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/nodeByRouteEdge.xml
2024-02-15 08:53:12 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/nodeByTrackEdge.xml
2024-02-15 08:53:15 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/platform.xml
2024-02-15 08:53:15 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/platformSide.xml
2024-02-15 08:53:17 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/routeEdge.xml
2024-02-15 08:53:21 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/shape.xml
2024-02-15 08:53:21 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/style.xml
2024-02-15 08:53:21 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/subLocation.xml
2024-02-15 08:53:22 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/trackEdge.xml
2024-02-15 08:53:23 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/validityDate.xml
2024-02-15 08:53:24 [DEBUG] Exporting file:/C:/Data/Interfac/INT/intb/micro/8.2/view.xml
java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
... 11 more
Caused by: java.lang.NullPointerException
at net.sf.saxon.expr.XPathContextMajor.getTargetComponent(XPathContextMajor.java:684)
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:376)
... 17 more
Some child xsl:result-document threads have not finished
Error
java.lang.RuntimeException: Internal error evaluating template rule in module
jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
java.lang.RuntimeException: Internal error evaluating template rule in module
jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1926)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.lambda$elaborateForPush$1(Block.java:853)
at net.sf.saxon.expr.instruct.Copy$CopyElaborator.lambda$elaborateForPush$0(Copy.java:589)
at net.sf.saxon.expr.instruct.TemplateRule.a
Error in xsl:sequence/@select on line 33 column 45 of batch.xslt:
FOER0000 Error signalled by application call on error()
In template xsl:initial-template on line 13 column 56 of batch.xslt:
Focus: absent
Local variables
$vv:v0 {fn:current-date() lt xs:date("2000-01-01")} = false()
$startTime = xs:dateTimeStamp("2024-02-15T08:46:43.449+01:00")
In template xsl:initial-template on line 13 column 56 of batch.xslt:
Focus: absent
Local variables
$vv:v0 {fn:current-date() lt xs:date("2000-01-01")} = false()
$startTime = xs:dateTimeStamp("2024-02-15T08:46:43.449+01:00")
Error signalled by application call on error()
2024-02-15 08:53:34 [ERROR] description: java.lang.RuntimeException: Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt(Internal error evaluating template rule in module jar:file:int-batch-DEV-SNAPSHOT.jar!/micro/merge-split-and-purge-versions.xslt)
2024-02-15 08:53:34 [ERROR] module: jar:file:int-batch-DEV-SNAPSHOT.jar!/shared/shared-functions.xslt
2024-02-15 08:53:34 [ERROR] line-number: 1062
2024-02-15 08:53:34 [ERROR] Batch execution failed - see above output for any hints
The dataset attached is, of course, a filtered dataset to avoid unnecessarily increasing the upload volume.
Files
Updated by Johan Gheys 2 months ago
- File saxon-transform-6348.zip saxon-transform-6348.zip added
Updated by Johan Gheys 2 months ago
- File shared-functions.xslt shared-functions.xslt added
Attached is the original (not cleaned out) shared-functions.xslt.
Updated by Michael Kay 2 months ago
After running it a dozen times or so, I got a failure, which is probably the same bug, though the symptoms are slightly different:
Error
java.lang.RuntimeException: Internal error evaluating template rule in module
file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt: Internal error evaluating template rule in module file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt
java.lang.RuntimeException: Internal error evaluating template rule in module file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt
at net.sf.saxon.expr.instruct.TemplateRule.applyLeavingTail(TemplateRule.java:386)
at net.sf.saxon.trans.Mode.handleRuleNotNull(Mode.java:587)
at net.sf.saxon.trans.Mode.applyTemplates(Mode.java:521)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:650)
at net.sf.saxon.expr.instruct.ResultDocument.processInstruction(ResultDocument.java:403)
at com.saxonica.config.EnterpriseConfiguration.lambda$processResultDocument$1(EnterpriseConfiguration.java:1929)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.lang.ClassCastException: class net.sf.saxon.expr.Component cannot be cast to class net.sf.saxon.expr.Component$M (net.sf.saxon.expr.Component and net.sf.saxon.expr.Component$M are in unnamed module of loader 'app')
at net.sf.saxon.expr.instruct.ApplyTemplates.getTargetMode(ApplyTemplates.java:303)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:613)
at net.sf.saxon.expr.instruct.Block$BlockElaborator.l
2024-02-22 17:49:26 [ERROR] description: java.lang.RuntimeException: Internal error evaluating template rule in module file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt: Internal error evaluating template rule in module file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt(Internal error evaluating template rule in module file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt)
2024-02-22 17:49:26 [ERROR] module: file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/shared-functions.xslt
2024-02-22 17:49:26 [ERROR] line-number: 385
Updated by Michael Kay 2 months ago
I'm not making much progress. As with all multithreading bugs, the main diagnostic process seems to be to stare at the code until you see something questionable. But let's start by writing down what I know.
Firstly, there's no evidence that saxon:transform is relevant to the problem.
What we can see, in both stack traces, is that there's an asynchronous call on xsl:result-document, which is processed in its own thread and immediately does apply-templates. The asynchronous thread should have been started with a completely clean copy of the dynamic context. But when apply-templates accesses the dynamic context to determine the current component, it finds in one case that it is null, and in the other case that it is a component of the wrong kind. This can only mean that the current component has been modified in a different thread. But of course, the code is carefully written to ensure this can't happen -- in theory.
Updated by Michael Kay 2 months ago
I added a diagnostic to XPathContext.setCurrentComponent() to check whether the same context object is ever updated from more than one thread. It shouldn't happen, and it doesn't. (But perhaps it does on the rare runs that fail?)
Updated by Michael Kay 2 months ago
After another half dozen successful runs, I got a failing run with a different failure:
Caused by: java.lang.UnsupportedOperationException: getLength() not available at net.sf.saxon.om.SequenceTool.getLength(SequenceTool.java:138) at net.sf.saxon.expr.sort.SortedIterator.buildArray(SortedIterator.java:202) at net.sf.saxon.expr.sort.SortedIterator.doSort(SortedIterator.java:268) at net.sf.saxon.expr.sort.SortedIterator.next(SortedIterator.java:156) at net.sf.saxon.expr.elab.PullElaborator.lambda$elaborateForPush$0(PullElaborator.java:39) at net.sf.saxon.expr.instruct.DocumentInstr$DocumentInstrElaborator.lambda$elaborateForItem$3(DocumentInstr.java:392)
This is actually reporting a ClassCastException - SortedIterator is doing
int allocated = SequenceTool.supportsGetLength(base) ? SequenceTool.getLength(base) : 100
and this can only mean that base was a LastPositionFinder when supportsGetLength() was called, and is no longer a LastPositionFinder when getLength() is called.
Well, this seems to be the result of a device used by SortedIterator to catch exceptions and defer them, and the device is misfiring, so all it tells us is that there has been an unexpected internal exception and we don't know what it is. So that's not very helpful. This code was written before we had UncheckedXPathException so I will change it to use that,
Updated by Michael Kay 2 months ago
I've now once again hit the failure
- ☐ java.lang.ClassCastException: class net.sf.saxon.expr.Component cannot be cast to class net.sf.saxon.expr.Component$M (net.sf.saxon.expr.Component and net.sf.saxon.expr.Component$M are in unnamed module of loader 'app')
but it also (perhaps in another thread) does
java.lang.UnsupportedOperationException: getLength() not available
at net.sf.saxon.om.SequenceTool.getLength(SequenceTool.java:138)
at net.sf.saxon.expr.sort.SortedIterator.buildArray(SortedIterator.java:199)
at net.sf.saxon.expr.sort.SortedIterator.doSort(SortedIterator.java:265)
Updated by Michael Kay 2 months ago
Alter another couple of dozen successful runs, another failure with
Caused by: java.lang.UnsupportedOperationException: getLength() not available at net.sf.saxon.om.SequenceTool.getLength(SequenceTool.java:138) at net.sf.saxon.expr.sort.SortedIterator.buildArray(SortedIterator.java:204)
despite the fact that SortedIterator,base is now final.
And the next failure is another ClassCastException, I added some diagnostics and it tells us
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#-1
Current component is net.sf.saxon.expr.instruct.GlobalVariable@5d683ff1
The -1 should be a line number....
I think it's very likely we're in the code at line 26 of this module:
<xsl:for-each select="$input-xml">
<xsl:result-document href="{$output-xml}" method="xml">
<xsl:apply-templates>
<xsl:with-param name="latest-release-xml" select="$latest-release-xml" tunnel="yes"/>
</xsl:apply-templates>
</xsl:result-document>
</xsl:for-each>
Updated by Michael Kay 2 months ago
I've now managed to display the name of the offending global variable:
Current component is variable day-before-working-date
In the debugger I've monitored where we set this variable to be the current component. It seems to be set twice (which is interesting), but in neither case is it overwriting any previous current component.
I found that line numbers are retained if Transform is run with the -l option.
Both evaluations of the global variable are from line 744, but they occur in different threads.
Updated by Michael Kay 2 months ago
A different manifestation this time:
java.lang.ClassCastException: class net.sf.saxon.expr.instruct.GlobalVariable cannot be cast to class net.sf.saxon.expr.instruct.UserFunction (net.sf.saxon.expr.instruct.GlobalVariable and net.sf.saxon.expr.instruct.UserFunction are in unnamed module of loader 'app')
at net.sf.saxon.expr.UserFunctionCall$UserFunctionCallElaborator.lambda$elaborateForPull$0(UserFunctionCall.java:743)
at net.sf.saxon.expr.instruct.ApplyTemplates$ApplyTemplatesElaborator.lambda$elaborateForPush$1(ApplyTemplates.java:634)
But in very much the same area: the component picked up from the currentComponent binding vector is the wrong component. Perhaps it's significant that it's a GlobalVariable muscling in again?
Updated by Michael Kay 2 months ago
In the latest incarnation the failing apply-templates is on line 672
<xsl:apply-templates mode="local:split-and-purge" select="shared:merge-versions($subLocation)"/>
and the current component is the function shared:merge-versions#1
Updated by Michael Kay 2 months ago
The getLength() failure has come up again, now with extra diagnostics:
Caused by: java.lang.UnsupportedOperationException: getLength() not available in class com.saxonica.ee.parallel.MultithreadedFocusTrackingIterator
That's interesting. From the Javadoc:
the synchronization is designed only to
- allow a call on {@link #getLength()} (caused by an XPath invocation of
last()) to occur - asynchronously with the thread that advances the iterator. This happens specifically when an
-
xsl:result-documentinstruction is executed asynchronously, and the code within - the body of the
xsl:result-documentinstruction callslast(). In this situation - the main thread (the one that advances the focus, and spawns new threads for
xsl:result-document) - must be suspended while the value of
last()is computed, which is done by reading the iterator - to completion; when the main thread resumes, there will be a new base iterator positioned over the materialized
- sequence that was read into memory as a side-effect of calling
last(). -
See bug 3927.
I've added more diagnostics for the next time it happens...
Updated by Michael Kay 2 months ago
ClassCastException again. This time:
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#229 Current component in net.sf.saxon.expr.XPathContextMajor@5036f29c is variable working-date
Here line 229 is
<xsl:apply-templates mode="local:split-and-purge" select="shared:merge-versions($graphicalStopSignal)"/>
which has no obvious relationship to the variable working-date
The time I've logged all calls to XPathContext.setCurrentComponent() (about 100K calls), and none of them sets the current component to this variable. There is only one entry that logs setting the current component for this context object, and that one sets it to the mode xsl:unnamed which is what we would expect (the relevant mode is the one of the calling template, not the called template). That setting happens a very long time before the crash.
NOTE: probably irrelevant, but worth investigating: we're frequently setting the current component twice consecutively to the same value:
net.sf.saxon.expr.XPathContextMajor@2003877a Set current component := function shared:extract-validities#3
net.sf.saxon.expr.XPathContextMajor@2003877a Set current component := function shared:extract-validities#3
net.sf.saxon.expr.XPathContextMajor@5e77f0f4 Set current component := function shared:open-file#2
net.sf.saxon.expr.XPathContextMajor@5e77f0f4 Set current component := function shared:open-file#2
net.sf.saxon.expr.XPathContextMajor@19b30c92 Set current component := function shared:open-file#1
net.sf.saxon.expr.XPathContextMajor@19b30c92 Set current component := function shared:open-file#1.
At best this suggests some inefficiency.
Next failure:
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#630 Current component in net.sf.saxon.expr.XPathContextMajor@27dd88fd is function shared:merge-versions#1
The one consistent feature is that it's always xsl:apply-templates that is failing to find the current component; other constructs, like function calls, seem to have no problem.
Updated by Michael Kay 2 months ago
I was wondering whether the problem might be related to JIT compilation of template rules, so I ran with -jit:off. On about the 15th attempt, it failed in the familiar way.
However, there's a new feature here. The diagnostic messages output for the ClassCastException now appear thrice, but interleaved.:
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#526
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#572
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#557
Current component in net.sf.saxon.expr.XPathContextMajor@3c34a303 is variable working-date
Current component in net.sf.saxon.expr.XPathContextMajor@645ea33b is variable working-date
Current component in net.sf.saxon.expr.XPathContextMajor@62c2c613 is variable working-date
This can only mean that the CCE has occurred simultaneously in 3 different threads. It's noticeable that although they affect three different xsl:apply-templates instructions, the incorrect current component is the same each time.
Ummmm. It's not actually the current component that's the wrong type, it's the target component, which we find via the current component. In the messages above, we're not actually displaying the current component, we're displaying the target component, which is the value of currentComponent.getComponentBindings().get(bindingSlot) So the currentComponent might be correct, but its componentBindings are incorrect...
Updated by Michael Kay 2 months ago
Now making this distinction in the diagnostics, I'm getting
In apply-templates at file:/Users/mike/bugs/2024/6348-Gheys/saxon-transform-6348/xslt/merge-split-and-purge-versions.xslt#713
Current component in net.sf.saxon.expr.XPathContextMajor@d65555 is mode xsl:unnamed
Target component in net.sf.saxon.expr.XPathContextMajor@d65555 (109) is variable working-date
The component xsl:unnamed contains all the template rules in the unnamed mode, and this has a large number of binding slots for its references to other components used by these template rules; hence the high slot number 109.
Perhaps something is going wrong with the allocation of component binding slots? And perhaps this is related to the use of saxon:transform?
It seems that setting -jit:off on the command line has no effect on the secondary stylesheet compiled using saxon:transform. This is still using JIT compilation of template rules. And when a template rule is first evaluated, additional binding slots are allocated to its containing mode, And if this happens in asynchronous code executed by xsl:result-document, then two template rules may be compiled concurrently and may be allocated the same slots.
That feels like the right explanation.
Updated by Michael Kay 2 months ago
Examination of the code confirms that there is no attempt to stop two concurrent JIT template initializations adding slots to the binding vector for the containing mode simultaneously, and the symptoms are consistent with this (at any rate, the "wrong target component" exceptions - it doesn't directly explain the getLength() problem).
To avoid long locks, the best strategy seems to be for template initialization to first calculate how many slots it needs in the binding vector, then do a synchronized allocation of a block of slots, and then do a second pass to insert the slot numbers. Or it could build a list of actions to be performed in this first pass, and then execute these actions in the second.
Updated by Michael Kay 2 months ago
Actually, I think the solution is simpler: it's enough to synchronize the three lines of code:
int slot = bindings.size();
ComponentBinding cb = new ComponentBinding(name, target);
bindings.add(cb);
(and the second line could be moved up...) That's obviously a very short single-threaded section.
Updated by Michael Kay 2 months ago
- Category set to Multithreading
- Status changed from New to Resolved
- Assignee set to Michael Kay
- Priority changed from Low to Normal
- Applies to branch 12, trunk added
- Fix Committed on Branch 12, trunk added
- Platforms .NET, Java added
Fixed on the 12,x and main branches.
SUMMARY: when xsl:result-document operates asynchronously, and JIT compilation of template rules is in effect, it is possible for two template rules to be compiled in parallel; since both might be allocating slots for component references (to functions, variables, named templates etc) in the binding vector for the containing mode, the allocation needs to be synchronised to keep everything consistent.
Updated by Johan Gheys 2 months ago
Indeed, we were not sure if this had anything to do with saxon:transform(). Whenever the phenomenon occurred with us, saxon:transform() was always involved (but maybe that just means we use saxon:transform() a lot). Anyway, thanks Michael for your persistence in reproducing and solving this bug. Thanks to your clear view, the solution is indeed surprisingly simple, but no less important.
Please register to edit this issue
.