yahoo-eng-team team mailing list archive

[Matt Riedemann <mriedem.os@xxxxxxxxx>]

** Changed in: nova/pike
       Status: Confirmed => Won't Fix

** Changed in: nova/queens
       Status: In Progress => Won't Fix

** Changed in: nova/queens
     Assignee: Matt Riedemann (mriedem) => (unassigned)

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

Title:
  nova-api startup does not scan cells looking for minimum nova-compute
  service version

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) pike series:
  Won't Fix
Status in OpenStack Compute (nova) queens series:
  Won't Fix
Status in OpenStack Compute (nova) rocky series:
  Fix Committed

Bug description:
  This CI job failed devstack setup because nova-api took longer than 60
  seconds to start (it took 64 seconds):

  http://logs.openstack.org/01/619701/5/gate/tempest-
  slow/2bb461b/controller/logs/screen-n-api.txt.gz

  Looking at what could be taking time in there, it was noticed that
  this is logged a lot:

  Dec 05 20:14:00.919520 ubuntu-xenial-ovh-bhs1-0000959981
  devstack@n-api.service[23459]: DEBUG nova.compute.rpcapi [None req-
  dfdfad07-2ff4-43ed-9f67-2acd59687e0c None None] Not caching compute
  RPC version_cap, because min service_version is 0. Please ensure a
  nova-compute service has been started. Defaulting to current version.
  {{(pid=23462) _determine_version_cap
  /opt/stack/nova/nova/compute/rpcapi.py:397}}

  That's coming from here:

  https://github.com/openstack/nova/blob/aed3e240138ad84352688611246363339414c98f/nova/compute/rpcapi.py#L396

  Which is when the compute rpcapi client is initialized, which happens
  when nova.compute.api.API is initialized:

  https://github.com/openstack/nova/blob/aed3e240138ad84352688611246363339414c98f/nova/compute/api.py#L266

  Which happens for most of the API extensions, e.g.:

  https://github.com/openstack/nova/blob/aed3e240138ad84352688611246363339414c98f/nova/api/openstack/compute/servers.py#L78

  So that init and DB query happens num_workers * num_extensions times
  (we have 2 workers in this case and it looks like there are at least
  29 instantiations of the compute API code in the extensions).

  The bigger problem is that in this case, nova-api is configured to hit
  cell0 for the [database]/connection:

  http://logs.openstack.org/01/619701/5/gate/tempest-
  slow/2bb461b/controller/logs/etc/nova/nova_conf.txt.gz

  [database]
  connection = mysql+pymysql://root:secretdatabase@127.0.0.1/nova_cell0?charset=utf8

  And there will not be nova-compute services in the cell0 database (if
  configured properly).

  So this query is always going to return 0, at least for devstack:

  https://github.com/openstack/nova/blob/aed3e240138ad84352688611246363339414c98f/nova/compute/rpcapi.py#L387

  We should really be scanning the cells to get the minimum nova-compute
  version using this:

  https://github.com/openstack/nova/blob/aed3e240138ad84352688611246363339414c98f/nova/objects/service.py#L481

  But even on first startup of nova-api before any computes are started
  and registered with a cell, that initial query will return 0 which
  means we won't cache the result and continue to do that query and log
  that message for extensions * workers.

  So there are really kind of two issues here:

  1. We're not iterating cells properly for that version check. This is
  the more important issue.

  2. We're needlessly doing this query on initial startup which slows
  down the startup (and contributes to timeouts the devstack jobs on
  slow nodes) and lots of excessive logging.

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