tempest-full job failing in stable/pike with 404 from keystone during tempest verify-config

[Matt Riedemann]

Been seeing this in pike patches today:

http://logs.openstack.org/84/529384/1/check/tempest-full/2f05681/job-output.txt.gz#_2017-12-22_16_23_09_553728

2017-12-22 16:23:08.888450 | controller | 2017-12-22 16:23:08.888 | venv runtests: PYTHONHASHSEED='3063682826'
2017-12-22 16:23:08.888509 | controller | 2017-12-22 16:23:08.888 | venv runtests: commands[0] | tempest verify-config -uro ../../../tmp/tmp.SJxepYUW30
2017-12-22 16:23:09.523336 | controller | 2017-12-22 16:23:09.522 | Traceback (most recent call last):
2017-12-22 16:23:09.523425 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/cmd/verify_tempest_config.py", line 486, in take_action
2017-12-22 16:23:09.523470 | controller | 2017-12-22 16:23:09.522 | main(parsed_args)
2017-12-22 16:23:09.523523 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/cmd/verify_tempest_config.py", line 450, in main
2017-12-22 16:23:09.523569 | controller | 2017-12-22 16:23:09.522 | 'verify_tempest_config', network_resources=net_resources)
2017-12-22 16:23:09.523624 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 141, in get_credentials_provider
2017-12-22 16:23:09.523663 | controller | 2017-12-22 16:23:09.522 | **get_dynamic_provider_params(identity_version))
2017-12-22 16:23:09.523715 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 73, in get_dynamic_provider_params
2017-12-22 16:23:09.523753 | controller | 2017-12-22 16:23:09.522 | fill_in=True, identity_version=identity_version)
2017-12-22 16:23:09.523807 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 254, in get_configured_admin_credentials
2017-12-22 16:23:09.523844 | controller | 2017-12-22 16:23:09.522 | identity_version=identity_version, **params)
2017-12-22 16:23:09.523892 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 298, in get_credentials
2017-12-22 16:23:09.523920 | controller | 2017-12-22 16:23:09.522 | **params)
2017-12-22 16:23:09.523964 | controller | 2017-12-22 16:23:09.522 | File "/opt/stack/tempest/tempest/lib/auth.py", line 648, in get_credentials
2017-12-22 16:23:09.523999 | controller | 2017-12-22 16:23:09.523 | creds = auth_provider.fill_credentials()
2017-12-22 16:23:09.524043 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/auth.py", line 124, in fill_credentials
2017-12-22 16:23:09.524075 | controller | 2017-12-22 16:23:09.523 | auth_data = self.get_auth()
2017-12-22 16:23:09.524117 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/auth.py", line 150, in get_auth
2017-12-22 16:23:09.524145 | controller | 2017-12-22 16:23:09.523 | self.set_auth()
2017-12-22 16:23:09.524187 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/auth.py", line 159, in set_auth
2017-12-22 16:23:09.524219 | controller | 2017-12-22 16:23:09.523 | self.cache = self._get_auth()
2017-12-22 16:23:09.524261 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/auth.py", line 314, in _get_auth
2017-12-22 16:23:09.524297 | controller | 2017-12-22 16:23:09.523 | token, auth_data = auth_func(**auth_params)
2017-12-22 16:23:09.524347 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/services/identity/v3/token_client.py", line 181, in get_token
2017-12-22 16:23:09.524389 | controller | 2017-12-22 16:23:09.523 | body = self.auth(**kwargs)
2017-12-22 16:23:09.524440 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/services/identity/v3/token_client.py", line 132, in auth
2017-12-22 16:23:09.524477 | controller | 2017-12-22 16:23:09.523 | resp, body = self.post(self.auth_url, body=body)
2017-12-22 16:23:09.524523 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 279, in post
2017-12-22 16:23:09.524566 | controller | 2017-12-22 16:23:09.523 | return self.request('POST', url, extra_headers, headers, body, chunked)
2017-12-22 16:23:09.524616 | controller | 2017-12-22 16:23:09.523 | File "/opt/stack/tempest/tempest/lib/services/identity/v3/token_client.py", line 164, in request
2017-12-22 16:23:09.524653 | controller | 2017-12-22 16:23:09.523 | 'Unexpected status code {0}'.format(resp.status))
2017-12-22 16:23:09.524686 | controller | 2017-12-22 16:23:09.523 | IdentityError: Got identity error
2017-12-22 16:23:09.524718 | controller | 2017-12-22 16:23:09.523 | Details: Unexpected status code 404
2017-12-22 16:23:09.524793 | controller | 2017-12-22 16:23:09.524 | Running config verification...
2017-12-22 16:23:09.553728 | controller | 2017-12-22 16:23:09.553 | ERROR: InvocationError: '/opt/stack/tempest/.tox/venv/bin/tempest verify-config -uro ../../../tmp/tmp.SJxepYUW30'

