hook failed: "identity-service-relation-changed" for keystone when connected to vault charm

[Ed Stewart]

Hi,

Successfully deploying an OpenStack environment mainly in LXD containers. Has been working successfully on a regular basis. We've now added vault into the bundle and linked to keystone plus some other services.

This reliably generates an error on keystone deploy with hook failed on "identity-service-relation-changed". The status of the model is this:

Model Controller Cloud/Region Version SLA Timestamp
xxxxx-ed-ssl2 google-controller google/us-east1 2.5.1 unsupported 09:31:05Z

App Version Status Scale Charm Store Rev OS Notes
aodh 6.0.1 active 1 aodh jujucharms 22 ubuntu
ceilometer 10.0.1 waiting 1 ceilometer jujucharms 258 ubuntu
ceilometer-agent 11.0.1 active 1 ceilometer-agent jujucharms 248 ubuntu
central-monitor active 1 nagios jujucharms 28 ubuntu
ceph-mon 13.2.4+dfsg1 active 3 ceph-mon jujucharms 31 ubuntu
ceph-osd 13.2.4+dfsg1 active 3 ceph-osd jujucharms 273 ubuntu
ceph-radosgw 13.2.4+dfsg1 active 1 ceph-radosgw jujucharms 263 ubuntu
cinder 13.0.2 active 1 cinder jujucharms 276 ubuntu
cinder-ceph 13.0.2 active 1 cinder-ceph jujucharms 238 ubuntu
dpcop-dashboard essex active 1 dpcop-dashboard local 0 ubuntu
glance 17.0.0 active 1 glance jujucharms 271 ubuntu
gnocchi 4.2.5 waiting 1 gnocchi jujucharms 16 ubuntu
grafana active 1 grafana jujucharms 23 ubuntu
keystone 14.0.1 error 1 keystone jujucharms 294 ubuntu
memcached active 1 memcached jujucharms 23 ubuntu
mongo-db 3.6.3 active 1 mongodb jujucharms 52 ubuntu
mysql 5.7.20-29.24 active 1 percona-cluster jujucharms 272 ubuntu
neutron-api 13.0.2 active 1 neutron-api jujucharms 266 ubuntu
neutron-gateway 13.0.2 active 1 neutron-gateway jujucharms 256 ubuntu
neutron-openvswitch 13.0.2 active 1 neutron-openvswitch jujucharms 255 ubuntu
nova-cloud-controller 18.0.3 active 1 nova-cloud-controller jujucharms 316 ubuntu
nova-compute 18.0.3 active 1 nova-compute jujucharms 293 ubuntu
ntp 3.2 active 2 ntp jujucharms 31 ubuntu
openstack-dashboard 14.0.1 waiting 1 openstack-dashboard local 32 ubuntu
prometheus active 1 prometheus jujucharms 7 ubuntu
prometheus-openstack-exporter active 1 prometheus-openstack-exporter jujucharms 6 ubuntu
rabbitmq-server 3.6.10 active 1 rabbitmq-server jujucharms 82 ubuntu
vault 1.0.3 active 1 vault jujucharms 12 ubuntu

Unit Workload Agent Machine Public address Ports Message
aodh/0* active idle 0/lxd/0 252.5.188.70 8042/tcp Unit is ready
ceilometer/0* waiting idle 0/lxd/1 252.5.185.186 Incomplete relations: database
central-monitor/0* active idle 0/lxd/2 252.5.184.115 80/tcp ready
ceph-mon/0 active idle 0/lxd/3 252.5.184.103 Unit is ready and clustered
ceph-mon/1 active idle 0/lxd/4 252.5.187.39 Unit is ready and clustered
ceph-mon/2* active idle 0/lxd/5 252.5.190.88 Unit is ready and clustered
ceph-osd/0 active idle 0/lxd/6 252.5.181.179 Unit is ready (3 OSD)
ceph-osd/1* active idle 0/lxd/7 252.5.188.135 Unit is ready (3 OSD)
ceph-osd/2 active idle 0/lxd/8 252.5.189.150 Unit is ready (3 OSD)
ceph-radosgw/0* active idle 0/lxd/9 252.5.180.19 80/tcp Unit is ready
cinder/0* active idle 0/lxd/10 252.5.180.221 8776/tcp Unit is ready
  cinder-ceph/0* active idle 252.5.180.221 Unit is ready
