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

[sundarkh]

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

[Jeba Paulaiyan (jebap)]

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
>

[OpenContrail Admin (ci-admin-f)]

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

[OpenContrail Admin (ci-admin-f)]

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

[OpenContrail Admin (ci-admin-f)]

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

[OpenContrail Admin (ci-admin-f)]

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

[sundarkh (sundar-kh)]

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

[sundarkh (sundar-kh)]

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
@

[sundarkh (sundar-kh)]

Seen with ubuntu b29 also

[sundarkh (sundar-kh)]

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_...

[Abhay Joshi (abhayj)]

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

[OpenContrail Admin (ci-admin-f)]

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

[Dheeraj Gautam (dgautam)]

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

[OpenContrail Admin (ci-admin-f)]

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

[Dheeraj Gautam (dgautam)]

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.