yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1812398] [NEW] DBNotAllowed tracebacks in nova-compute logs

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Fri, 18 Jan 2019 14:44:38 -0000
Reply-to: Bug 1812398 <1812398@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

This seems to be a regression in Stein (which was backported to
stable/rocky), but I'm seeing these tracebacks in the nova-compute logs
in stein CI jobs (and on the old side of grenade which would be rocky):

http://logs.openstack.org/80/630980/5/check/grenade-
py3/49818d8/logs/screen-n-cpu.txt.gz#_Jan_17_08_04_31_907868

Jan 17 08:04:31.907868 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.cmd.common [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] No db access allowed in nova-compute:   File "/usr/local/lib/python3.5/dist-packages/eventlet/greenthread.py", line 214, in main
Jan 17 08:04:31.908055 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     result = function(*args, **kwargs)
Jan 17 08:04:31.908244 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/utils.py", line 810, in context_wrapper
Jan 17 08:04:31.908416 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return func(*args, **kwargs)
Jan 17 08:04:31.908593 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 437, in gather_result
Jan 17 08:04:31.908774 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     with target_cell(context, cell_mapping) as cctxt:
Jan 17 08:04:31.908951 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/usr/lib/python3.5/contextlib.py", line 59, in __enter__
Jan 17 08:04:31.909129 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return next(self.gen)
Jan 17 08:04:31.909303 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 406, in target_cell
Jan 17 08:04:31.909468 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     set_target_cell(cctxt, cell_mapping)
Jan 17 08:04:31.909634 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 380, in set_target_cell
Jan 17 08:04:31.909800 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     get_or_set_cached_cell_and_set_connections()
Jan 17 08:04:31.909981 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
Jan 17 08:04:31.910147 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return f(*args, **kwargs)
Jan 17 08:04:31.910313 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 370, in get_or_set_cached_cell_and_set_connections
Jan 17 08:04:31.910504 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     db_connection_string)
Jan 17 08:04:31.910671 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/db/api.py", line 80, in create_context_manager
Jan 17 08:04:31.910836 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return IMPL.create_context_manager(connection=connection)
Jan 17 08:04:31.911019 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/cmd/common.py", line 46, in __call__
Jan 17 08:04:31.911186 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     stacktrace = "".join(traceback.format_stack())
Jan 17 08:04:31.911367 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: 
Jan 17 08:04:31.911557 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: DEBUG oslo_concurrency.lockutils [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] Lock "00000000-0000-0000-0000-000000000000" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.003s {{(pid=29129) inner /usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py:285}}
Jan 17 08:04:31.911732 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] Error gathering result from cell 00000000-0000-0000-0000-000000000000: nova.exception.DBNotAllowed: nova-compute
Jan 17 08:04:31.911897 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context Traceback (most recent call last):
Jan 17 08:04:31.912064 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 366, in get_or_set_cached_cell_and_set_connections
Jan 17 08:04:31.912227 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     cell_tuple = CELL_CACHE[cell_mapping.uuid]
Jan 17 08:04:31.912391 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context KeyError: '00000000-0000-0000-0000-000000000000'
Jan 17 08:04:31.912563 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context 
Jan 17 08:04:31.912736 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context During handling of the above exception, another exception occurred:
Jan 17 08:04:31.912903 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context 
Jan 17 08:04:31.913068 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context Traceback (most recent call last):
Jan 17 08:04:31.913244 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 437, in gather_result
Jan 17 08:04:31.913411 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     with target_cell(context, cell_mapping) as cctxt:
Jan 17 08:04:31.913577 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/usr/lib/python3.5/contextlib.py", line 59, in __enter__
Jan 17 08:04:31.913747 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return next(self.gen)
Jan 17 08:04:31.913929 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 406, in target_cell
Jan 17 08:04:31.914093 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     set_target_cell(cctxt, cell_mapping)
Jan 17 08:04:31.914259 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 380, in set_target_cell
Jan 17 08:04:31.914451 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     get_or_set_cached_cell_and_set_connections()
Jan 17 08:04:31.914630 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
Jan 17 08:04:31.914796 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return f(*args, **kwargs)
Jan 17 08:04:31.914961 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 370, in get_or_set_cached_cell_and_set_connections
Jan 17 08:04:31.915136 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     db_connection_string)
Jan 17 08:04:31.915312 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/db/api.py", line 80, in create_context_manager
Jan 17 08:04:31.915489 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return IMPL.create_context_manager(connection=connection)
Jan 17 08:04:31.915653 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/cmd/common.py", line 50, in __call__
Jan 17 08:04:31.915817 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     raise exception.DBNotAllowed(service_name)
Jan 17 08:04:31.915980 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context nova.exception.DBNotAllowed: nova-compute
Jan 17 08:04:31.916146 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context

** Affects: nova
     Importance: High
         Status: Confirmed


** Tags: compute 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/1812398

Title:
  DBNotAllowed tracebacks in nova-compute logs

Status in OpenStack Compute (nova):
  Confirmed

