NSXV - SQL Exception while creating Metadata edges

[Daniel 'f0o' Preussker]

M Release, RDO Trunk repo.
CentOS 7, SELinux permissive.
NSX 6.2.4.4292526 (Manager) 6.2.47844 (Controllers)
vSphere 6.x

When attempting to provision edges for metadata proxy appliances it fails at two stages;

I will describe both underneath each other with the respective python dump (apologies for the wall of text already)

============================= Stage 1:

It creates a Logical Switch and a Security Group.
It ends with an exception: This session is in 'prepared' state; no further SQL can be emitted within this transaction.

============================= Relevant log excerpt:

2016-10-22 09:09:30.116 25641 DEBUG oslo_concurrency.lockutils [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] Acquired semaphore "nsx-edge-pool" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2016-10-22 09:09:30.202 25641 DEBUG oslo_concurrency.lockutils [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] Releasing semaphore "nsx-edge-pool" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters [-] DB exception wrapped.
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 688, in _commit_impl
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters self.engine.dialect.do_commit(self.connection)
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2514, in do_commit
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters dbapi_connection.commit()
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 719, in commit
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters self._read_ok_packet()
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters pkt = self._read_packet()
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters packet_header = self._read_bytes(4)
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters data = self._rfile.read(num_bytes)
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters RuntimeError: reentrant call inside <_io.BufferedReader name=7>
2016-10-22 09:09:30.266 25641 ERROR oslo_db.sqlalchemy.exc_filters
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters [-] DB exception wrapped.
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 668, in _rollback_impl
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters self.engine.dialect.do_rollback(self.connection)
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters dbapi_connection.rollback()
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 724, in rollback
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters self._read_ok_packet()
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters pkt = self._read_packet()
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters packet_header = self._read_bytes(4)
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters data = self._rfile.read(num_bytes)
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters RuntimeError: reentrant call inside <_io.BufferedReader name=7>
2016-10-22 09:09:30.269 25641 ERROR oslo_db.sqlalchemy.exc_filters
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy [-] Exception (exceptions.RuntimeError) reentrant call inside <_io.BufferedReader name=7> while creating internal edge for metadata service
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy Traceback (most recent call last):
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 385, in _setup_new_proxy_edge
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy allow_metadata=False)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/plugin.py", line 1566, in create_router
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy lrouter = super(NsxVPluginV2, self).create_router(context, router)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/neutron/db/l3_db.py", line 1642, in create_router
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy router)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/neutron/db/l3_db.py", line 220, in create_router
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy router_db = self._create_router_db(context, r, r['tenant_id'])
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/neutron/db/l3_db.py", line 215, in _create_router_db
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy return router_db
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 502, in __exit__
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self.rollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 63, in __exit__
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy compat.reraise(type_, value, traceback)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 502, in __exit__
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self.rollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 423, in rollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy transaction._rollback_impl()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 461, in _rollback_impl
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy t[1].rollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1563, in rollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._do_rollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1601, in _do_rollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self.connection._rollback_impl()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 670, in _rollback_impl
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._handle_dbapi_exception(e, None, None, None, None)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1334, in _handle_dbapi_exception
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._autorollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 791, in _autorollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._root._rollback_impl()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 670, in _rollback_impl
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._handle_dbapi_exception(e, None, None, None, None)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1266, in _handle_dbapi_exception
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy exc_info
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy reraise(type(exception), exception, tb=exc_tb)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 668, in _rollback_impl
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self.engine.dialect.do_rollback(self.connection)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy dbapi_connection.rollback()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 724, in rollback
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._read_ok_packet()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy pkt = self._read_packet()
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy packet_header = self._read_bytes(4)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy data = self._rfile.read(num_bytes)
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy DBAPIError: (exceptions.RuntimeError) reentrant call inside <_io.BufferedReader name=7>
2016-10-22 09:09:30.270 25641 ERROR vmware_nsx.plugins.nsx_v.md_proxy
2016-10-22 09:09:30.287 25641 DEBUG oslo_concurrency.lockutils [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] Releasing semaphore "nsx-metadata-init" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2016-10-22 09:09:30.288 25641 DEBUG oslo_concurrency.lockutils [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] Lock "manager" released by "neutron.manager._create_instance" :: held 7.812s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282
2016-10-22 09:09:30.288 25641 ERROR neutron.service [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] Unrecoverable error: please check log for details. [919/1943]
2016-10-22 09:09:30.288 25641 ERROR neutron.service Traceback (most recent call last):
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/service.py", line 107, in serve_wsgi
2016-10-22 09:09:30.288 25641 ERROR neutron.service service.start()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/service.py", line 80, in start
2016-10-22 09:09:30.288 25641 ERROR neutron.service self.wsgi_app = _run_wsgi(self.app_name)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/service.py", line 234, in _run_wsgi
2016-10-22 09:09:30.288 25641 ERROR neutron.service app = config.load_paste_app(app_name)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/common/config.py", line 287, in load_paste_app
2016-10-22 09:09:30.288 25641 ERROR neutron.service app = loader.load_app(app_name)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/oslo_service/wsgi.py", line 353, in load_app
2016-10-22 09:09:30.288 25641 ERROR neutron.service return deploy.loadapp("config:%s" % self.config_path, name=name)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 247, in loadapp
2016-10-22 09:09:30.288 25641 ERROR neutron.service return loadobj(APP, uri, name=name, **kw)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 272, in loadobj
2016-10-22 09:09:30.288 25641 ERROR neutron.service return context.create()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self.object_type.invoke(self)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
2016-10-22 09:09:30.288 25641 ERROR neutron.service **context.local_conf)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:09:30.288 25641 ERROR neutron.service val = callable(*args, **kw)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/urlmap.py", line 25, in urlmap_factory
2016-10-22 09:09:30.288 25641 ERROR neutron.service app = loader.get_app(app_name, global_conf=global_conf)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
2016-10-22 09:09:30.288 25641 ERROR neutron.service name=name, global_conf=global_conf).create()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self.object_type.invoke(self)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
2016-10-22 09:09:30.288 25641 ERROR neutron.service **context.local_conf)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:09:30.288 25641 ERROR neutron.service val = callable(*args, **kw)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/auth.py", line 71, in pipeline_factory
2016-10-22 09:09:30.288 25641 ERROR neutron.service app = loader.get_app(pipeline[-1])
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
2016-10-22 09:09:30.288 25641 ERROR neutron.service name=name, global_conf=global_conf).create()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self.object_type.invoke(self)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 146, in invoke
2016-10-22 09:09:30.288 25641 ERROR neutron.service return fix_call(context.object, context.global_conf, **context.local_conf)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:09:30.288 25641 ERROR neutron.service val = callable(*args, **kw)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 71, in factory
2016-10-22 09:09:30.288 25641 ERROR neutron.service return cls(**local_config)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 75, in __init__
2016-10-22 09:09:30.288 25641 ERROR neutron.service plugin = manager.NeutronManager.get_plugin()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 233, in get_plugin
2016-10-22 09:09:30.288 25641 ERROR neutron.service return weakref.proxy(cls.get_instance().plugin)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 227, in get_instance
2016-10-22 09:09:30.288 25641 ERROR neutron.service cls._create_instance()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 271, in inner
2016-10-22 09:09:30.288 25641 ERROR neutron.service return f(*args, **kwargs)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 213, in _create_instance
2016-10-22 09:09:30.288 25641 ERROR neutron.service cls._instance = cls()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 116, in __init__
2016-10-22 09:09:30.288 25641 ERROR neutron.service plugin_provider)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 149, in _get_plugin_instance
2016-10-22 09:09:30.288 25641 ERROR neutron.service return plugin_class()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/quota/resource_registry.py", line 121, in wrapper
2016-10-22 09:09:30.288 25641 ERROR neutron.service return f(*args, **kwargs)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/plugin.py", line 186, in __init__
2016-10-22 09:09:30.288 25641 ERROR neutron.service nsx_v_md_proxy.NsxVMetadataProxyHandler(self))
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 116, in __init__
2016-10-22 09:09:30.288 25641 ERROR neutron.service self.proxy_edge_ips = self._get_proxy_edges()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 265, in _get_proxy_edges
2016-10-22 09:09:30.288 25641 ERROR neutron.service self._setup_new_proxy_edge, remaining_cfg_ips):
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/eventlet/greenpool.py", line 238, in next
2016-10-22 09:09:30.288 25641 ERROR neutron.service val = self.waiters.get().wait()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 175, in wait
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self._exit_event.wait()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait
2016-10-22 09:09:30.288 25641 ERROR neutron.service return hubs.get_hub().switch()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self.greenlet.switch()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 214, in main
2016-10-22 09:09:30.288 25641 ERROR neutron.service result = function(*args, **kwargs)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 458, in _setup_new_proxy_edge
2016-10-22 09:09:30.288 25641 ERROR neutron.service self.context, filters={'device_id': [rtr_id]})
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib/python2.7/site-packages/neutron/db/db_base_plugin_v2.py", line 1387, in get_ports
2016-10-22 09:09:30.288 25641 ERROR neutron.service for c in query:
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2736, in __iter__
2016-10-22 09:09:30.288 25641 ERROR neutron.service return self._execute_and_instances(context)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2749, in _execute_and_instances
2016-10-22 09:09:30.288 25641 ERROR neutron.service close_with_result=True)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2740, in _connection_from_session
2016-10-22 09:09:30.288 25641 ERROR neutron.service **kw)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 905, in connection
2016-10-22 09:09:30.288 25641 ERROR neutron.service execution_options=execution_options)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 910, in _connection_for_bind
2016-10-22 09:09:30.288 25641 ERROR neutron.service engine, execution_options)
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 313, in _connection_for_bind
2016-10-22 09:09:30.288 25641 ERROR neutron.service self._assert_active()
2016-10-22 09:09:30.288 25641 ERROR neutron.service File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 202, in _assert_active
2016-10-22 09:09:30.288 25641 ERROR neutron.service "This session is in 'prepared' state; no further "
2016-10-22 09:09:30.288 25641 ERROR neutron.service InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.
2016-10-22 09:09:30.288 25641 ERROR neutron.service
2016-10-22 09:09:30.290 25641 CRITICAL neutron [req-1fe2d564-b66f-4862-87a8-be05d6009977 - - - - -] InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.

