test_evacuate_late_server_group_policy_check randomly fails with KeyError: 'fake-node'

[Matt Riedemann]

Seen here:

http://logs.openstack.org/08/541008/5/check/openstack-tox-py27/c3a8321/job-output.txt.gz#_2018-02-07_18_17_26_892813

2018-02-07 18:17:26.881691 | ubuntu-xenial | {1} nova.tests.unit.compute.test_compute_mgr.ComputeManagerUnitTestCase.test_evacuate_late_server_group_policy_check [0.077324s] ... FAILED
2018-02-07 18:17:26.881781 | ubuntu-xenial |
2018-02-07 18:17:26.881847 | ubuntu-xenial | Captured traceback:
2018-02-07 18:17:26.881911 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~
2018-02-07 18:17:26.882005 | ubuntu-xenial | Traceback (most recent call last):
2018-02-07 18:17:26.882270 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
2018-02-07 18:17:26.882364 | ubuntu-xenial | return func(*args, **keywargs)
2018-02-07 18:17:26.882589 | ubuntu-xenial | File "nova/tests/unit/compute/test_compute_mgr.py", line 3973, in test_evacuate_late_server_group_policy_check
2018-02-07 18:17:26.882679 | ubuntu-xenial | request_spec=request_spec)
2018-02-07 18:17:26.882967 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 226, in inner
2018-02-07 18:17:26.883058 | ubuntu-xenial | return func(*args, **kwargs)
2018-02-07 18:17:26.883186 | ubuntu-xenial | File "nova/exception_wrapper.py", line 76, in wrapped
2018-02-07 18:17:26.883284 | ubuntu-xenial | function_name, call_dict, binary)
2018-02-07 18:17:26.883566 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-02-07 18:17:26.883643 | ubuntu-xenial | self.force_reraise()
2018-02-07 18:17:26.883934 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-02-07 18:17:26.884052 | ubuntu-xenial | six.reraise(self.type_, self.value, self.tb)
2018-02-07 18:17:26.884180 | ubuntu-xenial | File "nova/exception_wrapper.py", line 67, in wrapped
2018-02-07 18:17:26.884283 | ubuntu-xenial | return f(self, context, *args, **kw)
2018-02-07 18:17:26.884428 | ubuntu-xenial | File "nova/compute/manager.py", line 186, in decorated_function
2018-02-07 18:17:26.884528 | ubuntu-xenial | "Error: %s", e, instance=instance)
2018-02-07 18:17:26.884810 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-02-07 18:17:26.884887 | ubuntu-xenial | self.force_reraise()
2018-02-07 18:17:26.885211 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-02-07 18:17:26.885333 | ubuntu-xenial | six.reraise(self.type_, self.value, self.tb)
2018-02-07 18:17:26.885479 | ubuntu-xenial | File "nova/compute/manager.py", line 156, in decorated_function
2018-02-07 18:17:26.885601 | ubuntu-xenial | return function(self, context, *args, **kwargs)
2018-02-07 18:17:26.885743 | ubuntu-xenial | File "nova/compute/utils.py", line 976, in decorated_function
2018-02-07 18:17:26.885865 | ubuntu-xenial | return function(self, context, *args, **kwargs)
2018-02-07 18:17:26.886010 | ubuntu-xenial | File "nova/compute/manager.py", line 214, in decorated_function
2018-02-07 18:17:26.886134 | ubuntu-xenial | kwargs['instance'], e, sys.exc_info())
2018-02-07 18:17:26.886293 | ubuntu-xenial | File "nova/compute/utils.py", line 104, in add_instance_fault_from_exc
2018-02-07 18:17:26.886367 | ubuntu-xenial | fault_obj.create()
2018-02-07 18:17:26.886661 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 226, in wrapper
2018-02-07 18:17:26.886758 | ubuntu-xenial | return fn(self, *args, **kwargs)
2018-02-07 18:17:26.886893 | ubuntu-xenial | File "nova/objects/instance_fault.py", line 78, in create
2018-02-07 18:17:26.887033 | ubuntu-xenial | db_fault = db.instance_fault_create(self._context, values)
2018-02-07 18:17:26.887170 | ubuntu-xenial | File "nova/db/api.py", line 1880, in instance_fault_create
2018-02-07 18:17:26.887302 | ubuntu-xenial | return IMPL.instance_fault_create(context, values)
2018-02-07 18:17:26.887435 | ubuntu-xenial | File "nova/db/sqlalchemy/api.py", line 239, in wrapped
2018-02-07 18:17:26.887538 | ubuntu-xenial | with ctxt_mgr.writer.using(context):
2018-02-07 18:17:26.887682 | ubuntu-xenial | File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
2018-02-07 18:17:26.887761 | ubuntu-xenial | return self.gen.next()
2018-02-07 18:17:26.888082 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 1035, in _transaction_scope
2018-02-07 18:17:26.888175 | ubuntu-xenial | context=context) as resource:
2018-02-07 18:17:26.888320 | ubuntu-xenial | File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
2018-02-07 18:17:26.888401 | ubuntu-xenial | return self.gen.next()
2018-02-07 18:17:26.888706 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 638, in _session
2018-02-07 18:17:26.888813 | ubuntu-xenial | bind=self.connection, mode=self.mode)
2018-02-07 18:17:26.889141 | ubuntu-xenial | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py27/local/lib/python2.7/site-packages/fixtures/_fixtures/monkeypatch.py", line 89, in avoid_get
2018-02-07 18:17:26.889254 | ubuntu-xenial | return captured_method(*args, **kwargs)
2018-02-07 18:17:26.889396 | ubuntu-xenial | File "nova/tests/fixtures.py", line 259, in _poison_configure
2018-02-07 18:17:26.889552 | ubuntu-xenial | raise Exception('This test uses methods that set internal oslo_db '
2018-02-07 18:17:26.889944 | ubuntu-xenial | Exception: This test uses methods that set internal oslo_db state, but it does not claim to use the database. This will conflict with the setup of tests that do use the database and cause failures later.
2018-02-07 18:17:26.889982 | ubuntu-xenial |
2018-02-07 18:17:26.890011 | ubuntu-xenial |
2018-02-07 18:17:26.890079 | ubuntu-xenial | Captured pythonlogging:
2018-02-07 18:17:26.890148 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~~~~~
2018-02-07 18:17:26.890424 | ubuntu-xenial | 2018-02-07 18:17:26,791 WARNING [oslo_config.cfg] Config option key_manager.api_class is deprecated. Use option key_manager.backend instead.
2018-02-07 18:17:26.890620 | ubuntu-xenial | 2018-02-07 18:17:26,817 INFO [nova.virt.driver] Loading compute driver 'fake.SmallFakeDriver'
2018-02-07 18:17:26.890778 | ubuntu-xenial | 2018-02-07 18:17:26,826 INFO [nova.compute.manager] Rebuilding instance
2018-02-07 18:17:26.891108 | ubuntu-xenial | 2018-02-07 18:17:26,826 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors).
2018-02-07 18:17:26.891327 | ubuntu-xenial | 2018-02-07 18:17:26,828 INFO [nova.compute.manager] disk not on shared storage, rebuilding from: 'None'
2018-02-07 18:17:26.891516 | ubuntu-xenial | 2018-02-07 18:17:26,830 ERROR [nova.compute.manager] Setting instance vm_state to ERROR
2018-02-07 18:17:26.891611 | ubuntu-xenial | Traceback (most recent call last):
2018-02-07 18:17:26.891782 | ubuntu-xenial | File "nova/compute/manager.py", line 7473, in _error_out_instance_on_exception
2018-02-07 18:17:26.891835 | ubuntu-xenial | yield
2018-02-07 18:17:26.891979 | ubuntu-xenial | File "nova/compute/manager.py", line 2930, in rebuild_instance
2018-02-07 18:17:26.892113 | ubuntu-xenial | instance, scheduled_node, node_type='destination')
2018-02-07 18:17:26.892315 | ubuntu-xenial | File "nova/compute/resource_tracker.py", line 1322, in delete_allocation_for_evacuated_instance
2018-02-07 18:17:26.892434 | ubuntu-xenial | instance, node, 'evacuated', node_type)
2018-02-07 18:17:26.892630 | ubuntu-xenial | File "nova/compute/resource_tracker.py", line 1330, in _delete_allocation_for_moved_instance
2018-02-07 18:17:26.892741 | ubuntu-xenial | cn_uuid = self.compute_nodes[node].uuid
2018-02-07 18:17:26.892813 | ubuntu-xenial | KeyError: 'fake-node'
2018-02-07 18:17:26.894043 | ubuntu-xenial | 2018-02-07 18:17:26,832 ERROR [root] Original exception being dropped: ['Traceback (most recent call last):\n', ' File "nova/compute/manager.py", line 202, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "nova/compute/manager.py", line 2930, in rebuild_instance\n instance, scheduled_node, node_type=\'destination\')\n', ' File "nova/compute/resource_tracker.py", line 1322, in delete_allocation_for_evacuated_instance\n instance, node, \'evacuated\', node_type)\n', ' File "nova/compute/resource_tracker.py", line 1330, in _delete_allocation_for_moved_instance\n cn_uuid = self.compute_nodes[node].uuid\n', "KeyError: 'fake-node'\n"]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22delete_allocation_for_evacuated_instance%5C%22%20AND%20message%3A%5C%22KeyError%3A%20'fake-node'%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

