Bug #1567434 “new hypervisor should appear with available resour...” : Bugs : OpenStack Compute (nova)

Vasyl Saienko (vsaienko) on 2016-04-07

description:

updated

Sarafraj Singh (sarafraj-singh) on 2016-04-07

tags:	added: ironic
Changed in nova:
assignee:	nobody → Sarafraj Singh (sarafraj-singh)

Sarafraj Singh (sarafraj-singh) on 2016-04-07

Changed in nova:
status:	New → Incomplete
status:	Incomplete → New

Revision history for this message

Sylvain Bauza (sylvain-bauza) wrote on 2016-04-08:

#1

So, the nova-compute ResourceTracker is updating this field and persisting it in DB (so that the scheduler can get it) in 3 cases :
- when the ResourceTracker (there is one per node) is initiated
- everytime a new instance is claimed for that node
- every 60 secs

What is strange is that the scheduler is getting the list of compute nodes when a request comes in, but that list is created by each ResourceTracker, which means that the RT wouldn't run update_available_resources.

Could you please provide us both the nova-compute logs and the nova-scheduler logs at the same time so we could verify if free_disk_gb is set ?

Changed in nova:
status:	New → Incomplete

Revision history for this message

Vasyl Saienko (vsaienko) wrote on 2016-04-11:

#2

The logs are huge, and can't be added to attach here. I have uploaded the to dropbox. There is the link https://www.dropbox.com/sh/3k1j0ewurizayc4/AADEzGQPpqpP4v83EdOijDwBa?dl=0

Changed in nova:
status:	Incomplete → New

Revision history for this message

Sylvain Bauza (sylvain-bauza) wrote on 2016-04-11:

#3

Couldn't you just truncate the n-cpu and n-sch logs by the time (within a 5-min time window) you saw the stack trace ?

I don't need a full log, just to get the audit and debug traces at the time the issue is appearing.

TBH, I don't really see how you can possibly set a value to None, the code is pretty defensive about that.

Sylvain Bauza (sylvain-bauza) on 2016-04-11

Changed in nova:
status:	New → Incomplete

John L. Villalovos (happycamp) on 2016-04-12

summary:

- new hypervisor should apper with available resources set to 0
+ new hypervisor should appear with available resources set to 0

Sarafraj Singh (sarafraj-singh) on 2016-04-13

Changed in nova:
assignee:	Sarafraj Singh (sarafraj-singh) → nobody

Revision history for this message

Jim Rollenhagen (jim-rollenhagen) wrote on 2016-04-20:

#4

Download full text (9.3 KiB)

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-...

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.

Revision history for this message

Sam Betts (sambetts) wrote on 2016-04-20:

#5

n-cpu.log:

2016-04-20 08:41:02.913 INFO nova.compute.resource_tracker [req-fd249d93-8a71-41cb-881e-734c1edc4911 None None] Final resource view: name=e5657c2c-f776-4c19-b537-4957376409d9 phys_ram=0MB used_ram=0MB phys_disk=0GB used_disk=0GB total_vcpus=0 used_vcpus=0 pci_stats=[]
2016-04-20 08:41:02.918 DEBUG oslo_messaging._drivers.amqpdriver [req-fd249d93-8a71-41cb-881e-734c1edc4911 None None] CALL msg_id: 14b7af32ef66444da0f5e5118e5f741d exchange 'nova' topic 'conductor' from (pid=9434) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:454
2016-04-20 08:41:03.063 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: 5d487f2909f24005ae31cc6632bad181 exchange 'nova' topic 'conductor' from (pid=9434) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:454
2016-04-20 08:41:03.071 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 14b7af32ef66444da0f5e5118e5f741d from (pid=9434) __call__ /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:302
2016-04-20 08:41:03.072 INFO nova.compute.resource_tracker [req-fd249d93-8a71-41cb-881e-734c1edc4911 None None] Compute_service record updated for ironic-ucsm-ironic-ucsm-provider-33459:e5657c2c-f776-4c19-b537-4957376409d9

n-sch.log:

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'

Based on comparing the n-sch and n-cpu logs, I can see that the nova scheduler starts dealing with this node, inbetween the the logs from the resource tracker handling this ComputeNode.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-04-20: Fix proposed to nova (master)

#6

Fix proposed to branch: master
Review: https://review.openstack.org/308348

Changed in nova:
assignee:	nobody → Sam Betts (sambetts)
status:	Incomplete → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-10-27: Change abandoned on nova (master)

#7

Change abandoned by Michael Still (<email address hidden>) on branch: master
Review: https://review.openstack.org/308348
Reason: This patch has been sitting unchanged for more than 12 weeks. I am therefore going to abandon it to keep the nova review queue sane. Please feel free to restore the change if you're still working on it.

Revision history for this message

Vasyl Saienko (vsaienko) wrote on 2016-12-01:

#8

Problem just appeared on ironic-multinode CI:

http://logs.openstack.org/36/404436/4/check/gate-tempest-dsvm-ironic-ipa-wholedisk-agent_ssh-tinyipa-multinode-nv/d13d19c/logs/screen-n-sch.txt.gz?level=ERROR

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-12-21: Fix proposed to nova (master)

#9

Fix proposed to branch: master
Review: https://review.openstack.org/413631

Changed in nova:
assignee:	Sam Betts (sambetts) → Vasyl Saienko (vsaienko)

Roman Podoliaka (rpodolyaka) on 2016-12-23

Changed in nova:
importance:	Undecided → Medium

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-01-07: Change abandoned on nova (master)

#10

Change abandoned by Vasyl Saienko (<email address hidden>) on branch: master
Review: https://review.openstack.org/413631

Revision history for this message

Sean Dague (sdague) wrote on 2017-06-23:

#11

There are no currently open reviews on this bug, changing
the status back to the previous state and unassigning. If
there are active reviews related to this bug, please include
links in comments.

Changed in nova:
status:	In Progress → Incomplete
assignee:	Vasyl Saienko (vsaienko) → nobody

Revision history for this message

Launchpad Janitor (janitor) wrote on 2017-08-23:

#12

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

Changed in nova:
status:	Incomplete → Expired

OpenStack Compute (nova)

new hypervisor should appear with available resources set to 0

Bug Description

Duplicates of this bug

Other bug subscribers

Remote bug watches