Lost relation data after juju killing upgrader/uniter on state connection lost.
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
juju-core |
Invalid
|
Medium
|
Unassigned |
Bug Description
[Environment details]
Juju-version: juju-1.
Ubuntu version: Trusty
[Reproduction steps]
I was unable to reproduce this exact behavior on juju-core 1.20.1
$ juju --show-log boostrap -e local -v
$ juju deploy keystone
$ juju deploy mysql
$ juju add-relation keystone mysql
$ juju ssh keystone:
ubuntu# grep connection /etc/keystone/
connection = mysql:/
Then force the jujud teardown:
$ service juju-agent-local stop
$[...]
The shutdown is noticed by the unit,
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.state.
unit-mysql-0: message repeated 10 times: [2014-08-13 19:52:36 ERROR juju.state.
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker.
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "logger": connection is shut down
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "upgrader": connection is shut down
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "apiaddressupda
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "uniter": connection is shut down
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "rsyslog": connection is shut down
unit-mysql-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:218 exited "api": connection is shut down
unit-mysql-0: 2014-08-13 19:52:39 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-mysql-0: 2014-08-13 19:52:42 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-mysql-0: 2014-08-13 19:52:45 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-mysql-0: 2014-08-13 19:52:48 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
Then the workers are restarted and the config-changed event is triggered:
unit-keystone-0: 2014-08-13 19:52:59 INFO juju-log Migrating the keystone database.
unit-keystone-0: 2014-08-13 19:52:59 INFO config-changed keystone stop/waiting
unit-keystone-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "uniter": connection is shut down
unit-keystone-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:207 fatal "rsyslog": connection is shut down
unit-keystone-0: 2014-08-13 19:52:36 ERROR juju.worker runner.go:218 exited "api": connection is shut down
unit-keystone-0: 2014-08-13 19:52:39 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-keystone-0: 2014-08-13 19:52:42 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-keystone-0: 2014-08-13 19:52:45 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-keystone-0: 2014-08-13 19:52:48 ERROR juju.worker runner.go:218 exited "api": unable to connect to "wss://
unit-keystone-0: 2014-08-13 19:53:00 INFO config-changed keystone start/running, process 4972
$ grep connection /etc/keystone/
connection = mysql:/
==================
This last step returns None, on juju-core 1.18.1, this relation data is populated by the keystone charm using
'database_host': relation_
[Summary]
1) For some undefined reason the agent lost connection with the state.
*juju.cmd.jujud agent.go:137 error pinging *api.State: connection is shut down
2) Then a 'environment change' event is triggered
* juju.worker.uniter uniter.go:747 new environment change
3) Juju kills uniter, upgrader, logger workers
4) Then the connection is restablished:
* juju apiclient.go:124 state/api: connection established
5) Then juju starts again the upgrader/uniter workers
* runner.go:262 worker: start "uniter" [..]
6) All the relations are joined again
* 2014-08-12 11:05:15 INFO juju.worker.uniter uniter.go:690 joining relation "glance:cluster"
7) And finally a config-changed event is triggered
* 2014-08-12 11:05:18 INFO juju.worker.uniter modes.go:382 ModeConfigChanged starting
[Issues]
- After this final config-changed event, the relation data that had been set previously ( database credentials ) has been lost, so the resulting configuration files written by the charms (that uses relation_get) have erroneous values ( empty strings ).
[ Logs ]
2014-08-12 10:50:58 INFO juju.worker.
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 ERROR juju watcher.go:66 state/api: error trying to stop watcher connection is shut down
2014-08-12 11:05:00 DEBUG juju.worker.uniter uniter.go:747 new environment change
2014-08-12 11:05:00 DEBUG juju.worker.
2014-08-12 11:05:00 ERROR juju.worker.
2014-08-12 11:05:00 INFO juju.cmd.jujud agent.go:137 error pinging *api.State: connection is shut down
2014-08-12 11:05:00 ERROR juju runner.go:209 worker: fatal "upgrader": watcher iteration error: EOF
2014-08-12 11:05:00 DEBUG juju runner.go:243 worker: killing "logger"
2014-08-12 11:05:00 DEBUG juju runner.go:243 worker: killing "uniter"
2014-08-12 11:05:00 DEBUG juju runner.go:243 worker: killing "rsyslog"
2014-08-12 11:05:00 INFO juju.cmd.jujud agent.go:137 error pinging *api.State: connection is shut down
2014-08-12 11:05:00 ERROR juju runner.go:209 worker: fatal "logger": watcher iteration error: EOF
2014-08-12 11:05:00 DEBUG juju.worker.uniter modes.go:384 ModeAbide exiting
2014-08-12 11:05:00 INFO juju.worker.uniter uniter.go:141 unit "glance/1" shutting down: tomb: dying
2014-08-12 11:05:00 DEBUG juju.worker.uniter runlistener.go:97 juju-run listener stopping
2014-08-12 11:05:00 DEBUG juju.worker.uniter runlistener.go:117 juju-run listener stopped
2014-08-12 11:05:00 INFO juju.cmd.jujud agent.go:137 error pinging *api.State: connection is shut down
2014-08-12 11:05:00 ERROR juju runner.go:209 worker: fatal "uniter": watcher iteration error: EOF
2014-08-12 11:05:00 INFO juju.cmd.jujud agent.go:137 error pinging *api.State: connection is shut down
2014-08-12 11:05:00 ERROR juju runner.go:209 worker: fatal "rsyslog": watcher iteration error: EOF
2014-08-12 11:05:00 INFO juju.rpc server.go:295 error closing codec: write tcp 10.30.0.101:17070: connection reset by peer
2014-08-12 11:05:00 ERROR juju runner.go:220 worker: exited "api": watcher iteration error: EOF
2014-08-12 11:05:00 INFO juju runner.go:254 worker: restarting "api" in 3s
2014-08-12 11:05:03 INFO juju runner.go:262 worker: start "api"
2014-08-12 11:05:03 INFO juju apiclient.go:114 state/api: dialing "wss://
2014-08-12 11:05:03 ERROR juju apiclient.go:119 state/api: websocket.Dial wss://10.
2014-08-12 11:05:03 ERROR juju runner.go:220 worker: exited "api": websocket.Dial wss://10.
2014-08-12 11:05:03 INFO juju runner.go:254 worker: restarting "api" in 3s
2014-08-12 11:05:06 INFO juju runner.go:262 worker: start "api"
2014-08-12 11:05:06 INFO juju apiclient.go:114 state/api: dialing "wss://
2014-08-12 11:05:06 INFO juju apiclient.go:124 state/api: connection established
2014-08-12 11:05:08 INFO juju runner.go:262 worker: start "upgrader"
2014-08-12 11:05:08 INFO juju runner.go:262 worker: start "logger"
2014-08-12 11:05:08 DEBUG juju.worker.logger logger.go:35 initial log config: "<root>
2014-08-12 11:05:08 INFO juju runner.go:262 worker: start "uniter"
2014-08-12 11:05:08 DEBUG juju.worker.logger logger.go:60 logger setup
2014-08-12 11:05:08 INFO juju runner.go:262 worker: start "rsyslog"
2014-08-12 11:05:08 DEBUG juju.worker.rsyslog worker.go:76 starting rsyslog worker mode 1 for "unit-glance-1" ""
2014-08-12 11:05:09 DEBUG juju.worker.rsyslog worker.go:168 Reloading rsyslog configuration
2014-08-12 11:05:12 INFO juju.worker.
2014-08-12 11:05:15 INFO juju.worker.
2014-08-12 11:05:15 INFO juju.worker.uniter uniter.go:690 joining relation "glance:cluster"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "glance:cluster"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "r2-compute:
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "r2-compute:
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "nova-cloud-
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "nova-cloud-
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "glance:ceph r1-mon:client"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "glance:ceph r1-mon:client"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "cinder:
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "cinder:
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "glance:shared-db mysql:shared-db"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "glance:shared-db mysql:shared-db"
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "glance:amqp rabbitmq-
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:716 joined relation "glance:amqp rabbitmq-
2014-08-12 11:05:16 INFO juju.worker.uniter uniter.go:690 joining relation "r1-compute:
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:716 joined relation "r1-compute:
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:690 joining relation "glance:ha hacluster-
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:716 joined relation "glance:ha hacluster-
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:690 joining relation "glance:
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:716 joined relation "glance:
2014-08-12 11:05:17 DEBUG juju.worker.uniter uniter.go:217 starting juju-run listener on unix:/var/
2014-08-12 11:05:17 INFO juju.worker.uniter uniter.go:112 unit "glance/1" started
2014-08-12 11:05:17 DEBUG juju.worker.uniter runlistener.go:84 juju-run listener running
2014-08-12 11:05:18 INFO juju.worker.uniter modes.go:382 ModeContinue starting
2014-08-12 11:05:18 INFO juju.worker.uniter modes.go:31 loading uniter state
2014-08-12 11:05:18 INFO juju.worker.uniter modes.go:48 continuing after "config-changed" hook
2014-08-12 11:05:18 DEBUG juju.worker.uniter modes.go:384 ModeContinue exiting
2014-08-12 11:05:18 INFO juju.worker.uniter modes.go:382 ModeConfigChanged starting
2014-08-12 11:05:18 DEBUG juju.worker.uniter uniter.go:747 new environment change
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 INFO juju.utils.fslock fslock.go:146 attempted lock failed "uniter-
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:18 DEBUG juju.worker.
2014-08-12 11:05:19 INFO juju.worker.uniter uniter.go:480 running "config-changed" hook
2014-08-12 11:05:19 INFO config-changed
description: | updated |
description: | updated |
Changed in juju-core: | |
importance: | High → Medium |
milestone: | next-stable → none |
tags: | added: sts |
This issue may be fixed. We will want to review this bug again to determine if it no longer affects 1.20 and 1.21.