[CI] Packaging tests fail with connection failure on opensuse and sles

[DaveCTurner]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+packaging-tests/2645/console

REPRODUCE WITH line says:

./gradlew :x-pack:qa:vagrant:vagrantOpensuse42#batsPackagingTest -Dtests.seed=7E7AE0563BF3B4A3

The main problem seems to be

07:47:13 # Connection failure to: http://127.0.0.1:9200/_xpack/security/user/kibana/_password?pretty failed: Read timed out

Unfortunately I can't find the server logs so can't see any more detail than this. Here's the relevant bit of the CI log:

07:46:01 ok 15 [RPM BOOTSTRAP PASSWORD] stop Elasticsearch
07:47:12 not ok 16 [TAR SETUP PASSWORD] test auto generated passwords
07:47:12 not ok 16 [TAR SETUP PASSWORD] test auto generated passwords
07:47:12 # (in test file /project/build/packaging/bats/tests/30_tar_setup_passwords.bats, line 60)
07:47:12 # (in test file /project/build/packaging/bats/tests/30_tar_setup_passwords.bats, line 60)
07:47:12 #   `false' failed
07:47:12 #   `false' failed
07:47:12 # Unpacking tarball to /tmp/elasticsearch
07:47:12 # checking for bin file elasticsearch-certgen
07:47:12 # checking for bin file elasticsearch-certgen.bat
07:47:12 # checking for bin file elasticsearch-certutil
07:47:12 # checking for bin file elasticsearch-certutil.bat
07:47:12 # checking for bin file elasticsearch-croneval
07:47:12 # checking for bin file elasticsearch-croneval.bat
07:47:12 # checking for bin file elasticsearch-migrate
07:47:12 # checking for bin file elasticsearch-migrate.bat
07:47:12 # checking for bin file elasticsearch-saml-metadata
07:47:12 # checking for bin file elasticsearch-saml-metadata.bat
07:47:12 # checking for bin file elasticsearch-setup-passwords
07:47:12 # checking for bin file elasticsearch-setup-passwords.bat
07:47:12 # checking for bin file elasticsearch-sql-cli
07:47:12 # checking for bin file elasticsearch-sql-cli.bat
07:47:13 # checking for bin file elasticsearch-sql-cli-7.0.0-alpha1-SNAPSHOT.jar
07:47:13 # checking for bin file elasticsearch-syskeygen
07:47:13 # checking for bin file elasticsearch-syskeygen.bat
07:47:13 # checking for bin file elasticsearch-users
07:47:13 # checking for bin file elasticsearch-users.bat
07:47:13 # checking for bin file x-pack-env
07:47:13 # checking for bin file x-pack-env.bat
07:47:13 # checking for bin file x-pack-security-env
07:47:13 # checking for bin file x-pack-security-env.bat
07:47:13 # checking for bin file x-pack-watcher-env
07:47:13 # checking for bin file x-pack-watcher-env.bat
07:47:13 # elasticsearch
07:47:13 # elasticsearch.bat
07:47:13 # elasticsearch-certgen
07:47:13 # elasticsearch-certgen.bat
07:47:13 # elasticsearch-certutil
07:47:13 # elasticsearch-certutil.bat
07:47:13 # elasticsearch-croneval
07:47:13 # elasticsearch-croneval.bat
07:47:13 # elasticsearch-env
07:47:13 # elasticsearch-env.bat
07:47:13 # elasticsearch-keystore
07:47:13 # elasticsearch-keystore.bat
07:47:13 # elasticsearch-migrate
07:47:13 # elasticsearch-migrate.bat
07:47:13 # elasticsearch-plugin
07:47:13 # elasticsearch-plugin.bat
07:47:13 # elasticsearch-saml-metadata
07:47:13 # elasticsearch-saml-metadata.bat
07:47:13 # elasticsearch-service.bat
07:47:13 # elasticsearch-service-mgr.exe
07:47:13 # elasticsearch-service-x64.exe
07:47:13 # elasticsearch-setup-passwords
07:47:13 # elasticsearch-setup-passwords.bat
07:47:13 # elasticsearch-sql-cli
07:47:13 # elasticsearch-sql-cli-7.0.0-alpha1-SNAPSHOT.jar
07:47:13 # elasticsearch-sql-cli.bat
07:47:13 # elasticsearch-syskeygen
07:47:13 # elasticsearch-syskeygen.bat
07:47:13 # Unpacking tarball to /tmp/elasticsearch
07:47:13 # checking for bin file elasticsearch-certgen
07:47:13 # checking for bin file elasticsearch-certgen.bat
07:47:13 # checking for bin file elasticsearch-certutil
07:47:13 # checking for bin file elasticsearch-certutil.bat
07:47:13 # checking for bin file elasticsearch-croneval
07:47:13 # checking for bin file elasticsearch-croneval.bat
07:47:13 # checking for bin file elasticsearch-migrate
07:47:13 # checking for bin file elasticsearch-migrate.bat
07:47:13 # checking for bin file elasticsearch-saml-metadata
07:47:13 # checking for bin file elasticsearch-saml-metadata.bat
07:47:13 # checking for bin file elasticsearch-setup-passwords
07:47:13 # checking for bin file elasticsearch-setup-passwords.bat
07:47:13 # checking for bin file elasticsearch-sql-cli
07:47:13 # checking for bin file elasticsearch-sql-cli.bat
07:47:13 # checking for bin file elasticsearch-sql-cli-7.0.0-alpha1-SNAPSHOT.jar
07:47:13 # checking for bin file elasticsearch-syskeygen
07:47:13 # checking for bin file elasticsearch-syskeygen.bat
07:47:13 # checking for bin file elasticsearch-users
07:47:13 # checking for bin file elasticsearch-users.bat
07:47:13 # checking for bin file x-pack-env
07:47:13 # checking for bin file x-pack-env.bat
07:47:13 # checking for bin file x-pack-security-env
07:47:13 # checking for bin file x-pack-security-env.bat
07:47:13 # checking for bin file x-pack-watcher-env
07:47:13 # checking for bin file x-pack-watcher-env.bat
07:47:13 # elasticsearch
07:47:13 # elasticsearch.bat
07:47:13 # elasticsearch-certgen
07:47:13 # elasticsearch-certgen.bat
07:47:13 # elasticsearch-certutil
07:47:13 # elasticsearch-certutil.bat
07:47:13 # elasticsearch-croneval
07:47:13 # elasticsearch-croneval.bat
07:47:13 # elasticsearch-env
07:47:13 # elasticsearch-env.bat
07:47:13 # elasticsearch-keystore
07:47:13 # elasticsearch-keystore.bat
07:47:13 # elasticsearch-migrate
07:47:13 # elasticsearch-migrate.bat
07:47:13 # elasticsearch-plugin
07:47:13 # elasticsearch-plugin.bat
07:47:13 # elasticsearch-saml-metadata
07:47:13 # elasticsearch-saml-metadata.bat
07:47:13 # elasticsearch-service.bat
07:47:13 # elasticsearch-service-mgr.exe
07:47:13 # elasticsearch-service-x64.exe
07:47:13 # elasticsearch-setup-passwords
07:47:13 # elasticsearch-setup-passwords.bat
07:47:13 # elasticsearch-sql-cli
07:47:13 # elasticsearch-sql-cli-7.0.0-alpha1-SNAPSHOT.jar
07:47:13 # elasticsearch-sql-cli.bat
07:47:13 # elasticsearch-syskeygen
07:47:13 # elasticsearch-syskeygen.bat
07:47:13 # el# el
07:47:13 asticsearch-translog
07:47:13 # elasticsearch-translog.bat
07:47:13 # elasticsearch-users
07:47:13 # elasticsearch-users.bat
07:47:13 # x-pack-env
07:47:13 # x-pack-env.bat
07:47:13 # x-pack-security-env
07:47:13 # x-pack-security-env.bat
07:47:13 # x-pack-watcher-env
07:47:13 # x-pack-watcher-env.bat
07:47:13 # Expected x-pack elasticsearch-setup-passwords tool exit code to be zero
07:47:13 # Initiating the setup of passwords for reserved users elastic,kibana,logstash_system,beats_system.
07:47:13 # The passwords will be randomly generated and printed to the console.
07:47:13 # Please confirm that you would like to continue [y/N]
07:47:13 # 
07:47:13 # 
07:47:13 # Connection failure to: http://127.0.0.1:9200/_xpack/security/user/kibana/_password?pretty failed: Read timed out
07:47:13 # 
07:47:13 # ERROR: Failed to set password for user [kibana].
07:47:13 asticsearch-translog
07:47:13 # elasticsearch-translog.bat
07:47:13 # elasticsearch-users
07:47:13 # elasticsearch-users.bat
07:47:13 # x-pack-env
07:47:13 # x-pack-env.bat
07:47:13 # x-pack-security-env
07:47:13 # x-pack-security-env.bat
07:47:13 # x-pack-watcher-env
07:47:13 # x-pack-watcher-env.bat
07:47:13 # Expected x-pack elasticsearch-setup-passwords tool exit code to be zero
07:47:13 # Initiating the setup of passwords for reserved users elastic,kibana,logstash_system,beats_system.
07:47:13 # The passwords will be randomly generated and printed to the console.
07:47:13 # Please confirm that you would like to continue [y/N]
07:47:13 # 
07:47:13 # 
07:47:13 # Connection failure to: http://127.0.0.1:9200/_xpack/security/user/kibana/_password?pretty failed: Read timed out
07:47:13 # 
07:47:13 # ERROR: Failed to set password for user [kibana].

