[OSTF] Platform OSTF tests failed with HTTPUnauthorized: HTTPUnauthorized (HTTP 401) error

[Andrey Sledzinskiy]

{

    "build_id": "2014-07-26_10-32-31",
    "ostf_sha": "8c328521b1444f22c50463b9432193e20ed33813",
    "build_number": "363",
    "auth_required": true,
    "api": "1.0",
    "nailgun_sha": "83cc9ed44ebc8dd97248483b6d414ebbc4cff3c0",
    "production": "docker",
    "fuelmain_sha": "6e05b0448d4dc52839e6c6d3696cc5129bf9e1c2",
    "astute_sha": "aa5aed61035a8dc4035ab1619a8bb540a7430a95",
    "feature_groups": [
        "mirantis"
    ],
    "release": "5.1",
    "fuellib_sha": "d1c7f67b3cf51978d3178c8666ea398f2477dcb5"

}

Steps:
1. Create next cluster - CentOS, simple, Flat nova-network, Ceilometer, 1 controller, 1 compute+cinder, 1 mongo
2. Deploy cluster
3. After successful deployment open Health Check tab and run Ceilometer create, update, check, delete alarm

Expected - test passed
Actual - test failed by timeout
In ceilometer-alarm-evaluator log on controller (node-2) get next errors:
ceilometer.alarm.service [-] alarm evaluation cycle failed
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service Traceback (most recent call last):
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometer/alarm/service.py", line 91, in _evaluate_assigned_alarms
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service alarms = self._assigned_alarms()
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometer/alarm/service.py", line 134, in _assigned_alarms
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service 'value': True}])
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/v2/alarms.py", line 71, in list
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service return self._list(options.build_url(self._path(), q))
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/base.py", line 58, in _list
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service resp, body = self.api.json_request('GET', url)
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/http.py", line 191, in json_request
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service resp, body_iter = self._http_request(url, method, **kwargs)
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/http.py", line 174, in _http_request
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service raise exc.from_response(resp, ''.join(body_iter))
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service HTTPUnauthorized: HTTPUnauthorized (HTTP 401)
2014-07-28 12:48:22.886 19972 TRACE ceilometer.alarm.service

Logs are attached

[Aleksey Kasatkin (alekseyk-ru)]

Cannot reproduce on later ISO. Performance issue maybe?

[Egor Kotko (ykotko)]

Reproduced on:
{"build_id": "2014-08-06_02-01-17", "ostf_sha": "be71965998364bf8e6415bd38b75c84b63aab867", "build_number": "405", "auth_required": true, "api": "1.0", "nailgun_sha": "f64b06c788e2b92fcb8e678ea6d0c9b86e8d0ab7", "production": "docker", "fuelmain_sha": "124ea87f1ac1c06e27613fe3b31fd5fc6b39e82d", "astute_sha": "99a790ad1b7526cbbd5bf8add0cb2b4e503fccd4", "feature_groups": ["mirantis"], "release": "5.1", "fuellib_sha": "513ec5cdcdef74c7419d5bae967b9edc7da8dbd7"}

[Vadim Rovachev (vrovachev)]

{"build_id": "2014-08-08_02-01-17", "ostf_sha": "e33390c275e225d648b36997460dc29b1a3c20ae", "build_number": "413", "auth_required": true, "api": "1.0", "nailgun_sha": "5bc33457e5a1f108b071ed0ef2a771ea0b610b22", "production": "docker", "fuelmain_sha": "16c54168143061724e635a20a99545a756725b49", "astute_sha": "b52910642d6de941444901b0f20e95ebbcb2b2e9", "feature_groups": ["mirantis"], "release": "5.1", "fuellib_sha": "d699fc178559e98cfd7d53b58478b46553ffe39e"}

Cannot reproduce

[Ilya Tyaptin (ityaptin)]

Hi! Tests are failed because a authentication token can't been authenticated after 10 minutes after creating.

