devstack

DBNotAllowed tracebacks in nova-compute logs when running in singleconductor mode (grenade)

Bug #1812398 reported by Matt Riedemann
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
devstack
Fix Released
Medium
Matt Riedemann

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

Revision history for this message
Matt Riedemann (mriedem) wrote :

I think it might be this change:

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

And looking at the grenade job failure, nova-compute is using nova.conf rather than nova-cpu.conf which is why it's hitting the API DB (which means something is wrong in devstack).

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

Jan 17 08:04:32.547867 ubuntu-xenial-inap-mtl01-0001764122 nova-compute[29129]: DEBUG oslo_service.service [None req-6462a6fa-ac8b-4802-bed8-18c335fc623f None None] command line args: ['--config-file', '/etc/nova/nova.conf'] {{(pid=29129) log_opt_values /usr/local/lib/python3.5/dist-packages/oslo_config/cfg.py:3008}}

Revision history for this message
Matt Riedemann (mriedem) wrote :

This change was meant as a dependency for the one above:

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

But with grenade, we run in singleconductor mode which means nova-compute isn't using nova-cpu.conf.

Revision history for this message
Matt Riedemann (mriedem) wrote :

Checking logstash it is just all grenade jobs:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22DBNotAllowed%3A%20nova-compute%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d

So we need to use a stripped down config file for nova-compute in singleconductor mode as well it sounds like, by at least removing the database config options.

Changed in nova:
status: Confirmed → Invalid
Changed in devstack:
status: New → Triaged
summary: - DBNotAllowed tracebacks in nova-compute logs
+ DBNotAllowed tracebacks in nova-compute logs when running in
+ singleconductor mode (grenade)
Changed in devstack:
importance: Undecided → Medium
no longer affects: nova
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to devstack (master)

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

Changed in devstack:
assignee: nobody → Matt Riedemann (mriedem)
status: Triaged → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to devstack (stable/rocky)

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/632095

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

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to devstack (master)

Reviewed: https://review.openstack.org/631811
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=82537871376afe98a286e1ba424cf192ae60869a
Submitter: Zuul
Branch: master

commit 82537871376afe98a286e1ba424cf192ae60869a
Author: Matt Riedemann <email address hidden>
Date: Fri Jan 18 10:42:13 2019 -0500

    Restrict database access to nova-compute in singleconductor mode

    Change I4820abe57a023050dd8d067c77e26028801ff288 removed access
    to the database for the nova-compute process but only in
    superconductor mode. Grenade runs in singleconductor mode though
    so we are getting tracebacks in nova-compute logs during grenade
    runs because nova-compute is running with nova.conf which is
    configured with access to the nova API database.

    This change handles removing database access for nova-compute
    generically to cover both the singleconductor and superconductor
    cases.

    Change-Id: I81301eeecc7669a169deeb1e2c5d298a595aab94
    Closes-Bug: #1812398

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

Reviewed: https://review.openstack.org/632095
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=1b2408b4f33710d404c4da4dde6bc096d6e691f4
Submitter: Zuul
Branch: stable/rocky

commit 1b2408b4f33710d404c4da4dde6bc096d6e691f4
Author: Matt Riedemann <email address hidden>
Date: Fri Jan 18 10:42:13 2019 -0500

    Restrict database access to nova-compute in singleconductor mode

    Change I4820abe57a023050dd8d067c77e26028801ff288 removed access
    to the database for the nova-compute process but only in
    superconductor mode. Grenade runs in singleconductor mode though
    so we are getting tracebacks in nova-compute logs during grenade
    runs because nova-compute is running with nova.conf which is
    configured with access to the nova API database.

    This change handles removing database access for nova-compute
    generically to cover both the singleconductor and superconductor
    cases.

    Change-Id: I81301eeecc7669a169deeb1e2c5d298a595aab94
    Closes-Bug: #1812398
    (cherry picked from commit 82537871376afe98a286e1ba424cf192ae60869a)

tags: added: in-stable-rocky
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to devstack (stable/queens)

Reviewed: https://review.openstack.org/632100
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=c7114582c0b88f379cae795c8bc88bf840d0965a
Submitter: Zuul
Branch: stable/queens

commit c7114582c0b88f379cae795c8bc88bf840d0965a
Author: Matt Riedemann <email address hidden>
Date: Fri Jan 18 10:42:13 2019 -0500

    Restrict database access to nova-compute in singleconductor mode

    Change I4820abe57a023050dd8d067c77e26028801ff288 removed access
    to the database for the nova-compute process but only in
    superconductor mode. Grenade runs in singleconductor mode though
    so we are getting tracebacks in nova-compute logs during grenade
    runs because nova-compute is running with nova.conf which is
    configured with access to the nova API database.

    This change handles removing database access for nova-compute
    generically to cover both the singleconductor and superconductor
    cases.

    Conflicts:
          lib/nova

    NOTE(mriedem): Conflict is due to not having change
    I2a98795674183e2c05c29e15a3a3bad1a22c0891 in stable/queens.

    Change-Id: I81301eeecc7669a169deeb1e2c5d298a595aab94
    Closes-Bug: #1812398
    (cherry picked from commit 82537871376afe98a286e1ba424cf192ae60869a)
    (cherry picked from commit 1b2408b4f33710d404c4da4dde6bc096d6e691f4)

tags: added: in-stable-queens
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.