Mirantis OpenStack

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

Bug #1454794 reported by Victor Ryzhenkin
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Mirantis OpenStack
Fix Committed
High
Igor Yozhikov
Mirantis OpenStack 6.1

Bug Description

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)
Changed in mos:
milestone: none → 6.1
Mike Scherbakov (mihgen)
Changed in mos:
assignee: nobody → MOS Heat (mos-heat)
Revision history for this message
Victor Ryzhenkin (vryzhenkin) wrote :

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

ruhe (ruhe)
Changed in mos:
importance: Critical → High
ruhe (ruhe)
Changed in mos:
assignee: MOS Heat (mos-heat) → Sergey Kraynev (skraynev)
status: Confirmed → In Progress
ruhe (ruhe)
summary: - Sometimes heat-client trying to authenticate by incorrect url
+ Sometimes in HA mode heat-client trying to authenticate by incorrect url
Revision history for this message
Victor Ryzhenkin (vryzhenkin) wrote : Re: Sometimes in HA mode heat-client trying to authenticate by incorrect url

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.

Revision history for this message
Sergey Kraynev (skraynev) wrote :

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.

Changed in mos:
assignee: Sergey Kraynev (skraynev) → Igor Yozhikov (iyozhikov)
ruhe (ruhe)
summary: - Sometimes in HA mode heat-client trying to authenticate by incorrect url
+ [Heat] Sometimes in HA mode heat-client trying to authenticate by
+ incorrect url
Revision history for this message
ruhe (ruhe) wrote :

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

Changed in mos:
status: In Progress → Incomplete
assignee: Igor Yozhikov (iyozhikov) → Victor Ryzhenkin (vryzhenkin)
Revision history for this message
Igor Yozhikov (iyozhikov) wrote :

* 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?

Revision history for this message
Dmitry Mescheryakov (dmitrymex) wrote :

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

Changed in mos:
milestone: 6.1 → 7.0
Revision history for this message
Victor Ryzhenkin (vryzhenkin) wrote :

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/

Changed in mos:
milestone: 7.0 → 6.1
assignee: Victor Ryzhenkin (vryzhenkin) → Igor Yozhikov (iyozhikov)
status: Incomplete → Confirmed
Revision history for this message
Victor Ryzhenkin (vryzhenkin) wrote :

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"

Revision history for this message
Victor Ryzhenkin (vryzhenkin) wrote :

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.

Leontiy Istomin (listomin)
tags: added: scale
Revision history for this message
Leontiy Istomin (listomin) wrote :

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

Revision history for this message
Igor Yozhikov (iyozhikov) wrote :

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.

Ekaterina Chernova (efedorova)
Changed in mos:
status: Confirmed → Won't Fix
status: Won't Fix → In Progress
Revision history for this message
Bogdan Dobrelya (bogdando) wrote :

Is this issue resolved now?

Revision history for this message
Bogdan Dobrelya (bogdando) wrote :

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

Igor Yozhikov (iyozhikov)
Changed in mos:
status: In Progress → Fix Committed
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.