It is showed in ceilometer-alarm-evaluator logs:
"
2014-07-28T13:08:22.158246+01:00 debug: 2014-07-28 12:08:22.602 19972 DEBUG urllib3.connectionpool [-] "POST /v2.0/tokens HTTP/1.1" 200 3532 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:330
2014-07-28T13:08:22.184226+01:00 debug: 2014-07-28 12:08:22.629 19972 DEBUG ceilometerclient.common.http [-] curl -i -X GET -H 'X-Auth-Token: 9c165bb761ab4cc18238f2e12fcbc06f' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'User-Agent: python-ceilometerclient' http://10.108.1.3:8777/v2/alarms?q.field=enabled&q.op=&q.type=&q.value=True log_curl_request /usr/lib/python2.6/site-packages/ceilometerclient/common/http.py:111
2014-07-28T13:08:22.432374+01:00 debug: 2014-07-28 12:08:22.877 19972 DEBUG ceilometerclient.common.http [-]
HTTP/1.0 200 OK
date: Mon, 28 Jul 2014 12:08:22 GMT
content-length: 2
content-type: application/json; charset=UTF-8
server: WSGIServer/0.1 Python/2.6.6

[]
 log_http_response /usr/lib/python2.6/site-packages/ceilometerclient/common/http.py:121
2014-07-28T13:08:22.433361+01:00 info: 2014-07-28 12:08:22.878 19972 INFO ceilometer.alarm.service [-] initiating evaluation cycle on 0 alarms
2014-07-28T13:18:21.981318+01:00 debug: 2014-07-28 12:18:22.608 19972 DEBUG ceilometerclient.common.http [-] curl -i -X GET -H 'X-Auth-Token: 9c165bb761ab4cc18238f2e12fcbc06f' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'User-Agent: python-ceilometerclient' http://10.108.1.3:8777/v2/alarms?q.field=enabled&q.op=&q.type=&q.value=True log_curl_request /usr/lib/python2.6/site-packages/ceilometerclient/common/http.py:111
2014-07-28T13:18:22.085927+01:00 debug: 2014-07-28 12:18:22.717 19972 DEBUG ceilometerclient.common.http [-]
HTTP/1.0 401 Unauthorized
date: Mon, 28 Jul 2014 12:18:22 GMT
content-length: 23
content-type: text/plain
www-authenticate: Keystone uri='http://10.108.2.3:35357'
server: WSGIServer/0.1 Python/2.6.6

Authentication required
"
2014-07-28T13:08:22.158246+01:00 - create keystone token
2014-07-28T13:08:22.432374+01:00 - first request to ceilometer. Response status - 200 OK
2014-07-28T13:18:22.085927+01:00 - second request to ceilometer. Response status - 401 Unauthorized

All following requests have a response status "401 Unauthorized" too.

This behavior is unusual for keystone, because auth token has 1 hour ttl by default.

May you give access to env with confirmation of this bug to Vadim Rovachev?

[Vadim Rovachev (vrovachev)]

in ceilometer-alarm-evulato.,log
----------------------------------------------------
Authentication required
 log_http_response /usr/lib/python2.6/site-packages/ceilometerclient/common/http.py:121
