** Description changed: 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: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.
** Also affects: nova Importance: Undecided Status: New -- 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/1572472 Title: Ironic Nova host manager Unsupported Operand Status in Ironic: New Status in OpenStack Compute (nova): New Bug description: 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. To manage notifications about this bug go to: https://bugs.launchpad.net/ironic/+bug/1572472/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp