Flakiness in github.com/docker/swarmkit/ca_test.TestRequestAndSaveNewCertificatesWithIntermediates

[ijc]

This test seems to timeout after 600s about 10-20% of the time in my testing:

$ for i in $(seq -w 1 10) ; do time make test | 2>&1 tee test-master.$i.log; done
...
$ grep -E 'ran too long|^(FAIL|ok  )\     github.com/docker/swarmkit/ca' test-master.*.log
test-master.01.log:ok  	github.com/docker/swarmkit/ca	17.772s
test-master.02.log:ok  	github.com/docker/swarmkit/ca	17.649s
test-master.03.log:ok  	github.com/docker/swarmkit/ca	17.134s
test-master.04.log:ok  	github.com/docker/swarmkit/ca	17.602s
test-master.05.log:ok  	github.com/docker/swarmkit/ca	17.248s
test-master.06.log:ok  	github.com/docker/swarmkit/ca	17.245s
test-master.07.log:ok  	github.com/docker/swarmkit/ca	17.943s
test-master.08.log:*** Test killed with quit: ran too long (10m0s).
test-master.08.log:FAIL	github.com/docker/swarmkit/ca	600.068s
test-master.09.log:ok  	github.com/docker/swarmkit/ca	19.579s
test-master.10.log:*** Test killed with quit: ran too long (10m0s).
test-master.10.log:FAIL	github.com/docker/swarmkit/ca	600.079s

I noticed this because I updated gRPC from v1.0.4 to v1.3.0 and the failure rate jumped to ~50% (which might provide an avenue to easier reproduction).

The failure only seems to occur with a full make test. I haven't been able to reproduce with go test github.com/docker/swarmkit/ca (with and without -race). The -race detector is not triggering.

Failure logs from the above:

• test-master.10.log
• test-master.08.log

[ijc]

I pushed my gRPC update to https://github.com/ijc25/swarmkit/tree/tickle-2221 might be useful since it makes it fail much more often (assuming it isn't adding some second failure mode). NB that branch also reduces the timeout from 600s to 60s since it was too boring waiting for it to fail, I think that is still more than long enough not to give false negatives.

[ijc]

Looks like this stops it happening:

diff --git a/ca/certificates_test.go b/ca/certificates_test.go
index dc34141d..f8c1d19e 100644
--- a/ca/certificates_test.go
+++ b/ca/certificates_test.go
@@ -380,7 +380,7 @@ func TestRequestAndSaveNewCertificatesNoIntermediate(t *testing.T) {
 }
 
 func TestRequestAndSaveNewCertificatesWithIntermediates(t *testing.T) {
-	t.Parallel()
+	//t.Parallel()
 
 	// use a RootCA with an intermediate
 	apiRootCA := api.RootCA{

Not a fix of course!

Separately I see these in the logs right before the failure, hard to say if they are related due to the parallelism and multiple tests though:

time="2017-06-07T16:03:18+01:00" level=error msg="failed to renew the certificate" error="rpc error: code = 5 desc = node z21sikivr2qpo0whm0yvfus0k not found when attempting to renew certificate" module=tls node.id=z21sikivr2qpo0whm0yvfus0k node.role=swarm-worker 
...
time="2017-06-07T16:03:18+01:00" level=error msg="failed to sign CSR" error="unable to perform certificate signing request: context canceled" method="(*Server).signNodeCert" module=ca node.id=pij3l0e2w2dw3xlxegc0ewzmr 

I wondered (as a complete wild guess) if maybe the "node not found" was due to cross talk between tests?