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