Looks like the actual failure is trying to create a token:

http://logs.openstack.org/84/529384/1/check/tempest-full/2f05681/controller/logs/tempest_log.txt.gz#_2017-12-22_16_23_09_520

2017-12-22 16:23:09.520 27885 INFO tempest.lib.common.rest_client [-] Request (main): 404 POST http://198.72.124.66/identity/v3/auth/tokens
2017-12-22 16:23:09.521 27885 DEBUG tempest.lib.common.rest_client [-] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: <omitted>
    Response - Headers: {u'date': 'Fri, 22 Dec 2017 16:23:09 GMT', 'status': '404', u'server': 'Apache/2.4.18 (Ubuntu)', u'content-length': '300', 'content-location': 'http://198.72.124.66/identity/v3/auth/tokens', u'content-type': 'text/html; charset=iso-8859-1', u'connection': 'close'}
        Body: <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>404 Not Found</title>
</head><body>
<h1>Not Found</h1>
<p>The requested URL /identity/v3/auth/tokens was not found on this server.</p>
<hr>
<address>Apache/2.4.18 (Ubuntu) Server at 198.72.124.66 Port 80</address>
</body></html>
 _log_request_full /opt/stack/tempest/tempest/lib/common/rest_client.py:434

Because the log path has changed, the controller/logs/ aren't index in logstash so I can only fingerprint this based on the failure in the console log.

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22ERROR%3A%20InvocationError%3A%20'%2Fopt%2Fstack%2Ftempest%2F.tox%2Fvenv%2Fbin%2Ftempest%20verify-config%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

[Takashi Natsume (natsume-takashi)]

It is reproducible.

http://logs.openstack.org/87/529987/1/check/tempest-full/9a2fa46/job-output.txt.gz

