[Heat] Sometimes in HA mode heat-client trying to authenticate by incorrect url

[Victor Ryzhenkin]

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  openstack_version: "2014.2.2-6.1"
  api: "1.0"
  build_number: "395"
  build_id: "2015-05-08_11-08-49"
  nailgun_sha: "46f55c293e4540d31bcaa6ca3fba77235fb27537"
  python-fuelclient_sha: "af6c9c3799b9ec107bcdc6dbf035cafc034526ce"
  astute_sha: "6a4dcd11c67af2917815f3678fb594c7412a4c97"
  fuel-library_sha: "f385d6a58298c702f8d4f14c452dcffdc0b1e2a3"
  fuel-ostf_sha: "740ded337bb2a8a9b3d505026652512257375c01"
  fuelmain_sha: "3eca5e8f7ca6a83faff5feeca92c21cff31c0af1"

Steps to reproduce:
1. Deploy OS-Neutron GRE, Murano, All Ceph, CentOS, HA (3 KVM Controllers, 1 Supermicro compute)
2. Deploy Murano environment

Actual result:

Sometimes deployment of Murano-env failed if environment was in online state over 12 hours.

Navigate to Project->Orchestration and get this error:
ERROR Unauthorized: ERROR: Authentication failed. Please try again with option --include-password or export HEAT_INCLUDE_PASSWORD=1

Refresh the page, and all OK.
Refresh one more time and got the same result.

There is traceback from Horizon:

<143>May 13 17:21:03 node-1 dashboard-openstack_dashboard.api.heat: DEBUG heatclient connection created using token "07e30616af164f17b2bd47165e2d566f" and url "http://172.18.92.100:8004/v1/877998dcaa484804a37b7338eaa5144f"
<143>May 13 17:21:03 node-1 dashboard-heatclient.common.http: DEBUG curl -i -X GET -H 'X-Auth-Token: {SHA1}f5dff478a4e100420656e755e0c3f0c4d78ef3e7' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'User-Agent: python-heatclient' http://172.18.92.100:8004/v1/877998dcaa484804a37b7338eaa5144f/stacks?sort_dir=desc&sort_key=created_at&limit=21
<143>May 13 17:21:06 node-1 dashboard-heatclient.common.http: DEBUG
HTTP/1.1 401 Unauthorized
content-length: 23
x-openstack-request-id: req-28ae8477-a6f2-4956-9dc3-ef57d7c8ffe2
connection: close
date: Wed, 13 May 2015 17:21:06 GMT
content-type: text/plain
www-authenticate: Keystone uri='https://127.0.0.1:35357'

Authentication required
<139>May 13 17:21:06 node-1 dashboard-horizon.exceptions: ERROR Unauthorized: ERROR: Authentication failed. Please try again with option --include-password or export HEAT_INCLUDE_PASSWORD=1
Authentication required
Traceback (most recent call last):
  File "/usr/share/openstack-dashboard/openstack_dashboard/wsgi/../../openstack_dashboard/dashboards/project/stacks/views.py", line 72, in get_data
    sort_dir=sort_dir)
  File "/usr/share/openstack-dashboard/openstack_dashboard/wsgi/../../openstack_dashboard/api/heat.py", line 76, in stacks_list
    stacks = list(stacks_iter)
  File "/usr/lib/python2.6/site-packages/heatclient/v1/stacks.py", line 85, in paginate
    stacks = self._list(url, 'stacks')
  File "/usr/lib/python2.6/site-packages/heatclient/openstack/common/apiclient/base.py", line 115, in _list
    body = self.client.get(url).json()
  File "/usr/lib/python2.6/site-packages/heatclient/common/http.py", line 280, in get
    return self.client_request("GET", url, **kwargs)
  File "/usr/lib/python2.6/site-packages/heatclient/common/http.py", line 273, in client_request
    resp, body = self.json_request(method, url, **kwargs)
  File "/usr/lib/python2.6/site-packages/heatclient/common/http.py", line 254, in json_request
    resp = self._http_request(url, method, **kwargs)
  File "/usr/lib/python2.6/site-packages/heatclient/common/http.py", line 207, in _http_request
    % resp.content)
HTTPUnauthorized: ERROR: Authentication failed. Please try again with option --include-password or export HEAT_INCLUDE_PASSWORD=1
Authentication required

In logs on one of the controller nodes in heat-api.log founded next error:

