Juniper Openstack

SM:R3.2build23: vm creation failure due to nova error at keystoneclient.exceptions.NotFound

Bug #1663866 reported by sundarkh
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Juniper Openstack
Status tracked in Trunk
R3.2
Fix Committed
High
Dheeraj Gautam
Juniper Openstack r3.2.2.0
Trunk
Fix Committed
High
Dheeraj Gautam
Juniper Openstack r4.0.0.0-fcs "r4.0.0.0"

Bug Description

SM:R3.2build23:centos: Keystone authentication failure

1) Install SM 3.2 build 23 ; reimage the target with centos 72;
2) Provision gets completed in single node setup
3) vm creation fails with keystone authentication failure

traceback

Traceback (most recent call last):
  File "tcutils/wrappers.py", line 73, in wrapper
    result = function(self, *args, **kwargs)
  File "scripts/heat/test_heat.py", line 233, in test_ecmp_svc_creation_with_heat
    vms = self.config_vms(end_vn_list)
  File "common/heat/base.py", line 185, in config_vms
    vm_fix = self.verify_vms(stack, vn_list, env, stack_name)
  File "common/heat/base.py", line 200, in verify_vms
    vn_obj=vn_list[0].obj, vm_name=vm1_name, connections=self.connections))
  File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 679, in useFixture
    reraise(*exc_info)
  File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 666, in useFixture
    fixture.setUp()
  File "/contrail-test/fixtures/vm_test.py", line 177, in setUp
    self.create()
  File "/contrail-test/fixtures/vm_test.py", line 214, in create
    fixed_ips=self.fixed_ips)
  File "/contrail-test/fixtures/openstack.py", line 101, in create_vm
    return self.nova_h.create_vm(vm_name=vm_name, image_name=image_name, vn_ids=vn_ids, **kwargs)
  File "/contrail-test/fixtures/nova_test.py", line 521, in create_vm
    min_count=count, max_count=count, userdata=userdata)
  File "/usr/lib/python2.7/dist-packages/novaclient/v2/servers.py", line 942, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/base.py", line 169, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line 449, in post
    return self._cs_request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line 424, in _cs_request
    resp, body = self._time_request(url, method, **kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line 397, in _time_request
    resp, body = self.request(url, method, **kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line 391, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'keystoneclient.exceptions.NotFound'> (HTTP 500) (Request-ID: req-8db274e2-284e-42c2-935a-19926fbdda4c)

Keystone log during vm creation

ges/keystone/middleware/core.py:314
2017-02-11 02:13:38.580 4411 INFO keystone.common.wsgi [req-7231bfb6-59e7-4db5-bd7d-2eb0e73424b5 - - - - -] GET http://10.204.217.112:35357/v2.0/tenants
2017-02-11 02:13:38.580 4411 DEBUG keystone.policy.backends.rules [req-7231bfb6-59e7-4db5-bd7d-2eb0e73424b5 - - - - -] enforce admin_required: {'user_id': u'0684da2d42f54fe29b2360f1ef8cfbc0', u'is_admin': 0, u'roles': [u'admin'], 'tenant_id': u'aedd0a5017924a72ae166d2e4c2e5bc9'} enforce /usr/lib/python2.7/site-packages/keystone/policy/backends/rules.py:76
2017-02-11 02:13:38.597 4411 INFO eventlet.wsgi.server [req-7231bfb6-59e7-4db5-bd7d-2eb0e73424b5 - - - - -] 172.17.0.1 - - [11/Feb/2017 02:13:38] "GET /v2.0/tenants HTTP/1.1" 200 2010 0.038864
2017-02-11 02:13:38.803 4410 DEBUG keystone.middleware.core [req-f76c3fc9-135b-4299-9dcf-535e8b94bdb0 - - - - -] There is either no auth token in the request or the certificate issuer is not trusted. No auth context will be set. process_request /usr/lib/python2.7/site-packages/keystone/middleware/core.py:310
2017-02-11 02:13:38.805 4410 INFO keystone.common.wsgi [req-f76c3fc9-135b-4299-9dcf-535e8b94bdb0 - - - - -] POST http://10.204.217.112:35357/v2.0/tokens
2017-02-11 02:13:38.937 4410 INFO eventlet.wsgi.server [req-f76c3fc9-135b-4299-9dcf-535e8b94bdb0 - - - - -] 172.17.0.1 - - [11/Feb/2017 02:13:38] "POST /v2.0/tokens HTTP/1.1" 200 4335 0.134523

nova-api log

2017-02-11 02:40:05.493 8933 INFO nova.osapi_compute.wsgi.server [req-6e8d5b8f-3e8e-4c2c-983f-2a7bbb715d13 deb4e9145db54bd9b0edc9dba6a69107 56f97773a5f8446ba62a7def30424def - - -] 172.17.0.1 "GET /v2/56f97773a5f8446ba62a7def30424def/os-availability-zone/detail HTTP/1.1" status: 200 len: 781 time: 0.2021399
2017-02-11 02:40:05.511 8932 INFO nova.osapi_compute.wsgi.server [req-b9c23cc6-0d34-45e3-9cb9-f4f902c51659 deb4e9145db54bd9b0edc9dba6a69107 56f97773a5f8446ba62a7def30424def - - -] 172.17.0.1 "GET /v2/56f97773a5f8446ba62a7def30424def/os-services?binary=nova-compute HTTP/1.1" status: 200 len: 387 time: 0.0281222
2017-02-11 02:40:23.367 8932 DEBUG nova.osapi_compute.wsgi.server [-] (8932) accepted ('172.17.0.1', 56187) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2017-02-11 02:40:23.370 8932 DEBUG keystoneclient.session [-] REQ: curl -g -i -X GET http://10.204.217.112:35357/v3/auth/tokens -H "X-Subject-Token: {SHA1}7e0e3f69f1d3ba6529de87615118703dd267abad" -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}bead95805037ce9cb78470b70b464e5685e3cc2d" _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198
2017-02-11 02:40:23.479 8932 DEBUG keystoneclient.session [-] RESP: [200] content-length: 7142 x-subject-token: {SHA1}7e0e3f69f1d3ba6529de87615118703dd267abad vary: X-Auth-Token connection: keep-alive date: Sat, 11 Feb 2017 10:40:23 GMT content-type: application/json x-openstack-request-id: req-af261384-53a9-4fc3-a47d-df45577cef50
RESP BODY: {"token": {"methods": ["password", "token"], "roles": [{"id": "35e74ec26c984b6ca3fef38d6fa94aba", "name": "admin"}], "expires_at": "2017-02-11T11:40:23.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "aedd0a5017924a72ae166d2e4c2e5bc9", "name": "admin"}, "catalog": "<removed>", "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "0684da2d42f54fe29b2360f1ef8cfbc0", "name": "admin"}, "audit_ids": ["FZUYTTrlTA6x7VrdjuW38g"], "issued_at": "2017-02-11T10:40:23.354166"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215
2017-02-11 02:40:23.482 8932 DEBUG nova.api.openstack.wsgi [req-e8ad12be-ddf9-43e9-9362-957cee23a4f8 0684da2d42f54fe29b2360f1ef8cfbc0 aedd0a5017924a72ae166d2e4c2e5bc9 - - -] Calling method '<bound method AvailabilityZoneController.detail of <nova.api.openstack.compute.availability_zone.AvailabilityZoneController object at 0x7226210>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:792
2017-02-11 02:40:23.523 8932 INFO nova.osapi_compute.wsgi.server [req-e8ad12be-ddf9-43e9-9362-957cee23a4f8 0684da2d42f54fe29b2360f1ef8cfbc0 aedd0a5017924a72ae166d2e4c2e5bc9 - - -] 172.17.0.1 "GET /v2/aedd0a5017924a72ae166d2e4c2e5bc9/os-availability-zone/detail HTTP/1.1" status: 200 len: 781 time: 0.1546571
2017-02-11 02:40:23.525 8932 DEBUG nova.osapi_compute.wsgi.server [-] (8932) accepted ('172.17.0.1', 56191) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2017-02-11 02:40:23.531 8932 DEBUG nova.api.openstack.wsgi [req-4ba507b2-ec58-4733-9e49-4526869b5bf7 0684da2d42f54fe29b2360f1ef8cfbc0 aedd0a5017924a72ae166d2e4c2e5bc9 - - -] Calling method '<bound method ServiceController.index of <nova.api.openstack.compute.services.ServiceController object at 0x75afa50>>' _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:792
2017-02-11 02:40:23.545 8932 INFO nova.osapi_compute.wsgi.server [req-4ba507b2-ec58-4733-9e49-4526869b5bf7 0684da2d42f54fe29b2360f1ef8cfbc0 aedd0a5017924a72ae166d2e4c2e5bc9 - - -] 172.17.0.1 "GET /v2/aedd0a5017924a72ae166d2e4c2e5bc9/os-services?binary=nova-compute HTTP/1.1" status: 200 len: 387 time: 0.0195000
~

Seen with centos,ubuntu Distros

See original description
sundarkh (sundar-kh)
summary: - SM:R3.2build23:centos: Keystone authentication failure
+ SM:R3.2build23:centos: nova error at keystoneclient.exceptions.NotFound
summary: - SM:R3.2build23:centos: nova error at keystoneclient.exceptions.NotFound
+ SM:R3.2build23:centos: vm creation failure due to nova error at
+ keystoneclient.exceptions.NotFound
description: updated
sundarkh (sundar-kh)
summary: - SM:R3.2build23:centos: vm creation failure due to nova error at
+ SM:R3.2build23: vm creation failure due to nova error at
keystoneclient.exceptions.NotFound
description: updated
tags: added: blok
tags: added: blocker
removed: blok
Abhay Joshi (abhayj)
Changed in juniperopenstack:
assignee: nobody → Dheeraj Gautam (dgautam)
Revision history for this message
Jeba Paulaiyan (jebap) wrote :

Senthil debugged and figured out the following as suggestion:

there are two options to resolve the issue. Both are as below.
Soln1: is the deprecated mode where in admin_auth_url didn’t have v2.0 set under neutron section
Soln2: is the new way going forward where one has to specify auth_plugin to use and username was missing too.

[root@nodeh8 ~]# diff /etc/nova/nova.conf.soln.1 /etc/nova/nova.conf.bk
2715c2715
< admin_auth_url=http://10.204.217.112:35357/v2.0
---
> admin_auth_url=http://10.204.217.112:35357/

[root@nodeh8 ~]# diff /etc/nova/nova.conf.soln.2 /etc/nova/nova.conf.bk
2741c2741
< auth_plugin=password
---
> #auth_plugin=<None>
 2805c2805
< username=neutron
---
> #username=<None>
 2809a2810
>

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] R3.2

Review in progress for https://review.opencontrail.org/28879
Submitter: Dheeraj Gautam (<email address hidden>)

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] master

Review in progress for https://review.opencontrail.org/28880
Submitter: Dheeraj Gautam (<email address hidden>)

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : A change has been merged

Reviewed: https://review.opencontrail.org/28879
Committed: http://github.org/Juniper/contrail-puppet/commit/416e8c395c9e91316d7db3d5e2561c12f91bf4b5
Submitter: Zuul (<email address hidden>)
Branch: R3.2

commit 416e8c395c9e91316d7db3d5e2561c12f91bf4b5
Author: Dheeraj Gautam <email address hidden>
Date: Thu Feb 16 22:20:36 2017 -0800

fix liberty vm launch

Closes-Bug: #1663866

launching vm was failing for authentication.

Change-Id: I275bb133563489ad10ace276ad926ad9d489b589

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote :

Reviewed: https://review.opencontrail.org/28880
Committed: http://github.org/Juniper/contrail-puppet/commit/c2e796b09d9d9d642db8f22787995de8e4ec4c4f
Submitter: Zuul (<email address hidden>)
Branch: master

commit c2e796b09d9d9d642db8f22787995de8e4ec4c4f
Author: Dheeraj Gautam <email address hidden>
Date: Thu Feb 16 22:20:36 2017 -0800

fix liberty vm launch

Closes-Bug: #1663866

launching vm was failing for authentication.

Change-Id: I275bb133563489ad10ace276ad926ad9d489b589

Revision history for this message
sundarkh (sundar-kh) wrote :

Launch vm fails with build 28 , with similar error as mentioned in the description, ; reopening the bug

Now, Seeing that

/etc/nova/nova.conf contains auth_plugin=v3password (which was earlier auth_plugin=password); Will update more based on the other distro behavior

Revision history for this message
sundarkh (sundar-kh) wrote :

Seeing on the following trace in nova compute log (This is nodea4 nova-compute log ) centos/kilo

2017-03-10 10:16:11.529 4700 TRACE nova.compute.manager [instance: 0fb023e6-d842-4a4a-9579-34483eb18ea6]
2017-03-10 10:16:23.151 4700 ERROR nova.compute.manager [-] Instance failed network setup after 1 attempt(s)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager Traceback (most recent call last):
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1782, in _allocate_network_async
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager dhcp_options=dhcp_options)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 411, in allocate_for_instance
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager get_client(context, admin=True))
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager auth_token = _ADMIN_AUTH.get_token(_SESSION)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 104, in get_token
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager return self.get_access(session).auth_token
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 144, in get_access
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager self.auth_ref = self.get_auth_ref(session)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager authenticated=False, log=False)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager return self.request(url, 'POST', **kwargs)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager return func(*args, **kwargs)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager raise exceptions.from_response(resp, method, url)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager NotFound: The resource could not be found. (HTTP 404)
2017-03-10 10:16:23.151 4700 TRACE nova.compute.manager
@

