Public bug reported: Seen in nova and cinder unit test runs in the gate:
http://logs.openstack.org/03/602403/1/gate/openstack-tox- py35/b4c9214/testr_results.html.gz http://logs.openstack.org/94/603194/1/gate/openstack-tox- py35/e37d161/testr_results.html.gz Years ago we updated the timeout scaling factor on those tests in nova: https://review.openstack.org/#/c/370805/ For bug 1216851. Looking at a timeout/failed run for nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync against a passing run: nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync [664.512994s] ... FAILED nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync [39.644814s] ... ok Based on that, it's clear that we're not just missing some timeout - it looks like we're totally breaking somewhere and only being caught by the timeout. There are a couple of errors in the logs when we see this: b'sqlalchemy.exc.ResourceClosedError: This result object does not return rows. It has been closed automatically.' 2018-09-19 05:35:08.697560 | ubuntu-xenial | b'' 2018-09-19 05:35:08.697658 | ubuntu-xenial | b'The above exception was the direct cause of the following exception:' 2018-09-19 05:35:08.697700 | ubuntu-xenial | b'' 2018-09-19 05:35:08.697772 | ubuntu-xenial | b'Traceback (most recent call last):' 2018-09-19 05:35:08.697957 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/oslo_db/sqlalchemy/test_migrations.py", line 585, in test_models_sync' 2018-09-19 05:35:08.698031 | ubuntu-xenial | b' self.db_sync(self.get_engine())' 2018-09-19 05:35:08.698174 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/unit/db/test_migrations.py", line 146, in db_sync' 2018-09-19 05:35:08.698285 | ubuntu-xenial | b' sa_migration.db_sync()' 2018-09-19 05:35:08.698451 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/db/sqlalchemy/migration.py", line 61, in db_sync' 2018-09-19 05:35:08.698522 | ubuntu-xenial | b' repository, version)' 2018-09-19 05:35:08.698682 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/api.py", line 186, in upgrade' 2018-09-19 05:35:08.698766 | ubuntu-xenial | b' return _migrate(url, repository, version, upgrade=True, err=err, **opts)' 2018-09-19 05:35:08.698823 | ubuntu-xenial | b' File "<decorator-gen-15>", line 2, in _migrate' 2018-09-19 05:35:08.698951 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/util/__init__.py", line 167, in with_engine' 2018-09-19 05:35:08.698991 | ubuntu-xenial | b' return f(*a, **kw)' 2018-09-19 05:35:08.699108 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/api.py", line 366, in _migrate' 2018-09-19 05:35:08.699164 | ubuntu-xenial | b' schema.runchange(ver, change, changeset.step)' 2018-09-19 05:35:08.699315 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/schema.py", line 93, in runchange' 2018-09-19 05:35:08.706788 | ubuntu-xenial | b' change.run(self.engine, step)' 2018-09-19 05:35:08.707005 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/script/py.py", line 148, in run' 2018-09-19 05:35:08.707058 | ubuntu-xenial | b' script_func(engine)' 2018-09-19 05:35:08.707248 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/db/sqlalchemy/migrate_repo/versions/315_add_migration_progresss_detail.py", line 30, in upgrade' 2018-09-19 05:35:08.707326 | ubuntu-xenial | b' shadow_migrations.create_column(column.copy())' 2018-09-19 05:35:08.707475 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/schema.py", line 475, in create_column' 2018-09-19 05:35:08.707538 | ubuntu-xenial | b' column.create(table=self, *p, **kw)' 2018-09-19 05:35:08.707684 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/schema.py", line 577, in create' 2018-09-19 05:35:08.707769 | ubuntu-xenial | b' engine._run_visitor(visitorcallable, self, connection, **kwargs)' 2018-09-19 05:35:08.707922 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1940, in _run_visitor' 2018-09-19 05:35:08.708036 | ubuntu-xenial | b' conn._run_visitor(visitorcallable, element, **kwargs)' 2018-09-19 05:35:08.708167 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1549, in _run_visitor' 2018-09-19 05:35:08.708217 | ubuntu-xenial | b' **kwargs).traverse_single(element)' 2018-09-19 05:35:08.708343 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 56, in traverse_single' 2018-09-19 05:35:08.708410 | ubuntu-xenial | b' ret = super(AlterTableVisitor, self).traverse_single(elem)' 2018-09-19 05:35:08.708534 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/sql/visitors.py", line 121, in traverse_single' 2018-09-19 05:35:08.708588 | ubuntu-xenial | b' return meth(obj, **kw)' 2018-09-19 05:35:08.708716 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 104, in visit_column' 2018-09-19 05:35:08.708752 | ubuntu-xenial | b' self.execute()' 2018-09-19 05:35:08.708870 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 44, in execute' 2018-09-19 05:35:08.708932 | ubuntu-xenial | b' return self.connection.execute(self.buffer.getvalue())' 2018-09-19 05:35:08.709049 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 942, in execute' 2018-09-19 05:35:08.709113 | ubuntu-xenial | b' return self._execute_text(object, multiparams, params)' 2018-09-19 05:35:08.709246 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text' 2018-09-19 05:35:08.709293 | ubuntu-xenial | b' statement, parameters' 2018-09-19 05:35:08.709420 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context' 2018-09-19 05:35:08.709452 | ubuntu-xenial | b' context)' 2018-09-19 05:35:08.709582 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception' 2018-09-19 05:35:08.709637 | ubuntu-xenial | b' util.raise_from_cause(newraise, exc_info)' 2018-09-19 05:35:08.709760 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause' 2018-09-19 05:35:08.709970 | ubuntu-xenial | b' reraise(type(exception), exception, tb=exc_tb, cause=cause)' 2018-09-19 05:35:08.710095 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 248, in reraise' 2018-09-19 05:35:08.710143 | ubuntu-xenial | b' raise value.with_traceback(tb)' 2018-09-19 05:35:08.710277 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context' 2018-09-19 05:35:08.710347 | ubuntu-xenial | b' context)' 2018-09-19 05:35:08.710523 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute' 2018-09-19 05:35:08.710585 | ubuntu-xenial | b' cursor.execute(statement, parameters)' 2018-09-19 05:35:08.710699 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/cursors.py", line 170, in execute' 2018-09-19 05:35:08.710744 | ubuntu-xenial | b' result = self._query(query)' 2018-09-19 05:35:08.710858 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/cursors.py", line 328, in _query' 2018-09-19 05:35:08.710896 | ubuntu-xenial | b' conn.query(q)' 2018-09-19 05:35:08.711046 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 516, in query' 2018-09-19 05:35:08.711131 | ubuntu-xenial | b' self._affected_rows = self._read_query_result(unbuffered=unbuffered)' 2018-09-19 05:35:08.711295 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 727, in _read_query_result' 2018-09-19 05:35:08.711339 | ubuntu-xenial | b' result.read()' 2018-09-19 05:35:08.711454 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 1066, in read' 2018-09-19 05:35:08.711510 | ubuntu-xenial | b' first_packet = self.connection._read_packet()' 2018-09-19 05:35:08.711630 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 656, in _read_packet' 2018-09-19 05:35:08.711680 | ubuntu-xenial | b' packet_header = self._read_bytes(4)' 2018-09-19 05:35:08.711797 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 690, in _read_bytes' 2018-09-19 05:35:08.711845 | ubuntu-xenial | b' data = self._rfile.read(num_bytes)' 2018-09-19 05:35:08.711911 | ubuntu-xenial | b' File "/usr/lib/python3.5/socket.py", line 575, in readinto' 2018-09-19 05:35:08.711988 | ubuntu-xenial | b' return self._sock.recv_into(b)' 2018-09-19 05:35:08.712132 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 360, in recv_into' 2018-09-19 05:35:08.712208 | ubuntu-xenial | b' return self._recv_loop(self.fd.recv_into, 0, buffer, nbytes, flags)' 2018-09-19 05:35:08.712333 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 348, in _recv_loop' 2018-09-19 05:35:08.712376 | ubuntu-xenial | b' self._read_trampoline()' 2018-09-19 05:35:08.712499 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 319, in _read_trampoline' 2018-09-19 05:35:08.712553 | ubuntu-xenial | b' timeout_exc=socket.timeout("timed out"))' 2018-09-19 05:35:08.712673 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 203, in _trampoline' 2018-09-19 05:35:08.712723 | ubuntu-xenial | b' mark_as_closed=self._mark_as_closed)' 2018-09-19 05:35:08.712844 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/__init__.py", line 162, in trampoline' 2018-09-19 05:35:08.712883 | ubuntu-xenial | b' return hub.switch()' 2018-09-19 05:35:08.713007 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/hub.py", line 294, in switch' 2018-09-19 05:35:08.713091 | ubuntu-xenial | b' return self.greenlet.switch()' 2018-09-19 05:35:08.713213 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/hub.py", line 346, in run' 2018-09-19 05:35:08.713254 | ubuntu-xenial | b' self.wait(sleep_time)' 2018-09-19 05:35:08.713367 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/poll.py", line 85, in wait' 2018-09-19 05:35:08.713414 | ubuntu-xenial | b' presult = self.do_poll(seconds)' 2018-09-19 05:35:08.713529 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/epolls.py", line 62, in do_poll' 2018-09-19 05:35:08.713575 | ubuntu-xenial | b' return self.poll.poll(seconds)' 2018-09-19 05:35:08.713721 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler' 2018-09-19 05:35:08.713771 | ubuntu-xenial | b' raise TimeoutException()' 2018-09-19 05:35:08.713819 | ubuntu-xenial | b'IndexError: tuple index out of range' 2018-09-19 05:35:08.713843 | ubuntu-xenial | b'' It looks like there are a few places things could be broken, since we have oslo.db, sqlalchemy-migrate, sqlalchemy, pymysql, and eventlet all involved here. Since we're appearing to hit a huge timeout, my guess is we're hitting some issue with eventlet and greenthread switches. ** Affects: cinder Importance: High Status: Confirmed ** Affects: nova Importance: High Status: Confirmed ** Tags: db gate-failure testing ** Also affects: cinder Importance: Undecided Status: New ** Changed in: cinder Status: New => Confirmed ** Changed in: cinder Importance: Undecided => High ** Summary changed: - mysql db opportunistic unit tests timing out intermittently in the gate + mysql db opportunistic unit tests timing out intermittently in the gate (bad thread switch?) -- 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/1793364 Title: mysql db opportunistic unit tests timing out intermittently in the gate (bad thread switch?) Status in Cinder: Confirmed Status in OpenStack Compute (nova): Confirmed Bug description: Seen in nova and cinder unit test runs in the gate: http://logs.openstack.org/03/602403/1/gate/openstack-tox- py35/b4c9214/testr_results.html.gz http://logs.openstack.org/94/603194/1/gate/openstack-tox- py35/e37d161/testr_results.html.gz Years ago we updated the timeout scaling factor on those tests in nova: https://review.openstack.org/#/c/370805/ For bug 1216851. Looking at a timeout/failed run for nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync against a passing run: nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync [664.512994s] ... FAILED nova.tests.unit.db.test_migrations.TestNovaMigrationsMySQL.test_models_sync [39.644814s] ... ok Based on that, it's clear that we're not just missing some timeout - it looks like we're totally breaking somewhere and only being caught by the timeout. There are a couple of errors in the logs when we see this: b'sqlalchemy.exc.ResourceClosedError: This result object does not return rows. It has been closed automatically.' 2018-09-19 05:35:08.697560 | ubuntu-xenial | b'' 2018-09-19 05:35:08.697658 | ubuntu-xenial | b'The above exception was the direct cause of the following exception:' 2018-09-19 05:35:08.697700 | ubuntu-xenial | b'' 2018-09-19 05:35:08.697772 | ubuntu-xenial | b'Traceback (most recent call last):' 2018-09-19 05:35:08.697957 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/oslo_db/sqlalchemy/test_migrations.py", line 585, in test_models_sync' 2018-09-19 05:35:08.698031 | ubuntu-xenial | b' self.db_sync(self.get_engine())' 2018-09-19 05:35:08.698174 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/unit/db/test_migrations.py", line 146, in db_sync' 2018-09-19 05:35:08.698285 | ubuntu-xenial | b' sa_migration.db_sync()' 2018-09-19 05:35:08.698451 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/db/sqlalchemy/migration.py", line 61, in db_sync' 2018-09-19 05:35:08.698522 | ubuntu-xenial | b' repository, version)' 2018-09-19 05:35:08.698682 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/api.py", line 186, in upgrade' 2018-09-19 05:35:08.698766 | ubuntu-xenial | b' return _migrate(url, repository, version, upgrade=True, err=err, **opts)' 2018-09-19 05:35:08.698823 | ubuntu-xenial | b' File "<decorator-gen-15>", line 2, in _migrate' 2018-09-19 05:35:08.698951 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/util/__init__.py", line 167, in with_engine' 2018-09-19 05:35:08.698991 | ubuntu-xenial | b' return f(*a, **kw)' 2018-09-19 05:35:08.699108 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/api.py", line 366, in _migrate' 2018-09-19 05:35:08.699164 | ubuntu-xenial | b' schema.runchange(ver, change, changeset.step)' 2018-09-19 05:35:08.699315 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/schema.py", line 93, in runchange' 2018-09-19 05:35:08.706788 | ubuntu-xenial | b' change.run(self.engine, step)' 2018-09-19 05:35:08.707005 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/versioning/script/py.py", line 148, in run' 2018-09-19 05:35:08.707058 | ubuntu-xenial | b' script_func(engine)' 2018-09-19 05:35:08.707248 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/db/sqlalchemy/migrate_repo/versions/315_add_migration_progresss_detail.py", line 30, in upgrade' 2018-09-19 05:35:08.707326 | ubuntu-xenial | b' shadow_migrations.create_column(column.copy())' 2018-09-19 05:35:08.707475 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/schema.py", line 475, in create_column' 2018-09-19 05:35:08.707538 | ubuntu-xenial | b' column.create(table=self, *p, **kw)' 2018-09-19 05:35:08.707684 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/schema.py", line 577, in create' 2018-09-19 05:35:08.707769 | ubuntu-xenial | b' engine._run_visitor(visitorcallable, self, connection, **kwargs)' 2018-09-19 05:35:08.707922 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1940, in _run_visitor' 2018-09-19 05:35:08.708036 | ubuntu-xenial | b' conn._run_visitor(visitorcallable, element, **kwargs)' 2018-09-19 05:35:08.708167 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1549, in _run_visitor' 2018-09-19 05:35:08.708217 | ubuntu-xenial | b' **kwargs).traverse_single(element)' 2018-09-19 05:35:08.708343 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 56, in traverse_single' 2018-09-19 05:35:08.708410 | ubuntu-xenial | b' ret = super(AlterTableVisitor, self).traverse_single(elem)' 2018-09-19 05:35:08.708534 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/sql/visitors.py", line 121, in traverse_single' 2018-09-19 05:35:08.708588 | ubuntu-xenial | b' return meth(obj, **kw)' 2018-09-19 05:35:08.708716 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 104, in visit_column' 2018-09-19 05:35:08.708752 | ubuntu-xenial | b' self.execute()' 2018-09-19 05:35:08.708870 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/migrate/changeset/ansisql.py", line 44, in execute' 2018-09-19 05:35:08.708932 | ubuntu-xenial | b' return self.connection.execute(self.buffer.getvalue())' 2018-09-19 05:35:08.709049 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 942, in execute' 2018-09-19 05:35:08.709113 | ubuntu-xenial | b' return self._execute_text(object, multiparams, params)' 2018-09-19 05:35:08.709246 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text' 2018-09-19 05:35:08.709293 | ubuntu-xenial | b' statement, parameters' 2018-09-19 05:35:08.709420 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context' 2018-09-19 05:35:08.709452 | ubuntu-xenial | b' context)' 2018-09-19 05:35:08.709582 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception' 2018-09-19 05:35:08.709637 | ubuntu-xenial | b' util.raise_from_cause(newraise, exc_info)' 2018-09-19 05:35:08.709760 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause' 2018-09-19 05:35:08.709970 | ubuntu-xenial | b' reraise(type(exception), exception, tb=exc_tb, cause=cause)' 2018-09-19 05:35:08.710095 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 248, in reraise' 2018-09-19 05:35:08.710143 | ubuntu-xenial | b' raise value.with_traceback(tb)' 2018-09-19 05:35:08.710277 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context' 2018-09-19 05:35:08.710347 | ubuntu-xenial | b' context)' 2018-09-19 05:35:08.710523 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute' 2018-09-19 05:35:08.710585 | ubuntu-xenial | b' cursor.execute(statement, parameters)' 2018-09-19 05:35:08.710699 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/cursors.py", line 170, in execute' 2018-09-19 05:35:08.710744 | ubuntu-xenial | b' result = self._query(query)' 2018-09-19 05:35:08.710858 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/cursors.py", line 328, in _query' 2018-09-19 05:35:08.710896 | ubuntu-xenial | b' conn.query(q)' 2018-09-19 05:35:08.711046 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 516, in query' 2018-09-19 05:35:08.711131 | ubuntu-xenial | b' self._affected_rows = self._read_query_result(unbuffered=unbuffered)' 2018-09-19 05:35:08.711295 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 727, in _read_query_result' 2018-09-19 05:35:08.711339 | ubuntu-xenial | b' result.read()' 2018-09-19 05:35:08.711454 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 1066, in read' 2018-09-19 05:35:08.711510 | ubuntu-xenial | b' first_packet = self.connection._read_packet()' 2018-09-19 05:35:08.711630 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 656, in _read_packet' 2018-09-19 05:35:08.711680 | ubuntu-xenial | b' packet_header = self._read_bytes(4)' 2018-09-19 05:35:08.711797 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/pymysql/connections.py", line 690, in _read_bytes' 2018-09-19 05:35:08.711845 | ubuntu-xenial | b' data = self._rfile.read(num_bytes)' 2018-09-19 05:35:08.711911 | ubuntu-xenial | b' File "/usr/lib/python3.5/socket.py", line 575, in readinto' 2018-09-19 05:35:08.711988 | ubuntu-xenial | b' return self._sock.recv_into(b)' 2018-09-19 05:35:08.712132 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 360, in recv_into' 2018-09-19 05:35:08.712208 | ubuntu-xenial | b' return self._recv_loop(self.fd.recv_into, 0, buffer, nbytes, flags)' 2018-09-19 05:35:08.712333 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 348, in _recv_loop' 2018-09-19 05:35:08.712376 | ubuntu-xenial | b' self._read_trampoline()' 2018-09-19 05:35:08.712499 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 319, in _read_trampoline' 2018-09-19 05:35:08.712553 | ubuntu-xenial | b' timeout_exc=socket.timeout("timed out"))' 2018-09-19 05:35:08.712673 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/greenio/base.py", line 203, in _trampoline' 2018-09-19 05:35:08.712723 | ubuntu-xenial | b' mark_as_closed=self._mark_as_closed)' 2018-09-19 05:35:08.712844 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/__init__.py", line 162, in trampoline' 2018-09-19 05:35:08.712883 | ubuntu-xenial | b' return hub.switch()' 2018-09-19 05:35:08.713007 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/hub.py", line 294, in switch' 2018-09-19 05:35:08.713091 | ubuntu-xenial | b' return self.greenlet.switch()' 2018-09-19 05:35:08.713213 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/hub.py", line 346, in run' 2018-09-19 05:35:08.713254 | ubuntu-xenial | b' self.wait(sleep_time)' 2018-09-19 05:35:08.713367 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/poll.py", line 85, in wait' 2018-09-19 05:35:08.713414 | ubuntu-xenial | b' presult = self.do_poll(seconds)' 2018-09-19 05:35:08.713529 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/eventlet/hubs/epolls.py", line 62, in do_poll' 2018-09-19 05:35:08.713575 | ubuntu-xenial | b' return self.poll.poll(seconds)' 2018-09-19 05:35:08.713721 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/py35/lib/python3.5/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler' 2018-09-19 05:35:08.713771 | ubuntu-xenial | b' raise TimeoutException()' 2018-09-19 05:35:08.713819 | ubuntu-xenial | b'IndexError: tuple index out of range' 2018-09-19 05:35:08.713843 | ubuntu-xenial | b'' It looks like there are a few places things could be broken, since we have oslo.db, sqlalchemy-migrate, sqlalchemy, pymysql, and eventlet all involved here. Since we're appearing to hit a huge timeout, my guess is we're hitting some issue with eventlet and greenthread switches. To manage notifications about this bug go to: https://bugs.launchpad.net/cinder/+bug/1793364/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
