Keystone service temporarily unavailable during rally

[Jason Hobbs]

A rally test for nova.delete_servers failed with this error:

 Fault: {'code': 500, 'created': '2020-09-07T08:52:03Z', 'message': 'Failed to delete allocations for consumer d6b9450f-7058-4fc4-b4de-69b2179997d6. Error: {"message": "The server is currently unavailable. Please try again at a later time.<br /><br />\\nThe Keystone service is temporarily unavailable.\\n\\n", "code": "503 Ser'}

https://solutions.qa.canonical.com/openstack/testRun/62b248a3-c889-44d5-a21e-3b258a053488

[Michael Skalka (mskalka)]

Saw again with this run: https://solutions.qa.canonical.com/openstack/testRun/64429282-ba38-4a59-9e1f-523c3abd8acf

Keystone logs are full of:

(keystone.server.flask.application): 2020-09-15 17:10:13,479 WARNING Could not find domain: admin_domain.
...
(keystone.server.flask.application): 2020-09-15 17:12:38,122 WARNING Could not find domain: Default.
...
(py.warnings): 2020-09-15 17:10:14,728 WARNING /usr/lib/python3/dist-packages/oslo_policy/policy.py:1007: UserWarning: Policy identity:create_grant failed scope check. The token used to make the request
was project scoped but the policy requires ['system', 'domain'] scope. This behavior may change in the future where using the intended scope is required
  warnings.warn(msg)
...

[John George (jog)]

Hit this another time in https://solutions.qa.canonical.com/openstack/testRun/42db1cfa-7240-415e-92ae-d2cf540f9675

[John George (jog)]

Subscribed to field high, as we're running into this bug on a regular basis.

[John George (jog)]

We see rally tests fail when this bug is present. In the latest test run both glance and Octavia tests failed while calling into python3.6/site-packages/keystoneauth1/session.py.

The keystone log on the juju unit is filled with the following messages and not mush else.
(keystone.server.flask.application): 2020-09-23 12:30:43,825 WARNING Could not find domain: admin_domain.
(keystone.server.flask.application): 2020-09-23 12:30:45,130 WARNING Could not find domain: admin_domain.
(py.warnings): 2020-09-23 12:30:48,151 WARNING /usr/lib/python3/dist-packages/oslo_policy/policy.py:1007: UserWarning: Policy identity:list_grants failed scope check. The token used to make the request was project scoped but the policy requires ['system', 'domain'] scope. This behavior may change in the future where using the intended scope is required
  warnings.warn(msg)

The juju crashdump is available at the following link:
https://oil-jenkins.canonical.com/artifacts/42db1cfa-7240-415e-92ae-d2cf540f9675/generated/generated/juju_maas_controller/juju-crashdump-controller-2020-09-23-12.43.15.tar.gz

The bundle is available at:
https://oil-jenkins.canonical.com/artifacts/42db1cfa-7240-415e-92ae-d2cf540f9675/config/config/bundle.yaml

Overlays to the bundle are:
https://oil-jenkins.canonical.com/artifacts/42db1cfa-7240-415e-92ae-d2cf540f9675/config/config/openstack_versioned_overlay.yaml
https://oil-jenkins.canonical.com/artifacts/42db1cfa-7240-415e-92ae-d2cf540f9675/config/config/overlay-hostnames.yaml

All test logs and artifacts can be found at the bottom of the test run pages posted in previous comments through the link titled "Click here to view full artifacts repository for this test run
"

[John George (jog)]

We hit an instance of this bug prior to rally. In this case the deployment was waiting for all units to settle but openstack-service-checks error'd trying to communicate with Keystone.
https://solutions.qa.canonical.com/openstack/testRun/a02cc863-6874-45e4-9e6e-9ea5950b9a12

[John George (jog)]

keystone-manage.log has the following error:

CRITICAL keystone [-] Unhandled error: oslo_db.exception.DBNonExistentTable: (sqlite3.OperationalError) no such table: credential
[SQL: SELECT credential.encrypted_blob AS credential_encrypted_blob, credential.id AS credential_id, credential.user_id AS credential_user_id, credential.project_id AS credential_project_id, credential.type AS credential_type, credential.key_hash AS credential_key_hash, credential.extra AS credential_extra
FROM credential]
(Background on this error at: http://sqlalche.me/e/e3q8)
2020-09-25 22:06:58.834 22172 ERROR keystone Traceback (most recent call last):
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1246, in _execute_context
2020-09-25 22:06:58.834 22172 ERROR keystone cursor, statement, parameters, context
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 581, in do_execute
2020-09-25 22:06:58.834 22172 ERROR keystone cursor.execute(statement, parameters)
2020-09-25 22:06:58.834 22172 ERROR keystone sqlite3.OperationalError: no such table: credential
2020-09-25 22:06:58.834 22172 ERROR keystone
2020-09-25 22:06:58.834 22172 ERROR keystone The above exception was the direct cause of the following exception:
2020-09-25 22:06:58.834 22172 ERROR keystone
2020-09-25 22:06:58.834 22172 ERROR keystone Traceback (most recent call last):
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/bin/keystone-manage", line 10, in <module>
2020-09-25 22:06:58.834 22172 ERROR keystone sys.exit(main())
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/cmd/manage.py", line 41, in main
2020-09-25 22:06:58.834 22172 ERROR keystone cli.main(argv=sys.argv, developer_config_file=developer_config)
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/cmd/cli.py", line 1379, in main
2020-09-25 22:06:58.834 22172 ERROR keystone CONF.command.cmd_class.main()
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/cmd/cli.py", line 780, in main
2020-09-25 22:06:58.834 22172 ERROR keystone klass.migrate_credentials()
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/cmd/cli.py", line 753, in migrate_credentials
2020-09-25 22:06:58.834 22172 ERROR keystone driver_hints.Hints()
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/common/driver_hints.py", line 42, in wrapper
2020-09-25 22:06:58.834 22172 ERROR keystone return f(self, hints, *args, **kwargs)
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/keystone/credential/backends/sql.py", line 69, in list_credentials
2020-09-25 22:06:58.834 22172 ERROR keystone return [s.to_dict() for s in credentials]
2020-09-25 22:06:58.834 22172 ERROR keystone File "/usr/lib/python3/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
2020-09-25 22:06:58.834 22172 ERROR keystone return self._execute_and_instances(context)
2020-09-25...

[Liam Young (gnuoy)]

The failure in comment #1 (https://solutions.qa.canonical.com/openstack/testRun/64429282-ba38-4a59-9e1f-523c3abd8acf) was cause by Bug #1826382 and should be resolved.

[Liam Young (gnuoy)]

...by https://review.opendev.org/#/c/755089/

[Billy Olsen (billy-olsen)]

Based on comment in #7, marking this as a duplicate to Bug #1826382.

[Billy Olsen (billy-olsen)]

Comment #3 doesn't feel related as the messages are referencing sqlite3 as the table, which can happen prior to the mysql database relations being added.

[Ed Bordin (edbordin)]

My mistake, that should have been: Comment #6 looks like a duplicate of Bug #1904599