[elasticmachine]

Pinging @elastic/es-core-infra

[DaveCTurner]

@andyb-elastic saw a similar failure some time back and this failure included the Elasticsearch logs which said this:

# [2018-02-27T10:45:38,258][INFO ][o.e.n.Node               ] initialized
# [2018-02-27T10:45:38,258][INFO ][o.e.n.Node               ] [OpH_qGq] starting ...
# [2018-02-27T10:45:38,409][INFO ][o.e.t.TransportService   ] [OpH_qGq] publish_address {127.0.0.1:9300}, bound_addresses {127.0.0.1:9300}
# [2018-02-27T10:45:38,422][WARN ][o.e.b.BootstrapChecks    ] [OpH_qGq] max file descriptors [4096] for elasticsearch process is too low, increase to at least [65536]
# [2018-02-27T10:45:41,463][INFO ][o.e.c.s.MasterService    ] [OpH_qGq] zen-disco-elected-as-master ([0] nodes joined), reason: master node changed {previous [], current [{OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8# [2018-02-27T10:45:41,463][INFO ][o.e.c.s.MasterService    ] [OpH_qGq] zen-disco-elected-as-master ([0] nodes joined), reason: master node changed {previous [], current [{OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8
370659328, ml.max_open_jobs=20, ml.enabled=true}]}
# [2018-02-27T10:45:41,467][INFO ][o.e.c.s.ClusterApplierService] [OpH_qGq] master node changed {previous [], current [{OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8370659328, ml.max_open_jobs=20, ml.enabled=true}]}, reason: apply cluster state (from master [master {OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8370659328, ml.max_open_jobs=20, ml.enabled=true} committed version [1] source [zen-disco-elected-as-master ([0] nodes joined)]])
# [2018-02-27T10:45:41,477][INFO ][o.e.x.s.t.n.SecurityNetty4HttpServerTransport] [OpH_qGq] publish_address {127.0.0.1:9200}, bound_addresses {127.0.0.1:9200}
# [2018-02-27T10:45:41,478][INFO ][o.e.n.Node               ] [OpH_qGq] started
# [2018-02-27T10:45:41,652][INFO ][o.e.g.GatewayService     ] [OpH_qGq] recovered [0] indices into cluster_state
# [2018-02-27T10:46:11,661][DEBUG][o.e.a.a.i.t.p.TransportPutIndexTemplateAction] [OpH_qGq] failed to put template [.monitoring-beats]
# org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (create-index-template [.monitoring-beats], cause [api]) within 30s
# 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:125) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_144]
# 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:124) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_144]
370659328, ml.max_open_jobs=20, ml.enabled=true}]}
# [2018-02-27T10:45:41,467][INFO ][o.e.c.s.ClusterApplierService] [OpH_qGq] master node changed {previous [], current [{OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8370659328, ml.max_open_jobs=20, ml.enabled=true}]}, reason: apply cluster state (from master [master {OpH_qGq}{OpH_qGqbSjOWzlsc2tPxfg}{3UZwOqnAT5KXgUcXlqfCxA}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8370659328, ml.max_open_jobs=20, ml.enabled=true} committed version [1] source [zen-disco-elected-as-master ([0] nodes joined)]])
# [2018-02-27T10:45:41,477][INFO ][o.e.x.s.t.n.SecurityNetty4HttpServerTransport] [OpH_qGq] publish_address {127.0.0.1:9200}, bound_addresses {127.0.0.1:9200}
# [2018-02-27T10:45:41,478][INFO ][o.e.n.Node               ] [OpH_qGq] started
# [2018-02-27T10:45:41,652][INFO ][o.e.g.GatewayService     ] [OpH_qGq] recovered [0] indices into cluster_state
# [2018-02-27T10:46:11,661][DEBUG][o.e.a.a.i.t.p.TransportPutIndexTemplateAction] [OpH_qGq] failed to put template [.monitoring-beats]
# org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (create-index-template [.monitoring-beats], cause [api]) within 30s
# 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:125) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_144]
# 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:124) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
# 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_144]
# 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1# 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1
.8.0_144]
# 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144]
...