Revision history for this message
sundarkh (sundar-kh) wrote :

Seen with ubuntu b29 also

Revision history for this message
sundarkh (sundar-kh) wrote :
Download full text (11.3 KiB)

With build 29 ubuntu/Kilo

Neutron Server Log during vm creation failure

2017-03-14 19:47:09.157 DEBUG [keystoneclient.auth.identity.v2] Making authentication request to http://10.204.217.112:35357/v2.0/tokens

2017-03-14 19:47:09.293 DEBUG [neutron_plugin_contrail.plugins.opencontrail.contrail_plugin] get_port(): filters: {u'device_id': [u'c0c19aad-aa8a-4444-87c8-701a99642af3', u'fbda332a-43d5-43a7-8d48-40dc56a1a701', u'23a5864a-d177-48ed-ac44-37d029652b50', u'0e2e1a08-d1ef-4c36-8dc0-a3b2b455db6b', u'38c6d945-41e8-4bc4-99a7-d31ce3d3306a', u'7dd8eba1-eca6-4b5d-99ea-8eed5583e12f', u'2ab683dc-f009-4b22-92ee-251062b4b548']} data: [{u'status': u'ACTIVE', u'binding:host_id': u'nodeh8', u'name': u'4bffbd51-5218-4662-95e0-4b5789938d33', u'admin_state_up': True, u'network_id': u'90f2b682-5025-47a3-821d-9d9f4975dff6', u'tenant_id': u'c1ac8f5263d3498f9fa13b2bc4f46113', u'binding:vif_details': {u'port_filter': True}, u'binding:vnic_type': u'normal', u'binding:vif_type': u'vrouter', u'device_owner': u'compute:nova', u'mac_address': u'02:4b:ff:bd:51:52', u'port_security_enabled': True, u'device_id': u'38c6d945-41e8-4bc4-99a7-d31ce3d3306a', u'fixed_ips': [{u'subnet_id': u'9c6cb02d-3494-4e5d-8e96-b2ffbec9a5bf', u'ip_address': u'201.153.235.3'}], u'id': u'4bffbd51-5218-4662-95e0-4b5789938d33', u'security_groups': [u'95024f7a-1710-4b21-8bff-d78a3e0c5fa9'], u'contrail:fq_name': [u'default-domain', u'ctest-TestSvcRegr-30759412', u'4bffbd51-5218-4662-95e0-4b5789938d33']}, {u'status': u'ACTIVE', u'binding:host_id': u'nodeh8', u'name': u'16ebcff7-9dcd-4aa4-a90c-269efeacbb80', u'admin_state_up': True, u'network_id': u'36a5b12f-b8e3-4975-b32c-56fc1fe8c97e', u'tenant_id': u'c1ac8f5263d3498f9fa13b2bc4f46113', u'binding:vif_details': {u'port_filter': True}, u'binding:vnic_type': u'normal', u'binding:vif_type': u'vrouter', u'device_owner': u'compute:nova', u'mac_address': u'02:16:eb:cf:f7:9d', u'port_security_enabled': True, u'device_id': u'2ab683dc-f009-4b22-92ee-251062b4b548', u'fixed_ips': [{u'subnet_id': u'404092e2-e62f-4041-ac56-8511e2d7031c', u'ip_address': u'22.228.142.3'}], u'id': u'16ebcff7-9dcd-4aa4-a90c-269efeacbb80', u'security_groups': [u'95024f7a-1710-4b21-8bff-d78a3e0c5fa9'], u'contrail:fq_name': [u'default-domain', u'ctest-TestSvcRegr-30759412', u'16ebcff7-9dcd-4aa4-a90c-269efeacbb80']}, {u'status': u'ACTIVE', u'binding:host_id': u'nodeh8', u'name': u'default-domain__ctest-TestSvcRegr-30759412__ctest-in_net_svc_instance-20658585_1__1__right__3', u'admin_state_up': True, u'network_id': u'90f2b682-5025-47a3-821d-9d9f4975dff6', u'tenant_id': u'c1ac8f5263d3498f9fa13b2bc4f46113', u'binding:vif_details': {u'port_filter': True}, u'binding:vnic_type': u'normal', u'binding:vif_type': u'vrouter', u'device_owner': u'compute:None', u'mac_address': u'02:30:37:35:74:71', u'port_security_enabled': True, u'device_id': u'0e2e1a08-d1ef-4c36-8dc0-a3b2b455db6b', u'fixed_ips': [{u'subnet_id': u'9c6cb02d-3494-4e5d-8e96-b2ffbec9a5bf', u'ip_address': u'201.153.235.4'}], u'id': u'00257e38-816c-4c0a-a12a-a96ce08a2121', u'security_groups': [u'95024f7a-1710-4b21-8bff-d78a3e0c5fa9'], u'contrail:fq_name': [u'default-domain', u'ctest-TestSvcRegr-30759412', u'default-domain_...

Revision history for this message
Abhay Joshi (abhayj) wrote :

Hi Dheeraj

Tested with Mitaka and the vm creation issue is not hit and it is successful with build 29

Issue seems to be inconsistent

Thanks
Sundar

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : [Review update] R3.2

Review in progress for https://review.opencontrail.org/29661
Submitter: Dheeraj Gautam (<email address hidden>)

Revision history for this message
Dheeraj Gautam (dgautam) wrote :

Found one possible issue with the Reboot and Nova_config ordering. Changed the code to ensure Reboot resource is always executed after Nova_config<| |>.

Revision history for this message
OpenContrail Admin (ci-admin-f) wrote : A change has been merged

Reviewed: https://review.opencontrail.org/29661
Committed: http://github.org/Juniper/contrail-puppet/commit/f5bf38b38c13814d2abde5efed0a25255f866923
Submitter: Zuul (<email address hidden>)
Branch: R3.2

commit f5bf38b38c13814d2abde5efed0a25255f866923
Author: Dheeraj Gautam <email address hidden>
Date: Thu Mar 16 15:50:12 2017 -0700

SM: ensure nova_config runs before system reboot.

Closes-Bug: #1663866

Nova_config must run before Reboot resources, else it may caused partial
configuration changes for nova.conf for compute.

Change-Id: Id472a7687bab551ca8b71191a69f86c674927b24

Revision history for this message
Dheeraj Gautam (dgautam) wrote :

Currently this issue happens randomly, possible cause of this is running Reboot resource in parallel to Nova_config resource and causes nova.conf configurations to be missing as system rebooted before nova.conf is sync'd with filesystem. This issue might come in ubuntu as well.

From /var/log/messages file, It was clear nova_config resources was applied and Reboot resource also was applied immediately. With the fix, Reboot resource will be applied after all Nova_config resource has been completed.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

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