yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1804325] [NEW] InstanceNotFound traceback errors in n-api logs while polling for server delete

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Tue, 20 Nov 2018 22:18:36 -0000
Reply-to: Bug 1804325 <1804325@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

As a result of this change:

https://review.openstack.org/#/c/591658/

The nova-api logs now traceback InstanceNotFound errors when polling a
server to be deleted, which is an expected situation and we shouldn't be
logging errors in the API logs for that:

http://logs.openstack.org/58/591658/22/check/tempest-
full/04cf08b/controller/logs/screen-n-api.txt.gz?level=ERROR

Nov 05 11:46:49.066760 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context [None req-8b6e5657-8ac9-4c33-9337-87c58b32fc7a tempest-DeleteServersAdminTestJSON-984972888 tempest-DeleteServersAdminTestJSON-984972888] Error gathering result from cell f40f1143-3d61-4e69-8377-a35e2fd47356: InstanceNotFound: Instance 45cbaca4-7e53-45df-99da-13674d0a241f could not be found.
Nov 05 11:46:49.067002 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context Traceback (most recent call last):
Nov 05 11:46:49.067223 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/context.py", line 441, in gather_result
Nov 05 11:46:49.067463 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     result = fn(cctxt, *args, **kwargs)
Nov 05 11:46:49.067708 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper
Nov 05 11:46:49.067932 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     result = fn(cls, context, *args, **kwargs)
Nov 05 11:46:49.068173 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/objects/instance.py", line 503, in get_by_uuid
Nov 05 11:46:49.068408 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     use_slave=use_slave)
Nov 05 11:46:49.068639 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 212, in wrapper
Nov 05 11:46:49.068954 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(*args, **kwargs)
Nov 05 11:46:49.069175 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/objects/instance.py", line 495, in _db_instance_get_by_uuid
Nov 05 11:46:49.069399 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     columns_to_join=columns_to_join)
Nov 05 11:46:49.069814 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/api.py", line 758, in instance_get_by_uuid
Nov 05 11:46:49.070036 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return IMPL.instance_get_by_uuid(context, uuid, columns_to_join)
Nov 05 11:46:49.070262 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 170, in wrapper
Nov 05 11:46:49.070523 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(*args, **kwargs)
Nov 05 11:46:49.070766 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 257, in wrapped
Nov 05 11:46:49.071002 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(context, *args, **kwargs)
Nov 05 11:46:49.071221 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1845, in instance_get_by_uuid
Nov 05 11:46:49.071517 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     columns_to_join=columns_to_join)
Nov 05 11:46:49.071756 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1854, in _instance_get_by_uuid
Nov 05 11:46:49.071990 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     raise exception.InstanceNotFound(instance_id=uuid)
Nov 05 11:46:49.072222 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context InstanceNotFound: Instance 45cbaca4-7e53-45df-99da-13674d0a241f could not be found.
Nov 05 11:46:49.072481 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context

** Affects: nova
     Importance: High
         Status: Triaged


** Tags: cells logging serviceability

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

Title:
  InstanceNotFound traceback errors in n-api logs while polling for
  server delete

Status in OpenStack Compute (nova):
  Triaged

Bug description:
  As a result of this change:

  https://review.openstack.org/#/c/591658/

  The nova-api logs now traceback InstanceNotFound errors when polling a
  server to be deleted, which is an expected situation and we shouldn't
  be logging errors in the API logs for that:

  http://logs.openstack.org/58/591658/22/check/tempest-
  full/04cf08b/controller/logs/screen-n-api.txt.gz?level=ERROR

  Nov 05 11:46:49.066760 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context [None req-8b6e5657-8ac9-4c33-9337-87c58b32fc7a tempest-DeleteServersAdminTestJSON-984972888 tempest-DeleteServersAdminTestJSON-984972888] Error gathering result from cell f40f1143-3d61-4e69-8377-a35e2fd47356: InstanceNotFound: Instance 45cbaca4-7e53-45df-99da-13674d0a241f could not be found.
  Nov 05 11:46:49.067002 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context Traceback (most recent call last):
  Nov 05 11:46:49.067223 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/context.py", line 441, in gather_result
  Nov 05 11:46:49.067463 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     result = fn(cctxt, *args, **kwargs)
  Nov 05 11:46:49.067708 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper
  Nov 05 11:46:49.067932 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     result = fn(cls, context, *args, **kwargs)
  Nov 05 11:46:49.068173 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/objects/instance.py", line 503, in get_by_uuid
  Nov 05 11:46:49.068408 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     use_slave=use_slave)
  Nov 05 11:46:49.068639 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 212, in wrapper
  Nov 05 11:46:49.068954 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(*args, **kwargs)
  Nov 05 11:46:49.069175 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/objects/instance.py", line 495, in _db_instance_get_by_uuid
  Nov 05 11:46:49.069399 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     columns_to_join=columns_to_join)
  Nov 05 11:46:49.069814 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/api.py", line 758, in instance_get_by_uuid
  Nov 05 11:46:49.070036 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return IMPL.instance_get_by_uuid(context, uuid, columns_to_join)
  Nov 05 11:46:49.070262 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 170, in wrapper
  Nov 05 11:46:49.070523 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(*args, **kwargs)
  Nov 05 11:46:49.070766 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 257, in wrapped
  Nov 05 11:46:49.071002 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     return f(context, *args, **kwargs)
  Nov 05 11:46:49.071221 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1845, in instance_get_by_uuid
  Nov 05 11:46:49.071517 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     columns_to_join=columns_to_join)
  Nov 05 11:46:49.071756 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context   File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1854, in _instance_get_by_uuid
  Nov 05 11:46:49.071990 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context     raise exception.InstanceNotFound(instance_id=uuid)
  Nov 05 11:46:49.072222 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context InstanceNotFound: Instance 45cbaca4-7e53-45df-99da-13674d0a241f could not be found.
  Nov 05 11:46:49.072481 ubuntu-xenial-rax-dfw-0000329307 devstack@n-api.service[5952]: ERROR nova.context

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1804325/+subscriptions
Follow ups

[Bug 1804325] Re: InstanceNotFound traceback errors in n-api logs while polling for server delete
From: OpenStack Infra, 2018-12-24