apiserver: sporadic test failure in pingerSuite.TestAgentConnectionDelaysShutdownWithPing

[Roger Peppe]

Here's an example of the failure:

http://juju-ci.vapour.ws:8080/job/github-merge-juju/9477/artifact/artifacts/trusty-out.log

Relevant excerpt from log:

 FAIL: pinger_test.go:102: pingerSuite.TestAgentConnectionDelaysShutdownWithPing

 [LOG] 0:00.002 INFO juju.state opening state, mongo addresses: ["localhost:48007"]; entity <nil>
 [LOG] 0:00.002 DEBUG juju.state dialing mongo
 [LOG] 0:00.004 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:48007"
 [LOG] 0:00.005 DEBUG juju.state connection established
 [LOG] 0:00.005 DEBUG juju.state mongodb login successful
 [LOG] 0:00.069 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:48007"
 [LOG] 0:00.069 INFO juju.state initializing controller model b8d87207-1ccb-49a3-8f9d-59a87a67e9f0
 [LOG] 0:00.139 INFO juju.state running state anonymously; using unique client id
 [LOG] 0:00.139 INFO juju.state starting standard state workers
 [LOG] 0:00.139 DEBUG juju.state.workers starting leadership lease manager
 [LOG] 0:00.145 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:48007"
 [LOG] 0:00.155 DEBUG juju.state.workers starting singular lease manager
 [LOG] 0:00.155 DEBUG juju.worker.lease waking to check leases at 1970-01-01 00:01:00.000000001 +0000 UTC
 [LOG] 0:00.161 DEBUG juju.state.workers starting transaction log watcher
 [LOG] 0:00.161 DEBUG juju.state.workers starting presence watcher
 [LOG] 0:00.161 INFO juju.state creating cloud image metadata storage
 [LOG] 0:00.161 DEBUG juju.worker.lease waking to check leases at 1970-01-01 00:01:00.000000001 +0000 UTC
 [LOG] 0:00.161 INFO juju.state started state for model-b8d87207-1ccb-49a3-8f9d-59a87a67e9f0 successfully
 [LOG] 0:00.170 INFO juju.apiserver new certificate addresses:
 [LOG] 0:00.170 INFO juju.apiserver listening on "[::]:56339"
 [LOG] 0:00.170 ERROR juju.apiserver Unable to prime /mnt/tmp/check-1468849411708413759/1/logsink.log (proceeding anyway): chown /mnt/tmp/check-1468849411708413759/1/logsink.log: operation not permitted
 [LOG] 0:00.170 DEBUG juju.apiserver Starting API http server on address "[::]:56339"
 [LOG] 0:00.173 INFO juju.state new machine "0" has preferred addresses: private "", public ""
 [LOG] 0:00.185 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:48007"
 [LOG] 0:00.225 INFO juju.api dialing "wss://localhost:56339/model/b8d87207-1ccb-49a3-8f9d-59a87a67e9f0/api"
 [LOG] 0:00.266 DEBUG juju.apiserver validate model uuid: controller model - b8d87207-1ccb-49a3-8f9d-59a87a67e9f0
 [LOG] 0:00.266 INFO juju.api connection established to "wss://localhost:56339/model/b8d87207-1ccb-49a3-8f9d-59a87a67e9f0/api"
 [LOG] 0:00.278 DEBUG juju.apiserver hostPorts: []
 pinger_test.go:115:
     checkConnectionDies(c, conn)
 pinger_test.go:159:
     c.Fatal("connection didn't get shut down")
 ... Error: connection didn't get shut down

 [LOG] 0:10.254 DEBUG juju.api RPC connection died
 [LOG] 0:10.254 INFO juju.apiserver closed listening socket "[::]:56339" with final error: <nil>
 [LOG] 0:10.254 DEBUG juju.apiserver API http server exited, final error was: accept tcp [::]:56339: use of closed network connection
 [LOG] 0:10.254 DEBUG juju.state.workers stopped state workers without error
 [LOG] 0:10.254 DEBUG juju.state closed state without error
 [LOG] 0:10.254 DEBUG juju.state closed state without error
 2016/10/11 16:17:27 http: TLS handshake error from 127.0.0.1:40072: tls: client offered an unsupported, maximum protocol version of 300
 2016/10/11 16:17:47 http: TLS handshake error from 127.0.0.1:60153: tls: first record does not look like a TLS handshake
 OOPS: 243 passed, 1 FAILED

[Roger Peppe (rogpeppe)]

BTW I wasn't able to replicate this locally.

[Anastasia (anastasia-macmood)]

I wonder if this is a duplicate of bug # 1627086.

[Menno Finlay-Smits (menno.smits)]

This is a different issue to bug 1627086.

[Anastasia (anastasia-macmood)]

Proposed fix: https://github.com/juju/juju/pull/6431