============================= Stage 2:

Upon restart it attempts to actually deploy the edge using previously created security group and logical switch but it fails due to a table constraint.

I'ts not unlikely that these two stages relate to each other as both fail due to an SQL issue.

The oddity to me is that only Stage 2 will tell me a meaningful error whereas Stage 1 is just an exception.

If I disable foreign constraint checks it will deploy 'fine'.

============================= Relevant log excerpt:

2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy [-] Exception This transaction is closed while creating internal edge for metadata service
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy Traceback (most recent call last):
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 385, in _setup_new_proxy_edge
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy allow_metadata=False)
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/plugin.py", line 1569, in create_router
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._process_nsx_router_create(context, router_db, r)
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 494, in __exit__
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._assert_active(deactive_ok=True, prepared_ok=True)
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 223, in _assert_active
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy raise sa_exc.ResourceClosedError(closed_msg)
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy ResourceClosedError: This transaction is closed
2016-10-22 09:12:34.208 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy
2016-10-22 09:12:34.225 2085 ERROR vmware_nsx.plugins.nsx_v.md_proxy [-] Exception (pymysql.err.IntegrityError) (1452, u'Cannot add or update a child row: a foreign key constraint fails (`neutron`.`routers`, CONSTRAINT `routers_ibfk_2` FOREIGN KEY (`standard_attr_id`) REFERENCES `standardattributes` (`id`) ON DELETE C
ASCADE)') while creating internal edge for metadata service

