[JENA-2074] Jetty crash when returning badly formed URIrefs as RDF/XML

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: Jena 3.17.0, Jena 4.0.0
• Fix Version/s: Jena 4.0.0
• Component/s: Fuseki
• Assignee: Andy Seaborne
• Reporter: Jon
• Created: 21/Mar/21 18:15
• Updated: 01/Apr/21 09:22
• Resolved: 23/Mar/21 17:41

Description

If the data loaded into Jena contains some badly-formed absolute URIrefs as the object of some triples (eg. </tmp/release/crawl/2021/02/19/page.1g2y60c-x43zpnt82fv>)..
then, when I query Fuseki passing HTTP header...

• ✅  "Accept: application/sparql-results+xml" - the results come back the same as was loaded.
• ✅ "Accept: application/n-triples" - the results come back the same as was loaded.
• ❌ "Accept: application/rdf+xml" - Fuseki logs the following exception:

13:09:11 ERROR Fuseki          :: Internal error
java.lang.IllegalArgumentException: setContentLength(267) when already written 8192
	at org.eclipse.jetty.server.Response.setContentLength(Response.java:823) ~[fuseki-server.jar:3.17.0]
	at javax.servlet.ServletResponseWrapper.setContentLength(ServletResponseWrapper.java:161) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.HttpServletResponseTracker.setContentLength(HttpServletResponseTracker.java:87) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.ServletOps.writeMessagePlainText(ServletOps.java:73) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.ServletOps.writeMessagePlainTextError(ServletOps.java:86) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.ServletOps.responseSendError(ServletOps.java:55) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.ActionExecLib.execAction(ActionExecLib.java:120) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.server.Dispatcher.dispatchAction(Dispatcher.java:118) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.server.Dispatcher.process(Dispatcher.java:110) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.server.Dispatcher.dispatch(Dispatcher.java:96) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:51) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:450) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:387) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) ~[fuseki-server.jar:3.17.0]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:284) ~[fuseki-server.jar:3.17.0]
	at org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:247) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1612) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1582) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:766) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773) [fuseki-server.jar:3.17.0]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905) [fuseki-server.jar:3.17.0]
	at java.lang.Thread.run(Thread.java:834) [?:?]

Seems the first 8192 bytes of the query results have been sent before the bad URIref is encountered, so it's too late to send just the error message on its own.
The main problem is that the error message that Fuseki is trying to report gets lost, going neither to the client nor the log file. The actual error looks like this:

Failed to write output in RDF/XML: Only well-formed absolute URIrefs can be included in RDF/XML output: </tmp/release/crawl/2021/02/19/page.1g2y60c-x43zpnt82fv> Code: 57/REQUIRED_COMPONENT_MISSING in SCHEME: A component that is required by the scheme is missing.

Ideally just the actual error message should get logged instead of the exception and stack trace.
Also the usual log entry recording the HTTP status and query duration doesn't appear.

As a dirty hack.. I tried commenting out the following line and it does avoid the exception:
https://github.com/apache/jena/blob/22c54db046b610f0ef1dbe5fadd4a8527af98fe8/jena-fuseki2/jena-fuseki-core/src/main/java/org/apache/jena/fuseki/servlets/ServletOps.java#L73

Another question is whether the HTTP status returned to the client (HTTP/1.1 400 Bad Request) is appropriate, given that the client-side query is valid and it's the server-side data that is at fault?

Issue Links

• relates to: JENA-2061 Fuseki XML result serializer outputs characters that are illegal per XML spec
• links to: GitHub Pull Request #963