Query returns 500 server error

[bartalusg]

Version

6.0.0

What happened?

When executing the query:

PREFIX rdfs: <http://www.w3.org/2000/01/rdf-schema#>
PREFIX sh: <http://www.w3.org/ns/shacl#>
PREFIX owl: <http://www.w3.org/2002/07/owl#>

SELECT ?classId ?nodeShape
WHERE {
    ?classId a owl:Class .
	{
		?nodeShape sh:targetClass ?classId .
	}
	UNION
	{
        ?classId rdfs:subClassOf+ ?superClassId .
    	?superClassId a owl:Class .
    	?nodeShape sh:targetClass ?superClassId .
	}	
}

I receive the following error:

org.apache.jena.query.QueryExecException: org.apache.jena.sparql.ARQInternalErrorException: Peek iterator is already empty
at org.apache.jena.sparql.engine.iterator.QueryIterFailed.buildException(QueryIterFailed.java:65)
at org.apache.jena.sparql.engine.iterator.QueryIterFailed.hasNextBinding(QueryIterFailed.java:53)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.engine.main.iterator.QueryIterUnion$1.hasNextBinding(QueryIterUnion.java:74)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:73)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.engine.iterator.QueryIterConvert.hasNextBinding(QueryIterConvert.java:61)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40)
at org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:125)
at org.apache.jena.sparql.exec.RowSetStream.hasNext(RowSetStream.java:51)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeQuery(SPARQLQueryProcessor.java:393)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:287)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeWithParameter(SPARQLQueryProcessor.java:227)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:212)
at org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:61)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execPost(SPARQLQueryProcessor.java:87)
at org.apache.jena.fuseki.servlets.ActionProcessor.process(ActionProcessor.java:38)
at org.apache.jena.fuseki.servlets.ActionBase.process(ActionBase.java:57)
at org.apache.jena.fuseki.servlets.ActionExecLib.execActionSub(ActionExecLib.java:127)
at org.apache.jena.fuseki.servlets.ActionExecLib.execAction(ActionExecLib.java:101)
at org.apache.jena.fuseki.server.Dispatcher.dispatchAction(Dispatcher.java:242)
at org.apache.jena.fuseki.server.Dispatcher.process(Dispatcher.java:232)
at org.apache.jena.fuseki.server.Dispatcher.dispatch(Dispatcher.java:150)
at org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:52)
at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1640)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:65)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:463)
at org.apache.shiro.web.servlet.AbstractShiroFilter.lambda$doFilterInternal$0(AbstractShiroFilter.java:378)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:91)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:84)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:389)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:376)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1640)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:351)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:304)
at org.eclipse.jetty.ee11.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee11.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1640)
at org.eclipse.jetty.ee11.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1602)
at org.eclipse.jetty.ee11.servlet.ServletChannel.dispatch(ServletChannel.java:868)
at org.eclipse.jetty.ee11.servlet.ServletChannel.handle(ServletChannel.java:449)
at org.eclipse.jetty.ee11.servlet.ServletHandler.handle(ServletHandler.java:470)
at org.eclipse.jetty.ee11.servlet.SessionHandler.handle(SessionHandler.java:763)
at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1224)
at org.eclipse.jetty.server.Server.handle(Server.java:197)
at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:720)
at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:412)
at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1810)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:492)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.epcRunTask(AdaptiveExecutionStrategy.java:428)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:401)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:255)
at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:204)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:317)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:1009)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1239)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1194)
at java.base/java.lang.Thread.run(Unknown Source)

Caused by: org.apache.jena.sparql.ARQInternalErrorException: Peek iterator is already empty
at org.apache.jena.tdb2.solver.OpExecutorTDB2.reorder(OpExecutorTDB2.java:307)
at org.apache.jena.tdb2.solver.OpExecutorTDB2.optimizeExecuteTriples(OpExecutorTDB2.java:207)
at org.apache.jena.tdb2.solver.OpExecutorTDB2.optimizeExecuteQuads(OpExecutorTDB2.java:242)
at org.apache.jena.tdb2.solver.OpExecutorTDB2.execute(OpExecutorTDB2.java:167)
at org.apache.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:64)
at org.apache.jena.sparql.algebra.op.OpQuadPattern.visit(OpQuadPattern.java:90)
at org.apache.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:46)
at org.apache.jena.sparql.engine.main.OpExecutor.exec(OpExecutor.java:118)
at org.apache.jena.tdb2.solver.OpExecutorTDB2.exec(OpExecutorTDB2.java:91)
at org.apache.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:228)
at org.apache.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:120)
at org.apache.jena.sparql.algebra.op.OpSequence.visit(OpSequence.java:77)
at org.apache.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:46)
at org.apache.jena.sparql.engine.main.OpExecutor.exec(OpExecutor.java:118)
at org.apache.jena.tdb2.solver.OpExecutorTDB2.exec(OpExecutorTDB2.java:91)
at org.apache.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:90)
at org.apache.jena.sparql.engine.main.QC.execute(QC.java:61)
at org.apache.jena.sparql.engine.main.iterator.QueryIterUnion$1.hasNextBinding(QueryIterUnion.java:83)

