yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1751472] Re: InventoryInUse exception is periodically logged as ERROR

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Tue, 17 Apr 2018 13:46:43 -0000
Reply-to: Bug 1751472 <1751472@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Also affects: nova/queens
   Importance: Undecided
       Status: New

** Also affects: nova/pike
   Importance: Undecided
       Status: New

** Changed in: nova/pike
       Status: New => In Progress

** Changed in: nova
   Importance: Low => Medium

** Changed in: nova/queens
       Status: New => In Progress

** Changed in: nova/queens
   Importance: Undecided => Medium

** Changed in: nova/pike
   Importance: Undecided => Medium

** Changed in: nova/pike
     Assignee: (unassigned) => Sylvain Bauza (sylvain-bauza)

** Changed in: nova/queens
     Assignee: (unassigned) => Sylvain Bauza (sylvain-bauza)

-- 
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/1751472

Title:
  InventoryInUse exception is periodically logged as ERROR

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) pike series:
  In Progress
Status in OpenStack Compute (nova) queens series:
  In Progress

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

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1751472/+subscriptions
References

[Bug 1751472] [NEW] InventoryInUse exception is periodically logged as ERROR
From: Hironori Shiina, 2018-02-24