yahoo-eng-team team mailing list archive

[OpenStack Infra <1829914@xxxxxxxxxxxxxxxxxx>]

Reviewed:  https://review.opendev.org/662715
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e11b589474e6e469442277d1e17d3140e8bf0d6b
Submitter: Zuul
Branch:    master

commit e11b589474e6e469442277d1e17d3140e8bf0d6b
Author: Takashi NATSUME <natsume.takashi@xxxxxxxxxxxxx>
Date:   Mon Jun 3 16:27:42 2019 +0900

    Fix no propagation of nova context request_id
    
    Nova context request_id is not propagated for
    port binding operations in neutron.
    So fix it.
    
    Change-Id: I76163c46b1f01ba7ff592d162b106ea2e5bb34cb
    Closes-Bug: #1829914


** Changed in: nova
       Status: In Progress => Fix Released

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

Title:
  nova context request_id is not propagated for port binding operations
  in neutron

Status in OpenStack Compute (nova):
  Fix Released

Bug description:
  While debugging a neutron failure from the nova logs, I'm tracing the
  API request through the nova logs using the request ID generated from
  the nova RequestContext created in the API.

  Down in the nova-compute code it's deleting a port binding resource in
  neutron, but because we are using keystoneauth1 to create the session
  to work with port binding resources:

  https://github.com/openstack/nova/blob/2e85453879533af0b4d0e1178797d26f026a9423/nova/network/neutronv2/api.py#L1342

  We aren't propagating the request id through like we would with using
  python-neutronclient:

  https://github.com/openstack/nova/blob/2e85453879533af0b4d0e1178797d26f026a9423/nova/network/neutronv2/api.py#L182

  Which makes tracing harder. For example, this is the nova-side of the
  request:

  May 16 19:47:42.950266 ubuntu-bionic-rax-dfw-0006201125 nova-compute[29518]: DEBUG nova.compute.manager [None req-7b5ea04d-ce59-4542-90df-6dabdbd8cde9 tempest-MigrationsAdminTest-90987790 tempest-MigrationsAdminTest-90987790] [instance: 21c45b79-b0f4-48a8-8949-9f480beb5864] Deleting port bindings for target host. {{(pid=29518) _revert_snapshot_based_resize_at_dest /opt/stack/nova/nova/compute/manager.py:4244}}
  May 16 19:47:43.269367 ubuntu-bionic-rax-dfw-0006201125 nova-compute[29518]: DEBUG nova.network.neutronv2.api [None req-7b5ea04d-ce59-4542-90df-6dabdbd8cde9 tempest-MigrationsAdminTest-90987790 tempest-MigrationsAdminTest-90987790] Deleted binding for port 0d72966a-5dd4-42c2-a2af-2d0952d8112f and host ubuntu-bionic-rax-dfw-0006201125. {{(pid=29518) delete_port_binding /opt/stack/nova/nova/network/neutronv2/api.py:1346}}

  Note the request_id there is req-7b5ea04d-ce59-4542-90df-6dabdbd8cde9.

  The related neutron server side logging is this:

  May 16 19:47:43.254159 ubuntu-bionic-rax-dfw-0006201125 neutron-server[20059]: DEBUG neutron.plugins.ml2.db [None req-aecdfb32-a470-4b68-a5e9-93cfaeb09e8c service neutron] For port 0d72966a-5dd4-42c2-a2af-2d0952d8112f, host ubuntu-bionic-rax-dfw-0006201125, cleared binding levels {{(pid=20439) clear_binding_levels /opt/stack/neutron/neutron/plugins/ml2/db.py:109}}
  May 16 19:47:43.266272 ubuntu-bionic-rax-dfw-0006201125 neutron-server[20059]: DEBUG neutron_lib.callbacks.manager [None req-aecdfb32-a470-4b68-a5e9-93cfaeb09e8c service neutron] Notify callbacks [] for binding, before_response {{(pid=20439) _notify_loop /usr/local/lib/python3.6/dist-packages/neutron_lib/callbacks/manager.py:193}}
  May 16 19:47:43.267360 ubuntu-bionic-rax-dfw-0006201125 neutron-server[20059]: INFO neutron.wsgi [None req-aecdfb32-a470-4b68-a5e9-93cfaeb09e8c service neutron] 10.209.34.72,10.209.34.72 "DELETE /v2.0/ports/0d72966a-5dd4-42c2-a2af-2d0952d8112f/bindings/ubuntu-bionic-rax-dfw-0006201125 HTTP/1.1" status: 204  len: 173 time: 0.1742756

  In that case, the request_id in the neutron logs is req-
  aecdfb32-a470-4b68-a5e9-93cfaeb09e8c.

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