[Matt Riedemann (mriedem)]

Turns out this test was failing as a result of the patch it was failing on, but without logging the exception it was lost:

Captured pythonlogging:
~~~~~~~~~~~~~~~~~~~~~~~
    2018-02-07 20:02:14,002 WARNING [oslo_config.cfg] Config option key_manager.api_class is deprecated. Use option key_manager.backend instead.
    2018-02-07 20:02:14,080 INFO [nova.virt.driver] Loading compute driver 'fake.SmallFakeDriver'
    2018-02-07 20:02:14,090 INFO [nova.compute.manager] Rebuilding instance
    2018-02-07 20:02:14,091 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors).
    2018-02-07 20:02:14,093 INFO [nova.compute.manager] disk not on shared storage, rebuilding from: 'None'
    2018-02-07 20:02:14,095 ERROR [nova.compute.manager] Unexpected failure during rebuild.
    Traceback (most recent call last):
      File "nova/compute/manager.py", line 2891, in rebuild_instance
        migration, request_spec)
      File "nova/compute/manager.py", line 2953, in _do_rebuild_instance_with_claim
        self._do_rebuild_instance(*args, **kwargs)
      File "nova/compute/manager.py", line 3015, in _do_rebuild_instance
        context)
      File "nova/image/api.py", line 65, in generate_image_url
        return "%s/images/%s" % (next(glance.get_api_servers(context)),
      File "nova/image/glance.py", line 130, in get_api_servers
        endpoint = re.sub(r'/v\d+(\.\d+)?/?$', '/', endpoint)
      File "/home/osboxes/git/nova/.tox/py27/lib/python2.7/re.py", line 155, in sub
        return _compile(pattern, flags).sub(repl, string, count)
    TypeError: expected string or buffer