'nova list' does not work when #ports*#instances is big number

[Miroslav Suchý]

I have OpenStack Icehouse and I got this error:
[root@fed-cloud09 ~(keystone_admin)]# nova list
ERROR: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-3b8fc3e4-310b-482c-ba20-0666502a1bcb)

And in /var/log/nova/nova-api.log there is:
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack Traceback (most recent call last):
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return req.get_response(self.application)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack application, catch_exc_info=False)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return resp(environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/keystoneclient/middleware/auth_token.py", line 679, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return self.app(env, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return resp(environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return resp(environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack response = self.app(environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return resp(environ, start_response)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 917, in __call__
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack content_type, body, accept)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 1009, in _process_stack
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack request, action_args)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 887, in post_process_extensions
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack **action_args)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/contrib/security_groups.py", line 601, in detail
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack self._extend_servers(req, list(resp_obj.obj['servers']))
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/contrib/security_groups.py", line 550, in _extend_servers
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack servers))
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/network/security_group/neutron_driver.py", line 345, in get_instances_security_groups_bindings
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack ports = self._get_ports_from_server_list(servers, neutron)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/nova/network/security_group/neutron_driver.py", line 304, in _get_ports_from_server_list
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack ports.extend(neutron.list_ports(**search_opts).get('ports'))
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 111, in with_params
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack ret = self.function(instance, *args, **kwargs)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 306, in list_ports
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack **_params)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1250, in list
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack for r in self._pagination(collection, path, **params):
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1263, in _pagination
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack res = self.get(path, params=params)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1236, in get
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack headers=headers, params=params)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1221, in retry_request
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack headers=headers, params=params)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1164, in do_request
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack self._handle_fault_response(status_code, replybody)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 1134, in _handle_fault_response
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack exception_handler_v20(status_code, des_error_body)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 91, in exception_handler_v20
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack message=message)
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack NeutronClientException: <html><body><h1>400 Bad request</h1>
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack Your browser sent an invalid request.
2015-04-13 13:47:22.065 18123 TRACE nova.api.openstack </body></html>

After some investigation I find that the problem seems to be in
  self._get_ports_from_server_list() which request (when incepted) by GET method.
when I debug do_request() of Client class. I found that the it tries to do:
 /v2.0/ports.json?device_id=0980a371-4991-466b-a471-e847c7d605aa&device_id=f9f8c2d8-7665-4ee8-b6e1-5446b61a1e55&device_id=3055cab9-c0a1-454b-88c3-f34ff92fbc1d&device_id=6d6e64b4-b043-4ba4-93b6-92c06aa7f4e9........

Which is likely too long.

Steps to reproduce:
1. Have 11 security groups
2. spin up 200 instances (both numbers are for one tenant)
3. try to do "nova list" on command line

This way the GET request have aprox. 9400 bytes, which exceed usual implementation of 8K.
I assume that correct way would be to send this query via POST.

[jichenjc (jichenjc)]

Guessing it's because neutron is use eventlet wsgi server and its max URI size is MAX_REQUEST_LINE = 8192
so yes, it's a bug , but not sure a POST can be used since it's using neutron API (still search whether neutron has this kind of API)

this is a log in nova says following

39 # NOTE: Neutron client has a max URL length of 8192, so we have
 40 # to limit the number of IDs we include in any single search. Really
 41 # doesn't seem to be any point in making this a config value.

[jichenjc (jichenjc)]

are you able to provide more info especially your REST API links (the 9400 characters)
I checked the code and looks to me we already handle it and I did a local test , it should be fine

Which version are you using now? thanks

[jichenjc (jichenjc)]

ok, I see it's Icehouse version ... the problem is solved and please update to latest version

[Miroslav Suchý (msuchy)]

Yes. Icehouse. If it is solved in latest version, then feel free to close this report.

[jichenjc (jichenjc)]

I don't have an env to run the test, but from code analysis and a local test on the logic
I think you should not have 200 ids to be transfered to neutron client in latest release
I will leave it 'incomplete' , if you can reproduce in Juno or Kilo or master, then we can continue the analysis, thanks

294 def _get_ports_from_server_list(self, servers, neutron):
295 """Returns a list of ports used by the servers."""
296
297 def _chunk_by_ids(servers, limit):
298 ids = []
299 for server in servers:
300 ids.append(server['id'])
301 if len(ids) >= limit:
302 yield ids
303 ids = []
304 if ids:
305 yield ids
306
307 # Note: Have to split the query up as the search criteria
308 # form part of the URL, which has a fixed max size
309 ports = []
310 for ids in _chunk_by_ids(servers, MAX_SEARCH_IDS): ----> it's 150 constant
311 search_opts = {'device_id': ids}
312 ports.extend(neutron.list_ports(**search_opts).get('ports'))

[Miroslav Suchý (msuchy)]

Hmm, the code is exactly the same in Icehouse (where I can reproduce it). So I'm afraid that the bug is still in current codebase.
However I do not have resources to deploy Juno or Kilo to reproduce there.

[jichenjc (jichenjc)]

I will see whether I can fake the '200' ids in my local env

if you can reproduce it , can you check whether line 301 take effect (pasted above)?
we guess the length is (36+ 11) = 47 * 200 = 9400 , but the logic shows
the maximum is 150 records allowed, so curious why the logic doesn' t take effect
from the call stack ,the function _get_ports_from_server_list is the error place
maybe you can add log or pdb it ?

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

[Miroslav Suchý (msuchy)]

Hmm. This is still valid bug.

[Liping Mao (limao)]

I reproduce this in Juno.

[Markus Zoeller (markus_z) (mzoeller)]

This bug report has an assignee for over 1 month but there is no patch
for that. It looks like that the chance of getting a patch is low.
I'm going to remove the assignee to signal to others that they can take
over if they like.

If you want to work on this, please:
* add yourself as assignee AND
* set the status to "In Progress" AND
* provide a (WIP) patch within the next 2 weeks after that.

If you need assistance, reach out on the IRC channel #openstack-nova or
use the mailing list.

[Sean Dague (sdague)]

Automatically discovered version icehouse in description. If this is incorrect, please update the description to include 'nova version: ...'