DB walk versions unit test is unstable

[Valeriy Ponomaryov]

Test 'manila.tests.db.migrations.alembic.test_migration.TestManilaMigrationsMySQL.test_walk_versions' is unstable.

It fails with following error [1]:

ft1.3017: manila.tests.db.migrations.alembic.test_migration.TestManilaMigrationsMySQL.test_walk_versions_StringException: Empty attachments:
  stdout

pythonlogging:'': {{{ERROR [manila.tests.test_migrations] Failed to migrate to version 5077ffcc5f1c on engine Engine(mysql+pymysql://openstack_citest:***@localhost/bdoesxrcph). Exception while running the migration: tuple index out of range}}}
stderr: {{{
/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/sql/default_comparator.py:153: SAWarning: The IN-predicate on "share_types.id" was invoked with an empty sequence. This results in a contradiction, which nonetheless can be expensive to evaluate. Consider alternative strategies for improved performance.
  'strategies for improved performance.' % expr)
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/fixtures/fixture.py", line 125, in cleanUp
    return self._cleanups(raise_errors=raise_first)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/fixtures/callmany.py", line 88, in __call__
    reraise(error[0], error[1], error[2])
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/fixtures/callmany.py", line 82, in __call__
    cleanup(*args, **kwargs)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/testresources/__init__.py", line 783, in tearDownResources
    resource[1].finishedWith(getattr(test, resource[0]), result)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/testresources/__init__.py", line 495, in finishedWith
    self._clean_all(resource, result)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/testresources/__init__.py", line 464, in _clean_all
    self.clean(resource)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/provision.py", line 127, in clean
    resource.database.engine)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/provision.py", line 263, in drop_all_objects
    self.impl.drop_all_objects(engine)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/provision.py", line 394, in drop_all_objects
    inspector = sqlalchemy.inspect(engine)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/inspection.py", line 63, in inspect
    ret = reg(subject)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 139, in _insp
    return Inspector.from_engine(bind)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 135, in from_engine
    return Inspector(bind)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 109, in __init__
    bind.connect().close()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2018, in connect
    return self._connection_cls(self, **kwargs)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 92, in __init__
    self.dispatch.engine_connect(self, self.__branch)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/event/attr.py", line 256, in __call__
    fn(*args, **kw)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py", line 72, in _connect_ping_listener
    connection.scalar(select([1]))
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 844, in scalar
    return self.execute(object, *multiparams, **params).scalar()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py", line 1064, in scalar
    row = self.first()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py", line 1038, in first
    return self._non_result(None)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/result.py", line 920, in _non_result
    "This result object does not return rows. "
sqlalchemy.exc.ResourceClosedError: This result object does not return rows. It has been closed automatically.
}}}

Traceback (most recent call last):
  File "manila/tests/db/migrations/alembic/test_migration.py", line 150, in test_walk_versions
    downgrade=self.downgrade)
  File "manila/tests/db/migrations/alembic/test_migration.py", line 89, in _walk_versions
    self._migrate_up(version.revision)
  File "manila/tests/db/migrations/alembic/test_migration.py", line 127, in _migrate_up
    self.migration_api.upgrade(version)
  File "manila/db/migrations/alembic/migration.py", line 51, in upgrade
    return alembic.command.upgrade(_alembic_config(), revision or 'head')
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/command.py", line 174, in upgrade
    script.run_env()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/script/base.py", line 397, in run_env
    util.load_python_file(self.dir, 'env.py')
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/util/pyfiles.py", line 81, in load_python_file
    module = load_module_py(module_id, path)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/util/compat.py", line 79, in load_module_py
    mod = imp.load_source(module_id, path, fp)
  File "/home/jenkins/workspace/gate-manila-python27/manila/db/migrations/alembic/env.py", line 41, in <module>
    run_migrations_online()
  File "/home/jenkins/workspace/gate-manila-python27/manila/db/migrations/alembic/env.py", line 36, in run_migrations_online
    context.run_migrations() # pylint: disable=E1101
  File "<string>", line 8, in run_migrations
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/runtime/environment.py", line 797, in run_migrations
    self.get_context().run_migrations(**kw)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/runtime/migration.py", line 312, in run_migrations
    step.migration_fn(**kw)
  File "/home/jenkins/workspace/gate-manila-python27/manila/db/migrations/alembic/versions/5077ffcc5f1c_add_share_instances.py", line 284, in upgrade
    upgrade_export_locations_table(connection)
  File "/home/jenkins/workspace/gate-manila-python27/manila/db/migrations/alembic/versions/5077ffcc5f1c_add_share_instances.py", line 247, in upgrade_export_locations_table
    'share_instance_export_locations')
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/operations/base.py", line 299, in batch_alter_table
    impl.flush()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/operations/batch.py", line 54, in flush
    fn(*arg, **kw)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/ddl/impl.py", line 183, in drop_constraint
    self._exec(schema.DropConstraint(const))
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/alembic/ddl/impl.py", line 118, in _exec
    return conn.execute(construct, *multiparams, **params)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
    return meth(self, multiparams, params)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/sql/ddl.py", line 68, in _execute_on_connection
    return connection._execute_ddl(self, multiparams, params)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 968, in _execute_ddl
    compiled
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
    context)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
    util.raise_from_cause(newraise, exc_info)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
    context)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
    cursor.execute(statement, parameters)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/cursors.py", line 146, in execute
    result = self._query(query)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/cursors.py", line 296, in _query
    conn.query(q)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/connections.py", line 781, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/connections.py", line 942, in _read_query_result
    result.read()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/connections.py", line 1138, in read
    first_packet = self.connection._read_packet()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
    packet_header = self._read_bytes(4)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
    data = self._rfile.read(num_bytes)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/pymysql/_socketio.py", line 59, in readinto
    return self._sock.recv_into(b)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 346, in recv_into
    timeout_exc=socket.timeout("timed out"))
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 201, in _trampoline
    mark_as_closed=self._mark_as_closed)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/__init__.py", line 162, in trampoline
    return hub.switch()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
    return self.greenlet.switch()
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 346, in run
    self.wait(sleep_time)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/poll.py", line 85, in wait
    presult = self.do_poll(seconds)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/eventlet/hubs/epolls.py", line 62, in do_poll
    return self.poll.poll(seconds)
  File "/home/jenkins/workspace/gate-manila-python27/.tox/py27/local/lib/python2.7/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
    raise TimeoutException()
