vmware-nsx

NSXV - SQL Exception while creating Metadata edges

Bug #1635811 reported by Daniel 'f0o' Preussker on 2016-10-22

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	vmware-nsx	New	Undecided	Unassigned

Bug Description

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

Revision history for this message

Daniel 'f0o' Preussker (dpreussker) wrote on 2016-10-22:

Download full text (14.8 KiB)

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:

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 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/cmd/eventlet/server/__init__.py", line 22, in main
2016-10-22 09:53:56.490 20546 ERROR neutron     server.boot_server(_main_neutron_server)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/server/__init__.py", line 37, in boot_server
2016-10-22 09:53:56.490 20546 ERROR neutron     server_func()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/cmd/eventlet/server/__init__.py", line 27, in _main_neutron_server
2016-10-22 09:53:56.490 20546 ERROR neutron     wsgi_eventlet.eventlet_wsgi_server()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/server/wsgi_eventlet.py", line 23, in eventlet_wsgi_server
2016-10-22 09:53:56.490 20546 ERROR neutron     neutron_api = service.serve_wsgi(service.NeutronApiService)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 110, in serve_wsgi
2016-10-22 09:53:56.490 20546 ERROR neutron     LOG.exception(_LE('Unrecoverable error: please check log '
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-10-22 09:53:56.490 20546 ERROR neutron     self.force_reraise()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-10-22 09:53:56.490 20546 ERROR neutron     six.reraise(self.type_, self.value, self.tb)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 107, in serve_wsgi
2016-10-22 09:53:56.490 20546 ERROR neutron     service.start()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 80, in start
2016-10-22 09:53:56.490 20546 ERROR neutron     self.wsgi_app = _run_wsgi(self.app_name)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/service.py", line 234, in _run_wsgi
2016-10-22 09:53:56.490 20546 ERROR neutron     app = config.load_paste_app(app_name)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/common/config.py", line 287, in load_paste_app
2016-10-22 09:53:56.490 20546 ERROR neutron     app = loader.load_app(app_name)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/oslo_service/wsgi.py", line 353, in load_app
2016-10-22 09:53:56.490 20546 ERROR neutron     return deploy.loadapp("config:%s" % self.config_path, name=name)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 247, in loadapp
2016-10-22 09:53:56.490 20546 ERROR neutron     return loadobj(APP, uri, name=name, **kw)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 272, in loadobj
2016-10-22 09:53:56.490 20546 ERROR neutron     return context.create()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:53:56.490 20546 ERROR neutron     return self.object_type.invoke(self)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
2016-10-22 09:53:56.490 20546 ERROR neutron     **context.local_conf)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:53:56.490 20546 ERROR neutron     val = callable(*args, **kw)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/urlmap.py", line 25, in urlmap_factory
2016-10-22 09:53:56.490 20546 ERROR neutron     app = loader.get_app(app_name, global_conf=global_conf)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
2016-10-22 09:53:56.490 20546 ERROR neutron     name=name, global_conf=global_conf).create()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:53:56.490 20546 ERROR neutron     return self.object_type.invoke(self)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 144, in invoke
2016-10-22 09:53:56.490 20546 ERROR neutron     **context.local_conf)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:53:56.490 20546 ERROR neutron     val = callable(*args, **kw)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/auth.py", line 71, in pipeline_factory
2016-10-22 09:53:56.490 20546 ERROR neutron     app = loader.get_app(pipeline[-1])
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 350, in get_app
2016-10-22 09:53:56.490 20546 ERROR neutron     name=name, global_conf=global_conf).create()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 710, in create
2016-10-22 09:53:56.490 20546 ERROR neutron     return self.object_type.invoke(self)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/loadwsgi.py", line 146, in invoke
2016-10-22 09:53:56.490 20546 ERROR neutron     return fix_call(context.object, context.global_conf, **context.local_conf)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/paste/deploy/util.py", line 55, in fix_call
2016-10-22 09:53:56.490 20546 ERROR neutron     val = callable(*args, **kw)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 71, in factory
2016-10-22 09:53:56.490 20546 ERROR neutron     return cls(**local_config)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/api/v2/router.py", line 75, in __init__
2016-10-22 09:53:56.490 20546 ERROR neutron     plugin = manager.NeutronManager.get_plugin()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 233, in get_plugin
2016-10-22 09:53:56.490 20546 ERROR neutron     return weakref.proxy(cls.get_instance().plugin)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 227, in get_instance
2016-10-22 09:53:56.490 20546 ERROR neutron     cls._create_instance()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 271, in inner
2016-10-22 09:53:56.490 20546 ERROR neutron     return f(*args, **kwargs)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 213, in _create_instance
2016-10-22 09:53:56.490 20546 ERROR neutron     cls._instance = cls()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 116, in __init__
2016-10-22 09:53:56.490 20546 ERROR neutron     plugin_provider)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/manager.py", line 149, in _get_plugin_instance
2016-10-22 09:53:56.490 20546 ERROR neutron     return plugin_class()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/quota/resource_registry.py", line 121, in wrapper
2016-10-22 09:53:56.490 20546 ERROR neutron     return f(*args, **kwargs)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/plugin.py", line 186, in __init__
2016-10-22 09:53:56.490 20546 ERROR neutron     nsx_v_md_proxy.NsxVMetadataProxyHandler(self))
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/vmware_nsx/plugins/nsx_v/md_proxy.py", line 116, in __init__
2016-10-22 09:53:56.490 20546 ERROR neutron     self.proxy_edge_ips = self._get_proxy_edges()
2016-10-22 09:53:56.490 20546 ERROR neutron   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:53:56.490 20546 ERROR neutron     self._setup_new_proxy_edge, remaining_cfg_ips):
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/eventlet/greenpool.py", line 238, in next
2016-10-22 09:53:56.490 20546 ERROR neutron     val = self.waiters.get().wait()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 175, in wait
2016-10-22 09:53:56.490 20546 ERROR neutron     return self._exit_event.wait()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 125, in wait
2016-10-22 09:53:56.490 20546 ERROR neutron     current.throw(*self._exc)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 214, in main
2016-10-22 09:53:56.490 20546 ERROR neutron     result = function(*args, **kwargs)
2016-10-22 09:53:56.490 20546 ERROR neutron   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:53:56.490 20546 ERROR neutron     self.context, filters={'device_id': [rtr_id]})
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib/python2.7/site-packages/neutron/db/db_base_plugin_v2.py", line 1387, in get_ports
2016-10-22 09:53:56.490 20546 ERROR neutron     for c in query:
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2736, in __iter__
2016-10-22 09:53:56.490 20546 ERROR neutron     return self._execute_and_instances(context)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2749, in _execute_and_instances
2016-10-22 09:53:56.490 20546 ERROR neutron     close_with_result=True)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2740, in _connection_from_session
2016-10-22 09:53:56.490 20546 ERROR neutron     **kw)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 905, in connection
2016-10-22 09:53:56.490 20546 ERROR neutron     execution_options=execution_options)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 910, in _connection_for_bind
2016-10-22 09:53:56.490 20546 ERROR neutron     engine, execution_options)
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 313, in _connection_for_bind
2016-10-22 09:53:56.490 20546 ERROR neutron     self._assert_active()
2016-10-22 09:53:56.490 20546 ERROR neutron   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 202, in _assert_active
2016-10-22 09:53:56.490 20546 ERROR neutron     "This session is in 'prepared' state; no further "
2016-10-22 09:53:56.490 20546 ERROR neutron InvalidRequestError: This session is in 'prepared' state; no further SQL can be emitted within this transaction.
2016-10-22 09:53:56.490 20546 ERROR neutron

After waiting 60s (One Coffee) and restarting the neutron process it starts up fine. Yet it spawns another metadata_proxy edge.

Both edges have the same IP assigned.

After this back and forth I delete the first metadataproxy from the SQL and destroy it's edge as I assume it's 'broken'.

The proxy itself works as expected. The deployment however is very tricky it seems

Revision history for this message

Daniel 'f0o' Preussker (dpreussker) wrote on 2016-10-22:

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.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.