Relevant output and stacktrace

Are you interested in making a pull request?

None

[afs]

Hi @bartalusg --

So we can recreate the situation, do you have some small amount of data that goes with the query?

What does the Fuseki server configuration look like?
Is it a problem with Fuseki 5.6.0 as well?

[Aklakan]

For jena-6.0.0, I could reproduce the issue based on the given query with this data on TDB2.
The query works for me on ARQ.

PREFIX sh: <http://www.w3.org/ns/shacl#>
PREFIX owl: <http://www.w3.org/2002/07/owl#>
PREFIX eg: <http://www.example.org/>

eg:MyClass a owl:Class .
eg:myNodeShape sh:targetClass eg:MyClass .

Also, replacing the property path with a plain triple pattern makes the query work. So on first glance the issue seems to be related to reordering w.r.t. to property paths with empty results.

SELECT ?classId ?nodeShape
WHERE {
    ?classId a owl:Class .
	{
		?nodeShape sh:targetClass ?classId .
	}
	UNION
	{
        ?classId rdfs:subClassOf+ ?superClassId . # <-- Remove + to make the query work.
    	?superClassId a owl:Class .
    	?nodeShape sh:targetClass ?superClassId .
	}	
}

Further investigation: The query worked on jena 5.6.0 from this download using the tdb2.tdbquery cli tool.

So the reported issue might have been introduced with #3603

[afs]

I'm not sure #3603 is the whole story. It removes if ( !input.hasNext() ) although TDB1 has the same change but works with the given example.

[Aklakan]

Yeah, #3603 looks related but I wasn't totally sure either so I phrased it as "might have been introduced". Tonight I won't find time to look deeper into this.

[afs]

No problem.

I have a fix (put back the if ( !input.hasNext() ) and there maybe a better fix.

I want to see why TDB1 isn't impacted. It may not go into this code in teh same situation as TDB2. It's been a while since I looked at this area.

[Aklakan]

There is a comment from me that there are cases where hasNext() may scan all data:

https://github.com/apache/jena/pull/3603/changes#r2546633206

So just putting it back in may will cause a different regression again.

[Aklakan]

Ah, perhaps I am pretty sure it just needs to be this, so that timeout during input.hasNext() yields a QueryIterFailed instead of failing the iterator construction:

try {
    if ( ! input.hasNext() )
        return input ;
} catch (Exception e) {
    return new QueryIterFailed(input, execCxt, e);
}

I though that removal of the input.hasNext() check was harmless, and avoid the need of a QueryIterFailed wrapping, because it would just lead to an empty iterator getting passed on - what could possibly go wrong? (all tests passed)
I did not consider an explicit check later down the call stack:

// at org.apache.jena.tdb2.solver.OpExecutorTDB2.reorder(OpExecutorTDB2.java:307)
            if ( ! peek.hasNext() )
                throw new ARQInternalErrorException("Peek iterator is already empty");

[afs]

@Aklakan

Is there any reason not to put try-catch-QueryIterFailed around the whole of optimizeExecute bodies?

---

The test

     if ( ! input.hasNext() )
            return input ;

isn't necessary but, generally, an idiom of having a quick check to make sure there is something to do is used.
If it wasn't for the check throwing ARQInternalErrorException, the code seems to work.

---

A short test case is:

PREFIX :  <http://example/>

SELECT *
WHERE {
     ?x :property* ?y .
     ?y :q1 123 .
     ?y :q2 456 .
}

even on an empty database. The key is a non-matching, non-mergable pattern then 2+ triples patterns - even { FILTER(false) } will do.

[Aklakan]

Overall it's ok to wrap the whole body - the relevant bit is that any iterator created inside of the body must not be left dangling if anything goes wrong - but that's prevented by input = peek:

    protected QueryIterator execute(BasicPattern pattern, ReorderTransformation reorder,
                                    QueryIterator input, ExecutionContext execCxt) {
        try {
                    // ...
                    QueryIterPeek peek = QueryIterPeek.create(input, execCxt) ;
                    input = peek ;
                    // ...
        } catch (Exception e) { return new QueryIterFailed(input, execCxt, e); }
    }

On the PR discussion I also added try-catch on the whole body: #3753 (comment)

Dangling iterators cause "open iterator" warnings by QueryIteratorCheck.