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

Fix random ES Rest timeout on index creation

    XMLWordPrintable

    Details

      Description

      The tests sometimes fail because of ES client timeout during the server startup while trying to create index.
      Note that the elasticsearch node is started but the create index timeout after 30s,
      it could be related to very slow disk IO or some full GC -> slave load

      KO
      bin/nuxeoctl start --strict --clid=/opt/build/hudson/instance.clid
      
      2018-10-02T01:34:09,030 WARN  [main] [org.nuxeo.elasticsearch.core.ElasticSearchEmbeddedNode] Elasticsearch embedded configuration is ONLY for testing purpose. You need to create a dedicated Elasticsearch cluster for production.
      2018-10-02T01:34:13,739 WARN  [main] [org.elasticsearch.deprecation.common.settings.Settings] [http.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2018-10-02T01:34:52,406 ERROR [main] [org.nuxeo.runtime.model.ComponentManager] Component service:org.nuxeo.elasticsearch.ElasticSearchComponent notification of application started failed: java.io.IOException: listener timeout after waiting for [30000] ms
      org.nuxeo.ecm.core.api.NuxeoException: java.io.IOException: listener timeout after waiting for [30000] ms
      	at org.nuxeo.elasticsearch.client.ESRestClient.createIndex(ESRestClient.java:213) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.initIndex(ElasticSearchAdminImpl.java:458) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
          at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.initIndex(ElasticSearchAdminImpl.java:357) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.initIndex(ElasticSearchAdminImpl.java:342) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.initIndexes(ElasticSearchAdminImpl.java:306) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.initializeIndexes(ElasticSearchAdminImpl.java:189) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.core.ElasticSearchAdminImpl.<init>(ElasticSearchAdminImpl.java:100) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.elasticsearch.ElasticSearchComponent.start(ElasticSearchComponent.java:168) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.model.impl.RegistrationInfoImpl.start(RegistrationInfoImpl.java:381) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.model.impl.ComponentManagerImpl.startComponent(ComponentManagerImpl.java:709) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.model.impl.ComponentManagerImpl.startComponents(ComponentManagerImpl.java:691) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.model.impl.ComponentManagerImpl.start(ComponentManagerImpl.java:792) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.osgi.OSGiRuntimeService.startComponents(OSGiRuntimeService.java:447) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.osgi.OSGiRuntimeService.frameworkEvent(OSGiRuntimeService.java:462) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.osgi.OSGiAdapter.fireFrameworkEvent(OSGiAdapter.java:223) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.osgi.application.loader.FrameworkLoader.doStart(FrameworkLoader.java:225) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.osgi.application.loader.FrameworkLoader.start(FrameworkLoader.java:124) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.deployment.NuxeoStarter.start(NuxeoStarter.java:124) [nuxeo-runtime-deploy-10.3-SNAPSHOT.jar:?]
      	at org.nuxeo.runtime.deployment.NuxeoStarter.contextInitialized(NuxeoStarter.java:93) [nuxeo-runtime-deploy-10.3-SNAPSHOT.jar:?]
      Caused by: java.io.IOException: listener timeout after waiting for [30000] ms
              at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:684) ~[elasticsearch-rest-client-6.3.0.jar:6.3.0]
              at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235) ~[elasticsearch-rest-client-6.3.0.jar:6.3.0]
              at org.elasticsearch.client.RestClient.performRequest(RestClient.java:198) ~[elasticsearch-rest-client-6.3.0.jar:6.3.0]
              at org.nuxeo.elasticsearch.client.ESRestClient.createIndex(ESRestClient.java:211) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
      
      2018-10-02T01:34:54,866 WARN  [elasticsearch[nuxeoNode][clusterApplierService#updateTask][T#1]] [org.elasticsearch.cluster.service.ClusterApplierService] cluster state applier task [apply cluster state (from master [master {nuxeoNode}{FVQ32L4USUaffofpe4yRYA}{-E0RehjLRwO6t0FrbDSmcw}{127.0.0.1}{127.0.0.1:9300} committed version [3] source [create-index [nuxeo-audit], cause [api]]])] took [31.9s] above the warn threshold of 30s
      2018-10-02T01:34:54,866 WARN  [elasticsearch[nuxeoNode][masterService#updateTask][T#1]] [org.elasticsearch.cluster.service.MasterService] cluster state update task [create-index [nuxeo-audit], cause [api]] took [32.4s] above the warn threshold of 30s
      2018-10-02T01:34:54,864 ERROR [main] [org.nuxeo.runtime.model.ComponentManager] Component service:org.nuxeo.ecm.core.uidgen.UIDGeneratorService notification of application started failed: null
      java.lang.NullPointerException: null
              at org.nuxeo.elasticsearch.ElasticSearchComponent.getClient(ElasticSearchComponent.java:240) ~[nuxeo-elasticsearch-core-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.elasticsearch.seqgen.ESUIDSequencer.init(ESUIDSequencer.java:64) ~[nuxeo-elasticsearch-seqgen-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.ecm.core.uidgen.UIDGeneratorComponent.start(UIDGeneratorComponent.java:63) ~[nuxeo-core-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.model.impl.RegistrationInfoImpl.start(RegistrationInfoImpl.java:381) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.model.impl.ComponentManagerImpl.startComponent(ComponentManagerImpl.java:709) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.model.impl.ComponentManagerImpl.startComponents(ComponentManagerImpl.java:691) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.model.impl.ComponentManagerImpl.start(ComponentManagerImpl.java:792) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.osgi.OSGiRuntimeService.startComponents(OSGiRuntimeService.java:447) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.osgi.OSGiRuntimeService.frameworkEvent(OSGiRuntimeService.java:462) [nuxeo-runtime-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.osgi.OSGiAdapter.fireFrameworkEvent(OSGiAdapter.java:223) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.osgi.application.loader.FrameworkLoader.doStart(FrameworkLoader.java:225) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.osgi.application.loader.FrameworkLoader.start(FrameworkLoader.java:124) [nuxeo-runtime-osgi-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.deployment.NuxeoStarter.start(NuxeoStarter.java:124) [nuxeo-runtime-deploy-10.3-SNAPSHOT.jar:?]
              at org.nuxeo.runtime.deployment.NuxeoStarter.contextInitialized(NuxeoStarter.java:93) [nuxeo-runtime-deploy-10.3-SNAPSHOT.jar:?]
      
      2018-10-02T01:34:58,055 ERROR [main] [org.nuxeo.runtime.osgi.OSGiRuntimeService] Nuxeo Platform Started
      ======================================================================
      = Component Loading Status: Pending: 0 / Missing: 0 / Unstarted: 3 / Total: 493
        - service:org.nuxeo.ecm.core.uidgen.UIDGeneratorService
        - service:org.nuxeo.ecm.platform.audit.service.NXAuditEventsService
        - service:org.nuxeo.elasticsearch.ElasticSearchComponent
      OK
      ======================================================================
      2018-10-02T09:30:57,489 WARN  [ElasticSearchEmbeddedNode] Elasticsearch embedded configuration is ONLY for testing purpose. You need to create a dedicated Elasticsearch cluster for production.
      2018-10-02T09:30:59,892 WARN  [Settings] [http.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2018-10-02T09:31:12,318 WARN  [ElasticSearchIndexingImpl] Trying to delete a non existing doc: {"id":"IxCd-15","type":"DELETE","docId":"1341611d-793a-4c94-bcdf-c72e7164ffff","path":"/document-route-models-root/SerialDocumentReview","repo":"default","recurse":true,"sync":false,"order":1538472672271007}
      2018-10-02T09:31:12,319 INFO  [OSGiRuntimeService] Nuxeo Platform Started
      ======================================================================
      = Component Loading Status: Pending: 0 / Missing: 0 / Unstarted: 0 / Total: 493
      ======================================================================
      2018-10-02T09:31:12,328 WARN  [ElasticSearchIndexingImpl] Trying to delete a non existing doc: {"id":"IxCd-4","type":"DELETE","docId":"b294c5fc-547f-44fe-98b8-99eb12d04acd","path":"/document-route-models-root/ParallelDocumentReview","repo":"default","recurse":true,"sync":false,"order":1538472672271007}
      2018-10-02 09:31:14.255 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 33352 ms
      

      Some failed builds:
      https://qa.nuxeo.org/jenkins/job/master/job/addons_FT_nuxeo-apidoc-master/1147/
      https://qa.nuxeo.org/jenkins/job/master/job/addons_FT_nuxeo-wopi-master/51/

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                • Created:
                  Updated: