TestRelationStatusWatcher intermittent failure

Bug #1750706 reported by Ian Booth
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Canonical Juju
Fix Released
High
Tim Penhey

Bug Description

FAIL: watcher_test.go:347: watcherSuite.TestRelationStatusWatcher

[LOG] 0:00.018 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.018 INFO juju.environs.testing uploading FAKE tools 2.3.4-precise-amd64
[LOG] 0:00.018 INFO juju.environs.testing uploading FAKE tools 2.3.4-trusty-amd64
[LOG] 0:00.023 INFO juju.environs.testing uploading FAKE tools 2.3.4-xenial-amd64
[LOG] 0:00.032 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.032 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.032 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.053 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.053 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.054 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.054 INFO juju.environs.tools Metadata for stream "released" unchanged
[LOG] 0:00.055 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.055 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.055 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.055 INFO juju.environs.testing uploading FAKE tools 2.3.4-precise-amd64
[LOG] 0:00.056 INFO juju.environs.testing uploading FAKE tools 2.3.4-trusty-amd64
[LOG] 0:00.076 INFO juju.environs.testing uploading FAKE tools 2.3.4-xenial-amd64
[LOG] 0:00.084 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.085 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.085 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.085 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.086 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.086 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.130 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.130 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-786621634245617206/17/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.132 INFO juju.environs.tools Metadata for stream "devel" unchanged
[LOG] 0:00.132 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.132 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.132 DEBUG juju.environs.bootstrap model "controller" supports service/machine networks: true
[LOG] 0:00.132 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.132 INFO cmd Loading image metadata
[LOG] 0:00.132 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=2.3.4
[LOG] 0:00.132 DEBUG juju.environs.tools finding agent binaries in stream: "released"
[LOG] 0:00.132 DEBUG juju.environs.tools reading agent binaries with major.minor version 2.3
[LOG] 0:00.132 DEBUG juju.environs.tools filtering agent binaries by version: 2.3.4
[LOG] 0:00.132 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:00.134 INFO juju.environs.bootstrap found 3 packaged agent binaries
[LOG] 0:00.135 INFO cmd Starting new instance for initial controller
[LOG] 0:00.135 INFO juju.provider.dummy would pick agent binaries from 2.3.4-xenial-amd64
[LOG] 0:00.135 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.135 INFO juju.environs.bootstrap newest version: 2.3.4
[LOG] 0:00.135 INFO juju.environs.bootstrap picked bootstrap agent binary version: 2.3.4
[LOG] 0:00.163 DEBUG juju.cloudconfig.instancecfg Setting numa ctl preference to false
[LOG] 0:00.163 INFO juju.state opening controller state, mongo addresses: ["localhost:46804"]; entity <nil>
[LOG] 0:00.163 DEBUG juju.state dialing mongo
[LOG] 0:00.164 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.167 DEBUG juju.state connection established
[LOG] 0:00.167 DEBUG juju.state mongodb login successful
[LOG] 0:00.237 DEBUG juju.state mongodb initialised
[LOG] 0:00.237 INFO juju.state running state anonymously; using unique client id
[LOG] 0:00.237 INFO juju.state starting standard state workers
[LOG] 0:00.237 DEBUG juju.worker start "txnlog"
[LOG] 0:00.238 INFO juju.worker start "txnlog"
[LOG] 0:00.238 DEBUG juju.worker start "presence"
[LOG] 0:00.238 DEBUG juju.worker start "pingbatcher"
[LOG] 0:00.238 DEBUG juju.worker start "leadership"
[LOG] 0:00.238 DEBUG juju.worker start "singular"
[LOG] 0:00.238 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.238 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.238 INFO juju.worker start "presence"
[LOG] 0:00.238 DEBUG juju.worker "presence" started
[LOG] 0:00.247 INFO juju.worker start "pingbatcher"
[LOG] 0:00.247 INFO juju.worker start "leadership"
[LOG] 0:00.247 INFO juju.worker start "singular"
[LOG] 0:00.247 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.248 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.248 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.248 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.248 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.253 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.257 DEBUG juju.worker "leadership" started
[LOG] 0:00.263 DEBUG juju.worker "txnlog" started
[LOG] 0:00.263 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.263 DEBUG juju.worker "pingbatcher" started
[LOG] 0:00.263 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.271 DEBUG juju.worker "singular" started
[LOG] 0:00.503 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
[LOG] 0:00.507 DEBUG juju.worker start "txnlog"
[LOG] 0:00.507 INFO juju.worker start "txnlog"
[LOG] 0:00.509 INFO juju.apiserver new certificate addresses:
[LOG] 0:00.510 WARNING juju.apiserver.logsink Unable to prime /tmp/juju-unittestfs/check-786621634245617206/16/logsink.log (proceeding anyway): chown /tmp/juju-unittestfs/check-786621634245617206/16/logsink.log: operation not permitted
[LOG] 0:00.510 INFO juju.state opening state, mongo addresses: ["localhost:46804"]; entity <nil>
[LOG] 0:00.510 DEBUG juju.state dialing mongo
[LOG] 0:00.510 INFO juju.apiserver listening on "[::]:45601"
[LOG] 0:00.516 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.516 DEBUG juju.worker "txnlog" started
[LOG] 0:00.520 DEBUG juju.state connection established
[LOG] 0:00.525 DEBUG juju.apiserver Starting API http server on address "[::]:45601"
[LOG] 0:00.561 DEBUG juju.state mongodb login successful
[LOG] 0:00.565 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.600 INFO juju.state running state anonymously; using unique client id
[LOG] 0:00.600 INFO juju.state starting standard state workers
[LOG] 0:00.600 DEBUG juju.worker start "txnlog"
[LOG] 0:00.600 INFO juju.worker start "txnlog"
[LOG] 0:00.600 DEBUG juju.worker start "presence"
[LOG] 0:00.600 DEBUG juju.worker start "pingbatcher"
[LOG] 0:00.600 DEBUG juju.worker start "leadership"
[LOG] 0:00.600 DEBUG juju.worker start "singular"
[LOG] 0:00.600 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.600 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.600 DEBUG juju.worker start "txnlog"
[LOG] 0:00.600 INFO juju.worker start "txnlog"
[LOG] 0:00.600 INFO juju.worker start "presence"
[LOG] 0:00.600 DEBUG juju.worker "presence" started
[LOG] 0:00.600 INFO juju.worker start "pingbatcher"
[LOG] 0:00.600 DEBUG juju.worker "txnlog" started
[LOG] 0:00.600 INFO juju.worker start "leadership"
[LOG] 0:00.600 INFO juju.worker start "singular"
[LOG] 0:00.601 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.601 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.601 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.601 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.601 DEBUG juju.worker "pingbatcher" started
[LOG] 0:00.601 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.602 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.615 DEBUG juju.api successfully dialed "wss://localhost:45601/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.615 INFO juju.api connection established to "wss://localhost:45601/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.627 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.627 DEBUG juju.apiserver model login: user-admin for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.628 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:46804"
[LOG] 0:00.650 DEBUG juju.worker "txnlog" started
[LOG] 0:00.662 DEBUG juju.worker "singular" started
[LOG] 0:00.663 DEBUG juju.worker "leadership" started
[LOG] 0:00.699 DEBUG juju.state setting API hostPorts: [[localhost:45601]]
[LOG] 0:00.729 INFO juju.state new machine "0" has preferred addresses: private "", public ""
[LOG] 0:00.767 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.768 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.776 DEBUG juju.api successfully dialed "wss://localhost:45601/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.776 INFO juju.api connection established to "wss://localhost:45601/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:01.332 DEBUG juju.apiserver model login: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.375 DEBUG juju.storage resource catalog entry created with id "4bca50e457844172575aeae34afc2a950a0d65e95226ed728026cee6b0f38ceea3e94161474806940e0360a62c34761a"
[LOG] 0:01.404 DEBUG juju.storage managed resource entry created with path "buckets/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms/local:quantal/mysql-1-8dc7bc05161dfdff0b4688eda2987ac336ca7ae572bafad6e2ea8a7b885989e2" -> "4bca50e457844172575aeae34afc2a950a0d65e95226ed728026cee6b0f38ceea3e94161474806940e0360a62c34761a"
[LOG] 0:01.427 DEBUG juju.state merged endpoint bindings modified: true, default: map[server: server-admin:], old: map[], new: map[], result: map[server: server-admin:]
[LOG] 0:01.509 DEBUG juju.storage resource catalog entry created with id "4b05554346b21b2c162a7e6fd543b0118eb504faec924f445c915f843d37397676e5c08745dd6236c796f62d1377a1b4"
[LOG] 0:01.517 DEBUG juju.storage managed resource entry created with path "buckets/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms/local:quantal/wordpress-3-b2764b5d42b17391006104681331f6a03705be4e83a12491c9534beccbbdb4eb" -> "4b05554346b21b2c162a7e6fd543b0118eb504faec924f445c915f843d37397676e5c08745dd6236c796f62d1377a1b4"
[LOG] 0:01.539 DEBUG juju.state merged endpoint bindings modified: true, default: map[cache: monitoring-port: url: db-client: logging-dir: db: foo-bar: admin-api:], old: map[], new: map[], result: map[foo-bar: admin-api: logging-dir: monitoring-port: url: db-client: cache: db:]
[LOG] 0:01.639 INFO juju.state new machine "1" has preferred addresses: private "", public ""
[LOG] 0:01.821 DEBUG juju.apiserver.common.crossmodel check 1 macaroons with required attrs: map[source-model-uuid:deadbeef-0bad-400d-8000-4b1d0d06f00d relation-key:wordpress:db mysql:server]
[LOG] 0:01.821 DEBUG juju.apiserver.common.crossmodel - mac model-deadbeef-0bad-400d-8000-4b1d0d06f00d relation-wordpress.db#mysql.server
[LOG] 0:01.821 DEBUG juju.apiserver.common.crossmodel check macaroons with declared attrs: map[source-model-uuid:deadbeef-0bad-400d-8000-4b1d0d06f00d relation-key:wordpress:db mysql:server username:fred]
[LOG] 0:01.821 DEBUG juju.apiserver.common.crossmodel macaroon check ok, attr: map[source-model-uuid:deadbeef-0bad-400d-8000-4b1d0d06f00d relation-key:wordpress:db mysql:server username:fred]
watcher_test.go:376:
    assertChange(life.Alive, true, "another reason")
