RDF4J Server java.util.concurrent.ExecutionException
67 views
Skip to first unread message
Dick Knowles
Nov 23, 2016, 3:47:32 PM11/23/16
to rdf4j...@googlegroups.com
I don't know whether this is a bug or my misuse of the RDF4J server. Any assistance would be appreciated.
I'm calling the RDF4J server from two different executions of a program that is updating some data on the server. The problem point is a clean-the-old before adding the new data. Both executions are at this code in my client at the same time. The code in RDFUploader is
50 public void clearSummaryData(final String contextUri) {
51 try (final RepositoryConnection conn = repo.getConnection()) {
52 conn.begin();
53 try {
54 final IRI context = conn.getValueFactory().createIRI( contextUri );
55 for ( USTC summaryProp : USTC.summaryProperties ) {
56 IRI prop = conn.getValueFactory().createIRI( summaryProp.getUri() );
57 conn.remove( (Resource) null, prop, null, context );
58 }
59 } catch ( RDFParseException | RepositoryException e ) {
60 conn.rollback();
61 throw new SIPException( "Could not clear summary values", e );
62 }
63 conn.commit();
64 }
65 }Both executions are going through the same list of properties, but in two different contexts. On the first "conn.remove( ...)" one execution gets
2016-Nov-23 14:33:51.223 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem:
Exception in thread "main" test.sip.SIPDataIngestException: org.eclipse.rdf4j.repository.RepositoryException:
at test.sip.RDFUploader.upload(RDFUploader.java:61)
at test.sip.RDFUploader.upload(RDFUploader.java:69)
at test.sip.ingest.IngestController.ingestPlanData(IngestController.java:269)
at test.sip.ingest.IngestController.ingestPlan(IngestController.java:230)
at test.sip.ingest.IngestController.main(IngestController.java:145)
Caused by: org.eclipse.rdf4j.repository.RepositoryException:
at org.eclipse.rdf4j.http.client.SparqlSession.execute(SparqlSession.java:1132)
at org.eclipse.rdf4j.http.client.SparqlSession.executeNoContent(SparqlSession.java:1083)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:845)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:792)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:679)
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.add(HTTPRepositoryConnection.java:506)
at test.sip.RDFUploader.upload(RDFUploader.java:58)
... 4 more
The other execution gets
2016-Nov-23 14:33:51.226 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem: Transaction handling error: null
2016-Nov-23 14:33:51.228 WARN [main] org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection:372
Rolling back transaction due to connection close
java.lang.Throwable: null
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.close(HTTPRepositoryConnection.java:372)
at test.sip.ingest.PostProcessor.clearSummaryData(PostProcessor.java:64)
at test.sip.ingest.IngestController.addSummaryData(IngestController.java:235)
at test.sip.ingest.IngestController.ingestPlanData(IngestController.java:272)
at test.sip.ingest.IngestController.ingestPlan(IngestController.java:230)
at test.sip.ingest.IngestController.main(IngestController.java:145)
2016-Nov-23 14:33:51.241 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem:
On the RDF4J Server side, these are the last few messages:
127.0.0.1 - - [23/Nov/2016:14:33:39 -0500] "POST /rdf4j-server/repositories/sip-repo/transactions HTTP/1.1" 201 -
127.0.0.1
- - [23/Nov/2016:14:33:39 -0500] "PUT
/rdf4j-server/repositories/sip-repo/transactions/319ff73a-eb5c-4a6c-a8a7-0cfcd397a301?preserveNodeId=true&action=DELETE
HTTP/1.1" 200 -
127.0.0.1 - - [23/Nov/2016:14:33:39 -0500] "PUT
/rdf4j-server/repositories/sip-repo/transactions/319ff73a-eb5c-4a6c-a8a7-0cfcd397a301?action=COMMIT
HTTP/1.1" 200 -
127.0.0.1 - - [23/Nov/2016:14:33:41 -0500] "POST /rdf4j-server/repositories/sip-repo/transactions HTTP/1.1" 201 -
127.0.0.1
- - [23/Nov/2016:14:33:41 -0500] "PUT
/rdf4j-server/repositories/sip-repo/transactions/8d887f69-bf52-4c84-a4f7-30f8ebc6db90?preserveNodeId=true&action=DELETE
HTTP/1.1" 200 -
127.0.0.1 - - [23/Nov/2016:14:33:41 -0500] "PUT
/rdf4j-server/repositories/sip-repo/transactions/8d887f69-bf52-4c84-a4f7-30f8ebc6db90?action=COMMIT
HTTP/1.1" 200 -
127.0.0.1 - - [23/Nov/2016:14:33:51 -0500] "POST
/rdf4j-server/repositories/sip-repo/statements?context=%3Chttp%3A%2F%2Fpurl.test%2Fsip%2Fgraphs%2FFY16-demo-opt%3E
HTTP/1.1" 204 -
127.0.0.1 - - [23/Nov/2016:14:33:51 -0500] "POST /rdf4j-server/repositories/sip-repo/transactions HTTP/1.1" 201 -
127.0.0.1
- - [23/Nov/2016:14:33:51 -0500] "PUT
/rdf4j-server/repositories/sip-repo/transactions/ab46e96a-9218-4271-834a-bf784a6fb4ed?preserveNodeId=true&action=DELETE
HTTP/1.1" 500 32
127.0.0.1 - - [23/Nov/2016:14:33:51 -0500] "POST
/rdf4j-server/repositories/sip-repo/statements?context=%3Chttp%3A%2F%2Fpurl.test%2Fsip%2Fgraphs%2FFY16-demo-no-opt%3E
HTTP/1.1" 500 -
127.0.0.1 - - [23/Nov/2016:14:33:51 -0500] "DELETE
/rdf4j-server/repositories/sip-repo/transactions/ab46e96a-9218-4271-834a-bf784a6fb4ed
HTTP/1.1" 500 -
But now the server seems broken. When I go to the RDF4J Workbench and ask for "Types" there's an exception:
23-Nov-2016
14:59:31.353 WARNING [pool-5-thread-3]
org.eclipse.rdf4j.http.client.SparqlSession.getErrorInfo Server reports
problem:
23-Nov-2016 14:59:31.495 WARNING [http-nio-8080-exec-2]
org.eclipse.rdf4j.workbench.commands.SummaryServlet.getResult Exception
occured during async request.
java.util.concurrent.ExecutionException: org.eclipse.rdf4j.repository.RepositoryException:
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:192)
at org.eclipse.rdf4j.workbench.commands.SummaryServlet.getResult(SummaryServlet.java:75)
at org.eclipse.rdf4j.workbench.commands.SummaryServlet.service(SummaryServlet.java:52)
at org.eclipse.rdf4j.workbench.base.TransformationServlet.service(TransformationServlet.java:119)
at org.eclipse.rdf4j.workbench.base.TransformationServlet.service(TransformationServlet.java:99)
at org.eclipse.rdf4j.workbench.base.AbstractServlet.service(AbstractServlet.java:125)
at org.eclipse.rdf4j.workbench.proxy.ProxyRepositoryServlet.service(ProxyRepositoryServlet.java:109)
at org.eclipse.rdf4j.workbench.proxy.WorkbenchServlet.service(WorkbenchServlet.java:213)
at org.eclipse.rdf4j.workbench.proxy.WorkbenchServlet.handleRequest(WorkbenchServlet.java:141)
at org.eclipse.rdf4j.workbench.proxy.WorkbenchServlet.service(WorkbenchServlet.java:109)
at org.eclipse.rdf4j.workbench.proxy.WorkbenchGateway.service(WorkbenchGateway.java:120)
at org.eclipse.rdf4j.workbench.base.AbstractServlet.service(AbstractServlet.java:125)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.eclipse.rdf4j.workbench.proxy.CacheFilter.doFilter(CacheFilter.java:62)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.eclipse.rdf4j.workbench.proxy.CookieCacheControlFilter.doFilter(CookieCacheControlFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:516)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1086)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:659)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.eclipse.rdf4j.repository.RepositoryException:
at org.eclipse.rdf4j.http.client.SparqlSession.execute(SparqlSession.java:1132)
at org.eclipse.rdf4j.http.client.SparqlSession.executeOK(SparqlSession.java:1056)
at org.eclipse.rdf4j.http.client.SesameSession.size(SesameSession.java:228)
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.size(HTTPRepositoryConnection.java:299)
at org.eclipse.rdf4j.workbench.commands.SummaryServlet$1.call(SummaryServlet.java:100)
at org.eclipse.rdf4j.workbench.commands.SummaryServlet$1.call(SummaryServlet.java:94)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
... 1 more
I have to stop and restart the RDF4J Server to clear this up. When I run just a single execution of my app, on either context, it works just fine. We're running RDF4J 2.0.1, so next week I'll upgrade to 2.1.2 to see if that fixes this problem.
Jeen Broekstra
Nov 23, 2016, 5:05:40 PM11/23/16
to rdf4j...@googlegroups.com
Hi Dick,
I am not immediately sure what is going on here. Unfortunately the Server log does not give us enough information. Are you quite sure there isn’t a stack trace in a WARN or ERROR message somewhere in the RDF4J Server log that can tell us more about what’s going on? If so, then that is something that we need to look into in itself: the lack of adequate error feedback.
It’s possible that you are running into a similar/related issue as https://github.com/eclipse/rdf4j/issues/630 . This was fixed in RDF4J 2.1.1, so it’s possible that after an upgrade you’re fine.
It’s also possible that you are running into some sort of update conflict. As a simple test, could you try setting your transaction isolation level to SERIALIZABLE for this bit of code, and see if that helps?
Jeen
--
You received this message because you are subscribed to the Google Groups "RDF4J Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rdf4j-users...@googlegroups.com.
To post to this group, send email to rdf4j...@googlegroups.com.
Visit this group at https://groups.google.com/group/rdf4j-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/rdf4j-users/CAEmHizAqR%2BkfcGb6pBebytDcqsytxgdn9R5HcaYjNoAEszQ5kQ%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.
Dick Knowles
Nov 28, 2016, 1:32:12 PM11/28/16
to RDF4J Users
Hi Jeen,
I was working on the upgrade when I read your reply, so now I've done two things: upgrade to RDF4J 2.1.2, and add SERIALIZABLE as you suggested. The results are the same, with a small change in errors shown. The first execution has the same errors. The second execution is almost the same, but the exception reported from the server is "IllegalMonitorStateException" instead of "null":
I was working on the upgrade when I read your reply, so now I've done two things: upgrade to RDF4J 2.1.2, and add SERIALIZABLE as you suggested. The results are the same, with a small change in errors shown. The first execution has the same errors. The second execution is almost the same, but the exception reported from the server is "IllegalMonitorStateException" instead of "null":
2016-Nov-28 12:43:38.447 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem: Transaction handling error: java.lang.IllegalMonitorStateException
2016-Nov-28 12:43:38.463 WARN [main] org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection:372
Rolling back transaction due to connection close
java.lang.Throwable: null
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.close(HTTPRepositoryConnection.java:372)
at test.sip.ingest.PostProcessor.clearSummaryData(PostProcessor.java:64)
at test.sip.ingest.IngestController.addSummaryData(IngestController.java:235)
at test.sip.ingest.IngestController.ingestPlanData(IngestController.java:272)
at test.sip.ingest.IngestController.ingestPlan(IngestController.java:230)
at test.sip.ingest.IngestController.main(IngestController.java:145)
And to add to the data, as you suggested, I had only copied from the Apache Tomcat log of the server, not the RDF4J log. Here are the stack traces from that log:
(Many "POST query", "Request ... is finished" pairs before this.)
[INFO ] 2016-11-28 12:43:23,625 [repositories/sip-repo] POST query 592045544
[INFO ] 2016-11-28 12:43:23,626 [repositories/sip-repo] Request for query 592045544 is finished
[INFO ] 2016-11-28 12:43:23,628 [repositories/sip-repo] POST query 908129695
[INFO ] 2016-11-28 12:43:23,628 [repositories/sip-repo] Request for query 908129695 is finished
[INFO ] 2016-11-28 12:43:26,724 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-28 12:43:26,754 [repositories/sip-repo] transaction started
[INFO ] 2016-11-28 12:43:26,787 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-28 12:43:26,832 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-28 12:43:26,835 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-28 12:43:26,941 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-28 12:43:26,946 [repositories/sip-repo] POST data to repository
[INFO ] 2016-11-28 12:43:26,947 [repositories/sip-repo] no base URI specified, using dummy 'foo:bar'
[INFO ] 2016-11-28 12:43:28,322 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-28 12:43:28,329 [repositories/sip-repo] transaction started
[INFO ] 2016-11-28 12:43:28,349 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-28 12:43:28,355 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-28 12:43:28,358 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-28 12:43:28,358 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-28 12:43:28,363 [repositories/sip-repo] POST data to repository
[INFO ] 2016-11-28 12:43:28,363 [repositories/sip-repo] no base URI specified, using dummy 'foo:bar'
[INFO ] 2016-11-28 12:43:38,393 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-28 12:43:38,401 [repositories/sip-repo] transaction started
[INFO ] 2016-11-28 12:43:38,405 [repositories/sip-repo] PUT txn operation
[ERROR] 2016-11-28 12:43:38,413 [repositories/sip-repo] Error while handling request
java.lang.IllegalMonitorStateException: null
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457)
at org.eclipse.rdf4j.sail.nativerdf.NativeSailStore$NativeSailSink.close(NativeSailStore.java:341)
at org.eclipse.rdf4j.sail.nativerdf.SailSourceModel.dataset(SailSourceModel.java:397)
at org.eclipse.rdf4j.sail.nativerdf.SailSourceModel.iterator(SailSourceModel.java:299)
at org.eclipse.rdf4j.sail.nativerdf.MemoryOverflowModel.iterator(MemoryOverflowModel.java:128)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:536)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:492)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:275)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.autoFlush(SailSourceBranch.java:359)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:221)
at org.eclipse.rdf4j.sail.base.DelegatingSailDataset.close(DelegatingSailDataset.java:45)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:216)
at org.eclipse.rdf4j.sail.base.SailSourceConnection.endUpdateInternal(SailSourceConnection.java:611)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.endUpdate(AbstractSailConnection.java:573)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flush(AbstractSailConnection.java:374)
at org.eclipse.rdf4j.repository.sail.SailRepositoryConnection.commit(SailRepositoryConnection.java:167)
at org.eclipse.rdf4j.http.server.repository.statements.StatementsController.getAddDataResult(StatementsController.java:452)
at org.eclipse.rdf4j.http.server.repository.statements.StatementsController.handleRequestInternal(StatementsController.java:125)
at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:147)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:50)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.github.ziplet.filter.compression.CompressingFilter.doFilter(CompressingFilter.java:300)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:516)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1086)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:659)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[WARN ] 2016-11-28 12:43:38,416 [repositories/sip-repo] Rolling back transaction due to connection close
java.lang.Throwable: null
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.close(AbstractSailConnection.java:224)
at org.eclipse.rdf4j.repository.sail.SailRepositoryConnection.close(SailRepositoryConnection.java:199)
at org.eclipse.rdf4j.http.server.repository.RepositoryInterceptor.cleanUpResources(RepositoryInterceptor.java:164)
at org.eclipse.rdf4j.http.server.ServerInterceptor.afterCompletion(ServerInterceptor.java:45)
at org.eclipse.rdf4j.http.server.ServerInterceptor$$FastClassBySpringCGLIB$$3d820688.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653)
at org.eclipse.rdf4j.http.server.repository.RepositoryInterceptor$$EnhancerBySpringCGLIB$$d55f98c4.afterCompletion(<generated>)
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:170)
at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1045)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:971)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.github.ziplet.filter.compression.CompressingFilter.doFilter(CompressingFilter.java:300)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:516)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1086)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:659)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[ERROR] 2016-11-28 12:43:38,443 [repositories/sip-repo] Error while handling request (500)
org.eclipse.rdf4j.http.server.ServerHTTPException: Transaction handling error: java.lang.IllegalMonitorStateException
at org.eclipse.rdf4j.http.server.repository.transaction.TransactionController.processModificationOperation(TransactionController.java:279)
at org.eclipse.rdf4j.http.server.repository.transaction.TransactionController.handleRequestInternal(TransactionController.java:182)
at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:147)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:50)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPut(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.github.ziplet.filter.compression.CompressingFilter.doFilter(CompressingFilter.java:300)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:516)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1086)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:659)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalMonitorStateException
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:192)
at org.eclipse.rdf4j.http.server.repository.transaction.Transaction.delete(Transaction.java:374)
at org.eclipse.rdf4j.http.server.repository.transaction.TransactionController.processModificationOperation(TransactionController.java:252)
... 35 common frames omitted
Caused by: java.lang.IllegalMonitorStateException: null
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457)
at org.eclipse.rdf4j.sail.nativerdf.NativeSailStore$NativeSailSink.close(NativeSailStore.java:341)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:279)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.autoFlush(SailSourceBranch.java:359)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:221)
at org.eclipse.rdf4j.sail.base.DelegatingSailDataset.close(DelegatingSailDataset.java:45)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:216)
at org.eclipse.rdf4j.sail.base.SailSourceConnection.endUpdateInternal(SailSourceConnection.java:611)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.endUpdate(AbstractSailConnection.java:573)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flush(AbstractSailConnection.java:374)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flushPendingUpdates(AbstractSailConnection.java:903)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.removeStatements(AbstractSailConnection.java:483)
at org.eclipse.rdf4j.repository.sail.SailRepositoryConnection.removeWithoutCommit(SailRepositoryConnection.java:382)
at org.eclipse.rdf4j.repository.base.AbstractRepositoryConnection.remove(AbstractRepositoryConnection.java:587)
at org.eclipse.rdf4j.http.server.repository.transaction.Transaction$WildcardRDFRemover.handleStatement(Transaction.java:498)
at org.eclipse.rdf4j.rio.binary.BinaryRDFParser.readStatement(BinaryRDFParser.java:196)
at org.eclipse.rdf4j.rio.binary.BinaryRDFParser.parse(BinaryRDFParser.java:99)
at org.eclipse.rdf4j.http.server.repository.transaction.Transaction.lambda$delete$10(Transaction.java:364)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
... 1 common frames omitted
[INFO ] 2016-11-28 12:43:38,476 [repositories/sip-repo] transaction rollback
[INFO ] 2016-11-28 12:43:38,481 [repositories/sip-repo] transaction rollback request finished.
Thanks,
Dick
Jeen Broekstra
Nov 28, 2016, 4:54:44 PM11/28/16
to rdf4j...@googlegroups.com
Ok, that shouldn’t happen. Looks like we overlooked something in the fix for issue #630.
I’ll start running some tests to try and reproduce. Could you open a bug report in our issue tracker with the relevant details and perhaps a link back to this discussion? If at all possible, a minimal example with sample data that reproduces the problem would be highly appreciated!
Cheers,
Jeen
To view this discussion on the web visit https://groups.google.com/d/msgid/rdf4j-users/5d7b0c1b-afba-4a7d-9217-53f598c0c916%40googlegroups.com.
Jeen Broekstra
Nov 28, 2016, 7:00:30 PM11/28/16
to rdf4j...@googlegroups.com
I have been trying to reproduce the problem based on the code snippet you showed me earlier, but have been unsuccessful: a test rig executing 6 concurrent transactions (1 read, 1 add, 4 delete doing basically the same kind of remove you are doing) executes without problems.
It’s possible it’s related to the data set size or structure: I’m testing on a small (~200,000 triples) set of code-generated data. But at this point I’m simply guessing. If you can construct a test case with sample data that demonstrates the problem, that would be very useful.
By the way: you say you tested with RDF4J 2.1.2, but the server stack trace you showed looks very similar to the problem we fixed in issue #630. Are you positive you updated both your client code and your actual RDF4J Server?
Regards,
Jeen
Dick Knowles
Nov 29, 2016, 10:43:32 AM11/29/16
to rdf4j...@googlegroups.com
Ahh! I updated server only. I'll try again with updates for the client, too.
To unsubscribe from this group and stop receiving emails from it, send an email to rdf4j-users+unsubscribe@googlegroups.com.
To post to this group, send email to rdf4j...@googlegroups.com.
Visit this group at https://groups.google.com/group/rdf4j-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/rdf4j-users/5d7b0c1b-afba-4a7d-9217-53f598c0c916%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
--
You received this message because you are subscribed to a topic in the Google Groups "RDF4J Users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rdf4j-users/qtqso7TFnWM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rdf4j-users+unsubscribe@googlegroups.com.
To post to this group, send email to rdf4j...@googlegroups.com.
Visit this group at https://groups.google.com/group/rdf4j-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/rdf4j-users/2F5ECAC0-BA7C-4CF9-8BF8-F669C8FF010F%40gmail.com.
Dick Knowles
Nov 29, 2016, 5:17:04 PM11/29/16
to RDF4J Users, Richard...@alumni.brown.edu
RDF4J v. 2.1.3, Server and Client(s). I'm still working on a minimal test case, but here are results for my original test on the newer version.
Execution 1:
Execution 1:
2016-Nov-29 17:01:39.529 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem:
Exception in thread "main" test.sip.SIPDataIngestException: org.eclipse.rdf4j.repository.RepositoryException:
at test.sip.RDFUploader.upload(RDFUploader.java:63)
at test.sip.RDFUploader.upload(RDFUploader.java:71)
at test.sip.ingest.IngestController.ingestPlanData(IngestController.java:269)
at test.sip.ingest.IngestController.ingestPlan(IngestController.java:230)
at test.sip.ingest.IngestController.main(IngestController.java:145)
Caused by: org.eclipse.rdf4j.repository.RepositoryException:
at org.eclipse.rdf4j.http.client.SparqlSession.execute(SparqlSession.java:1132)
at org.eclipse.rdf4j.http.client.SparqlSession.executeNoContent(SparqlSession.java:1083)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:845)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:792)
at org.eclipse.rdf4j.http.client.SesameSession.upload(SesameSession.java:679)
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.add(HTTPRepositoryConnection.java:506)
at test.sip.RDFUploader.upload(RDFUploader.java:60)
... 4 more
Execution 2:
2016-Nov-29 17:01:39.512 WARN [main] org.eclipse.rdf4j.http.client.SparqlSession:1182
Server reports problem: Transaction handling error: java.lang.IllegalMonitorStateException
2016-Nov-29 17:01:39.574 WARN [main] org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection:372
Rolling back transaction due to connection close
java.lang.Throwable: null
at org.eclipse.rdf4j.repository.http.HTTPRepositoryConnection.close(HTTPRepositoryConnection.java:372)
at test.sip.ingest.PostProcessor.clearSummaryData(PostProcessor.java:64)
at test.sip.ingest.IngestController.addSummaryData(IngestController.java:235)
at test.sip.ingest.IngestController.ingestPlanData(IngestController.java:272)
at test.sip.ingest.IngestController.ingestPlan(IngestController.java:230)
at test.sip.ingest.IngestController.main(IngestController.java:145)
And stack traces from RDF4J Server log:
[INFO ] 2016-11-29 17:01:25,824 [repositories/sip-repo] POST query 592045544
[INFO ] 2016-11-29 17:01:25,825 [repositories/sip-repo] Request for query 592045544 is finished
[INFO ] 2016-11-29 17:01:25,827 [repositories/sip-repo] POST query 908129695
[INFO ] 2016-11-29 17:01:25,828 [repositories/sip-repo] Request for query 908129695 is finished
[INFO ] 2016-11-29 17:01:26,491 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-29 17:01:26,525 [repositories/sip-repo] transaction started
[INFO ] 2016-11-29 17:01:26,562 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-29 17:01:26,599 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-29 17:01:26,602 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-29 17:01:26,740 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-29 17:01:26,744 [repositories/sip-repo] POST data to repository
[INFO ] 2016-11-29 17:01:26,745 [repositories/sip-repo] no base URI specified, using dummy 'foo:bar'
[INFO ] 2016-11-29 17:01:28,839 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-29 17:01:28,848 [repositories/sip-repo] transaction started
[INFO ] 2016-11-29 17:01:28,878 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-29 17:01:28,878 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-29 17:01:28,880 [repositories/sip-repo] PUT txn operation
[INFO ] 2016-11-29 17:01:28,882 [repositories/sip-repo] PUT txn operation request finished.
[INFO ] 2016-11-29 17:01:28,885 [repositories/sip-repo] POST data to repository
[INFO ] 2016-11-29 17:01:28,886 [repositories/sip-repo] no base URI specified, using dummy 'foo:bar'
[INFO ] 2016-11-29 17:01:39,456 [repositories/sip-repo] POST transaction start
[INFO ] 2016-11-29 17:01:39,457 [repositories/sip-repo] transaction started
[INFO ] 2016-11-29 17:01:39,463 [repositories/sip-repo] PUT txn operation
[ERROR] 2016-11-29 17:01:39,491 [repositories/sip-repo] Error while handling request
java.lang.IllegalMonitorStateException: null
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457)
at org.eclipse.rdf4j.sail.nativerdf.NativeSailStore$NativeSailSink.close(NativeSailStore.java:341)
at org.eclipse.rdf4j.sail.nativerdf.SailSourceModel.dataset(SailSourceModel.java:397)
at org.eclipse.rdf4j.sail.nativerdf.SailSourceModel.iterator(SailSourceModel.java:299)
at org.eclipse.rdf4j.sail.nativerdf.MemoryOverflowModel.iterator(MemoryOverflowModel.java:128)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:536)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:492)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.flush(SailSourceBranch.java:275)
at org.eclipse.rdf4j.sail.base.SailSourceBranch.autoFlush(SailSourceBranch.java:359)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:221)
at org.eclipse.rdf4j.sail.base.DelegatingSailDataset.close(DelegatingSailDataset.java:45)
at org.eclipse.rdf4j.sail.base.SailSourceBranch$2.close(SailSourceBranch.java:216)
at org.eclipse.rdf4j.sail.base.SailSourceConnection.endUpdateInternal(SailSourceConnection.java:611)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.endUpdate(AbstractSailConnection.java:580)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flush(AbstractSailConnection.java:377)[WARN ] 2016-11-29 17:01:39,496 [repositories/sip-repo] Rolling back transaction due to connection close
[ERROR] 2016-11-29 17:01:39,503 [repositories/sip-repo] Error while handling request (500)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.endUpdate(AbstractSailConnection.java:580)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flush(AbstractSailConnection.java:377)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.flushPendingUpdates(AbstractSailConnection.java:917)
at org.eclipse.rdf4j.sail.helpers.AbstractSailConnection.removeStatements(AbstractSailConnection.java:490)
at org.eclipse.rdf4j.repository.sail.SailRepositoryConnection.removeWithoutCommit(SailRepositoryConnection.java:382)
at org.eclipse.rdf4j.repository.base.AbstractRepositoryConnection.remove(AbstractRepositoryConnection.java:587)
at org.eclipse.rdf4j.http.server.repository.transaction.Transaction$WildcardRDFRemover.handleStatement(Transaction.java:498)
at org.eclipse.rdf4j.rio.binary.BinaryRDFParser.readStatement(BinaryRDFParser.java:196)
at org.eclipse.rdf4j.rio.binary.BinaryRDFParser.parse(BinaryRDFParser.java:99)
at org.eclipse.rdf4j.http.server.repository.transaction.Transaction.lambda$delete$10(Transaction.java:364)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
... 1 common frames omitted
[INFO ] 2016-11-29 17:01:39,585 [repositories/sip-repo] transaction rollback
[INFO ] 2016-11-29 17:01:39,586 [repositories/sip-repo] transaction rollback request finished.
Dick Knowles
Nov 30, 2016, 10:21:46 AM11/30/16
to RDF4J Users
Reply all
Reply to author
Forward
0 new messages