Keystoneauth does not consistently add the collect-timing parameter

[Andras Kovi]

Mistral devstack tests started to fail due to the following error [1]

2018-06-04 19:23:37.223185 Server-side error: "no such option collect_timing in group [keystone_authtoken]". Detail:
2018-06-04 19:23:37.223221 Traceback (most recent call last):
2018-06-04 19:23:37.223226
2018-06-04 19:23:37.223231 File "/usr/local/lib/python2.7/dist-packages/wsmeext/pecan.py", line 85, in callfunction
2018-06-04 19:23:37.223235 result = f(self, *args, **kwargs)
2018-06-04 19:23:37.223239
2018-06-04 19:23:37.223243 File "/opt/stack/mistral/mistral/api/controllers/v2/event_trigger.py", line 81, in post
2018-06-04 19:23:37.223247 workflow_params=values.get('workflow_params'),
2018-06-04 19:23:37.223251
2018-06-04 19:23:37.223255 File "/opt/stack/mistral/mistral/db/utils.py", line 88, in decorate
2018-06-04 19:23:37.223259 return retry.call(_with_auth_context, auth_ctx, func, *args, **kw)
2018-06-04 19:23:37.223263
2018-06-04 19:23:37.223267 File "/opt/stack/mistral/mistral/utils/rest_utils.py", line 247, in call
2018-06-04 19:23:37.223271 return super(MistralRetrying, self).call(fn, *args, **kwargs)
2018-06-04 19:23:37.223275
2018-06-04 19:23:37.223279 File "/usr/local/lib/python2.7/dist-packages/tenacity/__init__.py", line 330, in call
2018-06-04 19:23:37.223283 start_time=start_time)
2018-06-04 19:23:37.223287
2018-06-04 19:23:37.223291 File "/usr/local/lib/python2.7/dist-packages/tenacity/__init__.py", line 279, in iter
2018-06-04 19:23:37.223295 return fut.result()
2018-06-04 19:23:37.223299
2018-06-04 19:23:37.223303 File "/usr/local/lib/python2.7/dist-packages/concurrent/futures/_base.py", line 455, in result
2018-06-04 19:23:37.223307 return self.__get_result()
2018-06-04 19:23:37.223311
2018-06-04 19:23:37.223315 File "/usr/local/lib/python2.7/dist-packages/tenacity/__init__.py", line 333, in call
2018-06-04 19:23:37.223319 result = fn(*args, **kwargs)
2018-06-04 19:23:37.223322
2018-06-04 19:23:37.223326 File "/opt/stack/mistral/mistral/db/utils.py", line 45, in _with_auth_context
2018-06-04 19:23:37.223330 return func(*args, **kw)
2018-06-04 19:23:37.223334
2018-06-04 19:23:37.223338 File "/opt/stack/mistral/mistral/services/triggers.py", line 186, in create_event_trigger
2018-06-04 19:23:37.223342 security.add_trust_id(values)
2018-06-04 19:23:37.223355
2018-06-04 19:23:37.223360 File "/opt/stack/mistral/mistral/services/security.py", line 110, in add_trust_id
2018-06-04 19:23:37.223364 trust = create_trust()
2018-06-04 19:23:37.223368
2018-06-04 19:23:37.223372 File "/opt/stack/mistral/mistral/services/security.py", line 45, in create_trust
2018-06-04 19:23:37.223376 trustee_id = keystone.client_for_admin().session.get_user_id()
2018-06-04 19:23:37.223380
2018-06-04 19:23:37.223384 File "/opt/stack/mistral/mistral/utils/openstack/keystone.py", line 143, in client_for_admin
2018-06-04 19:23:37.223388 return _admin_client()
2018-06-04 19:23:37.223392
2018-06-04 19:23:37.223396 File "/opt/stack/mistral/mistral/utils/openstack/keystone.py", line 136, in _admin_client
2018-06-04 19:23:37.223400 auth=auth
2018-06-04 19:23:37.223403
2018-06-04 19:23:37.223408 File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/loading/session.py", line 270, in load_from_conf_options
2018-06-04 19:23:37.223412 return Session().load_from_conf_options(*args, **kwargs)
2018-06-04 19:23:37.223416
2018-06-04 19:23:37.223420 File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/loading/session.py", line 251, in load_from_conf_options
2018-06-04 19:23:37.223424 kwargs.setdefault('collect_timing', c.collect_timing)
2018-06-04 19:23:37.223428
2018-06-04 19:23:37.223432 File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 3409, in __getattr__
2018-06-04 19:23:37.223436 return self._conf._get(name, self._group)
2018-06-04 19:23:37.223440
2018-06-04 19:23:37.223444 File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2950, in _get
2018-06-04 19:23:37.223448 value, loc = self._do_get(name, group, namespace)
2018-06-04 19:23:37.223452
2018-06-04 19:23:37.223456 File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2968, in _do_get
2018-06-04 19:23:37.223460 info = self._get_opt_info(name, group)
2018-06-04 19:23:37.223464
2018-06-04 19:23:37.223468 File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 3130, in _get_opt_info
2018-06-04 19:23:37.223474 raise NoSuchOptError(opt_name, group)
2018-06-04 19:23:37.223481
2018-06-04 19:23:37.223487 NoSuchOptError: no such option collect_timing in group [keystone_authtoken]