2015-05-13 17:47:32.562 866 INFO urllib3.connectionpool [-] Starting new HTTPS connection (734): 127.0.0.1
2015-05-13 17:47:32.563 866 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: Unable to establish connection to https://127.0.0.1:35357/
2015-05-13 17:47:33.564 866 DEBUG keystoneclient.session [-] REQ: curl -i -X GET https://127.0.0.1:35357/ -H "Accept: application/json" -H "User-Agent: python-keystoneclient" _http_log_request /usr/lib/python2.6/site-packages/keystoneclient/session.py:155
2015-05-13 17:47:33.566 866 INFO urllib3.connectionpool [-] Starting new HTTPS connection (735): 127.0.0.1
2015-05-13 17:47:33.569 866 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: Unable to establish connection to https://127.0.0.1:35357/
2015-05-13 17:47:35.571 866 DEBUG keystoneclient.session [-] REQ: curl -i -X GET https://127.0.0.1:35357/ -H "Accept: application/json" -H "User-Agent: python-keystoneclient" _http_log_request /usr/lib/python2.6/site-packages/keystoneclient/session.py:155
2015-05-13 17:47:35.573 866 INFO urllib3.connectionpool [-] Starting new HTTPS connection (736): 127.0.0.1
2015-05-13 17:47:35.575 866 ERROR keystonemiddleware.auth_token [-] HTTP connection exception: Unable to establish connection to https://127.0.0.1:35357/
2015-05-13 17:47:35.576 866 DEBUG keystonemiddleware.auth_token [-] Token validation failure. _validate_token /usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py:885
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token Traceback (most recent call last):
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 877, in _validate_token
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token retry)
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 1396, in verify_token
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token self._auth_version = self._choose_api_version()
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 1468, in _choose_api_version
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token versions_supported_by_server = self._get_supported_versions()
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 1488, in _get_supported_versions
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token response, data = self._json_request('GET', '/', authenticated=False)
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 1558, in _json_request
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token response = self._http_request(method, path, **kwargs)
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.6/site-packages/keystonemiddleware/auth_token.py", line 1537, in _http_request
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token raise NetworkError('Unable to communicate with keystone')
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token NetworkError: Unable to communicate with keystone
2015-05-13 17:47:35.576 866 TRACE keystonemiddleware.auth_token
2015-05-13 17:47:35.577 866 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2015-05-13 17:47:35.578 866 INFO keystonemiddleware.auth_token [-] Invalid user token - rejecting request

Looks like the heat trying to auth itself by incorrect url.
The snapshot will be available later.

[Victor Ryzhenkin (vryzhenkin)]

Snapshot available by following link:
https://drive.google.com/a/mirantis.com/file/d/0B3tqtKJGirwwdXIyOXNDNUlBakk/view?usp=sharing

[Victor Ryzhenkin (vryzhenkin)]

In this log we found that after deployment heat-api on node-3 starts without config.
After restart of heat-engine the problem is gone.

[Sergey Kraynev (skraynev)]

Debugging show, that issue was related with incorrect deploying:

all nodes except node-3 have heat-api process started with correct configuration.
But heat-api on node-3 in start log show, that all specified in config options are None, i.e. it started without configuration file.

I suppose, that root cause is: wrong order (may unexpected fail during deployment), which lead to starting heat-api before configuration file was created (heat.conf).

Victor will post detailed logs, which demonstrate my words.

[ruhe (ruhe)]

Moving to incomplete. We need to collect more data about this issue and provide an access to environment where this issue can be reproduced.

[Igor Yozhikov (iyozhikov)]

* Deployment log analyses doesn't show any errors.
* I've got a question about HTTPS inside these heat-api log entries, is it ok?:
2015-05-12 14:00:59.209 866 DEBUG heat-api [-] keystone_authtoken.auth_protocol = https log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-13 15:53:33.191 866 DEBUG keystoneclient.session [-] REQ: curl -i -X GET https://127.0.0.1:35357/ -H "Accept: application/json" -H "User-Agent: python-keystoneclient" _http_log_request /usr/lib/python2.6/site-packages/keystoneclient/session.py:155
2015-05-13 15:53:33.213 866 INFO urllib3.connectionpool [-] Starting new HTTPS connection (1): 127.0.0.1
2015-05-13 15:53:33.217 866 WARNING keystonemiddleware.auth_token [-] Retrying on HTTP connection exception: Unable to establish connection to https://127.0.0.1:35357/
* Can't reproduce same situation, QA team, could you try to reproduce this issue and leave EVN alive for further investigation?

[Dmitry Mescheryakov (dmitrymex)]

It is rather late, the bug is rarely reproducible and non critical. Moving to 7.0.

[Victor Ryzhenkin (vryzhenkin)]

This issue reproduced again in System tests:
http://jenkins-product.srt.mirantis.net:8080/view/6.1_swarm/job/6.1.system_test.centos.services_ha/137/

