Comment 4 for bug 1567434

From a duplicate bug https://bugs.launchpad.net/nova/+bug/1572472

There is a timeout issue that I see when running the Cisco Ironic Third party CI:

    Traceback (most recent call last):
      File "tempest/test.py", line 113, in wrapper
        return f(self, *func_args, **func_kwargs)
      File "/opt/stack/ironic/ironic_tempest_plugin/tests/scenario/test_baremetal_basic_ops.py", line 113, in test_baremetal_server_ops
        self.boot_instance()
      File "/opt/stack/ironic/ironic_tempest_plugin/tests/scenario/baremetal_manager.py", line 150, in boot_instance
        self.wait_node(self.instance['id'])
      File "/opt/stack/ironic/ironic_tempest_plugin/tests/scenario/baremetal_manager.py", line 116, in wait_node
        raise lib_exc.TimeoutException(msg)
    tempest.lib.exceptions.TimeoutException: Request timed out
    Details: Timed out waiting to get Ironic node by instance id 0a252cd1-a020-40da-911b-2becd1820306

On further investigation into the issue I see this error in the n-sch.log, which I expect is leading to the node not being available in nova, so the instance never gets assigned to the Ironic node:

2016-04-20 08:41:02.953 ERROR oslo_messaging.rpc.dispatcher [req-e5ae7418-e311-491e-99b3-86aeaa0b4e3c tempest-BaremetalBasicOps-171486249 tempest-BaremetalBasicOps-1004295680] Exception during message handling: unsupported operand type(s) for *: 'NoneType' and 'int'
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher incoming.message))
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 150, in inner
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher return func(*args, **kwargs)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/manager.py", line 104, in select_destinations
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher dests = self.driver.select_destinations(ctxt, spec_obj)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 53, in select_destinations
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher selected_hosts = self._schedule(context, spec_obj)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 104, in _schedule
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher hosts = self._get_all_host_states(elevated)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 145, in _get_all_host_states
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher return self.host_manager.get_all_host_states(context)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/host_manager.py", line 574, in get_all_host_states
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher self._get_instance_info(context, compute))
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/host_manager.py", line 180, in update
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher return _locked_update(self, compute, service, aggregates, inst_dict)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/host_manager.py", line 169, in _locked_update
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher self._update_from_compute_node(compute)
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/nova/nova/scheduler/ironic_host_manager.py", line 44, in _update_from_compute_node
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher self.free_disk_mb = compute.free_disk_gb * 1024
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher TypeError: unsupported operand type(s) for *: 'NoneType' and 'int'
2016-04-20 08:41:02.953 TRACE oslo_messaging.rpc.dispatcher
2016-04-20 08:41:03.478 ERROR oslo_messaging._drivers.common [req-e5ae7418-e311-491e-99b3-86aeaa0b4e3c tempest-BaremetalBasicOps-171486249 tempest-BaremetalBasicOps-1004295680] Returning exception unsupported operand type(s) for *: 'NoneType' and 'int' to caller
2016-04-20 08:41:03.478 ERROR oslo_messaging._drivers.common [req-e5ae7418-e311-491e-99b3-86aeaa0b4e3c tempest-BaremetalBasicOps-171486249 tempest-BaremetalBasicOps-1004295680] ['Traceback (most recent call last):\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch\n result = func(ctxt, **new_args)\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 150, in inner\n return func(*args, **kwargs)\n', ' File "/opt/stack/nova/nova/scheduler/manager.py", line 104, in select_destinations\n dests = self.driver.select_destinations(ctxt, spec_obj)\n', ' File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 53, in select_destinations\n selected_hosts = self._schedule(context, spec_obj)\n', ' File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 104, in _schedule\n hosts = self._get_all_host_states(elevated)\n', ' File "/opt/stack/nova/nova/scheduler/filter_scheduler.py", line 145, in _get_all_host_states\n return self.host_manager.get_all_host_states(context)\n', ' File "/opt/stack/nova/nova/scheduler/host_manager.py", line 574, in get_all_host_states\n self._get_instance_info(context, compute))\n', ' File "/opt/stack/nova/nova/scheduler/host_manager.py", line 180, in update\n return _locked_update(self, compute, service, aggregates, inst_dict)\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner\n return f(*args, **kwargs)\n', ' File "/opt/stack/nova/nova/scheduler/host_manager.py", line 169, in _locked_update\n self._update_from_compute_node(compute)\n', ' File "/opt/stack/nova/nova/scheduler/ironic_host_manager.py", line 44, in _update_from_compute_node\n self.free_disk_mb = compute.free_disk_gb * 1024\n', "TypeError: unsupported operand type(s) for *: 'NoneType' and 'int'\n"]

This log seems to document the ComputeNode update that's causing this error:

2016-04-20 08:41:02.952 DEBUG nova.scheduler.host_manager [req-e5ae7418-e311-491e-99b3-86aeaa0b4e3c tempest-BaremetalBasicOps-171486249 tempest-BaremetalBasicOps-1004295680] Update host state from compute node: ComputeNode(cpu_allocation_ratio=16.0,cpu_info='',created_at=2016-04-20T08:41:02Z,current_workload=None,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=0,free_disk_gb=None,free_ram_mb=None,host='ironic-ucsm-ironic-ucsm-provider-33459',host_ip=10.0.199.6,hypervisor_hostname='e5657c2c-f776-4c19-b537-4957376409d9',hypervisor_type='ironic',hypervisor_version=1,id=26,local_gb=0,local_gb_used=0,memory_mb=0,memory_mb_used=0,metrics=None,numa_topology=None,pci_device_pools=None,ram_allocation_ratio=1.0,running_vms=None,service_id=None,stats={cpu_arch='x86'},supported_hv_specs=[],updated_at=None,uuid=b5dc8328-fad6-497d-be3d-4a2d76a27e30,vcpus=0,vcpus_used=0) from (pid=25619) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:168

As you can see free_disk_gb is None for some reason... for reference other ComputeNode update calls look like:

Update host state from compute node: ComputeNode(cpu_allocation_ratio=16.0,cpu_info='',created_at=2016-04-20T08:41:01Z,current_workload=0,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=0,free_disk_gb=0,free_ram_mb=0,host='ironic-ucsm-ironic-ucsm-provider-33459',host_ip=10.0.199.6,hypervisor_hostname='82a1afd6-db7c-47bc-b44f-36cc30e46f58',hypervisor_type='ironic',hypervisor_version=1,id=25,local_gb=0,local_gb_used=0,memory_mb=0,memory_mb_used=0,metrics='[]',numa_topology=None,pci_device_pools=PciDevicePoolList,ram_allocation_ratio=1.0,running_vms=0,service_id=None,stats={cpu_arch='x86'},supported_hv_specs=[],updated_at=2016-04-20T08:41:02Z,uuid=dcd97316-8f0c-4363-961e-56ee17ae1953,vcpus=0,vcpus_used=0) from (pid=25619) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:168

Which as you can see free_disk_gb is 0, which is how the other node should be also.