Add logging when filtering returns nothing.
When hosts are filtered for a request, and no host passes all the filters, operators can only see the last filter run; they have no visibility into which filter removed which host. This attempts to improve this situation by tracking the hosts remaining after each filter is run and the number of hosts removed. If no host is left, to log that information along with the reservation ID and instance UUID of the request. Since that can be a lot of information, it will call LOG.info with just the counts for all but the final filter, which will contain the last deleted host names; LOG.debug will output the full record of each filter and the hosts remaining after each step. This will better enable operators to determine why a particular host was not selected. Change-Id: I6173274a03bd8712eb4d63c7a998bb02abdecf4b Blueprint: no-valid-host-reporting
This commit is contained in:
EdLeafe
parent
70946d48cc
commit
0f67836de2
|
|
@ -68,18 +68,57 @@ class BaseFilterHandler(loadables.BaseLoader):
|
|||
def get_filtered_objects(self, filters, objs, filter_properties, index=0):
|
||||
list_objs = list(objs)
|
||||
LOG.debug("Starting with %d host(s)", len(list_objs))
|
||||
# Track the hosts as they are removed. The 'full_filter_results' list
|
||||
# contains the host/nodename info for every host that passes each
|
||||
# filter, while the 'part_filter_results' list just tracks the number
|
||||
# removed by each filter, unless the filter returns zero hosts, in
|
||||
# which case it records the host/nodename for the last batch that was
|
||||
# removed. Since the full_filter_results can be very large, it is only
|
||||
# recorded if the LOG level is set to debug.
|
||||
part_filter_results = []
|
||||
full_filter_results = []
|
||||
log_msg = "%(cls_name)s: (start: %(start)s, end: %(end)s)"
|
||||
for filter_ in filters:
|
||||
if filter_.run_filter_for_index(index):
|
||||
cls_name = filter_.__class__.__name__
|
||||
start_count = len(list_objs)
|
||||
objs = filter_.filter_all(list_objs, filter_properties)
|
||||
if objs is None:
|
||||
LOG.debug("Filter %s says to stop filtering", cls_name)
|
||||
return
|
||||
list_objs = list(objs)
|
||||
if not list_objs:
|
||||
end_count = len(list_objs)
|
||||
part_filter_results.append(log_msg % {"cls_name": cls_name,
|
||||
"start": start_count, "end": end_count})
|
||||
if list_objs:
|
||||
remaining = [(getattr(obj, "host", obj),
|
||||
getattr(obj, "nodename", ""))
|
||||
for obj in list_objs]
|
||||
full_filter_results.append((cls_name, remaining))
|
||||
else:
|
||||
LOG.info(_LI("Filter %s returned 0 hosts"), cls_name)
|
||||
full_filter_results.append((cls_name, None))
|
||||
break
|
||||
LOG.debug("Filter %(cls_name)s returned "
|
||||
"%(obj_len)d host(s)",
|
||||
{'cls_name': cls_name, 'obj_len': len(list_objs)})
|
||||
if not list_objs:
|
||||
# Log the filtration history
|
||||
rspec = filter_properties.get("request_spec", {})
|
||||
inst_props = rspec.get("instance_properties", {})
|
||||
msg_dict = {"res_id": inst_props.get("reservation_id", ""),
|
||||
"inst_uuid": inst_props.get("uuid", ""),
|
||||
"str_results": str(full_filter_results),
|
||||
}
|
||||
full_msg = ("Filtering removed all hosts for the request with "
|
||||
"reservation ID '%(res_id)s' and instance ID "
|
||||
"'%(inst_uuid)s'. Filter results: %(str_results)s"
|
||||
) % msg_dict
|
||||
msg_dict["str_results"] = str(part_filter_results)
|
||||
part_msg = _LI("Filtering removed all hosts for the request with "
|
||||
"reservation ID '%(res_id)s' and instance ID "
|
||||
"'%(inst_uuid)s'. Filter results: %(str_results)s"
|
||||
) % msg_dict
|
||||
LOG.debug(full_msg)
|
||||
LOG.info(part_msg)
|
||||
return list_objs
|
||||
|
|
|
|||
|
|
@ -18,6 +18,7 @@ Tests For Scheduler Host Filters.
|
|||
import inspect
|
||||
import sys
|
||||
|
||||
import mock
|
||||
from six.moves import range
|
||||
|
||||
from nova import filters
|
||||
|
|
@ -36,6 +37,13 @@ class Filter2(filters.BaseFilter):
|
|||
|
||||
|
||||
class FiltersTestCase(test.NoDBTestCase):
|
||||
|
||||
def setUp(self):
|
||||
super(FiltersTestCase, self).setUp()
|
||||
with mock.patch.object(loadables.BaseLoader, "__init__") as mock_load:
|
||||
mock_load.return_value = None
|
||||
self.filter_handler = filters.BaseFilterHandler(filters.BaseFilter)
|
||||
|
||||
def test_filter_all(self):
|
||||
filter_obj_list = ['obj1', 'obj2', 'obj3']
|
||||
filter_properties = 'fake_filter_properties'
|
||||
|
|
@ -201,3 +209,71 @@ class FiltersTestCase(test.NoDBTestCase):
|
|||
filter_objs_initial,
|
||||
filter_properties)
|
||||
self.assertIsNone(result)
|
||||
|
||||
def test_get_filtered_objects_info_log_none_returned(self):
|
||||
LOG = filters.LOG
|
||||
|
||||
class FilterA(filters.BaseFilter):
|
||||
def filter_all(self, list_objs, filter_properties):
|
||||
# return all but the first object
|
||||
return list_objs[1:]
|
||||
|
||||
class FilterB(filters.BaseFilter):
|
||||
def filter_all(self, list_objs, filter_properties):
|
||||
# return an empty list
|
||||
return []
|
||||
|
||||
filter_a = FilterA()
|
||||
filter_b = FilterB()
|
||||
all_filters = [filter_a, filter_b]
|
||||
hosts = ["Host0", "Host1", "Host2"]
|
||||
fake_res_id = "reservation"
|
||||
fake_uuid = "uuid"
|
||||
filt_props = {"request_spec": {"instance_properties": {
|
||||
"reservation_id": fake_res_id,
|
||||
"uuid": fake_uuid}}}
|
||||
with mock.patch.object(LOG, "info") as mock_log:
|
||||
result = self.filter_handler.get_filtered_objects(
|
||||
all_filters, hosts, filt_props)
|
||||
self.assertFalse(result)
|
||||
# FilterA should leave Host1 and Host2; FilterB should leave None.
|
||||
exp_output = ("['FilterA: (start: 3, end: 2)', "
|
||||
"'FilterB: (start: 2, end: 0)']")
|
||||
cargs = mock_log.call_args[0][0]
|
||||
self.assertIn("with reservation ID '%s'" % fake_res_id, cargs)
|
||||
self.assertIn("and instance ID '%s'" % fake_uuid, cargs)
|
||||
self.assertIn(exp_output, cargs)
|
||||
|
||||
def test_get_filtered_objects_debug_log_none_returned(self):
|
||||
LOG = filters.LOG
|
||||
|
||||
class FilterA(filters.BaseFilter):
|
||||
def filter_all(self, list_objs, filter_properties):
|
||||
# return all but the first object
|
||||
return list_objs[1:]
|
||||
|
||||
class FilterB(filters.BaseFilter):
|
||||
def filter_all(self, list_objs, filter_properties):
|
||||
# return an empty list
|
||||
return []
|
||||
|
||||
filter_a = FilterA()
|
||||
filter_b = FilterB()
|
||||
all_filters = [filter_a, filter_b]
|
||||
hosts = ["Host0", "Host1", "Host2"]
|
||||
fake_res_id = "reservation"
|
||||
fake_uuid = "uuid"
|
||||
filt_props = {"request_spec": {"instance_properties": {
|
||||
"reservation_id": fake_res_id,
|
||||
"uuid": fake_uuid}}}
|
||||
with mock.patch.object(LOG, "debug") as mock_log:
|
||||
result = self.filter_handler.get_filtered_objects(
|
||||
all_filters, hosts, filt_props)
|
||||
self.assertFalse(result)
|
||||
# FilterA should leave Host1 and Host2; FilterB should leave None.
|
||||
exp_output = ("[('FilterA', [('Host1', ''), ('Host2', '')]), " +
|
||||
"('FilterB', None)]")
|
||||
cargs = mock_log.call_args[0][0]
|
||||
self.assertIn("with reservation ID '%s'" % fake_res_id, cargs)
|
||||
self.assertIn("and instance ID '%s'" % fake_uuid, cargs)
|
||||
self.assertIn(exp_output, cargs)
|
||||
|
|
|
|||
Loading…
Reference in New Issue