OpenStack Compute (nova)

downgrade the exception log in update_instance_cache_with_nw_info

  1. Series ocata
  2. Bug #1618822
Bug #1618822 reported by jichenjc
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
jichenjc
Ocata
Fix Committed
Medium
Matt Riedemann

Bug Description

when compute node is down, nova api can accept delete action and delete the instance
then during compute start up, periodic task will check whether the instance is deleted in api layer
 then performance actions

saw those logs because actually the info case is already deleted so it's a valid case and should not report this exception ,just a log info should be fine

2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] Traceback (most recent call last):
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 50, in update_instance_cache_with_nw_info
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] ic.save(update_cells=update_cells)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 197, in wrapper
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] ctxt, self, fn.__name__, args, kwargs)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/conductor/rpcapi.py", line 242, in object_action
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] objmethod=objmethod, args=args, kwargs=kwargs)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 158, in call
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] retry=self.retry)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] timeout=timeout, retry=retry)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 431, in send
ages/oslo_messaging/_drivers/amqpdriver.py", line 431, in send
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] retry=retry)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 422, in _send
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] raise result
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] InstanceInfoCacheNotFound_Remote: Info cache for instance d6a78566-0f7d-4173-b35a-b45d2054ba71 could not be found.
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] Traceback (most recent call last):
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 447, in _object_dispatch
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] return getattr(target, method)(*args, **kwargs)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 213, in wrapper
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] return fn(self, *args, **kwargs)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 98, in save
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] {'network_info': nw_info_json})
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 857, in instance_info_cache_update
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] return IMPL.instance_info_cache_update(context, instance_uuid, values)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 216, in wrapper
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] return f(*args, **kwargs)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2684, in instance_info_cache_update
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] instance_uuid=instance_uuid)
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] InstanceInfoCacheNotFound: Info cache for instance d6a78566-0f7d-4173-b35a-b45d2054ba71 could not be found.
2016-08-31 10:13:56.878 25191 ERROR nova.network.base_api [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71]

2016-08-31 10:13:57.101 25191 WARNING nova.compute.manager [req-7801f16c-8845-4825-a18e-9806d142882c - - - - -] [instance: d6a78566-0f7d-4173-b35a-b45d2054ba71] Periodic cleanup failed to delete instance: Info cache for instance d6a78566-0f7d-4173-b35a-b45d2054ba71 could not be found.
Traceback (most recent call last):

  File "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 447, in _object_dispatch
    return getattr(target, method)(*args, **kwargs)

  File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 213, in wrapper
    return fn(self, *args, **kwargs)

  File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 98, in save
    {'network_info': nw_info_json})

  File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 857, in instance_info_cache_update
    return IMPL.instance_info_cache_update(context, instance_uuid, values)

  File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 216, in wrapper
    return f(*args, **kwargs)

  File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2684, in instance_info_cache_update
    instance_uuid=instance_uuid)

InstanceInfoCacheNotFound: Info cache for instance d6a78566-0f7d-4173-b35a-b45d2054ba71 could not be found.

jichenjc (jichenjc)
Changed in nova:
assignee: nobody → jichenjc (jichenjc)
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/363585

Changed in nova:
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on nova (master)

Change abandoned by jichenjc (<email address hidden>) on branch: master
Review: https://review.openstack.org/363585
Reason: we have another patch for this bug

Matt Riedemann (mriedem)
Changed in nova:
importance: Undecided → Medium
OpenStack Infra (hudson-openstack)
Changed in nova:
assignee: jichenjc (jichenjc) → Matt Riedemann (mriedem)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

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

commit ef85c99f5e5ba091b6711d76c88d50aa2dae6989
Author: jichenjc <email address hidden>
Date: Sun Jul 31 21:42:01 2016 +0800

    no instance info cache update if instance deleted

    Avoid instance info cache update if the instance is deleted,
    as the deleted instance's info cache is already deleted in
    db layer and it will report InstanceInfoCacheNotFound
    exception and lead to a few exception logs in compute.

    Please note this is different to regular info cache and
    lead to InstanceInfoCacheNotFound exception, it's in the
    case when you first create the info cache after instance
    delete and InstanceInfo is also deleted.

    Change-Id: I860e9e7c7ef458722135a21c6c5745f5519c56c4
    Closes-Bug: 1618822

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

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/492140

Matt Riedemann (mriedem)
Changed in nova:
assignee: Matt Riedemann (mriedem) → jichenjc (jichenjc)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 16.0.0.0rc1

This issue was fixed in the openstack/nova 16.0.0.0rc1 release candidate.

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

Reviewed: https://review.openstack.org/492140
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=db9cd37a591e4ebce1926556bc4ed8ef908439e4
Submitter: Jenkins
Branch: stable/ocata

commit db9cd37a591e4ebce1926556bc4ed8ef908439e4
Author: jichenjc <email address hidden>
Date: Sun Jul 31 21:42:01 2016 +0800

    no instance info cache update if instance deleted

    Avoid instance info cache update if the instance is deleted,
    as the deleted instance's info cache is already deleted in
    db layer and it will report InstanceInfoCacheNotFound
    exception and lead to a few exception logs in compute.

    Please note this is different to regular info cache and
    lead to InstanceInfoCacheNotFound exception, it's in the
    case when you first create the info cache after instance
    delete and InstanceInfo is also deleted.

    Change-Id: I860e9e7c7ef458722135a21c6c5745f5519c56c4
    Closes-Bug: 1618822
    (cherry picked from commit ef85c99f5e5ba091b6711d76c88d50aa2dae6989)

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

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

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.