IndexError: tuple index out of range

[1] http://logs.openstack.org/13/228513/5/check/gate-manila-python27/7ca019a/testr_results.html.gz

[Valeriy Ponomaryov (vponomaryov)]

Setting 'high' priority as it is influences gates stability.

[NidhiMittalHada (nidhimittal19)]

working on this

[NidhiMittalHada (nidhimittal19)]

HI Valeriy,

stack@controller:/opt/stack/manila$ sudo tox -v -epy27 manila.tests.db.migrations.alembic.test_migration.TestManilaMigrationsMySQL.test_walk_versions

using tox.ini: /opt/stack/manila/tox.ini
using tox-2.2.1 from /usr/local/lib/python2.7/dist-packages/tox/__init__.pyc
py27 create: /opt/stack/manila/.tox/py27
  /opt/stack/manila/.tox$ /usr/bin/python -m virtualenv --python /usr/bin/python2.7 py27 >/opt/stack/manila/.tox/py27/log/py27-0.log
py27 installdeps: -r/opt/stack/manila/requirements.txt, -r/opt/stack/manila/test-requirements.txt
  /opt/stack/manila$ /opt/stack/manila/.tox/py27/bin/pip install -r/opt/stack/manila/requirements.txt -r/opt/stack/manila/test-requirements.txt >/opt/stack/manila/.tox/py27/log/py27-1.log
py27 develop-inst: /opt/stack/manila
  /opt/stack/manila$ /opt/stack/manila/.tox/py27/bin/pip install -e /opt/stack/manila >/opt/stack/manila/.tox/py27/log/py27-2.log
