yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1800472] [NEW] nova.tests.functional.test_server_group.ServerGroupTestV264.test_boot_servers_with_affinity_no_valid_host intermittently failing with "OpenStackApiNotFoundException: Item not found"

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Mon, 29 Oct 2018 13:51:03 -0000
Reply-to: Bug 1800472 <1800472@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

http://logs.openstack.org/48/613348/1/check/nova-tox-functional/16b5d01
/job-output.txt.gz#_2018-10-29_10_14_46_484703

2018-10-29 10:14:46.550516 | ubuntu-xenial |     2018-10-29 10:14:45,457 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 480 microversion: 2.64 time: 0.182153
2018-10-29 10:14:46.550841 | ubuntu-xenial |     2018-10-29 10:14:45,485 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/e5f8520d-9f2f-4895-bcf8-485e50898bd0" status: 200 len: 1806 microversion: 2.64 time: 0.023981
2018-10-29 10:14:46.551172 | ubuntu-xenial |     2018-10-29 10:14:45,639 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A40%2CMEMORY_MB%3A4096%2CVCPU%3A2" status: 200 len: 467 microversion: 1.29
2018-10-29 10:14:46.551333 | ubuntu-xenial |     2018-10-29 10:14:45,657 INFO [nova.filters] Filter ServerGroupAffinityFilter returned 0 hosts
2018-10-29 10:14:46.552003 | ubuntu-xenial |     2018-10-29 10:14:45,657 INFO [nova.filters] Filtering removed all hosts for the request with instance ID 'e5f8520d-9f2f-4895-bcf8-485e50898bd0'. Filter results: ['RetryFilter: (start: 1, end: 1)', 'AvailabilityZoneFilter: (start: 1, end: 1)', 'ComputeFilter: (start: 1, end: 1)', 'ComputeCapabilitiesFilter: (start: 1, end: 1)', 'ImagePropertiesFilter: (start: 1, end: 1)', 'ServerGroupAntiAffinityFilter: (start: 1, end: 1)', 'ServerGroupAffinityFilter: (start: 1, end: 0)']
2018-10-29 10:14:46.552140 | ubuntu-xenial |     2018-10-29 10:14:45,658 ERROR [nova.conductor.manager] Failed to schedule instances
2018-10-29 10:14:46.552209 | ubuntu-xenial |     Traceback (most recent call last):
2018-10-29 10:14:46.552345 | ubuntu-xenial |       File "nova/conductor/manager.py", line 1255, in schedule_and_build_instances
2018-10-29 10:14:46.552423 | ubuntu-xenial |         instance_uuids, return_alternates=True)
2018-10-29 10:14:46.552545 | ubuntu-xenial |       File "nova/conductor/manager.py", line 750, in _schedule_instances
2018-10-29 10:14:46.552626 | ubuntu-xenial |         return_alternates=return_alternates)
2018-10-29 10:14:46.552740 | ubuntu-xenial |       File "nova/scheduler/utils.py", line 953, in wrapped
2018-10-29 10:14:46.552810 | ubuntu-xenial |         return func(*args, **kwargs)
2018-10-29 10:14:46.552942 | ubuntu-xenial |       File "nova/scheduler/client/__init__.py", line 53, in select_destinations
2018-10-29 10:14:46.553051 | ubuntu-xenial |         instance_uuids, return_objects, return_alternates)
2018-10-29 10:14:46.553167 | ubuntu-xenial |       File "nova/scheduler/client/__init__.py", line 37, in __run_method
2018-10-29 10:14:46.553268 | ubuntu-xenial |         return getattr(self.instance, __name)(*args, **kwargs)
2018-10-29 10:14:46.553387 | ubuntu-xenial |       File "nova/scheduler/client/query.py", line 42, in select_destinations
2018-10-29 10:14:46.553483 | ubuntu-xenial |         instance_uuids, return_objects, return_alternates)
2018-10-29 10:14:46.553596 | ubuntu-xenial |       File "nova/scheduler/rpcapi.py", line 158, in select_destinations
2018-10-29 10:14:46.553703 | ubuntu-xenial |         return cctxt.call(ctxt, 'select_destinations', **msg_args)
2018-10-29 10:14:46.553934 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 179, in call
2018-10-29 10:14:46.553995 | ubuntu-xenial |         retry=self.retry)
2018-10-29 10:14:46.554235 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/transport.py", line 128, in _send
2018-10-29 10:14:46.554280 | ubuntu-xenial |         retry=retry)
2018-10-29 10:14:46.554693 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send
2018-10-29 10:14:46.554906 | ubuntu-xenial |         return self._send(target, ctxt, message, wait_for_reply, timeout)
2018-10-29 10:14:46.555228 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 209, in _send
2018-10-29 10:14:46.555319 | ubuntu-xenial |         raise failure
2018-10-29 10:14:46.555485 | ubuntu-xenial |     NoValidHost: No valid host was found. There are not enough hosts available.
2018-10-29 10:14:46.555816 | ubuntu-xenial |     2018-10-29 10:14:45,697 WARNING [nova.scheduler.utils] Failed to compute_task_build_instances: No valid host was found. There are not enough hosts available.
2018-10-29 10:14:46.556006 | ubuntu-xenial |     2018-10-29 10:14:45,698 WARNING [nova.scheduler.utils] Setting instance to ERROR state.

