Recorded as JENA-523 https://issues.apache.org/jira/browse/JENA-523
On 28/08/13 09:43, Andy Seaborne wrote:
On 27/08/13 22:47, Taylor, Stuart Rae wrote:Hi Andy, I didn't have the '--verbose' flag set when I created the logs for the previous message so I didn't get the update query that caused the exception. However I've tried again with verbose logging, and managed to get the exception thrown for the select query. The queries *should* be valid SPARQL (they're run several times in our system), but I will get some better logs asap. In this case, I have an update which returns HTTP 200: INSERT { ?subject hc:associatedWith hc:633 ; } WHERE { ?subject ?p ?o FILTER ( ?subject = hc:90623 ) } Then the next select query triggers the ConcurrentModificationException in my last message. Sorry for the vagueness. I will try to isolate the conditions tomorrow.If I understand what's going on (and I don't :-) ... It's the first exception that matters - the later ones are consequences of the 17:43:33 WARN DatasetGraphText :: Exception in abort: Can't abort a write lock-transaction It is true you can't aborted a lock-managed transaction ... but the code seems to include the setup (parsing the update) in the So ... 1/ Need to find why the abort happened - the stacktrace suggested a parse error but I'm not 100% sure. 2/ The code ought to clean up better anyway (the later exceptions). AndyThanks, Stuart. ________________________________________ From: Andy Seaborne <[email protected]> Sent: 27 August 2013 21:36 To: [email protected] Subject: Re: Fuseki concurrency problems: text search + inference Stuart - quick question - and from code review, not use test running ... What was the update? Could it be that there was a syntax error in it? Andy On 27/08/13 18:16, Stuart Taylor wrote:Hi all, I'm having some more problems with Fuseki and full text search. I have an InfModel backed by a TDB dataset, which I've added a Lucene text index to. I'm having problems with updates and select queries resulting in exceptions being thrown by Fuseki. I am running Fuseki 0.2.8-SNAPSHOT 20130826-0756 which should include the fixes for JENA-522 (where I was having problems earlier). Unfortunately I haven't managed to come up with a complete running example which reproduces the problem, but while I do that the stack traces from Fuseki's log might be able to shed some light on what is happening. I have also added the assembler file for my Fuseki set up at the end of this message. After some SPARQL Update queries I occasionally get: 17:43:33 WARN DatasetGraphText :: Exception in abort: Can't abort a write lock-transaction com.hp.hpl.jena.sparql.JenaTransactionException: Can't abort a write lock-transaction at com.hp.hpl.jena.sparql.core.DatasetGraphWithLock._abort(DatasetGraphWithLock.java:100) at com.hp.hpl.jena.sparql.core.DatasetGraphTrackActive.abort(DatasetGraphTrackActive.java:56) at org.apache.jena.query.text.DatasetGraphText.abort(DatasetGraphText.java:139) at org.apache.jena.fuseki.servlets.HttpAction.abort(HttpAction.java:142) at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:248) at org.apache.jena.fuseki.servlets.SPARQL_Update.executeForm(SPARQL_Update.java:212) at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:110) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeLifecycle(SPARQL_ServletBase.java:184) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeAction(SPARQL_ServletBase.java:165) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.execCommonWorker(SPARQL_ServletBase.java:153) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:73) at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.java:80) at javax.servlet.http.HttpServlet.service(HttpServlet.java:755) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:457) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) at org.eclipse.jetty.server.Server.handle(Server.java:370) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489) at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:960) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1021) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:298) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) at java.lang.Thread.run(Thread.java:722) 17:43:33 WARN HttpAction :: Transaction still active in endWriter - no commit or abort seen (forced abort) 17:43:33 WARN DatasetGraphText :: Exception in abort: this IndexWriter is closed org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:614) at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:628) at org.apache.lucene.index.IndexWriter.rollback(IndexWriter.java:1974) at org.apache.jena.query.text.TextIndexLucene.abortIndexing(TextIndexLucene.java:107) at org.apache.jena.query.text.DatasetGraphText.abort(DatasetGraphText.java:137) at org.apache.jena.fuseki.servlets.HttpAction.endWrite(HttpAction.java:153) at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:257) at org.apache.jena.fuseki.servlets.SPARQL_Update.executeForm(SPARQL_Update.java:212) at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:110) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeLifecycle(SPARQL_ServletBase.java:184) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeAction(SPARQL_ServletBase.java:165) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.execCommonWorker(SPARQL_ServletBase.java:153) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:73) at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.java:80) at javax.servlet.http.HttpServlet.service(HttpServlet.java:755) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:457) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) at org.eclipse.jetty.server.Server.handle(Server.java:370) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489) at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:960) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1021) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:298) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) at java.lang.Thread.run(Thread.java:722) Then running SELECT queries shortly after results in: 17:46:23 WARN Fuseki :: [13] RC = 500 : Iterator: started at 24, now 30 java.util.ConcurrentModificationException: Iterator: started at 24, now 30 at com.hp.hpl.jena.tdb.sys.DatasetControlMRSW.policyError(DatasetControlMRSW.java:157) at com.hp.hpl.jena.tdb.sys.DatasetControlMRSW.access$000(DatasetControlMRSW.java:32) at com.hp.hpl.jena.tdb.sys.DatasetControlMRSW$IteratorCheckNotConcurrent.checkCourrentModification(DatasetControlMRSW.java:110) at com.hp.hpl.jena.tdb.sys.DatasetControlMRSW$IteratorCheckNotConcurrent.hasNext(DatasetControlMRSW.java:118) at org.apache.jena.atlas.iterator.Iter$4.hasNext(Iter.java:312) at org.apache.jena.atlas.iterator.Iter$4.hasNext(Iter.java:312) at org.apache.jena.atlas.iterator.Iter$4.hasNext(Iter.java:312) at org.apache.jena.atlas.iterator.Iter.hasNext(Iter.java:910) at com.hp.hpl.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90) at com.hp.hpl.jena.util.iterator.NiceIterator$1.hasNext(NiceIterator.java:103) at com.hp.hpl.jena.util.iterator.NiceIterator$1.hasNext(NiceIterator.java:103) at com.hp.hpl.jena.reasoner.rulesys.impl.TopLevelTripleMatchFrame.nextMatch(TopLevelTripleMatchFrame.java:55) at com.hp.hpl.jena.reasoner.rulesys.impl.LPInterpreter.run(LPInterpreter.java:330) at com.hp.hpl.jena.reasoner.rulesys.impl.LPInterpreter.next(LPInterpreter.java:192) at com.hp.hpl.jena.reasoner.rulesys.impl.Generator.pump(Generator.java:250) at com.hp.hpl.jena.reasoner.rulesys.impl.Generator.pump(Generator.java:237) at com.hp.hpl.jena.reasoner.rulesys.impl.LPBRuleEngine.pump(LPBRuleEngine.java:308) at com.hp.hpl.jena.reasoner.rulesys.impl.LPTopGoalIterator.moveForward(LPTopGoalIterator.java:109) at com.hp.hpl.jena.reasoner.rulesys.impl.LPTopGoalIterator.hasNext(LPTopGoalIterator.java:222) at com.hp.hpl.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90) at com.hp.hpl.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90) at com.hp.hpl.jena.util.iterator.FilterIterator.hasNext(FilterIterator.java:54) at com.hp.hpl.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90) at com.hp.hpl.jena.util.iterator.FilterIterator.hasNext(FilterIterator.java:54) at com.hp.hpl.jena.sparql.engine.iterator.QueryIterTriplePattern$TripleMapper.hasNextBinding(QueryIterTriplePattern.java:151) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:81) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.iterator.QueryIterBlockTriples.hasNextBinding(QueryIterBlockTriples.java:64) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:40) at com.hp.hpl.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:112) at com.hp.hpl.jena.sparql.engine.ResultSetStream.hasNext(ResultSetStream.java:75) at com.hp.hpl.jena.sparql.resultset.ResultSetMem.<init>(ResultSetMem.java:97) at com.hp.hpl.jena.query.ResultSetFactory.makeRewindable(ResultSetFactory.java:420) at com.hp.hpl.jena.sparql.resultset.TextOutput.write(TextOutput.java:149) at com.hp.hpl.jena.sparql.resultset.TextOutput.write(TextOutput.java:132) at com.hp.hpl.jena.sparql.resultset.TextOutput.write(TextOutput.java:120) at com.hp.hpl.jena.sparql.resultset.TextOutput.format(TextOutput.java:67) at com.hp.hpl.jena.query.ResultSetFormatter.out(ResultSetFormatter.java:135) at org.apache.jena.fuseki.servlets.ResponseResultSet$3.output(ResponseResultSet.java:238) at org.apache.jena.fuseki.servlets.ResponseResultSet.output(ResponseResultSet.java:283) at org.apache.jena.fuseki.servlets.ResponseResultSet.textOutput(ResponseResultSet.java:244) at org.apache.jena.fuseki.servlets.ResponseResultSet.doResponseResultSet$(ResponseResultSet.java:145) at org.apache.jena.fuseki.servlets.ResponseResultSet.doResponseResultSet(ResponseResultSet.java:88) at org.apache.jena.fuseki.servlets.SPARQL_Query.sendResults(SPARQL_Query.java:348) at org.apache.jena.fuseki.servlets.SPARQL_Query.execute(SPARQL_Query.java:244) at org.apache.jena.fuseki.servlets.SPARQL_Query.executeWithParameter(SPARQL_Query.java:195) at org.apache.jena.fuseki.servlets.SPARQL_Query.perform(SPARQL_Query.java:80) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeLifecycle(SPARQL_ServletBase.java:184) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeAction(SPARQL_ServletBase.java:165) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.execCommonWorker(SPARQL_ServletBase.java:153) at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:73) at org.apache.jena.fuseki.servlets.SPARQL_Query.doGet(SPARQL_Query.java:61) at javax.servlet.http.HttpServlet.service(HttpServlet.java:735) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1448) at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82) at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:294) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) at org.eclipse.jetty.server.Server.handle(Server.java:370) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489) at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:949) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1011) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:298) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) at java.lang.Thread.run(Thread.java:722) 17:46:23 INFO Fuseki :: [13] 500 Iterator: started at 24, now 30 (25 ms) Here is the assembler file: @prefix : <#> . @prefix fuseki: <http://jena.apache.org/fuseki#><http://jena.apache.org/fuseki#> . @prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#><http://www.w3.org/1999/02/22-rdf-syntax-ns#> . @prefix rdfs: <http://www.w3.org/2000/01/rdf-schema#><http://www.w3.org/2000/01/rdf-schema#> . @prefix tdb: <http://jena.hpl.hp.com/2008/tdb#><http://jena.hpl.hp.com/2008/tdb#> . @prefix ja: <http://jena.hpl.hp.com/2005/11/Assembler#><http://jena.hpl.hp.com/2005/11/Assembler#> . @prefix text: <http://jena.apache.org/text#><http://jena.apache.org/text#> . @prefix dc: <http://purl.org/dc/terms/><http://purl.org/dc/terms/> . [] rdf:type fuseki:Server ; # Timeout - server-wide default: milliseconds. # Format 1: "1000" -- 1 second timeout # Format 2: "10000,60000" -- 10s timeout to first result, then 60s timeout to for rest of query. # See java doc for ARQ.queryTimeout ja:context [ ja:cxtName "arq:queryTimeout" ; ja:cxtValue "12000,50000" ] ; fuseki:services ( <#service1> ) . # Custom code. [] ja:loadClass "com.hp.hpl.jena.tdb.TDB" . # TDB tdb:DatasetTDB rdfs:subClassOf ja:RDFDataset . tdb:GraphTDB rdfs:subClassOf ja:Model . ## Initialize text query [] ja:loadClass "org.apache.jena.query.text.TextQuery" . # A TextDataset is a regular dataset with a text index. text:TextDataset rdfs:subClassOf ja:RDFDataset . # Lucene index text:TextIndexLucene rdfs:subClassOf text:TextIndex . ## --------------------------------------------------------------- ## Service with only SPARQL query on an inference model. ## Inference model bbase data in TDB. <#service1> rdf:type fuseki:Service ; rdfs:label "TDB/text service" ; fuseki:name "dataset" ; # http://host/dataset fuseki:serviceQuery "query" ; fuseki:serviceUpdate "update" ; fuseki:serviceUpload "upload" ; fuseki:serviceReadWriteGraphStore "data" ; fuseki:serviceReadGraphStore "get" ; fuseki:dataset <#dataset_fulltext> ; . <#dataset_inf> rdf:type ja:RDFDataset ; ja:defaultGraph <#model_inf> . <#model_inf> rdf:type ja:Model ; ja:baseModel <#tdbGraph> ; ja:reasoner [ ja:reasonerURL <http://jena.hpl.hp.com/2003/OWLMicroFBRuleReasoner><http://jena.hpl.hp.com/2003/OWLMicroFBRuleReasoner> ] . <#tdbDataset> rdf:type tdb:DatasetTDB ; tdb:location "Data" . <#tdbGraph> rdf:type tdb:GraphTDB ; tdb:dataset <#tdbDataset> . # Dataset with full text index. <#dataset_fulltext> rdf:type text:TextDataset ; text:dataset <#dataset_inf> ; ##text:dataset <#tdbDataset> ; text:index <#indexLucene> . # Text index description <#indexLucene> a text:TextIndexLucene ; text:directory <file:Lucene><file:Lucene> ; ##text:directory "mem" ; text:entityMap <#entMap> ; . # Mapping in the index # URI stored in field "uri" # rdfs:label is mapped to field "text" <#entMap> a text:EntityMap ; text:entityField "uri" ; text:defaultField "text" ; text:map ( [ text:field "text" ; text:predicate dc:title ] [ text:field "text" ; text:predicate dc:description ] ) . Any advice appreciated! Thanks, Stuart. The University of Aberdeen is a charity registered in Scotland, No SC013683.The University of Aberdeen is a charity registered in Scotland, No SC013683.
