Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-23828

Random Read timed out in NuxeoDriveObjectTest

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Minor
    • Resolution: Unresolved
    • Affects Version/s: 9.10-SNAPSHOT
    • Fix Version/s: QualifiedToSchedule
    • Component/s: Rest API, Tests

      Description

      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?

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:

                  PagerDuty

                  Error rendering 'com.pagerduty.jira-server-plugin:PagerDuty'. Please contact your Jira administrators.