2017-12-26 03:51:06.686366 | controller | 2017-12-26 03:51:06.686 | venv runtests: PYTHONHASHSEED='2489918815'
2017-12-26 03:51:06.686415 | controller | 2017-12-26 03:51:06.686 | venv runtests: commands[0] | tempest verify-config -uro ../../../tmp/tmp.9bqD2wFOA4
2017-12-26 03:51:07.355947 | controller | 2017-12-26 03:51:07.355 | Traceback (most recent call last):
2017-12-26 03:51:07.356057 | controller | 2017-12-26 03:51:07.355 | File "/opt/stack/tempest/tempest/cmd/verify_tempest_config.py", line 486, in take_action
2017-12-26 03:51:07.356133 | controller | 2017-12-26 03:51:07.355 | main(parsed_args)
2017-12-26 03:51:07.356211 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/cmd/verify_tempest_config.py", line 450, in main
2017-12-26 03:51:07.356272 | controller | 2017-12-26 03:51:07.356 | 'verify_tempest_config', network_resources=net_resources)
2017-12-26 03:51:07.356362 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 141, in get_credentials_provider
2017-12-26 03:51:07.356420 | controller | 2017-12-26 03:51:07.356 | **get_dynamic_provider_params(identity_version))
2017-12-26 03:51:07.356492 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 73, in get_dynamic_provider_params
2017-12-26 03:51:07.356542 | controller | 2017-12-26 03:51:07.356 | fill_in=True, identity_version=identity_version)
2017-12-26 03:51:07.356623 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 254, in get_configured_admin_credentials
2017-12-26 03:51:07.356687 | controller | 2017-12-26 03:51:07.356 | identity_version=identity_version, **params)
2017-12-26 03:51:07.356760 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/common/credentials_factory.py", line 298, in get_credentials
2017-12-26 03:51:07.356795 | controller | 2017-12-26 03:51:07.356 | **params)
2017-12-26 03:51:07.356853 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/lib/auth.py", line 648, in get_credentials
2017-12-26 03:51:07.356897 | controller | 2017-12-26 03:51:07.356 | creds = auth_provider.fill_credentials()
2017-12-26 03:51:07.356955 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/lib/auth.py", line 124, in fill_credentials
2017-12-26 03:51:07.356995 | controller | 2017-12-26 03:51:07.356 | auth_data = self.get_auth()
2017-12-26 03:51:07.357049 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/lib/auth.py", line 150, in get_auth
2017-12-26 03:51:07.357083 | controller | 2017-12-26 03:51:07.356 | self.set_auth()
2017-12-26 03:51:07.357137 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tempest/tempest/lib/auth.py", line 159, in set_auth
2017-12-26 03:51:07.357178 | controller | 2017-12-26 03:51:07.356 | self.cache = self._get_auth()
2017-12-26 03:51:07.357259 | controller | 2017-12-26 03:51:07.356 | File "/opt/stack/tem...

[Matt Riedemann (mriedem)]

My understanding is this is due to changes in the job definition for the new tempest-full job which only works on master because some changes needed in devstack are not in the stable branches. Andrea Frittoli should know more of the details on what needed to change to get tempest-full working on master and what needs to happen in stable branches.

[Lee Yarwood (lyarwood)]

I attempted to reproduce this locally without any luck yesterday. I don't think this is due to missing devstack changes but it's very likely that I've missed something obvious. It would be really useful if we had httpd logs after a failure like this btw.

I've pushed the following project-config change to unblock stable/pike in the short-term:

Avoid running tempest-full on stable/pike
https://review.openstack.org/#/c/530894/

[chandan kumar (chkumar246)]

As per this review https://review.openstack.org/#/c/530915/ -> Make sure we only run tempest-full on master needs to be backported to stable branches in order to make it working properly.

[Attila Fazekas (afazekas)]

This can help on the stable branch https://bugs.launchpad.net/tempest/+bug/1739829 .

[Attila Fazekas (afazekas)]

This can help on the stable branch https://review.openstack.org/#/c/531046/ .

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/531305
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=ff3047f0c32b6f18417d8a93c271bd03ce042420
Submitter: Zuul
Branch: master

commit ff3047f0c32b6f18417d8a93c271bd03ce042420
Author: Armando Migliaccio <email address hidden>
Date: Thu Jan 4 07:55:08 2018 -0800

    Relocate branch conditional for tempest-full job

    This condition was added to openstack-zuul-jobs in [1], but it created
    bug #1739829 as a side effect. While addressing the issue [2] it was
    noticed that conditional could be located in the tempest repo itself,
    so this patch aims at cleaning things up a bit and reduce the moving
    parts.

    [1] I799ea86f3c445bb067950a8cbc237999d621e3a9
    [2] I5d34e5b983b720dc1913d00ccc1a16d81a040d49
    Needed-by: Ibfbc925af6eb274ced53312301b1733136ba4455
    Partial-bug: #1739829

    Change-Id: I8e0aa11cd2d92d5d6f5e9147a407374948920e7f