2014-07-28T13:18:22.086987+01:00 warning: 2014-07-28 12:18:22.718 19972 WARNING ceilometerclient.common.http [-] Request returned failure status.
2014-07-28T13:18:22.098190+01:00 err: 2014-07-28 12:18:22.721 19972 ERROR ceilometer.alarm.service [-] alarm evaluation cycle failed
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service Traceback (most recent call last):
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometer/alarm/service.py", line 91, in _evaluate_assigned_alarms
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service alarms = self._assigned_alarms()
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometer/alarm/service.py", line 134, in _assigned_alarms
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service 'value': True}])
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/v2/alarms.py", line 71, in list
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service return self._list(options.build_url(self._path(), q))
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/base.py", line 58, in _list
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service resp, body = self.api.json_request('GET', url)
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/http.py", line 191, in json_request
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service resp, body_iter = self._http_request(url, method, **kwargs)
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service File "/usr/lib/python2.6/site-packages/ceilometerclient/common/http.py", line 174, in _http_request
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service raise exc.from_response(resp, ''.join(body_iter))
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service HTTPUnauthorized: HTTPUnauthorized (HTTP 401)
2014-07-28 12:18:22.721 19972 TRACE ceilometer.alarm.service
2014-07-28T13:28:22.635434+01:00 debug: 2014-07-28 12:28:22.587 19972 DEBUG ceilometerclient.common.http [-] curl -i -X GET -H 'X-Auth-Token: 9c165bb761ab4cc18238f2e12fcbc06f' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'User-Agent: python-ceilometerclient' http://10.108.1.3:8777/v2/alarms?q.field=enabled&q.op=&q.type=&q.value=True log_curl_request /usr/lib/python2.6/site-packages/ceilometerclient/common/http.py:111
2014-07-28T13:28:22.735242+01:00 debug: 2014-07-28 12:28:22.687 19972 DEBUG ceilometerclient.common.http [-]
HTTP/1.0 401 Unauthorized
date: Mon, 28 Jul 2014 12:28:22 GMT
content-length: 23
content-type: text/plain
www-authenticate: Keystone uri='http://10.108.2.3:35357'
server: WSGIServer/0.1 Python/2.6.6
----------------------------------------------------
in keystone-all.log(with token 9c1...

[Timur Nurlygayanov (tnurlygayanov)]

This issue reproduced for Murano/Sahara/Ceilometer platform tests. During the status pulling we can see many 200 response codes, and after that 401 code, looks like we lost keystone auth token.

This error can be reproduced, for example, if we have incorrect keystone configuration.

Need to check keystone configuration and after that enable logging and verify that we correctly work with keystone authentication.

[Timur Nurlygayanov (tnurlygayanov)]

Keystone configuration is correct, we save token for 60 minutes.
Looks like the root of this problem in incorrect OSTF tests initialization - we authorrize in init method and when we run tests, token will be already incorrect.

[Dennis Dmitriev (ddmitriev)]

Cannot reproduce on ISO#439
Need more information about exact cluster configuration, and how many times OSTF had been performed before it failed (or not).

{"build_id": "2014-08-15_02-01-17", "ostf_sha": "d2a894d228c1f3c22595a77f04b1e00d09d8e463", "build_number": "439", "auth_required": true, "api": "1.0", "nailgun_sha": "7d7e862ccbdbaa36785b95028d37ac91d7aca440", "production": "docker", "fuelmain_sha": "4f7f45d6a020cc5d49ff5c7ee249522a6de7a096", "astute_sha": "b52910642d6de941444901b0f20e95ebbcb2b2e9", "feature_groups": ["mirantis"], "release": "5.1", "fuellib_sha": "d72cd84468ad9846d4768c11df039c43978a5028"}

[Andrew Woodward (xarses)]

Incomplete for more than one week. If this is still an issue please re-open the bug

[Ihor Kalnytskyi (ikalnytskyi)]

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "5.1"
  api: "1.0"
  build_number: "11"
  build_id: "2014-09-17_21-40-34"
  astute_sha: "f5fbd89d1e0e1f22ef9ab2af26da5ffbfbf24b13"
  fuellib_sha: "d9b16846e54f76c8ebe7764d2b5b8231d6b25079"
  ostf_sha: "64cb59c681658a7a55cc2c09d079072a41beb346"
  nailgun_sha: "eb8f2b358ea4bb7eb0b2a0075e7ad3d3a905db0d"
  fuelmain_sha: "8ef433e939425eabd1034c0b70e90bdf888b69fd"

Can't reproduce on RC 5.

[Dima Shulyak (dshulyak)]

Timur, what is your opinion? It was sporadic issue and it is resolved now?

[Dima Shulyak (dshulyak)]

>>> Looks like the root of this problem in incorrect OSTF tests initialization - we authorrize in init method and when we run tests, token will be already incorrect.

Why it will be incorrect?

[Timur Nurlygayanov (tnurlygayanov)]

Dmitry, this issue reproduced not in 100% and we don't know why it is reproduced.

[Dmitry Mescheryakov (dmitrymex)]

It is too late to fix this in 6.0 because of Soft Code Freeze, hence move it to 6.0.1

[Dmitry Mescheryakov (dmitrymex)]

That is a medium issue, not going to fix it in maintenance release

[Vitaly Gusev (vgusev)]

Can't reproduce on ISO:
VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  api: "1.0"
  build_number: "233"
  build_id: "2015-03-26_21-32-43"
  nailgun_sha: "b163f6fc77d6639aaffd9dd992e1ad96951c3bbf"
  python-fuelclient_sha: "e5e8389d8d481561a4d7107a99daae07c6ec5177"
  astute_sha: "3f1ece0318e5e93eaf48802fefabf512ca1dce40"
  fuellib_sha: "9c7716bc2ce6075065d7d9dcf96f4c94662c0b56"
  ostf_sha: "a4cf5f218c6aea98105b10c97a4aed8115c15867"
  fuelmain_sha: "320b5f46fc1b2798f9e86ed7df51d3bda1686c10"