worker/metricworker: test timeout under race detector

[Dave Cheney]

FAIL: sender_test.go:29: SenderSuite.TestSender

[LOG] 0:00.072 DEBUG juju.environs.tools reading v1.* tools
[LOG] 0:00.073 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-precise-amd64
[LOG] 0:00.105 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-trusty-amd64
[LOG] 0:00.122 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-xenial-amd64
[LOG] 0:00.163 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.164 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.164 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.317 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.320 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.328 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.385 INFO juju.environs.tools Metadata for stream "released" unchanged
[LOG] 0:00.385 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.386 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.386 DEBUG juju.environs.tools reading v1.* tools
[LOG] 0:00.386 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-precise-amd64
[LOG] 0:00.395 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-trusty-amd64
[LOG] 0:00.429 INFO juju.environs.testing uploading FAKE tools 2.0-beta8-xenial-amd64
[LOG] 0:00.448 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.473 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.477 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.482 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.482 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.483 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.595 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.598 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-8174500698854481858/4/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.629 INFO juju.environs.tools Metadata for stream "devel" unchanged
[LOG] 0:00.629 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.629 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.645 DEBUG juju.environs.bootstrap model "admin" supports service/machine networks: true
[LOG] 0:00.646 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.646 INFO juju.environs.bootstrap looking for bootstrap tools: version=2.0-beta8
[LOG] 0:00.646 INFO juju.environs.tools finding tools in stream "devel"
[LOG] 0:00.646 INFO juju.environs.tools reading tools with major.minor version 2.0
[LOG] 0:00.646 INFO juju.environs.tools filtering tools by version: 2.0-beta8
[LOG] 0:00.679 INFO juju.provider.dummy would pick tools from 2.0-beta8-xenial-amd64
[LOG] 0:00.681 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.681 INFO juju.state opening state, mongo addresses: ["localhost:40751"]; entity <nil>
[LOG] 0:00.681 DEBUG juju.state dialing mongo
[LOG] 0:00.694 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:00.698 DEBUG juju.state connection established
[LOG] 0:00.698 DEBUG juju.state mongodb login successful
[LOG] 0:00.819 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:00.822 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.002 INFO juju.state running state anonymously; using unique client id
[LOG] 0:01.003 INFO juju.state starting standard state workers
[LOG] 0:01.003 DEBUG juju.state.workers starting leadership lease manager
[LOG] 0:01.011 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:01.029 DEBUG juju.state.workers starting singular lease manager
[LOG] 0:01.029 DEBUG juju.worker.lease waking to check leases at 2016-05-31 22:40:51.84251813 +0000 UTC
[LOG] 0:01.045 DEBUG juju.state.workers starting transaction log watcher
[LOG] 0:01.046 DEBUG juju.state.workers starting presence watcher
[LOG] 0:01.046 DEBUG juju.worker.lease waking to check leases at 2016-05-31 22:40:51.858994916 +0000 UTC
[LOG] 0:01.056 INFO juju.state creating cloud image metadata storage
[LOG] 0:01.056 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:01.090 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
[LOG] 0:01.112 INFO juju.environs.bootstrap newest version: 2.0-beta8
[LOG] 0:01.112 INFO juju.environs.bootstrap picked bootstrap tools version: 2.0-beta8
[LOG] 0:01.112 INFO juju.apiserver listening on "[::]:33125"
[LOG] 0:01.113 INFO juju.state opening state, mongo addresses: ["localhost:40751"]; entity <nil>
[LOG] 0:01.113 DEBUG juju.state dialing mongo
[LOG] 0:01.118 ERROR juju.apiserver Unable to prime /tmp/check-8174500698854481858/3/logsink.log (proceeding anyway): chown /tmp/check-8174500698854481858/3/logsink.log: operation not permitted
[LOG] 0:01.119 DEBUG juju.apiserver Starting API http server on address "[::]:33125"
[LOG] 0:01.129 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:01.133 DEBUG juju.state connection established
[LOG] 0:01.135 DEBUG juju.state mongodb login successful
[LOG] 0:01.192 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:01.196 INFO juju.state running state anonymously; using unique client id
[LOG] 0:01.196 INFO juju.state starting standard state workers
[LOG] 0:01.197 DEBUG juju.state.workers starting leadership lease manager
[LOG] 0:01.201 DEBUG juju.state.workers starting singular lease manager
[LOG] 0:01.201 DEBUG juju.worker.lease waking to check leases at 2016-05-31 22:40:52.014419759 +0000 UTC
[LOG] 0:01.204 DEBUG juju.state.workers starting transaction log watcher
[LOG] 0:01.204 DEBUG juju.state.workers starting presence watcher
[LOG] 0:01.206 INFO juju.state creating cloud image metadata storage
[LOG] 0:01.206 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:01.209 DEBUG juju.worker.lease waking to check leases at 2016-05-31 22:40:52.021925033 +0000 UTC
[LOG] 0:01.221 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:40751"
[LOG] 0:01.240 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:01.249 INFO juju.api dialing "wss://localhost:33125/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:01.318 INFO juju.apiserver [1] API connection from 127.0.0.1:57798, active connections: 1
[LOG] 0:01.320 INFO juju.api connection established to "wss://localhost:33125/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:01.322 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.324 DEBUG juju.apiserver <- [1] <unknown> {"RequestId":1,"Type":"Admin","Version":3,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:01.336 DEBUG juju.apiserver hostPorts: []
[LOG] 0:01.337 DEBUG juju.apiserver -> [1] user-admin@local 13.571541ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:01.396 DEBUG juju.state setting API hostPorts: [[localhost:33125]]
sender_test.go:38:
    c.Fatalf("the cleanup function should have fired by now")
... Error: the cleanup function should have fired by now

[LOG] 0:11.454 DEBUG juju.api health ping failed: connection is shut down
[LOG] 0:11.455 DEBUG juju.state.workers stopped state workers without error
[LOG] 0:11.457 INFO juju.apiserver [1] user-admin@local API connection terminated after 10.13893766s, active connections: 0
[LOG] 0:11.459 DEBUG juju.state closed state without error
[LOG] 0:11.459 INFO juju.provider.dummy reset model
[LOG] 0:11.459 DEBUG juju.apiserver API http server exited, final error was: accept tcp [::]:33125: use of closed network connection
[LOG] 0:11.460 INFO juju.apiserver closed listening socket "[::]:33125" with final error: close tcp [::]:33125: use of closed network connection
[LOG] 0:11.461 DEBUG juju.state.workers stopped state workers without error
[LOG] 0:11.462 DEBUG juju.state closed state without error
[LOG] 0:11.462 DEBUG juju.state closed state without error
[LOG] 0:11.475 INFO juju.testing reset successfully reset admin password
[LOG] 0:11.490 INFO juju.testing reset successfully reset admin password
[LOG] 0:11.499 INFO juju.testing reset successfully reset admin password
OOPS: 2 passed, 1 FAILED
--- FAIL: TestAll (11.74s)
FAIL
FAIL github.com/juju/juju/worker/metricworker 12.241s