placement logs an ERROR when PUT /allocation result in an invalid inventory

Bug #1705487 reported by Balazs Gibizer
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Jay Pipes

Bug Description

When an allocation requests on placement results in an invalid inventory due to the capacity is exceeded then placement return HTTP 409 properly but at the same time logs an ERROR log (see below).
The ERROR log is not necessary as this is not a software error.

Jul 20 11:44:38 ubuntu <email address hidden>[9538]: [pid: 9543|app: 0|req: 790/1579] 192.168.122.191 () {66 vars in 1440 bytes} [Thu Jul 20 11:44:38 2017] PUT /placement/allocations/485c7480-939c-4b88-8c
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG nova.api.openstack.placement.requestlog [None req-ce309a62-3819-4ccb-8491-828046235f2d service placement] Starting request: 192.168.122.191 "GET
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-ce309a62-3819-4ccb-8491-828046235f2d service placement] Acquired semaphore "rc_cache" {{(pid=9542) lock /usr
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-ce309a62-3819-4ccb-8491-828046235f2d service placement] Releasing semaphore "rc_cache" {{(pid=9542) lock /us
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: INFO nova.api.openstack.placement.requestlog [None req-ce309a62-3819-4ccb-8491-828046235f2d service placement] 192.168.122.191 "GET /placement/allocati
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: [pid: 9542|app: 0|req: 790/1580] 192.168.122.191 () {60 vars in 1344 bytes} [Thu Jul 20 11:44:38 2017] GET /placement/allocations/9fff84b6-71e4-4f53-ad
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG nova.api.openstack.placement.requestlog [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Starting request: 192.168.122.191 "PUT
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Acquired semaphore "rc_cache" {{(pid=9543) lock /usr
Jul 20 11:44:38 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Releasing semaphore "rc_cache" {{(pid=9543) lock /us
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Acquired semaphore "rc_cache" {{(pid=9543) lock /usr
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Releasing semaphore "rc_cache" {{(pid=9543) lock /us
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Acquired semaphore "rc_cache" {{(pid=9543) lock /usr
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: DEBUG oslo_concurrency.lockutils [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Releasing semaphore "rc_cache" {{(pid=9543) lock /us
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Bad inventory: InvalidInventor
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation Traceback (most recent call last):
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation File "/opt/stack/nova/nova/api/openstack/placement/handlers/allocation.py", line 249, in _set_
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation allocations.create_all()
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation File "/opt/stack/nova/nova/objects/resource_provider.py", line 1869, in create_all
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation self._set_allocations(self._context, self.objects)
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 979, in
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation return fn(*args, **kwargs)
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation File "/opt/stack/nova/nova/objects/resource_provider.py", line 1829, in _set_allocations
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation before_gens = _check_capacity_exceeded(conn, allocs)
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation File "/opt/stack/nova/nova/objects/resource_provider.py", line 1633, in _check_capacity_exceed
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation resource_provider=rp_uuid)
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation InvalidInventory: Inventory for 'CUSTOM_MAGIC' on resource provider 'a0a1d7f3-41f0-448f-ba36-e57
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: ERROR nova.api.openstack.placement.handlers.allocation
Jul 20 11:44:39 ubuntu <email address hidden>[9538]: DEBUG nova.api.openstack.placement.wsgi_wrapper [None req-149d9b07-f06c-4b5b-ae8d-504d2a51340e service placement] Placement API returning an error resp

Tags: placement
tags: added: placement
Revision history for this message
Jay Pipes (jaypipes) wrote :

Sure, this is a straightforward bug and fix. Just need to make the LOG be a DEBUG level not ERROR since, as Gibi points out, it's not a software error. Merely attempted to allocate against a full provider.

Changed in nova:
status: New → Triaged
importance: Undecided → Low
assignee: nobody → Jay Pipes (jaypipes)
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/485726

Changed in nova:
status: Triaged → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/485726
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=66988da3db3bf73cd380db303bd0ca9bebcb3c64
Submitter: Jenkins
Branch: master

commit 66988da3db3bf73cd380db303bd0ca9bebcb3c64
Author: Jay Pipes <email address hidden>
Date: Thu Jul 20 11:58:09 2017 -0400

    Remove improper LOG.exception() calls in placement

    The PUT /allocations Placement API handler was improperly calling
    LOG.exception() when two normal-operation events were occurring:

    1) When a concurrent attempt to allocate against the same resource
    providers had occurred

    2) When, due to another process consuming resources concurrently
    resulted in capacity being exceeded on one or more of the requested
    providers

    Neither of the above scenarios is a software error and so the
    LOG.exception() calls have been removed.

    Change-Id: I569b28313e52d979ac9be5bea88c021a0664d851
    Fixes-bug: #1705487

Changed in nova:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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