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

[Matt Riedemann]

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.

[Matt Riedemann (mriedem)]

Looks like we need to pass this header through on requests:

https://github.com/openstack/oslo.middleware/blob/3.38.0/oslo_middleware/request_id.py#L27

like this:

https://github.com/openstack/nova/blob/2e85453879533af0b4d0e1178797d26f026a9423/nova/scheduler/client/report.py#L252

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/662715

[OpenStack Infra (hudson-openstack)]

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 <email address hidden>
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

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/670694

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/670694
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=bb551ddd74fafa3be1c168e9e49e052d2ff75a4b
Submitter: Zuul
Branch: stable/stein

commit bb551ddd74fafa3be1c168e9e49e052d2ff75a4b
Author: Takashi NATSUME <email address hidden>
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.

    Conflicts:
      nova/tests/unit/network/test_neutronv2.py

      The conflict is due to not including
      I1788389d11a9f3b6b0bd0b75d2184be9e90983bb in stable/stein

    Change-Id: I76163c46b1f01ba7ff592d162b106ea2e5bb34cb
    Closes-Bug: #1829914
    (cherry picked from commit e11b589474e6e469442277d1e17d3140e8bf0d6b)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 19.0.2 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 20.0.0.0rc1 release candidate.