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
