yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1572472] Re: Ironic Nova host manager Unsupported Operand

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sam Betts <sam@xxxxxxxxxxxxxx>
Date: Wed, 20 Apr 2016 09:47:10 -0000
Reply-to: Bug 1572472 <1572472@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** 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