Bug description:
  This seems to be a regression in Stein (which was backported to
  stable/rocky), but I'm seeing these tracebacks in the nova-compute
  logs in stein CI jobs (and on the old side of grenade which would be
  rocky):

  http://logs.openstack.org/80/630980/5/check/grenade-
  py3/49818d8/logs/screen-n-cpu.txt.gz#_Jan_17_08_04_31_907868

  Jan 17 08:04:31.907868 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.cmd.common [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] No db access allowed in nova-compute:   File "/usr/local/lib/python3.5/dist-packages/eventlet/greenthread.py", line 214, in main
  Jan 17 08:04:31.908055 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     result = function(*args, **kwargs)
  Jan 17 08:04:31.908244 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/utils.py", line 810, in context_wrapper
  Jan 17 08:04:31.908416 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return func(*args, **kwargs)
  Jan 17 08:04:31.908593 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 437, in gather_result
  Jan 17 08:04:31.908774 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     with target_cell(context, cell_mapping) as cctxt:
  Jan 17 08:04:31.908951 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/usr/lib/python3.5/contextlib.py", line 59, in __enter__
  Jan 17 08:04:31.909129 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return next(self.gen)
  Jan 17 08:04:31.909303 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 406, in target_cell
  Jan 17 08:04:31.909468 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     set_target_cell(cctxt, cell_mapping)
  Jan 17 08:04:31.909634 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 380, in set_target_cell
  Jan 17 08:04:31.909800 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     get_or_set_cached_cell_and_set_connections()
  Jan 17 08:04:31.909981 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
  Jan 17 08:04:31.910147 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return f(*args, **kwargs)
  Jan 17 08:04:31.910313 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/context.py", line 370, in get_or_set_cached_cell_and_set_connections
  Jan 17 08:04:31.910504 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     db_connection_string)
  Jan 17 08:04:31.910671 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/db/api.py", line 80, in create_context_manager
  Jan 17 08:04:31.910836 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     return IMPL.create_context_manager(connection=connection)
  Jan 17 08:04:31.911019 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:   File "/opt/stack/old/nova/nova/cmd/common.py", line 46, in __call__
  Jan 17 08:04:31.911186 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]:     stacktrace = "".join(traceback.format_stack())
  Jan 17 08:04:31.911367 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: 
  Jan 17 08:04:31.911557 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: DEBUG oslo_concurrency.lockutils [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] Lock "00000000-0000-0000-0000-000000000000" released by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.003s {{(pid=29129) inner /usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py:285}}
  Jan 17 08:04:31.911732 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context [None req-c9643771-9860-4f34-ab37-3ea1a6dd9872 None None] Error gathering result from cell 00000000-0000-0000-0000-000000000000: nova.exception.DBNotAllowed: nova-compute
  Jan 17 08:04:31.911897 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context Traceback (most recent call last):
  Jan 17 08:04:31.912064 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 366, in get_or_set_cached_cell_and_set_connections
  Jan 17 08:04:31.912227 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     cell_tuple = CELL_CACHE[cell_mapping.uuid]
  Jan 17 08:04:31.912391 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context KeyError: '00000000-0000-0000-0000-000000000000'
  Jan 17 08:04:31.912563 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context 
  Jan 17 08:04:31.912736 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context During handling of the above exception, another exception occurred:
  Jan 17 08:04:31.912903 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context 
  Jan 17 08:04:31.913068 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context Traceback (most recent call last):
  Jan 17 08:04:31.913244 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 437, in gather_result
  Jan 17 08:04:31.913411 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     with target_cell(context, cell_mapping) as cctxt:
  Jan 17 08:04:31.913577 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/usr/lib/python3.5/contextlib.py", line 59, in __enter__
  Jan 17 08:04:31.913747 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return next(self.gen)
  Jan 17 08:04:31.913929 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 406, in target_cell
  Jan 17 08:04:31.914093 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     set_target_cell(cctxt, cell_mapping)
  Jan 17 08:04:31.914259 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 380, in set_target_cell
  Jan 17 08:04:31.914451 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     get_or_set_cached_cell_and_set_connections()
  Jan 17 08:04:31.914630 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/usr/local/lib/python3.5/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
  Jan 17 08:04:31.914796 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return f(*args, **kwargs)
  Jan 17 08:04:31.914961 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/context.py", line 370, in get_or_set_cached_cell_and_set_connections
  Jan 17 08:04:31.915136 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     db_connection_string)
  Jan 17 08:04:31.915312 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/db/api.py", line 80, in create_context_manager
  Jan 17 08:04:31.915489 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     return IMPL.create_context_manager(connection=connection)
  Jan 17 08:04:31.915653 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context   File "/opt/stack/old/nova/nova/cmd/common.py", line 50, in __call__
  Jan 17 08:04:31.915817 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context     raise exception.DBNotAllowed(service_name)
  Jan 17 08:04:31.915980 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context nova.exception.DBNotAllowed: nova-compute
  Jan 17 08:04:31.916146 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: ERROR nova.context

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

[Bug 1812398] Re: DBNotAllowed tracebacks in nova-compute logs
From: Matt Riedemann, 2019-01-18