firewallerSuite.TestWatch failed with: watcher sent unexpected change: (_, true)

[Heather Lanigan]

http://ci.jujucharms.com/job/make-check-juju/3172

13:39:58 ----------------------------------------------------------------------
13:39:58 FAIL: firewaller_test.go:79: firewallerSuite.TestWatch
13:39:58
13:39:58 [LOG] 0:00.005 DEBUG juju.environs.tools reading v1.* agent binaries
13:39:58 [LOG] 0:00.005 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-xenial-amd64
13:39:58 [LOG] 0:00.023 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-bionic-amd64
13:39:58 [LOG] 0:00.024 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-precise-amd64
13:39:58 [LOG] 0:00.024 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-trusty-amd64
13:39:58 [LOG] 0:00.027 INFO juju.environs.tools Writing tools/streams/v1/index2.json
13:39:58 [LOG] 0:00.028 INFO juju.environs.tools Writing tools/streams/v1/index.json
13:39:58 [LOG] 0:00.028 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
13:39:58 [LOG] 0:00.043 DEBUG juju.environs.tools reading v1.* agent binaries
13:39:58 [LOG] 0:00.043 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-xenial-amd64
13:39:58 [LOG] 0:00.044 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-bionic-amd64
13:39:58 [LOG] 0:00.065 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-precise-amd64
13:39:58 [LOG] 0:00.065 INFO juju.environs.testing uploading FAKE tools 2.6-beta1-trusty-amd64
13:39:58 [LOG] 0:00.073 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-8220372148741452558/59/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
13:39:58 [LOG] 0:00.075 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-8220372148741452558/59/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
13:39:58 [LOG] 0:00.075 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-8220372148741452558/59/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
13:39:58 [LOG] 0:00.076 INFO juju.environs.tools Writing tools/streams/v1/index2.json
13:39:58 [LOG] 0:00.076 INFO juju.environs.tools Writing tools/streams/v1/index.json
13:39:58 [LOG] 0:00.076 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.bootstrap network management by juju enabled: true
13:39:58 [LOG] 0:00.093 INFO cmd Loading image metadata
13:39:58 [LOG] 0:00.093 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=2.6-beta1
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.tools reading agent binaries with major.minor version 2.6
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.tools filtering agent binaries by version: 2.6-beta1
13:39:58 [LOG] 0:00.093 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
13:39:58 [LOG] 0:00.100 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-8220372148741452558/59/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
13:39:58 [LOG] 0:00.102 INFO juju.environs.bootstrap found 4 packaged agent binaries
13:39:58 [LOG] 0:00.102 INFO cmd Starting new instance for initial controller
13:39:58 [LOG] 0:00.102 INFO juju.provider.dummy would pick agent binaries from 2.6-beta1-bionic-amd64
13:39:58 [LOG] 0:00.102 INFO juju.provider.dummy creating bootstrap instance
13:39:58 [LOG] 0:00.102 INFO juju.environs.bootstrap newest version: 2.6-beta1
13:39:58 [LOG] 0:00.102 INFO juju.environs.bootstrap picked bootstrap agent binary version: 2.6-beta1
13:39:58 [LOG] 0:00.114 DEBUG juju.cloudconfig.instancecfg Setting numa ctl preference to false
13:39:58 [LOG] 0:00.115 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.145 DEBUG juju.state mongodb initialised
13:39:58 [LOG] 0:00.145 INFO juju.state running state anonymously; using unique store id
13:39:58 [LOG] 0:00.145 INFO juju.state starting standard state workers
13:39:58 [LOG] 0:00.146 INFO juju.state creating cloud image metadata storage
13:39:58 [LOG] 0:00.146 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
13:39:58 [LOG] 0:00.147 DEBUG juju.state.presence using $bit operations with Mongo 3.6.3
13:39:58 [LOG] 0:00.147 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.147 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.147 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.147 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.151 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
13:39:58 [LOG] 0:00.283 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
13:39:58 [LOG] 0:00.292 WARNING juju.apiserver.logsink Unable to prime /tmp/juju-unittestfs/check-8220372148741452558/58/logsink.log (proceeding anyway): chown /tmp/juju-unittestfs/check-8220372148741452558/58/logsink.log: operation not permitted
13:39:58 [LOG] 0:00.299 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.342 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.357 INFO juju.state starting standard state workers
13:39:58 [LOG] 0:00.357 INFO juju.state creating cloud image metadata storage
13:39:58 [LOG] 0:00.357 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
13:39:58 [LOG] 0:00.357 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.357 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.357 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.358 DEBUG juju.state.presence using $bit operations with Mongo 3.6.3
13:39:58 [LOG] 0:00.362 DEBUG juju.environs ControllerInstances returned: [localhost]
13:39:58 [LOG] 0:00.363 DEBUG juju.api looked up localhost -> [127.0.0.1]
13:39:58 [LOG] 0:00.369 DEBUG juju.apiserver [1] API connection from 127.0.0.1:56134
13:39:58 [LOG] 0:00.369 DEBUG juju.api successfully dialed "wss://localhost:43955/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
13:39:58 [LOG] 0:00.370 INFO juju.api connection established to "wss://localhost:43955/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
13:39:58 [LOG] 0:00.371 DEBUG juju.apiserver <- [1] {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
13:39:58 [LOG] 0:00.387 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
13:39:58 [LOG] 0:00.387 DEBUG juju.apiserver model login: user-admin for deadbeef-0bad-400d-8000-4b1d0d06f00d
13:39:58 [LOG] 0:00.387 DEBUG juju.apiserver -> [1] 16.013399ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
13:39:58 [LOG] 0:00.392 DEBUG juju.state setting apiHostPorts: [[localhost:43955]]
13:39:58 [LOG] 0:00.392 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:36847"
13:39:58 [LOG] 0:00.412 DEBUG juju.state setting apiHostPortsForAgents: [[localhost:43955]]
13:39:58 [LOG] 0:00.437 INFO juju.state new machine "0" has preferred addresses: private "", public ""
13:39:58 [LOG] 0:00.484 INFO juju.state new machine "1" has preferred addresses: private "", public ""
13:39:58 [LOG] 0:00.544 INFO juju.state new machine "2" has preferred addresses: private "", public ""
13:39:58 [LOG] 0:00.636 DEBUG juju.charm charm is not in revision control directory
13:39:58 [LOG] 0:00.642 DEBUG juju.storage resource catalog entry created with id "a479abaf8dfa0c366eb761c90a9d8c402b6dcba5184ff1bdca23dc28d4bcdbb73eccdc2cf459de4c17f02266d3882a1b"
13:39:58 [LOG] 0:00.652 DEBUG juju.storage managed resource entry created with path "buckets/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms/local:quantal/wordpress-3-175972324c476997a0c9a6fc6ab55d930ebcfee66e30b10c99d6ca227d8d86f7" -> "a479abaf8dfa0c366eb761c90a9d8c402b6dcba5184ff1bdca23dc28d4bcdbb73eccdc2cf459de4c17f02266d3882a1b"
13:39:58 [LOG] 0:00.695 DEBUG juju.state merged endpoint bindings modified: true, default: map[url: cache: foo-bar: db-client: admin-api: db: logging-dir: monitoring-port:], old: map[], new: map[], result: map[db-client: admin-api: db: logging-dir: monitoring-port: url: cache: foo-bar:]
13:39:58 [LOG] 0:00.814 DEBUG juju.state new application "wordpress" added to backing state
13:39:58 [LOG] 0:00.864 DEBUG juju.state new unit "wordpress/0" added to backing state
13:39:58 [LOG] 0:00.867 INFO juju.state getting a public address for unit "wordpress/0" failed:
13:39:58 [LOG] 0:00.867 INFO juju.state getting a private address for unit "wordpress/0" failed:
13:39:58 [LOG] 0:00.911 INFO juju.state getting a public address for unit "wordpress/0" failed:
13:39:58 [LOG] 0:00.911 INFO juju.state getting a private address for unit "wordpress/0" failed:
13:39:58 [LOG] 0:00.924 DEBUG juju.state new unit "wordpress/1" added to backing state
13:39:58 [LOG] 0:00.927 INFO juju.state getting a public address for unit "wordpress/1" failed:
13:39:58 [LOG] 0:00.927 INFO juju.state getting a private address for unit "wordpress/1" failed:
13:39:58 [LOG] 0:00.979 INFO juju.state getting a public address for unit "wordpress/1" failed:
13:39:58 [LOG] 0:00.980 INFO juju.state getting a private address for unit "wordpress/1" failed:
13:39:58 [LOG] 0:01.064 DEBUG juju.state new unit "wordpress/2" added to backing state
13:39:58 [LOG] 0:01.066 INFO juju.state getting a public address for unit "wordpress/2" failed:
13:39:58 [LOG] 0:01.066 INFO juju.state getting a private address for unit "wordpress/2" failed:
13:39:58 [LOG] 0:01.080 DEBUG juju.charm charm is not in revision control directory
13:39:58 [LOG] 0:01.081 WARNING juju.charm making "/home/ubuntu/go/src/github.com/juju/juju/testcharms/charm-repo/quantal/mysql/hooks/install" executable in charm
13:39:58 [LOG] 0:01.081 WARNING juju.charm making "/home/ubuntu/go/src/github.com/juju/juju/testcharms/charm-repo/quantal/mysql/hooks/update-status" executable in charm
13:39:58 [LOG] 0:01.088 DEBUG juju.storage resource catalog entry created with id "ff16a20c112ef4f3fe47e022751ffb9502e6bd2069fd381a0ad74687672691a490f0844ed79138a0e49c054e679fac95"
13:39:58 [LOG] 0:01.096 DEBUG juju.storage managed resource entry created with path "buckets/deadbeef-0bad-400d-8000-4b1d0d06f00d/charms/local:quantal/mysql-1-461e62dd82dab4a5643a3056fa250221e65f676fbc76d9d5749e82a03abfe61c" -> "ff16a20c112ef4f3fe47e022751ffb9502e6bd2069fd381a0ad74687672691a490f0844ed79138a0e49c054e679fac95"
13:39:58 [LOG] 0:01.152 DEBUG juju.state merged endpoint bindings modified: true, default: map[metrics-client: server: server-admin:], old: map[], new: map[], result: map[server: server-admin: metrics-client:]
13:39:58 [LOG] 0:01.210 DEBUG juju.state new application "mysql" added to backing state
13:39:58 firewaller_test.go:80:
13:39:58 s.testWatch(c, s.firewaller, cannotWatchUnits)
13:39:58 /home/ubuntu/go/src/github.com/juju/juju/state/testing/watcher.go:94:
13:39:58 c.Fatalf("watcher sent unexpected change: (_, %v)", ok)
13:39:58 ... Error: watcher sent unexpected change: (_, true)
13:39:58
13:39:58 [LOG] 0:01.289 DEBUG juju.api RPC connection died
13:39:58 [LOG] 0:01.289 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:43955->127.0.0.1:56134: write: broken pipe
13:39:58 [LOG] 0:01.289 DEBUG juju.apiserver [1] user-admin API connection terminated after 919.876099ms
13:39:58 [LOG] 0:01.290 DEBUG juju.state closed state without error
13:39:58 [LOG] 0:01.290 INFO juju.provider.dummy reset model
13:39:58 [LOG] 0:01.290 DEBUG juju.provider.dummy closing httpServer
13:39:58 [LOG] 0:01.290 DEBUG juju.provider.dummy stopping apiServer
13:39:58 [LOG] 0:01.296 DEBUG juju.provider.dummy stopping modelCache worker
13:39:58 [LOG] 0:01.296 DEBUG juju.provider.dummy closing apiStatePool
13:39:58 [LOG] 0:01.297 DEBUG juju.state closed state without error
13:39:58 [LOG] 0:01.298 DEBUG juju.provider.dummy resetting MgoServer
13:39:58 [LOG] 0:01.307 INFO juju.testing reset successfully reset admin password
13:39:58 [LOG] 0:01.316 INFO juju.testing reset successfully reset admin password
13:39:58
13:39:58 ----------------------------------------------------------------------

[Canonical Juju QA Bot (juju-qa-bot)]

This bug has not been updated in 2 years, so we're marking it Low importance. If you believe this is incorrect, please update the importance.