Not sure why the Elasticsearch log wasn't included in the build failure above but it'd be mighty useful if it could appear in future.

If it is the same situation then this is failing to put a bunch of index templates within the 30 seconds timeout. It's not a network issue, since this is a one-node cluster. It'd be useful to see DEBUG logging from:

org.elasticsearch.action.support.master.TransportMasterNodeAction
org.elasticsearch.action.admin.indices.template.put.TransportPutIndexTemplateAction

(edited - I originally mentioned mappings, but this is not that)

[andyb-elastic]

Another similar one

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+packaging-tests/2658/console
build-2658-opensuse.txt

[andyb-elastic]

And another

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+packaging-tests/2660/console
build-2660-opensuse.txt

@DaveCTurner do you have a recommendation for any logging I can add to get more information about why the node is failing to process these cluster state events?

[DaveCTurner]

The logs seem somewhat garbled - messages seem to be duplicated in a funny order. Nonetheless, this bit seems unusually slow:

# [2018-05-06T06:46:39,483][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-es] for index patterns [.monitoring-es-6-*]
# [2018-05-06T06:46:43,843][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-beats] for index patterns [.monitoring-beats-6-*]
# [2018-05-06T06:46:48,220][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-alerts] for index patterns [.monitoring-alerts-6]
# [2018-05-06T06:46:52,596][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-kibana] for index patterns [.monitoring-kibana-6-*]
open_jobs=20, ml.enabled=true}]}, reason: apply cluster state (from master [master {I3r5omj}{I3r5omjKR5evfgfM8ftPbA}{v_6FY1TySDyGEKnupaxjCg}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8370659328, ml.max_open_jobs=20, ml.enabled=true} committed version [1] source [zen-disco-elected-as-master ([0] nodes joined)[, ]]])
# [2018-05-06T06:46:18,995][INFO ][o.e.x.s.t.n.SecurityNetty4HttpServerTransport] [I3r5omj] publish_address {127.0.0.1:9200}, bound_addresses {127.0.0.1:9200}
# [2018-05-06T06:46:18,995][INFO ][o.e.n.Node               ] [I3r5omj] started
# [2018-05-06T06:46:23,813][INFO ][o.e.g.GatewayService     ] [I3r5omj] recovered [0] indices into cluster_state
# [2018-05-06T06:46:23,931][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.watch-history-7] for index patterns [.watcher-history-7*]
# [2018-05-06T06:46:28,449][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.watches] for index patterns [.watches*]
# [2018-05-06T06:46:32,919][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.triggered_watches] for index patterns [.triggered_watches*]
# [2018-05-06T06:46:35,044][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-logstash] for index patterns [.monitoring-logstash-6-*]
# [2018-05-06T06:46:39,483][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-es] for index patterns [.monitoring-es-6-*]
# [2018-05-06T06:46:43,843][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-beats] for index patterns [.monitoring-beats-6-*]
# [2018-05-06T06:46:48,220][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-alerts] for index patterns [.monitoring-alerts-6]
# [2018-05-06T06:46:52,596][INFO ][o.e.c.m.MetaDataIndexTemplateService] [I3r5omj] adding template [.monitoring-kibana] for index patterns [.monitoring-kibana-6-*]
# [2018-05-06T06:46:53,834][ERROR][o.e.x.m.e.l.LocalExporter] failed to set monitoring pipeline [xpack_# [2018-05-06T06:46:53,834][ERROR][o.e.x.m.e.l.LocalExporter] failed to set monitoring pipeline [xpack_
monitoring_6]
# org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (put-pipeline-xpack_monitoring_6) within 30s

