VM launch is failing on scale setup : port list timed out when multi-tenancy is enabled

[chhandak]

Unable to launch VM on scale setup
-----------------------------------------

root@5b7s1:/opt/contrail/utils# nova boot --image fbe2af9e-165c-4612-8267-1183fc36bb2d vm100-chhandak1 --flavor 3 --nic net-id=aedfe4ab-c6ce-4f7b-9194-d31ece252ce6
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'keystoneclient.exceptions.ConnectionRefused'> (HTTP 500) (Request-ID: req-5fa1a364-83e8-40d6-9449-397049771fff)

Roledef
---------
#Role definition of the hosts.
env.roledefs = {
    'all': [host1,host2,host3,host4,host5,host6,host7,host8,host9,host10], 'cfgm': [host1,host2,host3],
    'openstack': [host1],
    'webui': [host1],
    'control': [host2,host3],
    'compute': [host4,host5,host6,host7,host8,host9,host10],
    'tsn': [host4,host5,host6,host7],
    'toragent': [host4,host5,host6,host7],
    'collector': [host2,host3],
    'database': [host1,host2,host3],
    'build': [host_build],
}

env.hostnames = {
    'all': ['5b7s1','5b7s2','5b7s3','5b7s4','5b7s5','5b7s6','5b7s7','5b7s8','5b7s9','5b7s10']
}

Nova conductor log
---------------------
 [Errno 32] Broken pipe. Trying again in 1 seconds.2016-05-24 11:13:48.171 24860 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 172.17.90.1:5672
2016-05-24 11:13:48.775 24863 INFO oslo.messaging._drivers.impl_rabbit [req-8c9cace2-bc1b-44d7-82a2-28b2dffccc84 - - - - -] Reconnected to AMQP server on 172.17.90.1:56722016-05-24 11:13:51.248 24841 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Socket closed2016-05-24 11:13:51.643 24850 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Socket closed
2016-05-24 11:13:52.968 24837 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: Socket closed2016-05-24 11:13:59.136 24841 ERROR oslo.messaging._drivers.impl_rabbit [req-515d96dd-e18a-496e-b622-a0ad22da16c9 - - - - -] AMQP server on 172.17.90.1:5672 is unreachable: [Errno 32] Broken pipe. Trying again in 1 seconds.
2016-05-24 11:13:59.937 24837 ERROR oslo.messaging._drivers.impl_rabbit [req-64cca608-82d1-4b01-83a0-f1c87e1a492b - - - - -] AMQP server on 172.17.90.1:5672 is unreachable: [Errno 32] Broken pipe. Trying again in 1 seconds.
2016-05-24 11:14:00.149 24841 INFO oslo.messaging._drivers.impl_rabbit [req-515d96dd-e18a-496e-b622-a0ad22da16c9 - - - - -] Reconnected to AMQP server on 172.17.90.1:5672
2016-05-24 11:14:00.203 24850 ERROR oslo.messaging._drivers.impl_rabbit [req-515d96dd-e18a-496e-b622-a0ad22da16c9 - - - - -] AMQP server on 172.17.90.1:5672 is unreachable: [Errno 32] Broken pipe. Trying again in 1 seconds.
2016-05-24 11:14:00.954 24837 INFO oslo.messaging._drivers.impl_rabbit [req-64cca608-82d1-4b01-83a0-f1c87e1a492b - - - - -] Reconnected to AMQP server on 172.17.90.1:5672
2016-05-24 11:14:01.217 24850 INFO oslo.messaging._drivers.impl_rabbit [req-515d96dd-e18a-496e-b622-a0ad22da16c9 - - - - -] Reconnected to AMQP server on 172.17.90.1:5672
2016-05-24 11:14:09.537 24809 ERROR oslo.messaging._drivers.impl_rabbit [-] AMQP server 172.17.90.1:5672 closed the connection. Check login credentials: Socket closed
2016-05-24 11:14:10.566 24809 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 172.17.90.1:5672
2016-05-24 11:14:10.948 24815 ERROR oslo.messaging._drivers.impl_rabbit [-] AMQP server 172.17.90.1:5672 closed the connection. Check login credentials: Socket closed
2016-05-24 11:14:11.974 24815 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP
server on 172.17.90.1:5672