[Daniel 'f0o' Preussker (dpreussker)]

Ok, just to clarify...

By 'fine' I mean that this happens as well:

After Stage1 completes, Remove the foreign check on the SQL and restart neutron-server
It will start deploying a metadata-proxy edge but throws this stackdump:

2016-10-22 09:53:37.124 20546 DEBUG oslo_concurrency.lockutils [req-1152bc36-e2e0-4ea6-a78b-2335a06389ee - - - - -] Acquired semaphore "nsx-edge-pool" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2016-10-22 09:53:37.216 20546 DEBUG oslo_concurrency.lockutils [req-1152bc36-e2e0-4ea6-a78b-2335a06389ee - - - - -] Releasing semaphore "nsx-edge-pool" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy [-] Exception This transaction is closed while creating internal edge for metadata service
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy Traceback (most recent call last):
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 385, in _setup_new_proxy_edge
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy allow_metadata=False)
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/plugin.py", line 1569, in create_router
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._process_nsx_router_create(context, router_db, r)
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 494, in __exit__
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy self._assert_active(deactive_ok=True, prepared_ok=True)
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 223, in _assert_active
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy raise sa_exc.ResourceClosedError(closed_msg)
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy ResourceClosedError: This transaction is closed
2016-10-22 09:53:37.315 20546 ERROR vmware_nsx.plugins.nsx_v.md_proxy
2016-10-22 09:53:37.495 20546 DEBUG vmware_nsx.db.nsxrouter [-] Nsx router extension successfully processed for router:00e6a406-c1b9-44a9-be02-a50a49926e05 _process_nsx_router_create /usr/lib/python2.7/site-packages/vmware_nsx/db/nsxrouter.py:63

The metadaproxy is indeed deployed and in the database. Seconds later (after adding vnics and other things it seems) it dies again with:

2016-10-22 09:53:56.490 20546 ERROR neutron Traceback (most recent call last): [30/1964]
2016-10-22 09:53:56.490 20546 ERROR neutron File "/usr/bin/neutron-server", line 10, in <module>
2016-10-22 09:53:56.490 20546 ERROR neutron sys.exit(main())
2016-10-22 09:53:56.490 2054...

[Daniel 'f0o' Preussker (dpreussker)]

Last addition:

It's worth to notice that by now I end up with 3 metadata_proxy_router entries in the routers table. Of which 1 does not exist at all, one is the assumed 'broken' one and the last one is the functioning one.