On my laptop it takes <1s to make all the templates:

[2018-05-07T18:25:36,684][WARN ][o.e.x.s.a.s.m.NativeRoleMappingStore] [0MEKNSQ] Failed to clear cache for realms [[]]
[2018-05-07T18:25:36,726][INFO ][o.e.g.GatewayService     ] [0MEKNSQ] recovered [0] indices into cluster_state
[2018-05-07T18:25:36,884][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.watch-history-7] for index patterns [.watcher-history-7*]
[2018-05-07T18:25:36,924][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.triggered_watches] for index patterns [.triggered_watches*]
[2018-05-07T18:25:36,955][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.watches] for index patterns [.watches*]
[2018-05-07T18:25:37,020][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.monitoring-logstash] for index patterns [.monitoring-logstash-6-*]
[2018-05-07T18:25:37,070][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.monitoring-es] for index patterns [.monitoring-es-6-*]
[2018-05-07T18:25:37,107][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.monitoring-alerts] for index patterns [.monitoring-alerts-6]
[2018-05-07T18:25:37,148][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.monitoring-beats] for index patterns [.monitoring-beats-6-*]
[2018-05-07T18:25:37,180][INFO ][o.e.c.m.MetaDataIndexTemplateService] [0MEKNSQ] adding template [.monitoring-kibana] for index patterns [.monitoring-kibana-6-*]
[2018-05-07T18:25:37,319][INFO ][o.e.l.LicenseService     ] [0MEKNSQ] license [6aae53f8-5ecf-4fc8-b66a-50f5e31c3ee7] mode [basic] - valid