watcher_test.go:335:
    c.Check(changes[0].SuspendedReason, gc.Equals, reason)
... obtained string = "reason"
... expected string = "another reason"

[LOG] 0:02.299 DEBUG juju.api RPC connection died
[LOG] 0:02.300 DEBUG juju.api RPC connection died
[LOG] 0:02.300 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:45601->127.0.0.1:33842: write: broken pipe
[LOG] 0:02.300 DEBUG juju.worker killing runner 0xc4203b4410
[LOG] 0:02.300 INFO juju.worker runner is dying
[LOG] 0:02.300 DEBUG juju.worker killing "txnlog"
[LOG] 0:02.300 INFO juju.worker stopped "txnlog", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "txnlog" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "txnlog" from known workers
[LOG] 0:02.300 DEBUG juju.worker killing runner 0xc4201c8a90
[LOG] 0:02.300 INFO juju.worker runner is dying
[LOG] 0:02.300 DEBUG juju.worker killing "txnlog"
[LOG] 0:02.300 DEBUG juju.worker killing "presence"
[LOG] 0:02.300 DEBUG juju.worker killing "pingbatcher"
[LOG] 0:02.300 DEBUG juju.worker killing "leadership"
[LOG] 0:02.300 DEBUG juju.worker killing "singular"
[LOG] 0:02.300 INFO juju.worker stopped "txnlog", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "txnlog" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "txnlog" from known workers
[LOG] 0:02.300 INFO juju.worker stopped "presence", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "presence" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "presence" from known workers
[LOG] 0:02.300 INFO juju.worker stopped "pingbatcher", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "pingbatcher" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "pingbatcher" from known workers
[LOG] 0:02.300 INFO juju.worker stopped "leadership", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "leadership" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "leadership" from known workers
[LOG] 0:02.300 INFO juju.worker stopped "singular", err: <nil>
[LOG] 0:02.300 DEBUG juju.worker "singular" done: <nil>
[LOG] 0:02.300 DEBUG juju.worker no restart, removing "singular" from known workers
[LOG] 0:02.300 DEBUG juju.state closed state without error
[LOG] 0:02.300 INFO juju.provider.dummy reset model
[LOG] 0:02.301 DEBUG juju.apiserver API http server exited, final error was: accept tcp [::]:45601: use of closed network connection
[LOG] 0:02.301 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:45601->127.0.0.1:33750: write: broken pipe
[LOG] 0:02.301 INFO juju.apiserver closed listening socket "[::]:45601" with final error: close tcp [::]:45601: use of closed network connection
[LOG] 0:02.301 DEBUG juju.worker killing runner 0xc4204d21a0
[LOG] 0:02.301 INFO juju.worker runner is dying
[LOG] 0:02.301 DEBUG juju.worker killing "txnlog"
[LOG] 0:02.301 DEBUG juju.worker killing "presence"
[LOG] 0:02.301 DEBUG juju.worker killing "pingbatcher"
[LOG] 0:02.301 DEBUG juju.worker killing "leadership"
[LOG] 0:02.301 DEBUG juju.worker killing "singular"
[LOG] 0:02.301 DEBUG juju.worker killing runner 0xc4207f0d00
[LOG] 0:02.301 INFO juju.worker runner is dying
[LOG] 0:02.301 DEBUG juju.worker killing "txnlog"
[LOG] 0:02.301 INFO juju.worker stopped "txnlog", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "txnlog" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "txnlog" from known workers
[LOG] 0:02.301 DEBUG juju.worker killing runner 0xc4204d21a0
[LOG] 0:02.301 INFO juju.worker stopped "txnlog", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "txnlog" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "txnlog" from known workers
[LOG] 0:02.301 INFO juju.worker stopped "presence", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "presence" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "presence" from known workers
[LOG] 0:02.301 INFO juju.worker stopped "pingbatcher", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "pingbatcher" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "pingbatcher" from known workers
[LOG] 0:02.301 INFO juju.worker stopped "leadership", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "leadership" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "leadership" from known workers
[LOG] 0:02.301 INFO juju.worker stopped "singular", err: <nil>
[LOG] 0:02.301 DEBUG juju.worker "singular" done: <nil>
[LOG] 0:02.301 DEBUG juju.worker no restart, removing "singular" from known workers
[LOG] 0:02.301 DEBUG juju.state closed state without error
[LOG] 0:02.304 INFO juju.testing reset successfully reset admin password
[LOG] 0:02.312 INFO juju.testing reset successfully reset admin password
OOPS: 9 passed, 1 FAILED

Changed in juju:
milestone: 2.4-beta1 → none
Tim Penhey (thumper)
Changed in juju:
assignee: nobody → Tim Penhey (thumper)
milestone: none → 2.5.2
status: Triaged → In Progress
Changed in juju:
milestone: 2.5.2 → 2.5.3
Tim Penhey (thumper)
Changed in juju:
status: In Progress → Fix Committed
Changed in juju:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.