[Victor Ryzhenkin (vryzhenkin)]

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  openstack_version: "2014.2.2-6.1"
  api: "1.0"
  build_number: "469"
  build_id: "2015-05-26_16-19-56"
  nailgun_sha: "f737675091bd1903aace0e36812e855ce47dfec7"
  python-fuelclient_sha: "e19f1b65792f84c4a18b5a9473f85ef3ba172fce"
  astute_sha: "0bd72c72369e743376864e8e8dabfe873d40450a"
  fuel-library_sha: "5cde6f16688486a37f3b280501e98a70883e0d06"
  fuel-ostf_sha: "87819878bc0ca572900e1f6933d9b99e666d6f62"
  fuelmain_sha: "13b3e9cf074ba1cf1ae06509c55fbab613c73f4e"

[Victor Ryzhenkin (vryzhenkin)]

I found this in heat-api.log

2015-05-27 09:15:57.214 8227 DEBUG heat-api [-] keystone_authtoken.admin_password = **** log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.216 8227 DEBUG heat-api [-] keystone_authtoken.admin_tenant_name = admin log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.217 8227 DEBUG heat-api [-] keystone_authtoken.admin_token = **** log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.218 8227 DEBUG heat-api [-] keystone_authtoken.admin_user = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.219 8227 DEBUG heat-api [-] keystone_authtoken.auth_admin_prefix = log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.220 8227 DEBUG heat-api [-] keystone_authtoken.auth_host = 127.0.0.1 log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.221 8227 DEBUG heat-api [-] keystone_authtoken.auth_port = 35357 log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.222 8227 DEBUG heat-api [-] keystone_authtoken.auth_protocol = https log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.223 8227 DEBUG heat-api [-] keystone_authtoken.auth_uri = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.224 8227 DEBUG heat-api [-] keystone_authtoken.auth_version = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.225 8227 DEBUG heat-api [-] keystone_authtoken.cache = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.226 8227 DEBUG heat-api [-] keystone_authtoken.cafile = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073
2015-05-27 09:15:57.228 8227 DEBUG heat-api [-] keystone_authtoken.certfile = None log_opt_values /usr/lib/python2.6/site-packages/oslo_config/cfg.py:2073

After restarting of heat services, Murano passed all tests.

[Leontii Istomin (listomin)]

reproduced the issue on scale lab:
api: '1.0'
astute_sha: b09729c64b695b2e6fcc88c31843321759ec45d5
auth_required: true
build_id: 2015-05-16_20-55-26
build_number: '425'
feature_groups:
- mirantis
fuel-library_sha: 1645fe45f226cdd6d2829bea9912d0baa3be5033
fuel-ostf_sha: 9ce1800749081780b8b2a4a7eab6586583ffaf33
fuelmain_sha: 0e970647a83d9a7d336c4cc253606d4dd0d59a60
nailgun_sha: 076566b5df37f681c3fd5b139c966d680d81e0a5
openstack_version: 2014.2.2-6.1
production: docker
python-fuelclient_sha: 38765563e1a7f14f45201fd47cf507393ff5d673
release: '6.1'

Baremetal,Ubuntu,IBP,HA,Neutron-vlan,Ceph-all,Nova-debug,Nova-quotas,6.1_425
Controllers:3 Computes:200

During rally light test (rally with small number iterations) all heat tests were failed.
rally.log:
http://paste.openstack.org/show/242458/
haproxy:
http://paste.openstack.org/show/242459/

heat-api and heat-engine were running with wrong config on node-43 (on other two controllers services was running with right configuration). Therefore when heat started used the following messages appeared in logs:
/var/log/upstart/heat-api.log
http://paste.openstack.org/show/242569/
/var/log/upstart/heat-engine.log
http://paste.openstack.org/show/242570/

But heat-engine is running via corosync, therefore when it was broken, corosunc started up it again I believe.

I restarted heat-api services on each controller node at ~ 28 10:29. After that heat-api on node-43 works fine:

heat logs and puppet logs from node-43 are here: http://mos-scale-share.mirantis.com/node-43-339.tar.gz

[Igor Yozhikov (iyozhikov)]

During investigation was found next:

Service started with default configuration parameters before config file was updated by puppet.

grep 'auth_' heat.conf
# From keystonemiddleware.auth_token
#auth_uri = <None>
#auth_version = <None>
#delay_auth_decision = false
# options or empty, auth_token will raise an exception on initialization.
#auth_admin_prefix =
#auth_host = 127.0.0.1
#auth_port = 35357
#auth_protocol = https

So we need add additional checks before start services or set small delay before start of service.

[Bogdan Dobrelya (bogdando)]

Is this issue resolved now?

[Bogdan Dobrelya (bogdando)]

I mean, after this patch https://review.openstack.org/#/c/187177