Looks like the test creates two servers in an affinity group and then
tries to create a third server in the group and expects it to fail
because there are not enough resources on the host with the other two
servers.

That all seems to work. The problem is when creating the 3rd server,
while waiting for its status to change to ERROR the API returns a 404:

2018-10-29 10:14:46.484852 | ubuntu-xenial | Captured traceback:
2018-10-29 10:14:46.484897 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~
2018-10-29 10:14:46.484967 | ubuntu-xenial |     Traceback (most recent call last):
2018-10-29 10:14:46.485159 | ubuntu-xenial |       File "nova/tests/functional/test_server_group.py", line 303, in test_boot_servers_with_affinity_no_valid_host
2018-10-29 10:14:46.485247 | ubuntu-xenial |         expected_status='ERROR')
2018-10-29 10:14:46.485394 | ubuntu-xenial |       File "nova/tests/functional/test_server_group.py", line 112, in _boot_a_server_to_group
2018-10-29 10:14:46.485490 | ubuntu-xenial |         self.admin_api, created_server, expected_status)
2018-10-29 10:14:46.485633 | ubuntu-xenial |       File "nova/tests/functional/integrated_helpers.py", line 259, in _wait_for_state_change
2018-10-29 10:14:46.485743 | ubuntu-xenial |         admin_api, server, {'status': expected_status}, max_retries)
2018-10-29 10:14:46.485892 | ubuntu-xenial |       File "nova/tests/functional/integrated_helpers.py", line 243, in _wait_for_server_parameter
2018-10-29 10:14:46.485980 | ubuntu-xenial |         server = admin_api.get_server(server['id'])
2018-10-29 10:14:46.486104 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 268, in get_server
2018-10-29 10:14:46.486218 | ubuntu-xenial |         return self.api_get('/servers/%s' % server_id).body['server']
2018-10-29 10:14:46.486330 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 225, in api_get
2018-10-29 10:14:46.486439 | ubuntu-xenial |         return APIResponse(self.api_request(relative_uri, **kwargs))
2018-10-29 10:14:46.486557 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 207, in api_request
2018-10-29 10:14:46.486671 | ubuntu-xenial |         raise OpenStackApiNotFoundException(response=response)
2018-10-29 10:14:46.486811 | ubuntu-xenial |     nova.tests.functional.api.client.OpenStackApiNotFoundException: Item not found

My guess would be something in this recent change is causing a problem
looking up the instance from the cell0 DB:

https://review.openstack.org/#/c/611665/

** Affects: nova
     Importance: Medium
         Status: Confirmed


** Tags: gate-failure testing

** Summary changed:

- nova.tests.functional.test_server_group.ServerGroupTestV264.test_boot_servers_with_affinity_no_valid_host intermittently failing with "Filter ServerGroupAffinityFilter returned 0 hosts"
+ nova.tests.functional.test_server_group.ServerGroupTestV264.test_boot_servers_with_affinity_no_valid_host intermittently failing with "OpenStackApiNotFoundException: Item not found"

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1800472