The issue seems to be related to the release of the patch "Collect timing information for API calls" [2]

[1] http://logs.openstack.org/85/527085/29/check/mistral-devstack/56e57ce/controller/logs/apache/mistral_api_log.txt.gz#_2018-06-04_19_23_37_223487
[2] https://review.openstack.org/#/c/568877/

[wangxiyuan (wangxiyuan)]

I think it's the irregular usage about keystoneauth in mistral.

Usually the service should first call https://github.com/openstack/keystoneauth/blob/master/keystoneauth1/loading/__init__.py#L32 to register the related options. Then the options can be used from the section/group where they are registered.

But it seems that mistral try to get these options from [keystone_authtoken] directly. Coincidently, Some options are contained in both "keystoneauth" and "keystonemiddleware", except "timeout", "collect_timing",and "split_loggers". Mistral only registered "timeout" by itself. https://github.com/openstack/mistral/blob/master/mistral/utils/openstack/keystone.py#L31 So the error happened.

Instead of registering the options one by one in mistral, if mistral use "register_session_conf_options", this kind of error will never happen.

[Brad P. Crochet (brad-9)]

Totally agree with @wangxiyuan. This does need a long-term fix.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/572788
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=d9e4a869466f3983847f1ca4d56074980eead412
Submitter: Zuul
Branch: master

commit d9e4a869466f3983847f1ca4d56074980eead412
Author: Brad P. Crochet <email address hidden>
Date: Wed Jun 6 10:10:59 2018 -0400

    Register the collect_timing keystone_authtoken option

    Icf00c66f57d20d2cef724c233160d3b1e0d52102 introduced a new option to
    keystoneauth1.loading. This adds that option to make Mistral happy.
    Also adds split_loggers.

    Change-Id: Ifac7617decc2990ff87b76d39bf0f72a61ff2b99
    Closes-Bug: #1775140

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/573642

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/mistral 7.0.0.0b2 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/573642
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=b07dfcbdec57a4a1c31fb2d677a284aba5515bbb
Submitter: Zuul
Branch: stable/queens

commit b07dfcbdec57a4a1c31fb2d677a284aba5515bbb
Author: Brad P. Crochet <email address hidden>
Date: Wed Jun 6 10:10:59 2018 -0400

    Register the collect_timing keystone_authtoken option

    Icf00c66f57d20d2cef724c233160d3b1e0d52102 introduced a new option to
    keystoneauth1.loading. This adds that option to make Mistral happy.
    Also adds split_loggers.

    Change-Id: Ifac7617decc2990ff87b76d39bf0f72a61ff2b99
    Closes-Bug: #1775140
    (cherry picked from commit d9e4a869466f3983847f1ca4d56074980eead412)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/572300
Committed: https://git.openstack.org/cgit/openstack/mistral/commit/?id=dcb4355e59de24481c2b669ccce54f3b7dba7ff1
Submitter: Zuul
Branch: master

commit dcb4355e59de24481c2b669ccce54f3b7dba7ff1
Author: wangxiyuan <email address hidden>
Date: Thu Jul 19 15:18:03 2018 +0800

    Use register_session_conf_options API

    Using this API is needed to correctly initialize the configuration.

    [keystone_authtoken] group is used for keystonemiddleware to validating
    token.

    The new [keystone] group is used for keystoneauth to initialization
    the keystone session.

    Co-Authored-By: wangxiyuan<email address hidden>

    Change-Id: Ie3ab512b0ab42c0f97b3099e0787f4edee08ddce
    Partial-Bug: #1775140

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/puppet-keystone 13.3.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/mistral 6.0.4 release.