yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1797771] Re: nova rebuild using openstack server rebuild is failing

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Wed, 24 Oct 2018 19:40:21 -0000
Reply-to: Bug 1797771 <1797771@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
This doesn't seem to be a nova problem, but a problem with your
database:

2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler [req-e8a61425-56dc-4dd7-bbca-05ae913f24c0 - - - - -] Failed to get metadata for instance id: b9f8fe03-a78b-43f3-bc1f-68ceaff3f978
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler Traceback (most recent call last):
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/api/metadata/handler.py", line 283, in _get_meta_by_instance_id
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     remote_address)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/api/metadata/handler.py", line 78, in get_metadata_by_instance_id
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     data = base.get_metadata_by_instance_id(instance_id, address)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/api/metadata/base.py", line 670, in get_metadata_by_instance_id
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return InstanceMetadata(instance, address)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/api/metadata/base.py", line 138, in __init__
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self.mappings = _format_instance_mapping(ctxt, instance)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/api/metadata/base.py", line 675, in _format_instance_mapping
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     ctxt, instance.uuid)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 184, in wrapper
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     result = fn(cls, context, *args, **kwargs)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/objects/block_device.py", line 357, in get_by_instance_uuid
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     context, instance_uuid, use_slave=use_slave)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 225, in wrapper
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return f(*args, **kwargs)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/objects/block_device.py", line 352, in _db_block_device_mapping_get_all_by_instance
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     context, instance_uuid)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 1305, in block_device_mapping_get_all_by_instance
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     instance_uuid)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 169, in wrapper
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return f(*args, **kwargs)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 270, in wrapped
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return f(context, *args, **kwargs)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 4192, in block_device_mapping_get_all_by_instance
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     filter_by(instance_uuid=instance_uuid).\
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2588, in all
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return list(self)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2736, in __iter__
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return self._execute_and_instances(context)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2749, in _execute_and_instances
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     close_with_result=True)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2740, in _connection_from_session
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     **kw)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 905, in connection
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     execution_options=execution_options)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 910, in _connection_for_bind
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     engine, execution_options)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 334, in _connection_for_bind
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     conn = bind.contextual_connect()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2041, in contextual_connect
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     **kwargs)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 92, in __init__
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self.dispatch.engine_connect(self, self.__branch)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/event/attr.py", line 256, in __call__
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     fn(*args, **kw)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py", line 72, in _connect_ping_listener
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     connection.scalar(select([1]))
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 844, in scalar
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return self.execute(object, *multiparams, **params).scalar()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return meth(self, multiparams, params)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     return connection._execute_clauseelement(self, multiparams, params)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     compiled_sql, distilled_params
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     context)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1334, in _handle_dbapi_exception
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self._autorollback()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 791, in _autorollback
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self._root._rollback_impl()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 670, in _rollback_impl
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self._handle_dbapi_exception(e, None, None, None, None)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1266, in _handle_dbapi_exception
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     exc_info
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     reraise(type(exception), exception, tb=exc_tb)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 668, in _rollback_impl
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self.engine.dialect.do_rollback(self.connection)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     dbapi_connection.rollback()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 724, in rollback
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     self._read_ok_packet()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     pkt = self._read_packet()
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     packet_header = self._read_bytes(4)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler     data = self._rfile.read(num_bytes)
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler DBAPIError: (exceptions.RuntimeError) reentrant call inside <_io.BufferedReader name=23>
2018-10-11 04:47:49.827 12628 ERROR nova.api.metadata.handler 
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool [req-e8a61425-56dc-4dd7-bbca-05ae913f24c0 - - - - -] Exception during reset or similar
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool Traceback (most recent call last):
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 636, in _finalize_fairy
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     fairy._reset(pool)
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 776, in _reset
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     pool._dialect.do_rollback(self)
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2526, in do_rollback
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     dbapi_connection.rollback()
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 724, in rollback
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     self._read_ok_packet()
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 698, in _read_ok_packet
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     pkt = self._read_packet()
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     packet_header = self._read_bytes(4)
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool     data = self._rfile.read(num_bytes)
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool RuntimeError: reentrant call inside <_io.BufferedReader name=23>
2018-10-11 04:47:49.832 12628 ERROR sqlalchemy.pool.QueuePool 
2018-10-11 04:47:49.834 12628 INFO nova.metadata.wsgi.server [req-e8a61425-56dc-4dd7-bbca-05ae913f24c0 - - - - -] 10.234.132.244,10.234.212.150 "GET /latest/meta-data/instance-type HTTP/1.1" status: 500 len: 229 time: 1.4219360
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters [req-76f03563-ac93-4b55-a4ee-420834ab3bf4 - - - - -] DB exception wrapped.
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     context)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 146, in execute
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 296, in _query
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 781, in query
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 942, in _read_query_result
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1138, in read
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 900, in _read_packet
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     recv_data = self._read_bytes(bytes_to_read)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters     data = self._rfile.read(num_bytes)
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters AttributeError: 'NoneType' object has no attribute 'read'
2018-10-11 04:47:49.835 12628 ERROR oslo_db.sqlalchemy.exc_filters 

** Changed in: nova
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1797771

Title:
  nova rebuild using openstack server rebuild is failing

Status in OpenStack Compute (nova):
  Invalid

Bug description:
  During rebuild of a switched off instance using openstack server
  rebuild commnad is failing with below error,

  START with options: [u'server', u'rebuild', u'--wait', u'--image', u'esis_cwg_ldap_rhel7u2_64_20SEP17', u'scspr0544339001', u'-v']
  command: server rebuild -> openstackclient.compute.v2.server.RebuildServer
  Using auth plugin: password
  /usr/lib/python2.7/site-packages/novaclient/v2/images.py:106: DeprecationWarning: The novaclient.v2.images module is deprecated and will be removed after Nova 15.0.0 is released. Use                            on-openstacksdk instead.
    'or python-openstacksdk instead.', DeprecationWarning)
  Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.                                                                                              <class 'sqlalchemy.exc.OperationalError'> (HTTP 500) (Request-ID: req-33df9b70-3422-43c3-a6ef-56283344944e)                                                                                                       END return value: 1

  -------------------------
  Version 
  -------
  # cat /etc/nova/release
  [Nova]
  vendor = RDO
  product = OpenStack Compute
  package = 1.el7
  ---------------------------------------
  b

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

[Bug 1797771] [NEW] nova rebuild using openstack server rebuild is failing
From: Manoj Moily, 2018-10-14