| 2018-02-26 12:07:32 |
Hironori Shiina |
description |
After a bare metal instance creation is started, an InventoryInUse exception is logged as ERROR with stack trace in the log of n-cpu.
Ironic virt driver returns an empty inventory for a node which is allocated[1]. Due to this, the resource tracker tried to delete this inventory, then it causes a conflict error because the resource provider for the ironic node is allocated. A waning message used to be logged for this conflict error[2]. After the recent change[3], an InventoryInUse exception is raised[4]. Then, this exception is logged as ERROR[5].
[1] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/virt/ironic/driver.py#L780
[2] https://github.com/openstack/nova/commit/26c593c91f008caab92ed52156dfe2d898955d3f#diff-94f87e728df6465becce5241f3da53c8L994
[3] https://github.com/openstack/nova/commit/26c593c91f008caab92ed52156dfe2d898955d3f#diff-94f87e728df6465becce5241f3da53c8
[4] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/scheduler/client/report.py#L878
[5] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/compute/manager.py#L7244
-----
The following log is from an ironic job[6].
[6] http://logs.openstack.org/19/546919/2/check/ironic-tempest-dsvm-ipa-partition-pxe_ipmitool-tinyipa-python3/2737ab0/logs/screen-n-cpu.txt.gz?level=DEBUG#_Feb_22_11_13_08_848696
Feb 22 11:13:08.848696 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.virt.ironic.driver [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Node 42ae69bd-c860-4eaa-8a36-fdee78425714 is not ready for a deployment, reporting an empty inventory for it. Node's provision state is deploying, power state is power off and maintenance is False. {{(pid=14029) get_inventory /opt/stack/new/nova/nova/virt/ironic/driver.py:752}}
Feb 22 11:13:08.956620 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Refreshing aggregate associations for resource provider fdd77c1d-5b1f-4a9a-b168-0fa93362b95d, aggregates: None {{(pid=14029) _refresh_associations /opt/stack/new/nova/nova/scheduler/client/report.py:773}}
Feb 22 11:13:08.977097 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.virt.ironic.driver [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] The flavor extra_specs for Ironic instance 803d864c-542e-4bb4-a89a-38da01cb8409 have been updated for custom resource class 'baremetal'. {{(pid=14029) _pike_flavor_migration /opt/stack/new/nova/nova/virt/ironic/driver.py:545}}
Feb 22 11:13:08.994233 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Refreshing trait associations for resource provider fdd77c1d-5b1f-4a9a-b168-0fa93362b95d, traits: None {{(pid=14029) _refresh_associations /opt/stack/new/nova/nova/scheduler/client/report.py:784}}
Feb 22 11:13:09.058940 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: INFO nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] [req-55086c0b-9068-49fb-ae94-cd870ab96cab] Inventory update conflict for fdd77c1d-5b1f-4a9a-b168-0fa93362b95d with generation ID 2
Feb 22 11:13:09.059437 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG oslo_concurrency.lockutils [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Lock "compute_resources" released by "nova.compute.resource_tracker.ResourceTracker._update_available_resource" :: held 0.249s {{(pid=14029) inner /usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py:285}}
Feb 22 11:13:09.062075 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Error updating resources for node 42ae69bd-c860-4eaa-8a36-fdee78425714.: nova.exception.InventoryInUse: Inventory for ''CUSTOM_BAREMETAL'' on resource provider 'fdd77c1d-5b1f-4a9a-b168-0fa93362b95d' in use.
Feb 22 11:13:09.062229 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager Traceback (most recent call last):
Feb 22 11:13:09.062343 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/manager.py", line 7245, in update_available_resource_for_node
Feb 22 11:13:09.062454 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager rt.update_available_resource(context, nodename)
Feb 22 11:13:09.062562 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 680, in update_available_resource
Feb 22 11:13:09.062669 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update_available_resource(context, resources)
Feb 22 11:13:09.062781 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
Feb 22 11:13:09.062896 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return f(*args, **kwargs)
Feb 22 11:13:09.063002 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 704, in _update_available_resource
Feb 22 11:13:09.063107 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._init_compute_node(context, resources)
Feb 22 11:13:09.063228 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 561, in _init_compute_node
Feb 22 11:13:09.063342 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update(context, cn)
Feb 22 11:13:09.063453 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 878, in _update
Feb 22 11:13:09.063557 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager inv_data,
Feb 22 11:13:09.063720 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/__init__.py", line 68, in set_inventory_for_provider
Feb 22 11:13:09.063826 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager parent_provider_uuid=parent_provider_uuid,
Feb 22 11:13:09.063939 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/__init__.py", line 37, in __run_method
Feb 22 11:13:09.064043 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return getattr(self.instance, __name)(*args, **kwargs)
Feb 22 11:13:09.064176 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 1015, in set_inventory_for_provider
Feb 22 11:13:09.064298 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update_inventory(context, rp_uuid, inv_data)
Feb 22 11:13:09.064414 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 66, in wrapper
Feb 22 11:13:09.064516 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return f(self, *a, **k)
Feb 22 11:13:09.064626 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 945, in _update_inventory
Feb 22 11:13:09.064742 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager if self._update_inventory_attempt(context, rp_uuid, inv_data):
Feb 22 11:13:09.064860 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 888, in _update_inventory_attempt
Feb 22 11:13:09.064986 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager resource_provider=rp_uuid,
Feb 22 11:13:09.065114 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager nova.exception.InventoryInUse: Inventory for ''CUSTOM_BAREMETAL'' on resource provider 'fdd77c1d-5b1f-4a9a-b168-0fa93362b95d' in use.
Feb 22 11:13:09.065248 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager |
After a bare metal instance creation is started, an InventoryInUse exception is logged as ERROR with stack trace in the log of n-cpu.
Ironic virt driver returns an empty inventory for a node which is allocated[1]. Due to this, the resource tracker tried to delete this inventory, then it causes a conflict error because the resource provider for the ironic node is allocated. A warning message used to be logged for this conflict error[2]. After the recent change[3], an InventoryInUse exception is raised[4]. Then, this exception is logged as ERROR[5].
[1] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/virt/ironic/driver.py#L780
[2] https://github.com/openstack/nova/commit/26c593c91f008caab92ed52156dfe2d898955d3f#diff-94f87e728df6465becce5241f3da53c8L994
[3] https://github.com/openstack/nova/commit/26c593c91f008caab92ed52156dfe2d898955d3f#diff-94f87e728df6465becce5241f3da53c8
[4] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/scheduler/client/report.py#L878
[5] https://github.com/openstack/nova/blob/26c593c91f008caab92ed52156dfe2d898955d3f/nova/compute/manager.py#L7244
-----
The following log is from an ironic job[6].
[6] http://logs.openstack.org/19/546919/2/check/ironic-tempest-dsvm-ipa-partition-pxe_ipmitool-tinyipa-python3/2737ab0/logs/screen-n-cpu.txt.gz?level=DEBUG#_Feb_22_11_13_08_848696
Feb 22 11:13:08.848696 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.virt.ironic.driver [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Node 42ae69bd-c860-4eaa-8a36-fdee78425714 is not ready for a deployment, reporting an empty inventory for it. Node's provision state is deploying, power state is power off and maintenance is False. {{(pid=14029) get_inventory /opt/stack/new/nova/nova/virt/ironic/driver.py:752}}
Feb 22 11:13:08.956620 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Refreshing aggregate associations for resource provider fdd77c1d-5b1f-4a9a-b168-0fa93362b95d, aggregates: None {{(pid=14029) _refresh_associations /opt/stack/new/nova/nova/scheduler/client/report.py:773}}
Feb 22 11:13:08.977097 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.virt.ironic.driver [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] The flavor extra_specs for Ironic instance 803d864c-542e-4bb4-a89a-38da01cb8409 have been updated for custom resource class 'baremetal'. {{(pid=14029) _pike_flavor_migration /opt/stack/new/nova/nova/virt/ironic/driver.py:545}}
Feb 22 11:13:08.994233 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Refreshing trait associations for resource provider fdd77c1d-5b1f-4a9a-b168-0fa93362b95d, traits: None {{(pid=14029) _refresh_associations /opt/stack/new/nova/nova/scheduler/client/report.py:784}}
Feb 22 11:13:09.058940 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: INFO nova.scheduler.client.report [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] [req-55086c0b-9068-49fb-ae94-cd870ab96cab] Inventory update conflict for fdd77c1d-5b1f-4a9a-b168-0fa93362b95d with generation ID 2
Feb 22 11:13:09.059437 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: DEBUG oslo_concurrency.lockutils [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Lock "compute_resources" released by "nova.compute.resource_tracker.ResourceTracker._update_available_resource" :: held 0.249s {{(pid=14029) inner /usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py:285}}
Feb 22 11:13:09.062075 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager [None req-10cd394d-b1be-4541-85ed-ff2275343fb5 service nova] Error updating resources for node 42ae69bd-c860-4eaa-8a36-fdee78425714.: nova.exception.InventoryInUse: Inventory for ''CUSTOM_BAREMETAL'' on resource provider 'fdd77c1d-5b1f-4a9a-b168-0fa93362b95d' in use.
Feb 22 11:13:09.062229 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager Traceback (most recent call last):
Feb 22 11:13:09.062343 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/manager.py", line 7245, in update_available_resource_for_node
Feb 22 11:13:09.062454 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager rt.update_available_resource(context, nodename)
Feb 22 11:13:09.062562 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 680, in update_available_resource
Feb 22 11:13:09.062669 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update_available_resource(context, resources)
Feb 22 11:13:09.062781 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
Feb 22 11:13:09.062896 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return f(*args, **kwargs)
Feb 22 11:13:09.063002 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 704, in _update_available_resource
Feb 22 11:13:09.063107 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._init_compute_node(context, resources)
Feb 22 11:13:09.063228 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 561, in _init_compute_node
Feb 22 11:13:09.063342 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update(context, cn)
Feb 22 11:13:09.063453 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 878, in _update
Feb 22 11:13:09.063557 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager inv_data,
Feb 22 11:13:09.063720 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/__init__.py", line 68, in set_inventory_for_provider
Feb 22 11:13:09.063826 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager parent_provider_uuid=parent_provider_uuid,
Feb 22 11:13:09.063939 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/__init__.py", line 37, in __run_method
Feb 22 11:13:09.064043 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return getattr(self.instance, __name)(*args, **kwargs)
Feb 22 11:13:09.064176 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 1015, in set_inventory_for_provider
Feb 22 11:13:09.064298 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager self._update_inventory(context, rp_uuid, inv_data)
Feb 22 11:13:09.064414 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 66, in wrapper
Feb 22 11:13:09.064516 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager return f(self, *a, **k)
Feb 22 11:13:09.064626 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 945, in _update_inventory
Feb 22 11:13:09.064742 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager if self._update_inventory_attempt(context, rp_uuid, inv_data):
Feb 22 11:13:09.064860 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager File "/opt/stack/new/nova/nova/scheduler/client/report.py", line 888, in _update_inventory_attempt
Feb 22 11:13:09.064986 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager resource_provider=rp_uuid,
Feb 22 11:13:09.065114 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager nova.exception.InventoryInUse: Inventory for ''CUSTOM_BAREMETAL'' on resource provider 'fdd77c1d-5b1f-4a9a-b168-0fa93362b95d' in use.
Feb 22 11:13:09.065248 ubuntu-xenial-ovh-bhs1-0002670096 nova-compute[14029]: ERROR nova.compute.manager |
|