glance/0* active idle 0/lxd/11 252.5.178.243 9292/tcp Unit is ready
gnocchi/0* waiting idle 0/lxd/12 252.5.184.8 8041/tcp 'identity-service' incomplete
grafana/0* active idle 0/lxd/13 252.5.182.253 3000/tcp Started grafana-server
keystone/0* error idle 0/lxd/14 252.5.184.123 5000/tcp hook failed: "identity-service-relation-changed"
memcached/0* active idle 0/lxd/15 252.5.182.48 11211/tcp Unit is ready
mongo-db/0* active idle 0/lxd/16 252.5.185.214 27017/tcp,27019/tcp,27021/tcp,28017/tcp Unit is ready
mysql/0* active idle 0/lxd/17 252.5.186.143 3306/tcp Unit is ready
neutron-api/0* active idle 0/lxd/18 252.5.185.67 9696/tcp Unit is ready
neutron-gateway/0* active idle 0 35.231.102.68 Unit is ready
  ntp/0* active idle 35.231.102.68 123/udp chrony: Ready
nova-cloud-controller/0* active idle 0/lxd/19 252.5.183.216 8774/tcp,8775/tcp,8778/tcp Unit is ready
nova-compute/0* active idle 0/lxd/20 252.5.179.17 Unit is ready
  ceilometer-agent/0* active idle 252.5.179.17 Unit is ready
  neutron-openvswitch/0* active idle 252.5.179.17 Unit is ready
  ntp/1 active idle 252.5.179.17 123/udp chrony: Ready
openstack-dashboard/0* waiting idle 0/lxd/21 252.5.177.101 80/tcp,443/tcp Incomplete relations: identity
  dpcop-dashboard/0* active idle 252.5.177.101 Unit is ready
prometheus-openstack-exporter/0* active idle 0/lxd/23 252.5.188.30 Ready
prometheus/0* active idle 0/lxd/22 252.5.176.199 9090/tcp,12321/tcp Ready
rabbitmq-server/0* active idle 0/lxd/24 252.5.177.106 5672/tcp Unit is ready
vault/0* active idle 0/lxd/25 252.5.190.163 8200/tcp Unit is ready (active: true, mlock: disabled)