py27 installed: aioeventlet==0.4,alembic==0.8.4,amqp==1.4.9,anyjson==0.3.3,appdirs==1.4.0,Babel==2.2.0,bashate==0.3.2,cachetools==1.1.5,cliff==1.15.0,cmd2==0.6.8,contextlib2==0.5.1,coverage==4.0.3,ddt==1.0.1,debtcollector==1.2.0,decorator==4.0.6,docutils==0.12,ecdsa==0.13,enum34==1.1.2,eventlet==0.17.4,extras==0.0.3,fasteners==0.14.1,fixtures==1.4.0,flake8==2.1.0,funcsigs==0.4,futures==3.0.3,futurist==0.9.0,greenlet==0.4.9,hacking==0.9.6,iso8601==0.1.11,Jinja2==2.8,keystoneauth1==2.2.0,keystonemiddleware==4.1.0,kombu==3.0.33,linecache2==1.0.0,lxml==3.5.0,Mako==1.0.3,-e git+https://github.com/openstack/manila.git@35b8ac7c05048fe6d78d06a040823799f1d76397#egg=manila-bug_1501272,MarkupSafe==0.23,mccabe==0.2.1,mock==1.3.0,monotonic==0.5,mox3==0.13.0,msgpack-python==0.4.6,netaddr==0.7.18,netifaces==0.10.4,ordereddict==1.1,os-client-config==1.13.1,oslo.concurrency==3.3.0,oslo.config==3.2.1,oslo.context==1.0.1,oslo.db==4.3.0,oslo.i18n==3.2.0,oslo.log==2.3.0,oslo.messaging==4.0.0,oslo.middleware==3.5.0,oslo.policy==1.3.0,oslo.rootwrap==3.1.0,oslo.serialization==2.2.0,oslo.service==1.3.0,oslo.utils==3.4.0,oslosphinx==4.2.0,oslotest==2.0.0,paramiko==1.16.0,Paste==2.0.2,PasteDeploy==1.5.2,pbr==1.8.1,pep8==1.5.6,prettytable==0.7.2,psycopg2==2.6.1,pycadf==2.0.1,pycrypto==2.6.1,pyflakes==0.8.1,Pygments==2.0.2,pyinotify==0.9.6,PyMySQL==0.7.1,pyparsing==2.0.7,python-cinderclient==1.5.0,python-dateutil==2.4.2,python-editor==0.5,python-keystoneclient==2.1.1,python-mimeparse==0.1.4,python-neutronclient==4.0.0,python-novaclient==3.2.0,python-subunit==1.2.0,pytz==2015.7,PyYAML==3.11,reno==1.3.0,repoze.lru==0.6,requests==2.9.1,requests-mock==0.7.0,requestsexceptions==1.1.2,retrying==1.3.3,Routes==2.2,simplejson==3.8.1,six==1.10.0,Sphinx==1.2.3,SQLAlchemy==1.0.11,sqlalchemy-migrate==0.10.0,sqlparse==0.1.18,stevedore==1.10.0,Tempita==0.5.2,testrepository==0.0.20,testresources==1.0.0,testscenarios==0.5.0,testtools==1.8.1,traceback2==1.4.0,trollius==2.0,unicodecsv==0.14.1,unittest2==1.1.0,WebOb==1.5.1,wheel==0.24.0,wrapt==1.10.6
py27 runtests: PYTHONHASHSEED='3782885513'
py27 runtests: commands[0] | find . -type f -name *.pyc -delete
  /opt/stack/manila$ /usr/bin/find . -type f -name *.pyc -delete
py27 runtests: commands[1] | python setup.py testr --testr-args=manila.test...

[NidhiMittalHada (nidhimittal19)]

Not reproduced.

[NidhiMittalHada (nidhimittal19)]

Its assignee's responsibility to find root cause.. its rarely reproduced ..

[Valeriy Ponomaryov (vponomaryov)]

Has been observed 40 times for last 7 days according to logstash: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%20%5C%22This%20result%20object%20does%20not%20return%20rows.%20It%20has%20been%20closed%20automatically%5C%22

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/291397

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/291397
Committed: https://git.openstack.org/cgit/openstack/manila/commit/?id=37c6e3179f96c6cd22b357030eee7a4218f3becd
Submitter: Jenkins
Branch: master

commit 37c6e3179f96c6cd22b357030eee7a4218f3becd
Author: Valeriy Ponomaryov <email address hidden>
Date: Thu Mar 10 21:56:31 2016 +0200

    Fix unstable DB migration tests

    Unit test 'test_walk_versions' in
    'manila.tests.db.migrations.alembic.test_migration' module
    takes abnormally very long time sometimes.
    In common cases it takes about 5-10 seconds in CI for Mitaka set of
    DB migrations.
    In CI runs when this test fails, 'postgres' variant takes
    about 47 seconds and mysql reaches common test timeout of 60 seconds.

    Note, that this test becomes slower with each
    addition of new DB migration. Also, 'pymysql' works much slower
    on slow nodes than 'psycopg2'.

    So, add new test decorator that sets individual test timeout.
    And make it be 5 minutes for mentioned test. In worst case of Mitaka
    DB migrations set it can take about 2 minutes, but make it bigger
    to have a margin for future releases.

    Change-Id: I233f96f29fe62231c2e7013b74c06396dd923f27
    Closes-Bug: #1501272

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/manila 2.0.0.0rc1 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/manila 2.0.0 release.