yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1823198] Re: NetworkAmbiguous traceback in nova-compute logs even though it's a user error

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1823198@xxxxxxxxxxxxxxxxxx>
Date: Tue, 23 Jul 2019 22:44:05 -0000
Reply-to: Bug 1823198 <1823198@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.opendev.org/650077
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=ade6c9393632e830c2368825568769853fce3b99
Submitter: Zuul
Branch:    master

commit ade6c9393632e830c2368825568769853fce3b99
Author: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date:   Thu Apr 4 13:04:33 2019 -0400

    Handle Invalid exceptions as expected in attach_interface
    
    The bug prompting this is a tempest test which is requesting
    a port attachment to a server but not specifying a port or
    network to use, so nova-compute looks for a valid network
    and finds there are two and raises NetworkAmbiguous. This
    is treated as a 400 error in the API but because this is a
    synchronous RPC call from nova-api to nova-compute,
    oslo.messaging logs an exception traceback for the unexpected
    error. That traceback is pretty gross in the compute logs for
    something that is a user error and the cloud operator has
    nothing to do to fix it.
    
    We can handle the traceback by registering our expected
    exceptions for the attach_interface method with oslo.messaging,
    which is what this change does.
    
    While looking to just add NetworkAmbiguous it became clear that
    lots of different user errors can be raised from this method
    and none of those should result in a traceback, so this change
    just expects Invalid and its subclasses.
    
    The one exception is InterfaceAttachFailed which is raised when
    something in allocate_port_for_instance or driver.attach_interface
    fails. That is an unexpected situation so the parent class for
    InterfaceAttachFailed is changed from Invalid to NovaException so
    it continues to be traced in the logs as an exception.
    InterfaceAttachFailedNoNetwork is kept as Invalid since it is a
    user error (trying to attach an interface when the user has no
    access to any networks).
    
    test_tagged_attach_interface_raises is adjusted to show the
    ExpectedException handling for one of the Invalid cases.
    
    Change-Id: I927ff1d8c8f45405833d6012b7d7af37b98b10a0
    Closes-Bug: #1823198


** 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/1823198

Title:
  NetworkAmbiguous traceback in nova-compute logs even though it's a
  user error

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) queens series:
  Triaged
Status in OpenStack Compute (nova) rocky series:
  Triaged
Status in OpenStack Compute (nova) stein series:
  In Progress

Bug description:
  There is a tempest negative test which is trying to attach a network
  interface to a server but it is not requesting a specific network or
  port:

  http://logs.openstack.org/58/637058/15/check/nova-
  next/f4e8140/logs/tempest.txt.gz#_2019-04-04_00_07_20_973

  2019-04-04 00:07:20.973 7584 INFO tempest.lib.common.rest_client [req-47bc59bc-01de-450c-9185-3c0b9dc4bf51 ] Request (AttachInterfacesTestJSON:test_create_list_show_delete_interfaces_by_network_port): 400 POST https://104.130.239.125/compute/v2.1/servers/7f24a95b-b5be-4269-980b-a92f3c07c7ca/os-interface 0.678s
  2019-04-04 00:07:20.974 7584 DEBUG tempest.lib.common.rest_client [req-47bc59bc-01de-450c-9185-3c0b9dc4bf51 ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
          Body: {"interfaceAttachment": {}}
      Response - Headers: {'date': 'Thu, 04 Apr 2019 00:07:20 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '115', 'x-openstack-request-id': 'req-47bc59bc-01de-450c-9185-3c0b9dc4bf51', 'x-compute-request-id': 'req-47bc59bc-01de-450c-9185-3c0b9dc4bf51', 'connection': 'close', 'status': '400', 'content-location': 'https://104.130.239.125/compute/v2.1/servers/7f24a95b-b5be-4269-980b-a92f3c07c7ca/os-interface'}
          Body: b'{"badRequest": {"code": 400, "message": "Multiple possible networks found, use a Network ID to be more specific."}}' _log_request_full /opt/stack/new/tempest/tempest/lib/common/rest_client.py:440

  Which results in a NetworkAmbiguous error response from the compute
  API as seen above.

  The problem is this is a synchronous call from nova-api to nova-
  compute and results in an exception traceback in the nova-compute
  logs:

  logs.openstack.org/58/637058/15/check/nova-
  next/f4e8140/logs/screen-n-cpu.txt.gz?level=TRACE#_Apr_04_00_07_20_968719

  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server [None req-47bc59bc-01de-450c-9185-3c0b9dc4bf51 tempest-AttachInterfacesTestJSON-791222649 tempest-AttachInterfacesTestJSON-791222649] Exception during message handling: nova.exception.NetworkAmbiguous: Multiple possible networks found, use a Network ID to be more specific.
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server Traceback (most recent call last):
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_messaging/rpc/server.py", line 166, in _process_incoming
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/exception_wrapper.py", line 79, in wrapped
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     function_name, call_dict, binary, tb)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     self.force_reraise()
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     raise value
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/exception_wrapper.py", line 69, in wrapped
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/utils.py", line 1349, in decorated_function
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/manager.py", line 213, in decorated_function
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     kwargs['instance'], e, sys.exc_info())
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     self.force_reraise()
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     raise value
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/manager.py", line 201, in decorated_function
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/compute/manager.py", line 6651, in attach_interface
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     bind_host_id=bind_host_id, tag=tag)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 1697, in allocate_port_for_instance
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     bind_host_id=bind_host_id, attach=True)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 1067, in allocate_for_instance
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     context, instance, neutron, requested_networks, ordered_networks)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server   File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 940, in _validate_requested_network_ids
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server     raise exception.NetworkAmbiguous(msg)
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server nova.exception.NetworkAmbiguous: Multiple possible networks found, use a Network ID to be more specific.
  Apr 04 00:07:20.968719 ubuntu-bionic-rax-iad-0004701322 nova-compute[32008]: ERROR oslo_messaging.rpc.server 

  We shouldn't traceback on this in the nova-compute logs because it's a
  user-error, but we also probably shouldn't even be getting this far if
  the API were validating the request body properly.

  According to the API reference:

  https://developer.openstack.org/api-ref/compute/?expanded=create-
  interface-detail#create-interface

  port_id and net_id are both optional but mutually exclusive.

  The problem is both are optional because if you don't request
  anything, nova-compute looks up the available network for the
  requesting tenant and picks one, but if there is more than one it's an
  error since the user needs to specify a port or network to use since
  nova can't decide (and there is no default network - see
  https://blueprints.launchpad.net/nova/+spec/deal-with-
  networkambiguous-error).

  So at the very least we should probably change the NetworkAmbiguous
  error to a warning and not traceback.

  This is an extremely latent bug so it's just marked low severity.

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

[Bug 1823198] [NEW] NetworkAmbiguous traceback in nova-compute logs even though it's a user error
From: Matt Riedemann, 2019-04-04