-
Type:
Bug
-
Status: Open
-
Priority:
Minor
-
Resolution: Unresolved
-
Affects Version/s: 9.10-SNAPSHOT
-
Fix Version/s: QualifiedToSchedule
The failing test was added for NXP-23589: "Serve Drive configuration from the config folder instead of accessing it directly through nuxeo.war".
See https://qa.nuxeo.org/jenkins/job/Deploy/job/IT-nuxeo-master-build/704/consoleFull
00:37:56 ------------------------------------------------------- 00:37:56 T E S T S 00:37:56 ------------------------------------------------------- 00:37:59 StorageConfiguration: Deploying JDBC using DatabaseH2 00:37:59 StorageConfiguration: Deploying a VCS repository 00:38:02 00:38:02,358 main ERROR [OSGiRuntimeService] Nuxeo Platform Started 00:38:02 ====================================================================== 00:38:02 = Component Loading Status: Pending: 0 / Missing: 1 / Unstarted: 0 / Total: 183 00:38:02 * test:tags-contrib references missing [target=org.nuxeo.ecm.platform.ws.session.WSRemotingSessionManagerImpl;point=loaders] 00:38:02 ====================================================================== 00:38:02 Running org.nuxeo.ecm.restapi.server.jaxrs.drive.NuxeoDriveObjectTest 00:39:03 00:39:03,169 main WARN [DetectThreadDeadlocksFeature] Thread dump available at target/tdump-1119205681710116550.log 00:39:04 00:39:04,517 main WARN [DetectThreadDeadlocksFeature] Thread dump available at target/tdump-6632876882739155585.log 00:39:04 Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 62.128 sec <<< FAILURE! - in org.nuxeo.ecm.restapi.server.jaxrs.drive.NuxeoDriveObjectTest 00:39:04 testGetConfiguration(org.nuxeo.ecm.restapi.server.jaxrs.drive.NuxeoDriveObjectTest) Time elapsed: 60.678 sec <<< ERROR! 00:39:04 com.sun.jersey.api.client.ClientHandlerException: java.net.SocketTimeoutException: Read timed out 00:39:04 at com.sun.jersey.client.apache4.ApacheHttpClient4Handler.handle(ApacheHttpClient4Handler.java:187) 00:39:04 at com.sun.jersey.api.client.filter.HTTPBasicAuthFilter.handle(HTTPBasicAuthFilter.java:105) 00:39:04 at com.sun.jersey.api.client.Client.handle(Client.java:652) 00:39:04 at com.sun.jersey.api.client.WebResource.handle(WebResource.java:682) 00:39:04 at com.sun.jersey.api.client.WebResource.access$200(WebResource.java:74) 00:39:04 at com.sun.jersey.api.client.WebResource$Builder.get(WebResource.java:509) 00:39:04 at org.nuxeo.ecm.restapi.test.BaseTest.getResponse(BaseTest.java:167) 00:39:04 at org.nuxeo.ecm.restapi.test.BaseTest.getResponse(BaseTest.java:112) 00:39:04 at org.nuxeo.ecm.restapi.server.jaxrs.drive.NuxeoDriveObjectTest.testGetConfiguration(NuxeoDriveObjectTest.java:58) 00:39:04 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 00:39:04 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 00:39:04 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 00:39:04 at java.lang.reflect.Method.invoke(Method.java:498) 00:39:04 at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) 00:39:04 at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) 00:39:04 at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) 00:39:04 at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeMethodRunStatement.evaluate(FeaturesRunner.java:285) 00:39:04 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeSetupStatement.evaluate(FeaturesRunner.java:301) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterMethodRunStatement.evaluate(FeaturesRunner.java:332) 00:39:04 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterTeardownStatement.evaluate(FeaturesRunner.java:351) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:429) 00:39:04 at org.nuxeo.runtime.test.runner.RuntimeDeployment$DeploymentStatement.evaluate(RuntimeDeployment.java:299) 00:39:04 at org.nuxeo.runtime.test.runner.RuntimeFeature$2$1.evaluate(RuntimeFeature.java:137) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:429) 00:39:04 at org.junit.rules.RunRules.evaluate(RunRules.java:20) 00:39:04 at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) 00:39:04 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) 00:39:04 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) 00:39:04 at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) 00:39:04 at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) 00:39:04 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) 00:39:04 at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) 00:39:04 at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterClassStatement.evaluate(FeaturesRunner.java:235) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:429) 00:39:04 at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeClassStatement.evaluate(FeaturesRunner.java:218) 00:39:04 at org.junit.rules.RunRules.evaluate(RunRules.java:20) 00:39:04 at org.junit.runners.ParentRunner.run(ParentRunner.java:363) 00:39:04 at org.junit.runners.Suite.runChild(Suite.java:128) 00:39:04 at org.junit.runners.Suite.runChild(Suite.java:27) 00:39:04 at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) 00:39:04 at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) 00:39:04 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) 00:39:04 at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) 00:39:04 at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) 00:39:04 at org.junit.runners.ParentRunner.run(ParentRunner.java:363) 00:39:04 at org.junit.runner.JUnitCore.run(JUnitCore.java:137) 00:39:04 at org.junit.runner.JUnitCore.run(JUnitCore.java:115) 00:39:04 at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:113) 00:39:04 at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:85) 00:39:04 at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:54) 00:39:04 at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:134) 00:39:04 at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) 00:39:04 at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) 00:39:04 at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) 00:39:04 Caused by: java.net.SocketTimeoutException: Read timed out 00:39:04 at java.net.SocketInputStream.socketRead0(Native Method) 00:39:04 at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) 00:39:04 at java.net.SocketInputStream.read(SocketInputStream.java:171) 00:39:04 at java.net.SocketInputStream.read(SocketInputStream.java:141) 00:39:04 at org.apache.http.impl.conn.LoggingInputStream.read(LoggingInputStream.java:84) 00:39:04 at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) 00:39:04 at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) 00:39:04 at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) 00:39:04 at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) 00:39:04 at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) 00:39:04 at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) 00:39:04 at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) 00:39:04 at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) 00:39:04 at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) 00:39:04 at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) 00:39:04 at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) 00:39:04 at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) 00:39:04 at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) 00:39:04 at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) 00:39:04 at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) 00:39:04 at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72) 00:39:04 at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) 00:39:04 at com.sun.jersey.client.apache4.ApacheHttpClient4Handler.handle(ApacheHttpClient4Handler.java:171)
Similarly to what has been done for NXP-15691: "Automation HTTP client instantiated in tests has no timeout", the timeout of the Jersey Apache HTTP client has already been set to 60 seconds: https://github.com/nuxeo/nuxeo/blob/master/nuxeo-features/nuxeo-features-test/src/main/java/org/nuxeo/jaxrs/test/JerseyClientHelper.java#L37
So increasing this timeout would probably not solve the problem.
But how to understand what is going on on the server-side?
Only things we have that might help:
- The attached test logs that show a 1-minute gap between the last fulltext indexing thread and the runtime shutdown:
00:38:02,366 Nuxeo-Work-fulltextUpdater-1 TRACE [WorkQueuing$Listener$1Tracing] [fulltextUpdater, 0, 0, 4, 0] -> changed on UNKNOWN [parentPath=, name=fulltextUpdater:8699397431131409.278049363]{{fState,beforeRun}} 00:39:03,176 main INFO [AbstractRuntimeService] Stopping Nuxeo Runtime service OSGi NXRuntime; version: 1.4.0{{fState,afterRun}{fSuite,class org.nuxeo.ecm.restapi.server.jaxrs.drive.NuxeoDriveObjectTest}} - The attached thread dump that shows the "Nuxeo-Work-fulltextUpdater-1" thread waiting:
"Nuxeo-Work-fulltextUpdater-1" - Thread t@44 java.lang.Thread.State: WAITING at sun.misc.Unsafe.park(Native Method) - parking to wait for <1c62c3fd> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.nuxeo.ecm.core.work.MemoryBlockingQueue.take(MemoryBlockingQueue.java:160) at org.nuxeo.ecm.core.work.MemoryBlockingQueue.take(MemoryBlockingQueue.java:44) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)
=> Could this be related to fulltext indexing taking too much time?
