BWC tests failed: transport.ports (No such file or directory)

[DaveCTurner]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+bwc-tests/6/console failed in a rather strange fashion.

Execution failed for task ':x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure'.
> java.io.FileNotFoundException: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+bwc-tests/x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/logs/transport.ports (No such file or directory)

(sadly no stack trace) and yet

$ zgrep consoleText.txt.gz -e 'x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/logs/transport.ports'
> java.io.FileNotFoundException: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+bwc-tests/x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/logs/transport.ports (No such file or directory)
[Google Cloud Storage Plugin] Uploading: x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/logs/transport.ports

I can see nothing in the logs that ties in with a failure to create the transport.ports file in ClusterFormationTasks#configureWaitTask, and the file is definitely there on the worker. Attaching the full logs here: consoleText.txt.gz.

The node log looks reasonable:

[2018-09-17T14:04:02,237][INFO ][o.e.n.Node               ] [node-0] initializing ...
[2018-09-17T14:04:02,299][INFO ][o.e.e.NodeEnvironment    ] [node-0] using [1] data paths, mounts [[/var/lib/jenkins (/dev/mapper/earjenkins)]], net usable_space [471.3gb], net total_space [1.8tb], spins? [no], types [ext4]
[2018-09-17T14:04:02,299][INFO ][o.e.e.NodeEnvironment    ] [node-0] heap size [1.9gb], compressed ordinary object pointers [true]
[2018-09-17T14:04:02,300][INFO ][o.e.n.Node               ] [node-0] node name [node-0], node ID [KmP2xFKOQ-GUCA15iuQURw]
[2018-09-17T14:04:02,300][INFO ][o.e.n.Node               ] [node-0] version[5.6.0], pid[121512], build[781a835/2017-09-07T03:09:58.087Z], OS[Linux/4.4.0-1061-aws/amd64], JVM["Oracle Corporation"/Java HotSpot(TM) 64-Bit Server VM/10/10+46]
[2018-09-17T14:04:02,300][INFO ][o.e.n.Node               ] [node-0] JVM arguments [-Xms2g, -Xmx2g, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -Djdk.io.permissionsUseCanonicalPath=true, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j.skipJansi=true, -XX:+HeapDumpOnOutOfMemoryError, -da:org.elasticsearch.xpack.monitoring.exporter.http.HttpExportBulk, -ea, -esa, -Des.path.home=/var/lib/jenkins/workspace/elastic+elasticsearch+6.x+bwc-tests/x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0]
[2018-09-17T14:04:03,323][INFO ][o.e.x.s.c.CryptoService  ] [node-0] system key [/var/lib/jenkins/workspace/elastic+elasticsearch+6.x+bwc-tests/x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/config/x-pack/system_key] has been loaded
[2018-09-17T14:04:03,441][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [aggs-matrix-stats]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [ingest-common]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [lang-expression]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [lang-groovy]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [lang-mustache]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [lang-painless]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [parent-join]
[2018-09-17T14:04:03,442][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [percolator]
[2018-09-17T14:04:03,443][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [reindex]
[2018-09-17T14:04:03,443][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [transport-netty3]
[2018-09-17T14:04:03,443][INFO ][o.e.p.PluginsService     ] [node-0] loaded module [transport-netty4]
[2018-09-17T14:04:03,443][INFO ][o.e.p.PluginsService     ] [node-0] loaded plugin [x-pack]
[2018-09-17T14:04:04,768][DEBUG][o.e.a.ActionModule       ] Using REST wrapper from plugin org.elasticsearch.xpack.XPackPlugin
[2018-09-17T14:04:05,385][INFO ][o.e.x.m.j.p.l.CppLogMessageHandler] [controller/121692] [Main.cc@128] controller (64 bit): Version 5.6.0 (Build 93aea61f57f7d8) Copyright (c) 2017 Elasticsearch BV
[2018-09-17T14:04:05,405][INFO ][o.e.d.DiscoveryModule    ] [node-0] using discovery type [zen]
[2018-09-17T14:04:06,074][INFO ][o.e.n.Node               ] [node-0] initialized
[2018-09-17T14:04:06,074][INFO ][o.e.n.Node               ] [node-0] starting ...
[2018-09-17T14:04:06,243][INFO ][o.e.t.TransportService   ] [node-0] publish_address {127.0.0.1:38071}, bound_addresses {[::1]:42238}, {127.0.0.1:38071}
[2018-09-17T14:04:06,280][INFO ][o.e.x.s.t.n.SecurityNetty4HttpServerTransport] [node-0] publish_address {127.0.0.1:35786}, bound_addresses {[::1]:35326}, {127.0.0.1:35786}
[2018-09-17T14:04:06,282][INFO ][o.e.n.Node               ] [node-0] started
[2018-09-17T14:04:09,282][WARN ][o.e.d.z.ZenDiscovery     ] [node-0] not enough master nodes discovered during pinging (found [[Candidate{node={node-0}{KmP2xFKOQ-GUCA15iuQURw}{ZEl7VkmgTiCdbpyASsDgIg}{127.0.0.1}{127.0.0.1:38071}{testattr=test, ml.max_open_jobs=10, ml.enabled=true}, clusterStateVersion=-1}]], but needed [3]), pinging again
[2018-09-17T14:04:12,284][WARN ][o.e.d.z.ZenDiscovery     ] [node-0] not enough master nodes discovered during pinging (found [[Candidate{node={node-0}{KmP2xFKOQ-GUCA15iuQURw}{ZEl7VkmgTiCdbpyASsDgIg}{127.0.0.1}{127.0.0.1:38071}{testattr=test, ml.max_open_jobs=10, ml.enabled=true}, clusterStateVersion=-1}]], but needed [3]), pinging again
...
[2018-09-17T14:06:12,327][WARN ][o.e.d.z.ZenDiscovery     ] [node-0] not enough master nodes discovered during pinging (found [[Candidate{node={node-0}{KmP2xFKOQ-GUCA15iuQURw}{ZEl7VkmgTiCdbpyASsDgIg}{127.0.0.1}{127.0.0.1:38071}{testattr=test, ml.max_open_jobs=10, ml.enabled=true}, clusterStateVersion=-1}]], but needed [3]), pinging again
[2018-09-17T14:06:14,372][INFO ][o.e.x.m.j.p.NativeController] Native controller process has stopped - no new native processes can be started
[2018-09-17T14:06:14,438][INFO ][o.e.n.Node               ] [node-0] stopping ...
[2018-09-17T14:06:14,455][WARN ][o.e.d.z.ZenDiscovery     ] [node-0] not enough master nodes discovered during pinging (found [[Candidate{node={node-0}{KmP2xFKOQ-GUCA15iuQURw}{ZEl7VkmgTiCdbpyASsDgIg}{127.0.0.1}{127.0.0.1:38071}{testattr=test, ml.max_open_jobs=10, ml.enabled=true}, clusterStateVersion=-1}]], but needed [3]), pinging again
[2018-09-17T14:06:14,467][INFO ][o.e.n.Node               ] [node-0] stopped
[2018-09-17T14:06:14,468][INFO ][o.e.n.Node               ] [node-0] closing ...
[2018-09-17T14:06:14,474][INFO ][o.e.n.Node               ] [node-0] closed

I'm not sure what step to take next to dig into this further.

[elasticmachine]

Pinging @elastic/es-core-infra

[DaveCTurner]

I looked at this again:

Execution failed for task ':x-pack:...#node1.configure'.
> java.io.FileNotFoundException: ...cluster/v5.6.0#oldClusterTestCluster node0/...

Note that this is node1 trying to find node0's transport ports file so it can write its own config file:

elasticsearch/buildSrc/src/main/groovy/org/elasticsearch/gradle/test/ClusterConfiguration.groovy

Lines 99 to 103 in 6646bcb

	ant.waitfor(maxwait: '40', maxwaitunit: 'second', checkevery: '500', checkeveryunit: 'millisecond') {
	resourceexists {
	file(file: seedNode.transportPortsFile.toString())
	}
	}

I suspect this could just be a slow CI run hitting this timeout; moreover we plan on changing this mechanism in #33675, so I'm closing this in favour of that issue.

[droberts195]

The same problem occurred in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+bwc-tests/38/console

> Task :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure FAILED

due to:

> java.io.FileNotFoundException: /var/lib/jenkins/workspace/elastic+elasticsearch+6.x+bwc-tests/x-pack/qa/rolling-upgrade/with-system-key/build/cluster/v5.6.0#oldClusterTestCluster node0/elasticsearch-5.6.0/logs/transport.ports (No such file or directory)

But I'll leave this issue closed as there's a plan to change how this works in #33675.

[jaymode]

I am reopening this issue as it is still occurring https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.5+bwc-tests/35/console. Even with the change, we still need a solution for older tests including BWC tests

[jaymode]

Another failure from today https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.5+bwc-tests/36/console

[DaveCTurner]

Thanks @jaymode, I agree. At the time I opened this issue I couldn't find any similar-looking occurrences. However there's been three other reports since then, which is too many to be explained by bad luck with timing. @original-brownbear could you take a look?

[original-brownbear]

@DaveCTurner sure on it :)

[original-brownbear]

@DaveCTurner even though it's unlikely it still seems like we're simply running into the timeout here:

The first line logged by node 0 in the last example above is this:

[2018-11-13T21:24:46,194][INFO ][o.e.n.Node               ] [node-0] initializing ...

Jenkins logs the start of the node at:

22:24:00 :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node0.start (Thread[Task worker for ':' Thread 9,5,main]) completed. Took 0.019 secs.

(one extra hour here fore me because I'm in UTC+1)

So assuming there's no craziness with the clocks it took over 40 seconds from running the run script to logging the first line (and writing the ports file happens after logging the first line).

Also I see this logged for the start of the configuration of node 1:

22:24:03 :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.extract (Thread[Task worker for ':' Thread 10,5,main]) completed. Took 0.611 secs.
22:24:03 :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure (Thread[Task worker for ':' Thread 10,5,main]) started.
22:24:05 
22:24:05 > Task :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure
22:24:05 Task ':x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure' is not up-to-date because:
22:24:05   Task has not declared any outputs despite executing actions.

and then the failure exactly 40s later:

22:24:43 > Task :x-pack:qa:rolling-upgrade:with-system-key:v5.6.0#oldClusterTestCluster#node1.configure FAILED

=> I think the Jenkins timestamps aren't skewed too much by output buffering.

Another piece of evidence that timestamps are okish is the timestamps in the archive of the logs:

-rw-r--r--@ 1 armin  staff      0 Nov 13 22:24:45 2018 rolling-upgrade_index_indexing_slowlog.log
-rw-r--r--@ 1 armin  staff      0 Nov 13 22:24:45 2018 rolling-upgrade_index_search_slowlog.log
-rw-r--r--@ 1 armin  staff     28 Nov 13 22:24:50 2018 transport.ports

... almost looks like the ordering in the Ant tasks is messed up for some reason since the node is started only after the wait has timed out (and both things are ant tasks).

-> still on it