You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@jena.apache.org by Bill Roberts <bi...@swirrl.com> on 2012/03/29 21:29:21 UTC
fuseki transaction trouble
Hi All (and especially Andy)
Have been doing some more data loading and made some progress, but hit another problem. I hope this time I have all the relevant info to help with diagnosis.
Now running latest fuseki snapshot.
Jena: VERSION: 2.7.0-incubating
Jena: BUILD_DATE: 2011-12-14T14:54:09+0000
ARQ: VERSION: 2.9.0-incubating
ARQ: BUILD_DATE: 2011-12-14T15:04:27+0000
TDB: VERSION: 0.9.0-incubating
TDB: BUILD_DATE: 2012-02-29T19:39:52+0000
Fuseki: VERSION: 0.2.2-incubating-SNAPSHOT
Fuseki: BUILD_DATE: 2012-03-27T05:17:50+0000
Was trying to PUT a 60MB ntriples file, when it looks from the logs that there was some kind of transaction related issue.
It appeared to work - I got a 201 Created, but it came back suspiciously quickly.
I then tried to load another file, much smaller - that didn't work - I never got a response from that PUT.
Relevant section of the log is here: (note that all the ASK queries are just a heartbeat thing that we have going for monitoring - but looks like one of those (request 350) might somehow have interfered with the big PUT (request 349) ??
(More commentary and another section of log file further down).
19:55:51 INFO Fuseki :: [349] PUT http://127.0.0.1:3030/dclg/data?graph=http://opendatacommunities.org/graph/administrative-geography
19:55:57 INFO Fuseki :: [350] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:55:57 INFO Fuseki :: [350] Query = ASK WHERE {?s ?p ?o}
19:55:57 INFO Fuseki :: [350] OK/ask
19:55:57 INFO Fuseki :: [350] 200 OK
19:56:03 WARN TDB :: Transaction not active: 350
19:56:03 INFO Fuseki :: [349] 201 Created
19:56:27 INFO Fuseki :: [351] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:56:27 INFO Fuseki :: [351] Query = ASK WHERE {?s ?p ?o}
19:56:27 INFO Fuseki :: [351] OK/ask
19:56:27 INFO Fuseki :: [351] 200 OK
19:56:57 INFO Fuseki :: [352] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:56:57 INFO Fuseki :: [352] Query = ASK WHERE {?s ?p ?o}
19:56:57 INFO Fuseki :: [352] OK/ask
19:56:57 INFO Fuseki :: [352] 200 OK
19:57:27 INFO Fuseki :: [353] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:57:27 INFO Fuseki :: [353] Query = ASK WHERE {?s ?p ?o}
19:57:27 INFO Fuseki :: [353] OK/ask
19:57:27 INFO Fuseki :: [353] 200 OK
19:57:45 INFO Fuseki :: [354] PUT http://127.0.0.1:3030/dclg/data?graph=http://opendatacommunities.org/graph/administrative-geography/metadata
19:57:57 INFO Fuseki :: [355] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:57:57 INFO Fuseki :: [355] Query = ASK WHERE {?s ?p ?o}
19:57:57 INFO Fuseki :: [355] OK/ask
19:57:57 INFO Fuseki :: [355] 200 OK
19:58:27 INFO Fuseki :: [356] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:58:27 INFO Fuseki :: [356] Query = ASK WHERE {?s ?p ?o}
19:58:27 INFO Fuseki :: [356] OK/ask
19:58:27 INFO Fuseki :: [356] 200 OK
19:58:58 INFO Fuseki :: [357] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:58:58 INFO Fuseki :: [357] Query = ASK WHERE {?s ?p ?o}
19:58:58 INFO Fuseki :: [357] OK/ask
19:58:58 INFO Fuseki :: [357] 200 OK
19:59:28 INFO Fuseki :: [358] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:59:28 INFO Fuseki :: [358] Query = ASK WHERE {?s ?p ?o}
19:59:28 INFO Fuseki :: [358] OK/ask
19:59:28 INFO Fuseki :: [358] 200 OK
19:59:58 INFO Fuseki :: [359] GET http://localhost:3030/dclg/sparql?query=ASK+WHERE+%7B%3Fs+%3Fp+%3Fo%7D
19:59:58 INFO Fuseki :: [359] Query = ASK WHERE {?s ?p ?o}
19:59:58 INFO Fuseki :: [359] OK/ask
19:59:58 INFO Fuseki :: [359] 200 OK
20:00:05 INFO Fuseki :: [360] GET http://127.0.0.1:3030/dclg/data?graph=http://opendatacommunities.org/graph/administrative-geography
20:00:05 INFO Fuseki :: [360] 404 No such graph: <http://opendatacommunities.org/graph/administrative-geography>
20:00:05 INFO Fuseki :: [361] PUT http://127.0.0.1:3030/dclg/data?graph=http://opendatacommunities.org/graph/administrative-geography/metadata
Request 360 seems to indicate that 349 didn't work - the graph that 349 was meant to load apparently doesn't exist.
Having realised that my second PUT (354) hadn't worked, I had a go at tidying up by deleting stuff. This led to the following chunk of log:
20:06:04 INFO Fuseki :: [62] DELETE http://127.0.0.1:3030/dclg/data?graph=http://opendatacommunities.org/graph/administrative-geography/metadata
20:06:04 WARN NodeTableTrans :: Txn[62]/W journalStartOffset not zero: 4522457/0x4501D9
************* UNEXPECTED [1]
Different ids for http://opendatacommunities.org/graph/administrative-geography: allocated: expected [00000000133D3C0C], got [0000000012F83A33]
>>>>>>>>>>
label = nodes
txn = Transaction: 62 : Mode=WRITE : State=PREPARING : /home/ubuntu/data/odc/
offset = 322780172
journalStartOffset = 4522457
journal = nodes.dat-jrnl
20:06:04 WARN SPARQL_REST$HttpActionREST :: Transaction still active in endWriter - no commit or abort seen (forced abort)
20:06:04 WARN SPARQL_REST$HttpActionREST :: Exception in forced abort (trying to continue)
com.hp.hpl.jena.tdb.transaction.TDBTransactionException: Transaction has already committed or aborted
at com.hp.hpl.jena.tdb.transaction.Transaction.abort(Transaction.java:146)
at com.hp.hpl.jena.tdb.transaction.DatasetGraphTxn.abort(DatasetGraphTxn.java:45)
at com.hp.hpl.jena.tdb.transaction.DatasetGraphTransaction._abort(DatasetGraphTransaction.java:112)
at com.hp.hpl.jena.tdb.migrate.DatasetGraphTrackActive.abort(DatasetGraphTrackActive.java:68)
at org.apache.jena.fuseki.servlets.HttpAction.endWrite(HttpAction.java:120)
at org.apache.jena.fuseki.servlets.SPARQL_REST_RW.doDelete(SPARQL_REST_RW.java:57)
at org.apache.jena.fuseki.servlets.SPARQL_REST.dispatch(SPARQL_REST.java:218)
at org.apache.jena.fuseki.servlets.SPARQL_REST.perform(SPARQL_REST.java:190)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:92)
at org.apache.jena.fuseki.servlets.SPARQL_REST.service(SPARQL_REST.java:176)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1359)
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:77)
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:144)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1330)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:478)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:225)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
at org.eclipse.jetty.server.Server.handle(Server.java:349)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:582)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
at java.lang.Thread.run(Thread.java:662)
20:06:04 WARN Fuseki :: [62] RC = 500 : Different ids for http://opendatacommunities.org/graph/administrative-geography: allocated: expected [00000000133D3C0C], got [0000000012F83A33]
com.hp.hpl.jena.tdb.TDBException: Different ids for http://opendatacommunities.org/graph/administrative-geography: allocated: expected [00000000133D3C0C], got [0000000012F83A33]
at com.hp.hpl.jena.tdb.transaction.NodeTableTrans.inconsistent(NodeTableTrans.java:212)
at com.hp.hpl.jena.tdb.transaction.NodeTableTrans.append(NodeTableTrans.java:200)
at com.hp.hpl.jena.tdb.transaction.NodeTableTrans.writeNodeJournal(NodeTableTrans.java:306)
at com.hp.hpl.jena.tdb.transaction.NodeTableTrans.commitPrepare(NodeTableTrans.java:266)
at com.hp.hpl.jena.tdb.transaction.Transaction.prepare(Transaction.java:131)
at com.hp.hpl.jena.tdb.transaction.Transaction.commit(Transaction.java:112)
at com.hp.hpl.jena.tdb.transaction.DatasetGraphTxn.commit(DatasetGraphTxn.java:40)
at com.hp.hpl.jena.tdb.transaction.DatasetGraphTransaction._commit(DatasetGraphTransaction.java:106)
at com.hp.hpl.jena.tdb.migrate.DatasetGraphTrackActive.commit(DatasetGraphTrackActive.java:60)
at org.apache.jena.fuseki.servlets.HttpAction.commit(HttpAction.java:105)
at org.apache.jena.fuseki.servlets.SPARQL_REST_RW.doDelete(SPARQL_REST_RW.java:51)
at org.apache.jena.fuseki.servlets.SPARQL_REST.dispatch(SPARQL_REST.java:218)
at org.apache.jena.fuseki.servlets.SPARQL_REST.perform(SPARQL_REST.java:190)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_ServletBase.java:92)
at org.apache.jena.fuseki.servlets.SPARQL_REST.service(SPARQL_REST.java:176)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1359)
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:77)
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:144)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1330)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:478)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:225)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
at org.eclipse.jetty.server.Server.handle(Server.java:349)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:582)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
at org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
at java.lang.Thread.run(Thread.java:662)
20:06:04 INFO Fuseki :: [62] 500 Different ids for http://opendatacommunities.org/graph/administrative-geography: allocated: expected [00000000133D3C0C], got [0000000012F83A33]
I have a copy of the broken database. The gzipped nodes.dat file is 18MB - I can send if that's useful, but obviously quite chunky.
Here is a listing of what's in the TDB directory
total 9616800
-rw-r--r-- 1 ubuntu ubuntu 1753219072 2012-03-29 19:55 GOSP.dat
-rw-r--r-- 1 ubuntu ubuntu 125829120 2012-03-29 19:55 GOSP.idn
-rw-r--r-- 1 ubuntu ubuntu 1820327936 2012-03-29 19:55 GPOS.dat
-rw-r--r-- 1 ubuntu ubuntu 134217728 2012-03-29 19:55 GPOS.idn
-rw-r--r-- 1 ubuntu ubuntu 1962934272 2012-03-29 19:55 GSPO.dat
-rw-r--r-- 1 ubuntu ubuntu 125829120 2012-03-29 19:55 GSPO.idn
-rw-r--r-- 1 ubuntu ubuntu 0 2012-03-29 19:03 journal.jrnl
-rw-r--r-- 1 ubuntu ubuntu 444596224 2012-03-29 20:06 node2id.dat
-rw-r--r-- 1 ubuntu ubuntu 16777216 2012-03-29 19:02 node2id.idn
-rw-r--r-- 1 ubuntu ubuntu 318257715 2012-03-29 19:03 nodes.dat
-rw-r--r-- 1 root root 4522457 2012-03-29 19:56 nodes.dat-jrnl
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 OSP.dat
-rw-r--r-- 1 ubuntu ubuntu 1753219072 2012-03-29 19:55 OSPG.dat
-rw-r--r-- 1 ubuntu ubuntu 109051904 2012-03-29 19:55 OSPG.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 OSP.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:10 POS.dat
-rw-r--r-- 1 ubuntu ubuntu 1769996288 2012-03-29 19:55 POSG.dat
-rw-r--r-- 1 ubuntu ubuntu 117440512 2012-03-29 19:55 POSG.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 POS.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 prefix2id.dat
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:10 prefix2id.idn
-rw-r--r-- 1 ubuntu ubuntu 0 2012-03-29 14:12 prefixes.dat
-rw-r--r-- 1 root root 0 2012-03-29 19:03 prefixes.dat-jrnl
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:10 prefixIdx.dat
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 prefixIdx.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 SPO.dat
-rw-r--r-- 1 ubuntu ubuntu 1912602624 2012-03-29 19:55 SPOG.dat
-rw-r--r-- 1 ubuntu ubuntu 117440512 2012-03-29 19:55 SPOG.idn
-rw-r--r-- 1 ubuntu ubuntu 8388608 2012-03-29 14:12 SPO.idn
Thanks in advance for any advice, and let me know if I can provide any more useful info.
Cheers
Bill