yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1381285] Re: Nexus driver keeps trying to configure VLAN at the switch

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Armando Migliaccio <1381285@xxxxxxxxxxxxxxxxxx>
Date: Thu, 01 Oct 2015 00:38:23 -0000
Reply-to: Bug 1381285 <1381285@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Also affects: networking-cisco
   Importance: Undecided
       Status: New

** No longer affects: neutron

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1381285

Title:
  Nexus driver keeps trying to configure VLAN at the switch

Status in networking-cisco:
  New

Bug description:
  OpenStack version: Juno

  Issue: Nexus driver keeps trying to configure VLAN at the switch after
  update_port_postcommit failed due to ssh connection issue

  Description:
  I used devstack to deploy Multi-Node OpenStack with Cisco Nexus ML2 plugin for VLAN network type.

  There’s a requirement to first ssh to the Nexus switch from the
  Controller node in order to set up the ssh credentials before
  launching VMs.

  I did not do that and caused the ssh exception and
  update_port_postcommit failure, resulting in the VLAN not configured
  at the Nexus switch.

  In the Controller’s screen-q-svc.log, it showed the Nexus driver repeatedly trying to configure the VLAN every 2+ seconds;
  and, after a few minutes, causing ssh failure to the Nexus switch from my MAC.  

  DANNCHOI-M-G07T:~ dannychoi$ ssh -l admin 172.22.191.67
  ssh_exchange_identification: Connection closed by remote host
  DANNCHOI-M-G07T:~ dannychoi$ ssh -l admin 172.22.191.67
  ssh_exchange_identification: Connection closed by remote host
  DANNCHOI-M-G07T:~ dannychoi$ ssh -l admin 172.22.191.67
  ssh_exchange_identification: Connection closed by remote host

  This continues until the VM is deleted; and after a few minutes, I can
  ssh to the Nexus switch from my MAC.

  Below is a snippet of the log that keeps repeating every 2+ seconds:

  2014-10-14 20:41:26.381 DEBUG neutron.context [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Arguments dropped when creating context: {u'project_name': None, u'tenant': None} from (pid=961) __init__ /opt/stack/neutron/neutron/context.py:83
  2014-10-14 20:41:26.382 DEBUG neutron.plugins.ml2.rpc [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Device 0f9454bc-1a31-4743-9c98-9c42a084e673 up at agent ovs-agent-qa4 from (pid=961) update_device_up /opt/stack/neutron/neutron/plugins/ml2/rpc.py:149
  2014-10-14 20:41:26.402 DEBUG neutron.openstack.common.lockutils [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Got semaphore "db-access" from (pid=961) lock /opt/stack/neutron/neutron/openstack/common/lockutils.py:168
  2014-10-14 20:41:26.426 DEBUG neutron.plugins.ml2.drivers.cisco.nexus.nexus_db_v2 [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] add_nexusport_binding() called from (pid=961) add_nexusport_binding /opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_db_v2.py:45
  2014-10-14 20:41:26.431 DEBUG neutron.plugins.ml2.drivers.cisco.nexus.nexus_db_v2 [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] get_nexusvlan_binding() called from (pid=961) get_nexusvlan_binding /opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_db_v2.py:39
  2014-10-14 20:41:26.437 DEBUG neutron.plugins.ml2.drivers.cisco.nexus.mech_cisco_nexus [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Nexus: create & trunk vlan %s from (pid=961) _configure_switch_entry /opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/mech_cisco_nexus.py:125
  2014-10-14 20:41:26.438 DEBUG neutron.plugins.ml2.drivers.cisco.nexus.nexus_network_driver [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] NexusDriver: 
        <config xmlns:xc="urn:ietf:params:xml:ns:netconf:base:1.0">
          <configure>
            <__XML__MODE__exec_configure>
              <vlan>
                <vlan-id-create-delete>
                  <__XML__PARAM_value>300</__XML__PARAM_value>
                  <__XML__MODE_vlan>
                    <name>
                      <vlan-name>dan-300</vlan-name>
                    </name>
                  </__XML__MODE_vlan>
                </vlan-id-create-delete>
              </vlan>

            </__XML__MODE__exec_configure>
          </configure>
        </config>
   from (pid=961) create_vlan /opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_network_driver.py:123
  2014-10-14 20:41:26.438 DEBUG ncclient.transport.session [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] <SSHSession(session, initial daemon)> created: client_capabilities=['urn:ietf:params:netconf:capability:writable-running:1.0', 'urn:ietf:params:netconf:capability:rollback-on-error:1.0', 'urn:ietf:params:netconf:capability:validate:1.0', 'urn:ietf:params:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file,https,sftp', 'urn:ietf:params:netconf:capability:candidate:1.0', 'urn:ietf:params:netconf:capability:xpath:1.0', 'urn:ietf:params:netconf:capability:startup:1.0', 'urn:ietf:params:xml:ns:netconf:base:1.0', 'urn:liberouter:params:netconf:capability:power-control:1.0urn:ietf:params:netconf:capability:interleave:1.0'] from (pid=961) __init__ /usr/local/lib/python2.7/dist-packages/ncclient/transport/session.py:42
  2014-10-14 20:41:26.438 DEBUG ncclient.transport.session [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] <SSHSession(session, initial daemon)> created: client_capabilities=['urn:ietf:params:netconf:capability:writable-running:1.0', 'urn:ietf:params:netconf:capability:rollback-on-error:1.0', 'urn:ietf:params:netconf:capability:validate:1.0', 'urn:ietf:params:netconf:capability:confirmed-commit:1.0', 'urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file,https,sftp', 'urn:ietf:params:netconf:capability:candidate:1.0', 'urn:ietf:params:netconf:capability:xpath:1.0', 'urn:ietf:params:netconf:capability:startup:1.0', 'urn:ietf:params:xml:ns:netconf:base:1.0', 'urn:liberouter:params:netconf:capability:power-control:1.0urn:ietf:params:netconf:capability:interleave:1.0'] from (pid=961) __init__ /usr/local/lib/python2.7/dist-packages/ncclient/transport/session.py:42
  2014-10-14 20:41:26.440 DEBUG ncclient.transport.ssh [-] starting thread (client mode): 0xa417d690L from (pid=961) _log /usr/local/lib/python2.7/dist-packages/paramiko/transport.py:1428
  2014-10-14 20:41:26.440 ERROR ncclient.transport.ssh [-] Exception: Error reading SSH protocol banner
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-] Traceback (most recent call last):
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-]   File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 1582, in run
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-]     self._check_banner()
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-]   File "/usr/local/lib/python2.7/dist-packages/paramiko/transport.py", line 1709, in _check_banner
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-]     raise SSHException('Error reading SSH protocol banner' + str(e))
  2014-10-14 20:41:26.441 ERROR ncclient.transport.ssh [-] SSHException: Error reading SSH protocol banner
  2014-10-14 20:41:26.442 ERROR ncclient.transport.ssh [-] 
  2014-10-14 20:41:26.442 ERROR neutron.plugins.ml2.managers [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Mechanism driver 'cisco_nexus' failed in update_port_postcommit
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers Traceback (most recent call last):
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 291, in _call_on_drivers
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     getattr(driver.obj, method_name)(context)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/mech_cisco_nexus.py", line 227, in update_port_postcommit
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     self._configure_switch_entry)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/mech_cisco_nexus.py", line 190, in _port_action
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     func(vlan_id, device_id, host_id)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/mech_cisco_nexus.py", line 127, in _configure_switch_entry
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     switch_ip, vlan_id, vlan_name, intf_type, nexus_port)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_network_driver.py", line 177, in create_and_trunk_vlan
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     self.create_vlan(nexus_host, vlan_id, vlan_name)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_network_driver.py", line 124, in create_vlan
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     self._edit_config(nexus_host, target='running', config=confstr)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_network_driver.py", line 66, in _edit_config
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     mgr = self.nxos_connect(nexus_host)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers   File "/opt/stack/neutron/neutron/plugins/ml2/drivers/cisco/nexus/nexus_network_driver.py", line 106, in nxos_connect
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers     raise cexc.NexusConnectFailed(nexus_host=nexus_host, exc=e)
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers NexusConnectFailed: Unable to connect to Nexus 172.22.191.67. Reason: Negotiation failed.
  2014-10-14 20:41:26.442 TRACE neutron.plugins.ml2.managers 
  2014-10-14 20:41:26.443 ERROR oslo.messaging.rpc.dispatcher [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Exception during message handling: update_port_postcommit failed.
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/neutron/neutron/plugins/ml2/rpc.py", line 161, in update_device_up
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     host)
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 1136, in update_port_status
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     self.mechanism_manager.update_port_postcommit(mech_context)
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 527, in update_port_postcommit
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     continue_on_failure=True)
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 302, in _call_on_drivers
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher     method=method_name
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher MechanismDriverError: update_port_postcommit failed.
  2014-10-14 20:41:26.443 TRACE oslo.messaging.rpc.dispatcher 
  2014-10-14 20:41:26.444 ERROR oslo.messaging._drivers.common [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Returning exception update_port_postcommit failed. to caller
  2014-10-14 20:41:26.444 ERROR oslo.messaging._drivers.common [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] ['Traceback (most recent call last):\n', '  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/opt/stack/neutron/neutron/plugins/ml2/rpc.py", line 161, in update_device_up\n    host)\n', '  File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 1136, in update_port_status\n    self.mechanism_manager.update_port_postcommit(mech_context)\n', '  File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 527, in update_port_postcommit\n    continue_on_failure=True)\n', '  File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 302, in _call_on_drivers\n    method=method_name\n', 'MechanismDriverError: update_port_postcommit failed.\n']
  2014-10-14 20:41:27.389 DEBUG neutron.context [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] Arguments dropped when creating context: {u'project_name': None, u'tenant': None} from (pid=961) __init__ /opt/stack/neutron/neutron/context.py:83
  2014-10-14 20:41:27.390 DEBUG neutron.plugins.ml2.db [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] get_port_and_sgs() called for port_id 0f9454bc-1a31-4743-9c98-9c42a084e673 from (pid=961) get_port_and_sgs /opt/stack/neutron/neutron/plugins/ml2/db.py:212
  2014-10-14 20:41:27.406 DEBUG neutron.plugins.ml2.db [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] get_port_and_sgs() called for port_id da4cfe0f-70fc-4fc3-ab1a-8a87df7ccabc from (pid=961) get_port_and_sgs /opt/stack/neutron/neutron/plugins/ml2/db.py:212
  2014-10-14 20:41:27.418 DEBUG neutron.plugins.ml2.db [req-25e05ffb-da63-4aaf-b7a8-6e58c0762abc None None] get_port_and_sgs() called for port_id a66e2f7b-17a9-4fb6-b450-d0ac4048b5ee from (pid=961) get_port_and_sgs /opt/stack/neutron/neutron/plugins/ml2/db.py:212

To manage notifications about this bug go to:
https://bugs.launchpad.net/networking-cisco/+bug/1381285/+subscriptions
References

[Bug 1381285] [NEW] Nexus driver keeps trying to configure VLAN at the switch
From: Danny Choi, 2014-10-15