yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1793364] Re: mysql db opportunistic unit tests timing out intermittently in the gate (bad thread switch?)

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Goutham Pacha Ravi <gouthamr@xxxxxxxxxx>
Date: Thu, 20 Sep 2018 23:42:16 -0000
Reply-to: Bug 1793364 <1793364@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Latching on, we had a similar failure on the manila gate today:
http://paste.openstack.org/show/730492/


** Also affects: manila
   Importance: Undecided
       Status: New

-- 
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 Manila:
  New
Status in OpenStack Compute (nova):
  Confirmed
Status in oslo.db:
  New

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
References

[Bug 1793364] [NEW] mysql db opportunistic unit tests timing out intermittently in the gate (bad thread switch?)
From: Matt Riedemann, 2018-09-19