Nova Api traceback
----------------------
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/validation/__init__.py", line 73, in wrapper
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/validation/__init__.py", line 73, in wrapper
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/servers.py", line 611, in create
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions **create_kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/hooks.py", line 149, in inner
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions rv = f(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1581, in create
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions check_server_group_quota=check_server_group_quota)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1181, in _create_instance
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions auto_disk_config, reservation_id, max_count)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 923, in _validate_and_build_base_options
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions requested_networks, max_count)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 533, in _check_requested_networks
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions max_count)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py", line 1178, in validate_networks
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions ports = neutron.list_ports(tenant_id=context.project_id)['ports']
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 102, in with_params
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions ret = self.function(instance, *args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 555, in list_ports
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return self.list('ports', self.ports_path, retrieve_all,
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 307, in list
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions res = []
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 320, in _pagination
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions while next:
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 293, in get
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return self.retry_request("GET", action, body=body,
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 270, in retry_request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return self.do_request(method, action, body=body,
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 200, in do_request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions content_type=self.content_type())
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 306, in do_request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return self.request(url, method, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 294, in request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions resp = super(SessionClient, self).request(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 95, in request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return self.session.request(url, method, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/keystoneclient/utils.py", line 337, in inner
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 386, in request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions resp = send(**kwargs)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 430, in _send_request
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions raise exceptions.ConnectionRefused(msg)
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions ConnectionRefused: Unable to establish connection to http://172.17.90.1:9696/v2.0/ports.json?tenant_id=08e92dd7543940179e98c45ed0c01d32
2016-05-24 11:10:58.644 17729 ERROR nova.api.openstack.extensions
@

[chhandak (chhandak)]

Copied logs to /auto/cores/1585318

[Ignatious Johnson Christopher (ijohnson-x)]

Objects are iterated and read from Cassandra and checked for READ permission during list_collection.
this is a second read from Cassandra, as we have already read all the objects once.

with the VMI's scaled up to 16K; the total Cassandra reads for neutron port-list is 16K+1. Fix is to avoid the redundant 16K reads and make use of the already read objects for checking permissions.

[OpenContrail Admin (ci-admin-f)]

Review in progress for https://review.opencontrail.org/20586
Submitter: Ignatious Johnson Christopher (<email address hidden>)

[OpenContrail Admin (ci-admin-f)]

Review in progress for https://review.opencontrail.org/20587
Submitter: Ignatious Johnson Christopher (<email address hidden>)

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/20586
Committed: http://github.org/Juniper/contrail-controller/commit/55f9899f42430db7792c2d4272e327a64f0edb0d
Submitter: Zuul
Branch: R3.0

commit 55f9899f42430db7792c2d4272e327a64f0edb0d
Author: Ignatious Johnson Christopher <email address hidden>
Date: Wed May 25 04:34:54 2016 +0000

Objects are iterated/read from Cassandra and checked
for READ permission during list_collection.This is a second read from Cassandra,
as we have already read all the objects once.

Fix is to avoid the redundant reads and make use of the already read objects
for checking permissions

Marking it partial because, same fix needs to be done in rbac aswell.
Partial-Bug: 1585318

Change-Id: Idb4f9f01214b5d56f85cdb8793ba0271747f64b6

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/20587
Committed: http://github.org/Juniper/contrail-controller/commit/718d5a1ff5f476af353325334f7bd41d91b4b94c
Submitter: Zuul
Branch: master

commit 718d5a1ff5f476af353325334f7bd41d91b4b94c
Author: Ignatious Johnson Christopher <email address hidden>
Date: Wed May 25 04:34:54 2016 +0000

Objects are iterated/read from Cassandra and checked
for READ permission during list_collection.This is a second read from Cassandra,
as we have already read all the objects once.

Fix is to avoid the redundant reads and make use of the already read objects
for checking permissions

Marking it partial because, same fix needs to be done in rbac aswell.
Partial-Bug: 1585318

Change-Id: Idb4f9f01214b5d56f85cdb8793ba0271747f64b6

[Ignatious Johnson Christopher (ijohnson-x)]

Same fix needs to be done in RBAC code path as well.

[Deepinder Setia (dsetia)]

Ignatius, your fix is actually in the RBAC code path (for collection API). Checking object permissions is the second aspect of RBAC. First aspect of RBAC is API permissions which doesn't involve fetching any object attribute. I will mark this bug fixed as a result of your fix above.

[Deepinder Setia (dsetia)]

I take it back. It appears Ignatius's change only applied to multi-tenancy and excluded RBAC API

[Ignatious Johnson Christopher (ijohnson-x)]

Fixed in Trunk with,

https://github.com/Juniper/contrail-controller/commit/b36cf7bf75ca2a4eb5f9e7f32634b91ab0879c2b#diff-b3e034a8e1ad5def63d15c26dff39a2eR94