Machine State DNS Inst id Series AZ Message
0 started 35.231.102.68 juju-6ca089-0 bionic us-east1-b RUNNING
0/lxd/0 started 252.5.188.70 juju-6ca089-0-lxd-0 bionic us-east1-b Container started
0/lxd/1 started 252.5.185.186 juju-6ca089-0-lxd-1 bionic us-east1-b Container started
0/lxd/2 started 252.5.184.115 juju-6ca089-0-lxd-2 bionic us-east1-b Container started
0/lxd/3 started 252.5.184.103 juju-6ca089-0-lxd-3 bionic us-east1-b Container started
0/lxd/4 started 252.5.187.39 juju-6ca089-0-lxd-4 bionic us-east1-b Container started
0/lxd/5 started 252.5.190.88 juju-6ca089-0-lxd-5 bionic us-east1-b Container started
0/lxd/6 started 252.5.181.179 juju-6ca089-0-lxd-6 bionic us-east1-b Container started
0/lxd/7 started 252.5.188.135 juju-6ca089-0-lxd-7 bionic us-east1-b Container started
0/lxd/8 started 252.5.189.150 juju-6ca089-0-lxd-8 bionic us-east1-b Container started
0/lxd/9 started 252.5.180.19 juju-6ca089-0-lxd-9 bionic us-east1-b Container started
0/lxd/10 started 252.5.180.221 juju-6ca089-0-lxd-10 bionic us-east1-b Container started
0/lxd/11 started 252.5.178.243 juju-6ca089-0-lxd-11 bionic us-east1-b Container started
0/lxd/12 started 252.5.184.8 juju-6ca089-0-lxd-12 bionic us-east1-b Container started
0/lxd/13 started 252.5.182.253 juju-6ca089-0-lxd-13 bionic us-east1-b Container started
0/lxd/14 started 252.5.184.123 juju-6ca089-0-lxd-14 bionic us-east1-b Container started
0/lxd/15 started 252.5.182.48 juju-6ca089-0-lxd-15 bionic us-east1-b Container started
0/lxd/16 started 252.5.185.214 juju-6ca089-0-lxd-16 bionic us-east1-b Container started
0/lxd/17 started 252.5.186.143 juju-6ca089-0-lxd-17 bionic us-east1-b Container started
0/lxd/18 started 252.5.185.67 juju-6ca089-0-lxd-18 bionic us-east1-b Container started
0/lxd/19 started 252.5.183.216 juju-6ca089-0-lxd-19 bionic us-east1-b Container started
0/lxd/20 started 252.5.179.17 juju-6ca089-0-lxd-20 bionic us-east1-b Container started
0/lxd/21 started 252.5.177.101 juju-6ca089-0-lxd-21 bionic us-east1-b Container started
0/lxd/22 started 252.5.176.199 juju-6ca089-0-lxd-22 xenial us-east1-b Container started
0/lxd/23 started 252.5.188.30 juju-6ca089-0-lxd-23 xenial us-east1-b Container started
0/lxd/24 started 252.5.177.106 juju-6ca089-0-lxd-24 bionic us-east1-b Container started
0/lxd/25 started 252.5.190.163 juju-6ca089-0-lxd-25 xenial us-east1-b Container started

Note we are using the latest released vault and keystone charms.

The error in the juju unit-keystone-0.log:

2019-03-28 09:38:06 DEBUG identity-service-relation-changed requests.exceptions.ConnectionError: HTTPConnectionPool(host='localhost', port=35337): Max retries exceeded with url: /v3/services (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fc1341a8a58>: Failed to establish a new connection: [Errno 111] Connection refused',))
2019-03-28 09:38:06 DEBUG identity-service-relation-changed

... and it's failing to connect because Apache hasn't started with SSL:

Mar 28 08:26:47 juju-6ca089-0-lxd-14 (keystone.common.controller)[20915]: 2019-03-28 08:26:47,147 WARNING RBAC: Bypassing authorization
Mar 28 08:26:47 juju-6ca089-0-lxd-14 (keystone.middleware.auth)[20915]: 2019-03-28 08:26:47,161 WARNING The use of the '[DEFAULT] admin_token' configurationoption presents a significant security risk and should not b
Mar 28 08:26:47 juju-6ca089-0-lxd-14 (keystone.common.controller)[20915]: 2019-03-28 08:26:47,162 WARNING RBAC: Bypassing authorization
Mar 28 08:35:02 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 08:35:02,684 WARNING You are not authorized to perform the requested action.
Mar 28 08:45:02 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 08:45:02,895 WARNING You are not authorized to perform the requested action.
Mar 28 08:55:03 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 08:55:03,073 WARNING You are not authorized to perform the requested action.
Mar 28 09:05:03 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 09:05:03,251 WARNING You are not authorized to perform the requested action.
Mar 28 09:15:03 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 09:15:03,443 WARNING You are not authorized to perform the requested action.
Mar 28 09:25:04 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 09:25:04,021 WARNING You are not authorized to perform the requested action.
Mar 28 09:35:04 juju-6ca089-0-lxd-14 (keystone.common.wsgi)[20915]: 2019-03-28 09:35:04,215 WARNING You are not authorized to perform the requested action.

No SSL directory in /etc/apache2:

root@juju-6ca089-0-lxd-14:/etc/apache2# ls -ltr
total 80
-rw-r--r-- 1 root root 320 Oct 10 18:59 ports.conf
-rw-r--r-- 1 root root 31063 Oct 10 18:59 magic
-rw-r--r-- 1 root root 1782 Oct 10 18:59 envvars
-rw-r--r-- 1 root root 7224 Oct 10 18:59 apache2.conf
drwxr-xr-x 2 root root 4096 Mar 28 08:13 conf-available
drwxr-xr-x 2 root root 12288 Mar 28 08:13 mods-available
drwxr-xr-x 2 root root 4096 Mar 28 08:13 conf-enabled
drwxr-xr-x 2 root root 4096 Mar 28 08:14 sites-enabled
drwxr-xr-x 2 root root 4096 Mar 28 08:15 sites-available
drwxr-xr-x 2 root root 4096 Mar 28 08:27 mods-enabled

Sometimes we do see an SSL directory, but it only contains some of the certificates. In these cases Apache doesn't start at all because it's wsgi-openstack-api.conf references certs which aren't in the SSL directory.

Logs attached

[Chris MacNaughton (chris.macnaughton)]

Can we get a copy of this bundle, at least the parts including keystone and vault?

[Ed Stewart (emcs2)]

here you go:

series: bionic
applications:

..

  keystone:
    charm: cs:keystone-294
    num_units: 1
    to:
    - lxd:0
    options:
      admin-password: dpcopopenstack
      openstack-origin: cloud:bionic-rocky
      os-public-hostname: dev.xxxx.xxxx.xxxx.net
      worker-multiplier: 0.25
    annotations:
      gui-x: "500"
      gui-y: "0"

..

  vault:
    charm: cs:vault-12
    series: xenial
    num_units: 1
    to:
    - lxd:0
    options:
      auto-generate-root-ca-cert: true
      totally-unsecure-auto-unlock: true
    annotations:
      gui-x: "750"
      gui-y: "250"
machines:
  "0":
    constraints: root-disk=500000 instance-type=n1-highmem-16
relations:
 ...
- - vault:shared-db
  - mysql:shared-db
- - vault:certificates
  - keystone:certificates
- - keystone:shared-db
  - mysql:shared-db
 ...

BTW, I'm getting the same thing on this bundle too which we were using for other testing:

machines:
  '0':
    series: bionic
    constraints: "instance-type=n1-standard-4 root-disk=500000"
series: bionic
variables:
  #openstack-origin: &openstack-origin distro
  openstack-origin: &openstack-origin cloud:bionic-rocky
relations:
- - keystone:shared-db
  - mysql:shared-db
- - glance:shared-db
  - mysql:shared-db
- - glance:identity-service
  - keystone:identity-service
- - keystone
  - keystone-saml-mellon
- - vault:shared-db
  - mysql:shared-db
- - vault:certificates
  - keystone:certificates
- - vault:certificates
  - glance:certificates
- - vault:certificates
  - openstack-dashboard:certificates
- - openstack-dashboard
  - keystone-saml-mellon
- - keystone:websso-trusted-dashboard
  - openstack-dashboard:websso-trusted-dashboard
- - openstack-dashboard:identity-service
  - keystone:identity-service
applications:
  mysql:
    constraints: mem=3072M
    charm: cs:~openstack-charmers-next/percona-cluster
    num_units: 1
    options:
      source: *openstack-origin
    to:
    - lxd:0
  keystone:
    series: bionic
    charm: cs:~openstack-charmers-next/keystone
    num_units: 1
    options:
      openstack-origin: *openstack-origin
      token-provider: 'fernet'
      token-expiration: 60
      os-public-hostname: 'auth.xxxxvxx.customera.internal'
    to:
    - lxd:0
  keystone-saml-mellon:
    series: bionic
    charm: cs:~openstack-charmers-next/keystone-saml-mellon
    num_units: 0
    options:
      idp-name: 'samltest'
      protocol-name: 'mapped'
      user-facing-name: "samltest.id"
      subject-confirmation-data-address-check: False
      nameid-formats: "urn:oasis:names:tc:SAML:1.1:nameid-format:emailAddress"
    resources:
      idp-metadata: './IdP_metadata_xxxx_domain.xml'
      sp-signing-keyinfo: './http_openstack_dev.xxxxxxx_5000_JustKeyInfo.xml'
      sp-private-key: './http_openstack_dev.xxxxxxxx_5000.pem'
  glance:
    charm: cs:~openstack-charmers-next/glance
    num_units: 1
    options:
      openstack-origin: *openstack-origin
    to:
    - lxd:0
  vault:
    num_units: 1
    charm: cs:~openstack-charmers-next/vault
    options:
      # these options need changing for production
      auto-generate-root-ca-cert: true
      totally-unsecure-auto-unlock: true
    to:
    - lxd:0
  openstack-dashboard...

[Chris MacNaughton (chris.macnaughton)]

mhm, my more basic bundle didn't hit that:

series: bionic

applications:
  mysql:
    charm: cs:percona-cluster
    num_units: 1
  keystone:
    charm: cs:keystone
    num_units: 1
  glance:
    charm: cs:glance
    num_units: 1
  vault:
    charm: cs:vault
    num_units: 1

relations:
  - [ keystone:shared-db, mysql:shared-db ]
  - [ glance:shared-db, mysql:shared-db ]
  - [ keystone:identity-service, glance:identity-service ]

  - [ vault:shared-db, mysql ]

  - [ keystone, vault:certificates ]
  - [ glance, vault:certificates ]

I'm going to try your test bundle

[Chris MacNaughton (chris.macnaughton)]

This also does not reproduce if I remove keystone-saml-mellon from your testing bundle, so I suspect it's related to the SAML integration bits.

[Ed Stewart (emcs2)]

ok thanks - the first bundle (the big one) doesn't have keystone-saml-mellon involved yet though..... were you able to reproduce at all yet?

[Alex Kavanagh (ajkavanagh)]

There is a small, unrelated, bug in the manger.py code in that it doesn't detect the socket closing and crashes out if a None is received from the uds_client.receive():

    # endless loop whilst we process messages from the caller
    while True:
        try:
            data = uds_client.receive()
            if data == "QUIT":
                break
            spec = json.loads(data)

Essentially, this needs to be "if data is None or data == 'QUIT': break" and then the manager.py will quietly exit.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/648448

[Chris MacNaughton (chris.macnaughton)]

I have now reproduced it with the simpler bundle without SAML involved, but I'm going to have to hand this over to David Ames as I'm End of Day.

[David Ames (thedac)]

We appear to be using soon to be deprecated testing settings. The auto-generate and unlock introduce the tls-certificate relation during deploy time. Which seems to have discovered a race condition.

  vault:
    options:
      # these options need changing for production
      auto-generate-root-ca-cert: true
      totally-unsecure-auto-unlock: true

Since this is not considered production worthy, can we please test using the documented [0] actions for setting up certificates in Vault post-deployment?

We will keep this bug but at a lower priority. The deprecation notice for these settings will be in the 19.04 release.

[0] https://docs.openstack.org/project-deploy-guide/charm-deployment-guide/latest/app-certificate-management.html

[Ed Stewart (emcs2)]

Thanks for the quick response.

We can obviously work around auto-generate-root-ca-cert, however, totally-unsecure-auto-unlock is invaluable to us in our automated CI/CD test environments as it allows automated stack builds.

Are they both being deprecated?

[David Ames (thedac)]

Ed,

The actions are still trivial to automate. They could be run in bash or here is an example we use for CI/CD in our testing with python [0].

The critical point is that the vault certificates setup happen after the deploy has settled.

The bug, which we still intend to fix but at a lower priority, is that during deploy time changing from http to https is a race condition nightmare.

[0] https://github.com/openstack-charmers/zaza/blob/master/zaza/charm_tests/vault/setup.py#L57

[Ed Stewart (emcs2)]

Hi David,

Thanks - we've removed the auto-generate-root-ca-cert option and instead generate the root ca via action once the bundle is settled.

For the vault unlock, I'll go through your python and see how we can replicate the logic

Thanks

[Ed Stewart (emcs2)]

Sorry should have clarified - by removing the auto-generate-root-ca-cert we're no longer hitting the race condition as you proposed - thanks again for the advice.

[David Ames (thedac)]

Ed, glad to hear it is working.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/650919

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/648448
Committed: https://git.openstack.org/cgit/openstack/charm-keystone/commit/?id=299a9520031b1563be9c38218e8d352f1ed59832
Submitter: Zuul
Branch: master

commit 299a9520031b1563be9c38218e8d352f1ed59832
Author: Alex Kavanagh <email address hidden>
Date: Thu Mar 28 15:56:18 2019 +0000

    Ensure that manager.py exits cleanly if charm closes socket

    In the related bug, the manager.py was crashing as it received
    (essentially) a socket close which resulted in no data being received.
    This wasn't handled properly resulting in a crash in the manager.py.
    This change simply allows the manager.py to exit cleanly, and the charm
    can restart it if it needs to.

    Change-Id: I76a435f48cdb8c201b0ddc529da947e6ed9ec031
    Related-Bug: #1822063

[Ryan Beisner (1chb1n)]

See related: https://bugs.launchpad.net/charm-keystone/+bug/1823743

[Alireza Nasri (sysnasri)]

I don't know this bug is related to my problem or not, unfortunately I cannot find out any workaround with my problem which is similar to this bug.

 return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python3/dist-packages/keystoneauth1/session.py", line 968, in request
    raise exceptions.from_response(resp, method, url)
keystoneauth1.exceptions.http.NotFound: Not Found (HTTP 404)
Traceback (most recent call last):
  File "./hooks/identity-service-relation-changed", line 935, in <module>
    main()
  File "./hooks/identity-service-relation-changed", line 928, in main
    hooks.execute(sys.argv)
  File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/hookenv.py", line 945, in execute
    self._hooks[hook_name]()
  File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1718, in wrapped_f
    return restart_on_change_helper(
  File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/host.py", line 747, in restart_on_change_helper
    r = lambda_f()
  File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1719, in <lambda>
    (lambda: f(*args, **kwargs)), __restart_map_cache['cache'],
  File "./hooks/identity-service-relation-changed", line 445, in identity_changed
    add_service_to_keystone(relation_id, remote_unit)
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1836, in add_service_to_keystone
    add_endpoint(region=settings['region'],
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 2046, in add_endpoint
    create_service_entry(service, service_type, desc)
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 985, in create_service_entry
    for service in manager.list_services():
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1200, in __call__
    return _proxy_manager_call(self._path, self.api_version, args, kwargs)
  File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/decorators.py", line 40, in _retry_on_exception_inner_2
    return f(*args, **kwargs)
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1244, in _proxy_manager_call
    raise e
  File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1238, in _proxy_manager_call
    raise RuntimeError(s)
RuntimeError: The call within manager.py failed with the error: 'Not Found (HTTP 404)'. The call was: path=['list_services'], args=(), kwargs={}, api_version=None

[David Ames (thedac)]

This bug may still exist. The workaround from comment #10 is confirmed in comments #13 and #14. This goes into the bucket of race condition bugs that occur when a service is accessed *during* deploy time. The low priority still seems correct. Removing myself as assignee.

[Alan Baghumian (alanbach)]

I encountered this exact same trace & error after adding an removing vertificates relationship with HA keystone (20.0.1) Focal/Xena charm rev. 608.

Only one out of 3 units started having this issue and the final solution was to remove the problematic unit and deploy a fresh one.