OpenStack Compute (nova)

InventoryInUse exception is periodically logged as ERROR

  1. Series pike
  2. Bug #1751472
Bug #1751472 reported by Hironori Shiina
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Hironori Shiina
Pike
Fix Committed
Medium
Sylvain Bauza
Queens
Fix Committed
Medium
Sylvain Bauza

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

See original description
Hironori Shiina (shiina-hironori)
description: updated
Sylvain Bauza (sylvain-bauza)
Changed in nova:
status: New → Confirmed
importance: Undecided → Low
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
assignee: nobody → Hironori Shiina (shiina-hironori)
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/553367
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=ac20fc22adb133d9de5f2ec15faad11b2de1987a
Submitter: Zuul
Branch: master

commit ac20fc22adb133d9de5f2ec15faad11b2de1987a
Author: Hironori Shiina <email address hidden>
Date: Thu Mar 15 20:44:50 2018 +0900

    ironic: Get correct inventory for deployed node

    _node_resources_unavailable() is supposed to be called after
    _node_resources_used() returns False. Because get_inventory() doesn't
    satisfy this condition, this method returns an empty inventory for a
    deployed bare metal node. It causes the resource tracker to try
    removing an allocated inventory from placement. This removal results
    in periodic unexpected errors.

    This patch calls _node_resources_used() prior to
    _node_resources_unanvailable() for getting a proper inventory.

    Change-Id: I6717ce19f6005c8ebb7af75437a72876c5a53f34
    Closes-Bug: 1751472

Changed in nova:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (stable/queens)

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/561923

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (stable/pike)

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/561925

Matt Riedemann (mriedem)
Changed in nova:
importance: Low → Medium
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (stable/queens)

Reviewed: https://review.openstack.org/561923
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=525ea3cfac0d91752bdac1bbca4191976d3c592a
Submitter: Zuul
Branch: stable/queens

commit 525ea3cfac0d91752bdac1bbca4191976d3c592a
Author: Hironori Shiina <email address hidden>
Date: Thu Mar 15 20:44:50 2018 +0900

    ironic: Get correct inventory for deployed node

    _node_resources_unavailable() is supposed to be called after
    _node_resources_used() returns False. Because get_inventory() doesn't
    satisfy this condition, this method returns an empty inventory for a
    deployed bare metal node. It causes the resource tracker to try
    removing an allocated inventory from placement. This removal results
    in periodic unexpected errors.

    This patch calls _node_resources_used() prior to
    _node_resources_unanvailable() for getting a proper inventory.

    Change-Id: I6717ce19f6005c8ebb7af75437a72876c5a53f34
    Closes-Bug: 1751472
    (cherry picked from commit ac20fc22adb133d9de5f2ec15faad11b2de1987a)

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (stable/pike)

Reviewed: https://review.openstack.org/561925
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=15aed7e0e0b4564d78db466e565e612eda6c502a
Submitter: Zuul
Branch: stable/pike

commit 15aed7e0e0b4564d78db466e565e612eda6c502a
Author: Hironori Shiina <email address hidden>
Date: Thu Mar 15 20:44:50 2018 +0900

    ironic: Get correct inventory for deployed node

    _node_resources_unavailable() is supposed to be called after
    _node_resources_used() returns False. Because get_inventory() doesn't
    satisfy this condition, this method returns an empty inventory for a
    deployed bare metal node. It causes the resource tracker to try
    removing an allocated inventory from placement. This removal results
    in periodic unexpected errors.

    This patch calls _node_resources_used() prior to
    _node_resources_unanvailable() for getting a proper inventory.

    Change-Id: I6717ce19f6005c8ebb7af75437a72876c5a53f34
    Closes-Bug: 1751472
    (cherry picked from commit ac20fc22adb133d9de5f2ec15faad11b2de1987a)
    (cherry picked from commit 525ea3cfac0d91752bdac1bbca4191976d3c592a)

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 18.0.0.0b1

This issue was fixed in the openstack/nova 18.0.0.0b1 development milestone.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 16.1.2

This issue was fixed in the openstack/nova 16.1.2 release.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 17.0.3

This issue was fixed in the openstack/nova 17.0.3 release.

Revision history for this message
Vladyslav Drok (vdrok) wrote :

This issue started to appear again -- http://logs.openstack.org/39/554439/20/check/ironic-tempest-dsvm-ipa-wholedisk-bios-agent_ipmitool-tinyipa/e3c2ae3/logs/screen-n-cpu.txt.gz#_May_15_14_51_20_013490

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.