Perhaps this will shed a little more light into where the time is going:

logger.org.elasticsearch.indices: DEBUG
logger.org.elasticsearch.gateway: TRACE

[droberts195]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+packaging-tests/2717/console is another instance of this.

Again the outermost error is:

07:01:21 # Connection failure to: http://127.0.0.1:9200/_xpack/security/user/kibana/_password?pretty failed: Read timed out

and the error in the Elasticsearch log is:

07:01:21 # [2018-05-25T07:01:13,198][ERROR][o.e.x.m.e.l.LocalExporter] failed to set monitoring pipeline [xpack_monitoring_2]
07:01:21 # org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (put-pipeline-xpack_monitoring_2) within 30s
07:01:21 # org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (put-pipeline-xpack_monitoring_2) within 30s
07:01:21 # 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:124) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:124) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_144]
07:01:21 # 	at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_144]
07:01:21 # 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:123) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:123) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:625) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:625) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
07:01:21 # 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_144]
07:01:21 # 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_144]
07:01:21 # 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_144]
07:01:21 # 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144]
07:01:21 # 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_144]
07:01:21 # 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144]

[DaveCTurner]

Similar story: adding templates is slow:

# [2018-05-25T07:00:43,002][INFO ][o.e.g.GatewayService     ] [rWPAvXn] recovered [0] indices into cluster_state
# [2018-05-25T07:00:43,134][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.watches] for index patterns [.watches*]
# [2018-05-25T07:00:43,871][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.watch-history-8] for index patterns [.watcher-history-8*]
# [2018-05-25T07:00:43,134][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.watches] for index patterns [.watches*]
# [2018-05-25T07:00:43,871][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.watch-history-8] for index patterns [.watcher-history-8*]
# [2018-05-25T07:00:44,744][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.triggered_watches] for index patterns [.triggered_watches*]
# [2018-05-25T07:00:49,884][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-logstash] for index patterns [.monitoring-logstash-6-*]
# [2018-05-25T07:00:44,744][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.triggered_watches] for index patterns [.triggered_watches*]
# [2018-05-25T07:00:49,884][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-logstash] for index patterns [.monitoring-logstash-6-*]
# [2018-05-25T07:00:54,904][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-es] for index patterns [.monitoring-es-6-*]
# [2018-05-25T07:00:59,906][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-beats] for index patterns [.monitoring-beats-6-*]
# [2018-05-25T07:00:54,904][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-es] for index patterns [.monitoring-es-6-*]
# [2018-05-25T07:00:59,906][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-beats] for index patterns [.monitoring-beats-6-*]
# [2018-05-25T07:01:04,968][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-alerts] for index patterns [.monitoring-alerts-6]
# [2018-05-25T07:01:09,960][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-kibana] for index patterns [.monitoring-kibana-6-*]
# [2018-05-25T07:01:04,968][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-alerts] for index patterns [.monitoring-alerts-6]
# [2018-05-25T07:01:09,960][INFO ][o.e.c.m.MetaDataIndexTemplateService] [rWPAvXn] adding template [.monitoring-kibana] for index patterns [.monitoring-kibana-6-*]
# [2018-05-25T07:01:13,010][ERROR][o.e.x.m.e.l.LocalExporter] failed to set monitoring pipeline [xpack_monitoring_6]

@andyb-elastic it doesn't look like we're getting extra detail yet. Could you check these settings are being applied in the right places?

logger.org.elasticsearch.indices: DEBUG
logger.org.elasticsearch.gateway: TRACE

[andyb-elastic]

They're not applied because I didn't follow up on this, my bad. I'll add them now

[andyb-elastic]

Setting that logging the right way ended up being a little involved, I'll push it next week in the interest of not breaking the build Friday afternoon

[cbuescher]

This looks very similar to me: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+packaging-tests/890/console

@andyb-elastic not sure which additional detail you are looking for, maybe this one shows more?