Title:
  nova.tests.functional.test_server_group.ServerGroupTestV264.test_boot_servers_with_affinity_no_valid_host
  intermittently failing with "OpenStackApiNotFoundException: Item not
  found"

Status in OpenStack Compute (nova):
  Confirmed

Bug description:
  http://logs.openstack.org/48/613348/1/check/nova-tox-
  functional/16b5d01/job-output.txt.gz#_2018-10-29_10_14_46_484703

  2018-10-29 10:14:46.550516 | ubuntu-xenial |     2018-10-29 10:14:45,457 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 480 microversion: 2.64 time: 0.182153
  2018-10-29 10:14:46.550841 | ubuntu-xenial |     2018-10-29 10:14:45,485 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/e5f8520d-9f2f-4895-bcf8-485e50898bd0" status: 200 len: 1806 microversion: 2.64 time: 0.023981
  2018-10-29 10:14:46.551172 | ubuntu-xenial |     2018-10-29 10:14:45,639 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A40%2CMEMORY_MB%3A4096%2CVCPU%3A2" status: 200 len: 467 microversion: 1.29
  2018-10-29 10:14:46.551333 | ubuntu-xenial |     2018-10-29 10:14:45,657 INFO [nova.filters] Filter ServerGroupAffinityFilter returned 0 hosts
  2018-10-29 10:14:46.552003 | ubuntu-xenial |     2018-10-29 10:14:45,657 INFO [nova.filters] Filtering removed all hosts for the request with instance ID 'e5f8520d-9f2f-4895-bcf8-485e50898bd0'. Filter results: ['RetryFilter: (start: 1, end: 1)', 'AvailabilityZoneFilter: (start: 1, end: 1)', 'ComputeFilter: (start: 1, end: 1)', 'ComputeCapabilitiesFilter: (start: 1, end: 1)', 'ImagePropertiesFilter: (start: 1, end: 1)', 'ServerGroupAntiAffinityFilter: (start: 1, end: 1)', 'ServerGroupAffinityFilter: (start: 1, end: 0)']
  2018-10-29 10:14:46.552140 | ubuntu-xenial |     2018-10-29 10:14:45,658 ERROR [nova.conductor.manager] Failed to schedule instances
  2018-10-29 10:14:46.552209 | ubuntu-xenial |     Traceback (most recent call last):
  2018-10-29 10:14:46.552345 | ubuntu-xenial |       File "nova/conductor/manager.py", line 1255, in schedule_and_build_instances
  2018-10-29 10:14:46.552423 | ubuntu-xenial |         instance_uuids, return_alternates=True)
  2018-10-29 10:14:46.552545 | ubuntu-xenial |       File "nova/conductor/manager.py", line 750, in _schedule_instances
  2018-10-29 10:14:46.552626 | ubuntu-xenial |         return_alternates=return_alternates)
  2018-10-29 10:14:46.552740 | ubuntu-xenial |       File "nova/scheduler/utils.py", line 953, in wrapped
  2018-10-29 10:14:46.552810 | ubuntu-xenial |         return func(*args, **kwargs)
  2018-10-29 10:14:46.552942 | ubuntu-xenial |       File "nova/scheduler/client/__init__.py", line 53, in select_destinations
  2018-10-29 10:14:46.553051 | ubuntu-xenial |         instance_uuids, return_objects, return_alternates)
  2018-10-29 10:14:46.553167 | ubuntu-xenial |       File "nova/scheduler/client/__init__.py", line 37, in __run_method
  2018-10-29 10:14:46.553268 | ubuntu-xenial |         return getattr(self.instance, __name)(*args, **kwargs)
  2018-10-29 10:14:46.553387 | ubuntu-xenial |       File "nova/scheduler/client/query.py", line 42, in select_destinations
  2018-10-29 10:14:46.553483 | ubuntu-xenial |         instance_uuids, return_objects, return_alternates)
  2018-10-29 10:14:46.553596 | ubuntu-xenial |       File "nova/scheduler/rpcapi.py", line 158, in select_destinations
  2018-10-29 10:14:46.553703 | ubuntu-xenial |         return cctxt.call(ctxt, 'select_destinations', **msg_args)
  2018-10-29 10:14:46.553934 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 179, in call
  2018-10-29 10:14:46.553995 | ubuntu-xenial |         retry=self.retry)
  2018-10-29 10:14:46.554235 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/transport.py", line 128, in _send
  2018-10-29 10:14:46.554280 | ubuntu-xenial |         retry=retry)
  2018-10-29 10:14:46.554693 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send
  2018-10-29 10:14:46.554906 | ubuntu-xenial |         return self._send(target, ctxt, message, wait_for_reply, timeout)
  2018-10-29 10:14:46.555228 | ubuntu-xenial |       File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_fake.py", line 209, in _send
  2018-10-29 10:14:46.555319 | ubuntu-xenial |         raise failure
  2018-10-29 10:14:46.555485 | ubuntu-xenial |     NoValidHost: No valid host was found. There are not enough hosts available.
  2018-10-29 10:14:46.555816 | ubuntu-xenial |     2018-10-29 10:14:45,697 WARNING [nova.scheduler.utils] Failed to compute_task_build_instances: No valid host was found. There are not enough hosts available.
  2018-10-29 10:14:46.556006 | ubuntu-xenial |     2018-10-29 10:14:45,698 WARNING [nova.scheduler.utils] Setting instance to ERROR state.

  Looks like the test creates two servers in an affinity group and then
  tries to create a third server in the group and expects it to fail
  because there are not enough resources on the host with the other two
  servers.

  That all seems to work. The problem is when creating the 3rd server,
  while waiting for its status to change to ERROR the API returns a 404:

  2018-10-29 10:14:46.484852 | ubuntu-xenial | Captured traceback:
  2018-10-29 10:14:46.484897 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~
  2018-10-29 10:14:46.484967 | ubuntu-xenial |     Traceback (most recent call last):
  2018-10-29 10:14:46.485159 | ubuntu-xenial |       File "nova/tests/functional/test_server_group.py", line 303, in test_boot_servers_with_affinity_no_valid_host
  2018-10-29 10:14:46.485247 | ubuntu-xenial |         expected_status='ERROR')
  2018-10-29 10:14:46.485394 | ubuntu-xenial |       File "nova/tests/functional/test_server_group.py", line 112, in _boot_a_server_to_group
  2018-10-29 10:14:46.485490 | ubuntu-xenial |         self.admin_api, created_server, expected_status)
  2018-10-29 10:14:46.485633 | ubuntu-xenial |       File "nova/tests/functional/integrated_helpers.py", line 259, in _wait_for_state_change
  2018-10-29 10:14:46.485743 | ubuntu-xenial |         admin_api, server, {'status': expected_status}, max_retries)
  2018-10-29 10:14:46.485892 | ubuntu-xenial |       File "nova/tests/functional/integrated_helpers.py", line 243, in _wait_for_server_parameter
  2018-10-29 10:14:46.485980 | ubuntu-xenial |         server = admin_api.get_server(server['id'])
  2018-10-29 10:14:46.486104 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 268, in get_server
  2018-10-29 10:14:46.486218 | ubuntu-xenial |         return self.api_get('/servers/%s' % server_id).body['server']
  2018-10-29 10:14:46.486330 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 225, in api_get
  2018-10-29 10:14:46.486439 | ubuntu-xenial |         return APIResponse(self.api_request(relative_uri, **kwargs))
  2018-10-29 10:14:46.486557 | ubuntu-xenial |       File "nova/tests/functional/api/client.py", line 207, in api_request
  2018-10-29 10:14:46.486671 | ubuntu-xenial |         raise OpenStackApiNotFoundException(response=response)
  2018-10-29 10:14:46.486811 | ubuntu-xenial |     nova.tests.functional.api.client.OpenStackApiNotFoundException: Item not found

  My guess would be something in this recent change is causing a problem
  looking up the instance from the cell0 DB:

  https://review.openstack.org/#/c/611665/

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1800472/+subscriptions
Follow ups

[Bug 1800472] Re: nova.tests.functional.test_server_group.ServerGroupTestV264.test_boot_servers_with_affinity_no_valid_host intermittently failing with "OpenStackApiNotFoundException: Item not found"
From: OpenStack Infra, 2018-12-12