Closed xquery closed 8 years ago
Please assign a milestone
thx Ganesh, I appreciate the reminder.
tests already have coverage, though if you would like to add you may look at MarkLogicRepositoryWriteCacheTest
I think this may be an issue with cache but I am not sure (or possibly transaction). I see that the test 'testGetStatementsInMultipleContexts' is failing. The following statements within the test fail with the wire trace provided below and the triples are not inserted.
try{ testAdminCon.begin(); testAdminCon.add(john, fname, johnfname, dirgraph); testAdminCon.add(john, lname, johnlname, dirgraph); testAdminCon.add(john, homeTel, johnhomeTel, dirgraph); testAdminCon.commit(); } catch(Exception e){ e.printStackTrace(); }
14:17:39.612 [main] DEBUG o.a.h.i.c.t.ThreadSafeClientConnManager - Released connection is reusable. 14:17:39.612 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Releasing connection [{}->http://localhost:8023][null] 14:17:39.613 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Pooling connection [{}->http://localhost:8023][null]; keep alive for 5000 MILLISECONDS 14:17:39.613 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Notifying no-one, there are no waiting threads 14:17:39.613 [main] DEBUG c.m.c.i.JerseyServices - Opening transaction 14:17:39.616 [main] DEBUG o.a.h.i.c.t.ThreadSafeClientConnManager - Get connection: {}->http://localhost:8023, timeout = 0 14:17:39.616 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - [{}->http://localhost:8023] total kept alive: 1, total issued: 1, total allocated: 2 out of 200 14:17:39.617 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Getting free connection [{}->http://localhost:8023][null] 14:17:39.617 [main] DEBUG o.a.h.i.c.DefaultHttpClient - Stale connection check 14:17:39.622 [main] DEBUG o.a.h.c.p.RequestAddCookies - CookieSpec selected: ignoreCookies 14:17:39.623 [main] DEBUG o.a.h.c.p.RequestAuthCache - Auth cache not set in the context 14:17:39.623 [main] DEBUG o.a.h.c.p.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED 14:17:39.623 [main] DEBUG o.a.h.i.c.DefaultHttpClient - Attempt 1 to execute request 14:17:39.623 [main] DEBUG o.a.h.i.c.DefaultClientConnection - Sending request: POST /v1/transactions HTTP/1.1 14:17:39.624 [main] DEBUG o.a.h.wire - >> "POST /v1/transactions HTTP/1.1[\r][\n]" 14:17:39.624 [main] DEBUG o.a.h.wire - >> "Authorization: Digest username="admin",realm="public",nonce="610ba2b5a22d34005feea34816145c7c",opaque="acbad648aeaee9b8",qop=auth,uri="/v1/transactions",cnonce="8eb6c02c",nc=00000009,response="a4ba44470f346a1359435d018e97161d"[\r][\n]" 14:17:39.625 [main] DEBUG o.a.h.wire - >> "Content-Length: 0[\r][\n]" 14:17:39.625 [main] DEBUG o.a.h.wire - >> "Host: localhost:8023[\r][\n]" 14:17:39.625 [main] DEBUG o.a.h.wire - >> "Connection: Keep-Alive[\r][\n]" 14:17:39.626 [main] DEBUG o.a.h.wire - >> "[\r][\n]" 14:17:39.626 [main] DEBUG o.a.h.headers - >> POST /v1/transactions HTTP/1.1 14:17:39.626 [main] DEBUG o.a.h.headers - >> Authorization: Digest username="admin",realm="public",nonce="610ba2b5a22d34005feea34816145c7c",opaque="acbad648aeaee9b8",qop=auth,uri="/v1/transactions",cnonce="8eb6c02c",nc=00000009,response="a4ba44470f346a1359435d018e97161d" 14:17:39.626 [main] DEBUG o.a.h.headers - >> Content-Length: 0 14:17:39.627 [main] DEBUG o.a.h.headers - >> Host: localhost:8023 14:17:39.627 [main] DEBUG o.a.h.headers - >> Connection: Keep-Alive 14:17:39.659 [main] DEBUG o.a.h.wire - << "HTTP/1.1 303 See Created Transaction[\r][\n]" 14:17:39.660 [main] DEBUG o.a.h.wire - << "Set-Cookie: HostId=14471192489018303339[\r][\n]" 14:17:39.660 [main] DEBUG o.a.h.wire - << "Location: /v1/transactions/3893465236721538293[\r][\n]" 14:17:39.660 [main] DEBUG o.a.h.wire - << "Server: MarkLogic[\r][\n]" 14:17:39.661 [main] DEBUG o.a.h.wire - << "Content-Length: 0[\r][\n]" 14:17:39.661 [main] DEBUG o.a.h.wire - << "Connection: Keep-Alive[\r][\n]" 14:17:39.661 [main] DEBUG o.a.h.wire - << "Keep-Alive: timeout=5[\r][\n]" 14:17:39.661 [main] DEBUG o.a.h.wire - << "[\r][\n]" 14:17:39.661 [main] DEBUG o.a.h.i.c.DefaultClientConnection - Receiving response: HTTP/1.1 303 See Created Transaction 14:17:39.661 [main] DEBUG o.a.h.headers - << HTTP/1.1 303 See Created Transaction 14:17:39.662 [main] DEBUG o.a.h.headers - << Set-Cookie: HostId=14471192489018303339 14:17:39.662 [main] DEBUG o.a.h.headers - << Location: /v1/transactions/3893465236721538293 14:17:39.662 [main] DEBUG o.a.h.headers - << Server: MarkLogic 14:17:39.662 [main] DEBUG o.a.h.headers - << Content-Length: 0 14:17:39.662 [main] DEBUG o.a.h.headers - << Connection: Keep-Alive 14:17:39.662 [main] DEBUG o.a.h.headers - << Keep-Alive: timeout=5 14:17:39.662 [main] DEBUG o.a.h.i.c.DefaultHttpClient - Connection can be kept alive for 5000 MILLISECONDS 14:17:39.663 [main] DEBUG o.a.h.i.c.t.ThreadSafeClientConnManager - Released connection is reusable. 14:17:39.663 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Releasing connection [{}->http://localhost:8023][null] 14:17:39.663 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Pooling connection [{}->http://localhost:8023][null]; keep alive for 5000 MILLISECONDS 14:17:39.663 [main] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Notifying no-one, there are no waiting threads 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "HTTP/1.1 400 Bad Request[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "Content-type: application/json; charset=UTF-8[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "Server: MarkLogic[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "Content-Length: 164[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "Connection: Keep-Alive[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "Keep-Alive: timeout=5[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "[\r][\n]" 14:17:40.654 [Timer-1] DEBUG o.a.h.i.c.DefaultClientConnection - Receiving response: HTTP/1.1 400 Bad Request 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << HTTP/1.1 400 Bad Request 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << Content-type: application/json; charset=UTF-8 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << Server: MarkLogic 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << Content-Length: 164 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << Connection: Keep-Alive 14:17:40.654 [Timer-1] DEBUG o.a.h.headers - << Keep-Alive: timeout=5 14:17:40.654 [Timer-1] DEBUG o.a.h.i.c.DefaultHttpClient - Connection can be kept alive for 5000 MILLISECONDS 14:17:40.654 [Timer-1] DEBUG o.a.h.wire - << "{"errorResponse":{"statusCode":400, "status":"Bad Request", "messageCode":"XDMP-NOTXN", "message":"XDMP-NOTXN: No transaction with identifier 2718268775740568204"}}" 14:17:41.513 [Timer-1] DEBUG o.a.h.i.c.t.ThreadSafeClientConnManager - Released connection is reusable. 14:17:41.513 [Timer-1] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Releasing connection [{}->http://localhost:8023][null] 14:17:41.514 [Timer-1] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Pooling connection [{}->http://localhost:8023][null]; keep alive for 5000 MILLISECONDS 14:17:41.514 [Timer-1] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Notifying no-one, there are no waiting threads org.openrdf.rio.RDFParseException: Request to MarkLogic server failed, check input is valid.14:17:41.516 [main] DEBUG c.m.s.s.c.WriteCacheTimerTask - flushing write cache 14:17:41.517 [main] DEBUG c.m.c.i.JerseyServices - Posting graphs
at com.marklogic.semantics.sesame.client.MarkLogicClientImpl.performAdd(MarkLogicClientImpl.java:306)
at com.marklogic.semantics.sesame.client.MarkLogicClient.sendAdd(MarkLogicClient.java:279)
at com.marklogic.semantics.sesame.client.WriteCacheTimerTask.flush(WriteCacheTimerTask.java:145)
at com.marklogic.semantics.sesame.client.WriteCacheTimerTask.run(WriteCacheTimerTask.java:118)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)
I see the same issue in another test which fails at assertThat(testAdminCon.size(), is(equalTo(2L))); . It passed the test assertThat(testAdminCon.size(), is(equalTo(1L))); which was a few lines above the line where it failed.
public void testSizeCommit()
throws Exception
{
testAdminCon.setIsolationLevel(IsolationLevels.SNAPSHOT);
assertThat(testAdminCon.size(), is(equalTo(0L)));
assertThat(testWriterCon.size(), is(equalTo(0L)));
try{
testAdminCon.begin();
testAdminCon.add(john, fname, johnfname,dirgraph);
assertThat(testAdminCon.size(), is(equalTo(1L)));
assertThat(testWriterCon.size(), is(equalTo(0L)));
testAdminCon.add(john, fname, feifname);
assertThat(testAdminCon.size(), is(equalTo(2L)));
assertThat(testWriterCon.size(), is(equalTo(0L)));
testAdminCon.commit();
}
catch (Exception e){
}
finally{
if (testAdminCon.isActive())
testAdminCon.rollback();
}
assertThat(testAdminCon.size(), is(equalTo(2L)));
assertThat(testWriterCon.size(), is(equalTo(2L)));
}
It's the first assertThat(testAdminCon.size(), is(equalTo(2L)));
or second that fails? If its the first I'm curious what happens when you comment out the assertions within the try{}. If the outer one then succeeds, I'd look at whether sync() is forced before size().
It is the first " assertThat(testAdminCon.size(), is(equalTo(2L)));" within the try block(line 13 in the code snippet ). I will try commenting them out and will let you know,
I have the following test;
@Test
public void testSizeCommitWithWriteCache()
throws Exception
{
conn.setIsolationLevel(IsolationLevels.SNAPSHOT);
readerRep.initialize();
MarkLogicRepositoryConnection rconn = readerRep.getConnection();
assertEquals(conn.size(),0L);
assertEquals(rconn.size(),0L);
Resource context1 = conn.getValueFactory().createURI("http://marklogic.com/test/context1");
ValueFactory f= conn.getValueFactory();
URI alice = f.createURI("http://example.org/people/alice");
URI name = f.createURI("http://example.org/ontology/name");
Literal alicesName = f.createLiteral("Alice1");
Statement st1 = f.createStatement(alice, name, alicesName, context1);
try{
conn.begin();
conn.add(st1);
assertEquals(conn.size(),1L);
assertEquals(rconn.size(),0L);
conn.commit();
}
catch (Exception e){
}
finally{
if (conn.isActive())
conn.rollback();
}
assertEquals(conn.size(),1L);
assertEquals(rconn.size(),1L);
conn.clear();
}
which is nearly identical and passes.
Can you try running the test 'testGetStatementsInMultipleContexts' with the latest server build ? I think that will be a good example for this issue
sure, will give it a try now.
I can verify there is a bug and see what is happening.
the first begin() & commit() block works fine.
The second begin() works and returns a new txid but the following commit() seems to use to use the first block txid ... strange, this could be a bug (w/ cookies?) in java api ... still researching.
this is unrelated to write cache operation.
09:10:13.451 [Test worker] DEBUG o.a.h.i.c.DefaultClientConnection - Sending request: POST /v1/transactions HTTP/1.1
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "POST /v1/transactions HTTP/1.1[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "Authorization: Digest username="admin",realm="public",nonce="adb1c88530815e201274b31cd439ac81",opaque="6966fa7ab7ff585a",qop=auth,uri="/v1/transactions",cnonce="fb5cdb02",nc=00000009,response="8a1e4667f8eb88b9db78d4b1b4240417"[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "Content-Length: 0[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "Host: localhost:8023[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "Connection: Keep-Alive[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.wire - >> "[\r][\n]"
09:10:13.451 [Test worker] DEBUG o.a.h.headers - >> POST /v1/transactions HTTP/1.1
09:10:13.451 [Test worker] DEBUG o.a.h.headers - >> Authorization: Digest username="admin",realm="public",nonce="adb1c88530815e201274b31cd439ac81",opaque="6966fa7ab7ff585a",qop=auth,uri="/v1/transactions",cnonce="fb5cdb02",nc=00000009,response="8a1e4667f8eb88b9db78d4b1b4240417"
09:10:13.451 [Test worker] DEBUG o.a.h.headers - >> Content-Length: 0
09:10:13.452 [Test worker] DEBUG o.a.h.headers - >> Host: localhost:8023
09:10:13.452 [Test worker] DEBUG o.a.h.headers - >> Connection: Keep-Alive
09:10:13.456 [Test worker] DEBUG o.a.h.wire - << "HTTP/1.1 303 See Created Transaction[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Set-Cookie: HostId=17203704648563896335[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Location: /v1/transactions/3881295397699324880[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Server: MarkLogic[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Content-Length: 0[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Connection: Keep-Alive[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "Keep-Alive: timeout=5[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.wire - << "[\r][\n]"
09:10:13.457 [Test worker] DEBUG o.a.h.i.c.DefaultClientConnection - Receiving response: HTTP/1.1 303 See Created Transaction
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << HTTP/1.1 303 See Created Transaction
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Set-Cookie: HostId=17203704648563896335
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Location: /v1/transactions/3881295397699324880
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Server: MarkLogic
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Content-Length: 0
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Connection: Keep-Alive
09:10:13.457 [Test worker] DEBUG o.a.h.headers - << Keep-Alive: timeout=5
09:10:13.458 [Test worker] DEBUG o.a.h.i.c.DefaultHttpClient - Connection can be kept alive for 5000 MILLISECONDS
09:10:13.458 [Test worker] DEBUG o.a.h.i.c.t.ThreadSafeClientConnManager - Released connection is reusable.
09:10:13.458 [Test worker] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Releasing connection [{}->http://localhost:8023][null]
09:10:13.458 [Test worker] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Pooling connection [{}->http://localhost:8023][null]; keep alive for 5000 MILLISECONDS
09:10:13.458 [Test worker] DEBUG o.a.h.i.c.t.ConnPoolByRoute - Notifying no-one, there are no waiting threads
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "HTTP/1.1 400 Bad Request[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "Content-type: application/json; charset=UTF-8[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "Server: MarkLogic[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "Content-Length: 164[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "Connection: Keep-Alive[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "Keep-Alive: timeout=5[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.wire - << "[\r][\n]"
09:10:13.976 [Timer-1] DEBUG o.a.h.i.c.DefaultClientConnection - Receiving response: HTTP/1.1 400 Bad Request
09:10:13.976 [Timer-1] DEBUG o.a.h.headers - << HTTP/1.1 400 Bad Request
09:10:13.976 [Timer-1] DEBUG o.a.h.headers - << Content-type: application/json; charset=UTF-8
09:10:13.976 [Timer-1] DEBUG o.a.h.headers - << Server: MarkLogic
09:10:13.977 [Timer-1] DEBUG o.a.h.headers - << Content-Length: 164
09:10:13.977 [Timer-1] DEBUG o.a.h.headers - << Connection: Keep-Alive
09:10:13.977 [Timer-1] DEBUG o.a.h.headers - << Keep-Alive: timeout=5
09:10:13.977 [Timer-1] DEBUG o.a.h.i.c.DefaultHttpClient - Connection can be kept alive for 5000 MILLISECONDS
09:10:13.977 [Timer-1] DEBUG o.a.h.wire - << "{"errorResponse":{"statusCode":400, "status":"Bad Request", "messageCode":"XDMP-NOTXN", "message":"XDMP-NOTXN: No transaction with identifier 9501142553799708113"}}"
actually thats happening intermittently (and follow up with @grechaw and Sam but I can also verify bug with iter getStatements as size() reports correctly.
and ... the problem is with write cache and threads and commiting at the right time ... fix forthcoming.
I see that the test 'testInsertDeleteInsertWhere' now fails intermittently. Please try running the entire suite and you can see this test failing more consistently.
I did run tests and I did not get this failure and I am still unable too after 3 runs.
Can you provide me trace of error ?
seems like these are passing now, we will continue watching over the next few days.
The test 'testInsertDeleteInsertWhere failed now with cache enabled. The stack trace is (Please use the latest test code )
java.lang.AssertionError: Expected: <(http://marklogicsparql.com/id#1111, http://marklogicsparql.com/addressbook#email, "jsnelson@marklogic.com"^^http://www.w3.org/2001/XMLSchema#string)> but: was <(http://marklogicsparql.com/id#1111, http://marklogicsparql.com/addressbook#email, "john.snelson@marklogic.com"^^http://www.w3.org/2001/XMLSchema#string)> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) at org.junit.Assert.assertThat(Assert.java:956) at org.junit.Assert.assertThat(Assert.java:923) at com.marklogic.sesame.functionaltests.MarkLogicRepositoryConnectionTest$3.handleStatement(MarkLogicRepositoryConnectionTest.java:1705) at org.openrdf.query.QueryResults.report(QueryResults.java:195) at com.marklogic.semantics.sesame.query.MarkLogicGraphQuery.evaluate(MarkLogicGraphQuery.java:85) at com.marklogic.semantics.sesame.MarkLogicRepositoryConnection.exportStatements(MarkLogicRepositoryConnection.java:779) at com.marklogic.sesame.functionaltests.MarkLogicRepositoryConnectionTest.testInsertDeleteInsertWhere(MarkLogicRepositoryConnectionTest.java:1699) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50) at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:675) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)
I am unable to replicate, running the individual test or the entire functional test suite.
We will discuss next steps to characterise the issue on your platform.
I've added a logback.xml to emit more logs ... pls set
Waiting to see if the one intermittentlyfailing test runs fine for some days in regression
Shipping the bug as the tests are running fine in regression
implement write cache to batch up update operations. This is an important optimisation and will push to get this in 1.0-1