OpenStack Keystone Charm

"shared-db-relation-changed" failed: exit status 1

Bug #1768236 reported by Chris Gregan on 2018-05-01

This bug report is a duplicate of: Bug #1775682: percona cluster completes client db relations before it has finished clustering. Edit Remove

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Keystone Charm	Invalid	Undecided	Unassigned

Bug Description

2018-05-01 04:05:58 DEBUG juju-log shared-db:64: Creating service credentials for 'gnocchi'
2018-05-01 04:05:59 DEBUG shared-db-relation-changed Traceback (most recent call last):
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 881, in <module>
2018-05-01 04:05:59 DEBUG shared-db-relation-changed main()
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 874, in main
2018-05-01 04:05:59 DEBUG shared-db-relation-changed hooks.execute(sys.argv)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/hookenv.py", line 801, in execute
2018-05-01 04:05:59 DEBUG shared-db-relation-changed self._hooks[hook_name]()
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1449, in wrapped_f
2018-05-01 04:05:59 DEBUG shared-db-relation-changed restart_functions)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/host.py", line 730, in restart_on_change_helper
2018-05-01 04:05:59 DEBUG shared-db-relation-changed r = lambda_f()
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1448, in <lambda>
2018-05-01 04:05:59 DEBUG shared-db-relation-changed (lambda: f(*args, **kwargs)), restart_map, stopstart,
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1810, in inner_synchronize_ca_if_changed2
2018-05-01 04:05:59 DEBUG shared-db-relation-changed ret = f(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 421, in db_changed
2018-05-01 04:05:59 DEBUG shared-db-relation-changed leader_init_db_if_ready(use_current_context=True)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 409, in leader_init_db_if_ready
2018-05-01 04:05:59 DEBUG shared-db-relation-changed update_all_identity_relation_units(check_db_ready=False)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 362, in update_all_identity_relation_units
2018-05-01 04:05:59 DEBUG shared-db-relation-changed identity_changed(relation_id=rid, remote_unit=unit)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1449, in wrapped_f
2018-05-01 04:05:59 DEBUG shared-db-relation-changed restart_functions)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/host.py", line 730, in restart_on_change_helper
2018-05-01 04:05:59 DEBUG shared-db-relation-changed r = lambda_f()
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1448, in <lambda>
2018-05-01 04:05:59 DEBUG shared-db-relation-changed (lambda: f(*args, **kwargs)), restart_map, stopstart,
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1810, in inner_synchronize_ca_if_changed2
2018-05-01 04:05:59 DEBUG shared-db-relation-changed ret = f(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 450, in identity_changed
2018-05-01 04:05:59 DEBUG shared-db-relation-changed add_service_to_keystone(relation_id, remote_unit)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 2111, in add_service_to_keystone
2018-05-01 04:05:59 DEBUG shared-db-relation-changed new_roles=roles)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1985, in create_service_credentials
2018-05-01 04:05:59 DEBUG shared-db-relation-changed domain=domain)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1931, in create_user_credentials
2018-05-01 04:05:59 DEBUG shared-db-relation-changed create_user(user, passwd, tenant=tenant, domain=domain)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 980, in create_user
2018-05-01 04:05:59 DEBUG shared-db-relation-changed domain_id=domain_id)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/manager.py", line 247, in create_user
2018-05-01 04:05:59 DEBUG shared-db-relation-changed project=tenant_id)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/debtcollector/renames.py", line 45, in wrapper
2018-05-01 04:05:59 DEBUG shared-db-relation-changed return f(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2018-05-01 04:05:59 DEBUG shared-db-relation-changed return wrapped(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/v3/users.py", line 95, in create
2018-05-01 04:05:59 DEBUG shared-db-relation-changed log=not bool(password))
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/base.py", line 174, in _post
2018-05-01 04:05:59 DEBUG shared-db-relation-changed resp, body = self.client.post(url, body=body, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 294, in post
2018-05-01 04:05:59 DEBUG shared-db-relation-changed return self.request(url, 'POST', **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 447, in request
2018-05-01 04:05:59 DEBUG shared-db-relation-changed resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 192, in request
2018-05-01 04:05:59 DEBUG shared-db-relation-changed return self.session.request(url, method, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2018-05-01 04:05:59 DEBUG shared-db-relation-changed return wrapped(*args, **kwargs)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 445, in request
2018-05-01 04:05:59 DEBUG shared-db-relation-changed raise exceptions.from_response(resp, method, url)
2018-05-01 04:05:59 DEBUG shared-db-relation-changed keystoneauth1.exceptions.http.InternalServerError: An unexpected error prevented the server from fulfilling your request. (HTTP 500) (Request-ID: req-c2531fa3-2255-4fae-a568-4d063f2140cd)
2018-05-01 04:05:59 ERROR juju.worker.uniter.operation runhook.go:114 hook "shared-db-relation-changed" failed: exit status 1

Tags:

Revision history for this message

Chris Gregan (cgregan) wrote on 2018-05-01:

juju-crashdump-52c7d173-5f53-4224-86fc-4a3007acff5c.tar.gz Edit (20.2 MiB, application/x-tar)

tags:

added: cdo-qa foundations-engine

Revision history for this message

Ante Karamatić (ivoks) wrote on 2018-06-06:

Download full text (4.4 KiB)

500 indicates problem with keystone. Keystone logs show:

(keystone.common.wsgi): 2018-05-01 04:05:59,108 ERROR (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')

Percona cluster (mysql/0) logs show that there were some actions going on at 04:05:58:

2018-05-01 04:05:58 82734 [Note] WSREP: declaring c1e0afc6 at tcp://192.168.33.158:4567 stable
2018-05-01 04:05:58 82734 [Note] WSREP: forgetting 999ff7f0 (tcp://192.168.33.160:4567)
2018-05-01 04:05:58 82734 [Note] WSREP: Node c1e0afc6 state prim
2018-05-01 04:05:58 82734 [Note] WSREP: view(view_id(PRIM,c1e0afc6,8) memb {
        c1e0afc6,0
        f91ae7d1,0
} joined {
} left {
} partitioned {
        999ff7f0,0
})
2018-05-01 04:05:58 82734 [Note] WSREP: save pc into disk
2018-05-01 04:05:58 82734 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2018-05-01 04:05:58 82734 [Note] WSREP: forgetting 999ff7f0 (tcp://192.168.33.160:4567)
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: sent state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: got state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca from 0 (juju-1839c4-12-lxd-7)
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: got state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca from 1 (juju-1839c4-0-lxd-6)
2018-05-01 04:05:58 82734 [Note] WSREP: Quorum results:
        version = 4,
        component = PRIMARY,
        conf_id = 7,
        members = 2/2 (joined/total),
        act_id = 1478,
        last_appl. = 1368,
        protocols = 0/7/3 (gcs/repl/appl),
        group UUID = 89685d15-4cf2-11e8-a960-5e0ce42b3022
2018-05-01 04:05:58 82734 [Note] WSREP: Flow-control interval: [23, 23]
2018-05-01 04:05:58 82734 [Note] WSREP: Trying to continue unpaused monitor
2018-05-01 04:05:58 82734 [Note] WSREP: New cluster view: global state: 89685d15-4cf2-11e8-a960-5e0ce42b3022:1478, view# 8: Primary, number of nodes: 2, my index: 1, protocol version 3
2018-05-01 04:05:58 82734 [Note] WSREP: Setting wsrep_ready to true
2018-05-01 04:05:58 82734 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2018-05-01 04:05:58 82734 [Note] WSREP: REPL Protocols: 7 (3, 2)
2018-05-01 04:05:58 82734 [Note] WSREP: Assign initial position for certification: 1478, protocol version: 3
2018-05-01 04:05:58 82734 [Note] WSREP: Service thread queue flushed.

mysql/1, which was primary mysql node at this time, shows that it was restarted:

500 indicates problem with keystone. Keystone logs show:

(keystone.common.wsgi): 2018-05-01 04:05:59,108 ERROR (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query')

Percona cluster (mysql/0) logs show that there were some actions going on at 04:05:58:

2018-05-01 04:05:58 82734 [Note] WSREP: declaring c1e0afc6 at tcp://192.168.33.158:4567 stable
2018-05-01 04:05:58 82734 [Note] WSREP: forgetting 999ff7f0 (tcp://192.168.33.160:4567)
2018-05-01 04:05:58 82734 [Note] WSREP: Node c1e0afc6 state prim
2018-05-01 04:05:58 82734 [Note] WSREP: view(view_id(PRIM,c1e0afc6,8) memb {
        c1e0afc6,0
        f91ae7d1,0
} joined {
} left {
} partitioned {
        999ff7f0,0
})
2018-05-01 04:05:58 82734 [Note] WSREP: save pc into disk
2018-05-01 04:05:58 82734 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2018-05-01 04:05:58 82734 [Note] WSREP: forgetting 999ff7f0 (tcp://192.168.33.160:4567)
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: sent state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: got state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca from 0 (juju-1839c4-12-lxd-7)
2018-05-01 04:05:58 82734 [Note] WSREP: STATE EXCHANGE: got state msg: f449b8b8-4cf4-11e8-b9ad-e6663299fcca from 1 (juju-1839c4-0-lxd-6)
2018-05-01 04:05:58 82734 [Note] WSREP: Quorum results:
        version    = 4,
        component  = PRIMARY,
        conf_id    = 7,
        members    = 2/2 (joined/total),
        act_id     = 1478,
        last_appl. = 1368,
        protocols  = 0/7/3 (gcs/repl/appl),
        group UUID = 89685d15-4cf2-11e8-a960-5e0ce42b3022
2018-05-01 04:05:58 82734 [Note] WSREP: Flow-control interval: [23, 23]
2018-05-01 04:05:58 82734 [Note] WSREP: Trying to continue unpaused monitor
2018-05-01 04:05:58 82734 [Note] WSREP: New cluster view: global state: 89685d15-4cf2-11e8-a960-5e0ce42b3022:1478, view# 8: Primary, number of nodes: 2, my index: 1, protocol version 3
2018-05-01 04:05:58 82734 [Note] WSREP: Setting wsrep_ready to true
2018-05-01 04:05:58 82734 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2018-05-01 04:05:58 82734 [Note] WSREP: REPL Protocols: 7 (3, 2)
2018-05-01 04:05:58 82734 [Note] WSREP: Assign initial position for certification: 1478, protocol version: 3
2018-05-01 04:05:58 82734 [Note] WSREP: Service thread queue flushed.

mysql/1, which was primary mysql node at this time, shows that it was restarted:

2018-05-01 04:05:58 33361 [Note] /usr/sbin/mysqld: Normal shutdown
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 452
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 464
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 432
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 360
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 493
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 494
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 489
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 490
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 488
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 492
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 485
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 486
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 411
2018-05-01 04:06:00 33361 [Note] WSREP: killing local connection: 487
...
2018-05-01 04:06:04 33361 [Note] /usr/sbin/mysqld: Shutdown complete

This restart seems to be initiated by systemd:

May  1 04:05:58 juju-1839c4-1-lxd-7 systemd[1]: Stopping LSB: Start and stop the mysql (Percona XtraDB Cluster) daemon...
May  1 04:05:58 juju-1839c4-1-lxd-7 mysql[147667]:  * Stopping MySQL (Percona XtraDB Cluster) mysqld

There haven't been pacemaker related actions at that time. What is interesting on mysql/1 is:

2018-05-01 04:05:54 DEBUG juju.worker.uniter.remotestate watcher.go:504 got a relation units change: {151 {map[telegraf/60:{0}] []}}

telegraf/60 was running on one of openstack-dashboard units. Looking at the relations, it seems that telegraf is using the wrong relation to mysql:

telegraf:
...
      mysql:
      - mysql

Should it not be juju-info relation, like all other services (note that mongodb is also wrong)?

Revision history for this message

Chris Gregan (cgregan) wrote on 2018-06-11:

juju-crashdump-6467f0cd-47f3-4138-bc87-0ecd1500e74a.tar.gz Edit (20.1 MiB, application/x-tar)

Reproduced in Xenial/Queens this past weekend

Revision history for this message

Chris Gregan (cgregan) wrote on 2018-06-11:

Bionic/Queens reproduction Edit (66.7 MiB, application/x-tar)

Revision history for this message

David Ames (thedac) wrote on 2018-06-11:

Download full text (3.2 KiB)

This is a race condition that is a duplicate of
https://bugs.launchpad.net/charm-hacluster/+bug/1775682

I'll summarize here but we will perform the work on 1775682

The race:

Keystone traces making connections to percona cluster at 18:24:
keystone_2/var/log/juju/unit-keystone-2.log:2018-06-09 18:24:59 DEBUG shared-db-relation-changed Traceback (most recent call last):

At this time the lead percona node is happily running shared-db-relation hooks:
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:41 DEBUG juju.worker.uniter.operation executor.go:91 preparing operation "run relation-changed (87; heat/2) hook"
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:41 DEBUG juju.worker.uniter.operation executor.go:91 executing operation "run relation-changed (87; heat/2) hook"
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:50 DEBUG juju.worker.uniter.operation executor.go:91 committing operation "run relation-changed (87; heat/2) hook"
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:50 DEBUG juju.worker.uniter.operation executor.go:60 running operation run relation-changed (114; openstack-dashboard/1) hook
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:50 DEBUG juju.worker.uniter.operation executor.go:91 preparing operation "run relation-changed (114; openstack-dashboard/1) hook"
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:50 DEBUG juju.worker.uniter.operation executor.go:91 executing operation "run relation-changed (114; openstack-dashboard/1) hook"
mysql_0/var/log/juju/unit-mysql-0.log:2018-06-09 18:24:59 DEBUG juju.worker.uniter.operation executor.go:91 committing operation "run relation-changed (114; openstack-dashboard/1) hook"

However the two non-leader nodes are completing their clustering. The deubg log makes this slightly opaque but here are the highlights:

mysql_1/var/log/juju/unit-mysql-1.log:2018-06-09 18:24:24 DEBUG juju.worker.uniter.operation executor.go:60 running operation run leader-settings-changed hook
mysql_1/var/log/juju/unit-mysql-1.log:2018-06-09 18:24:24 DEBUG juju.worker.uniter.operation executor.go:91 preparing operation "run leader-settings-changed hook"
mysql_1/var/log/juju/unit-mysql-1.log:2018-06-09 18:24:24 DEBUG juju.worker.uniter.operation executor.go:91 executing operation "run leader-settings-changed hook"
mysql_1/var/log/juju/unit-mysql-1.log:2018-06-09 18:24:28 DEBUG juju-log Waiting 30 seconds for operation ...

mysql_2/var/log/juju/unit-mysql-2.log:2018-06-09 18:23:40 DEBUG juju.worker.uniter.operation executor.go:60 running operation run leader-settings-changed hook
mysql_2/var/log/juju/unit-mysql-2.log:2018-06-09 18:23:40 DEBUG juju.worker.uniter.operation executor.go:91 preparing operation "run leader-settings-changed hook"
mysql_2/var/log/juju/unit-mysql-2.log:2018-06-09 18:23:40 DEBUG juju.worker.uniter.operation executor.go:91 executing operation "run leader-settings-changed hook"
mysql_2/var/log/juju/unit-mysql-2.log:2018-06-09 18:23:45 DEBUG juju-log Waiting 60 seconds for operation ...

The Waiting nn seconds for operation is our hint. At the end of that wait period mysql will restart. Depending on where the VIP is located this will lead to broken mysq...

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

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

Changed in charm-keystone:
status:	New → Invalid