test_walk_versions tests fail with "IndexError: tuple index out of range" after timeout

Bug #1687027 reported by Ihar Hrachyshka on 2017-04-28
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
neutron
High
Slawek Kaplonski

Bug Description

http://logs.openstack.org/99/460399/1/check/gate-neutron-dsvm-functional-ubuntu-xenial/25de43d/testr_results.html.gz

Traceback (most recent call last):
  File "neutron/tests/base.py", line 115, in func
    return f(self, *args, **kwargs)
  File "neutron/tests/base.py", line 115, in func
    return f(self, *args, **kwargs)
  File "neutron/tests/functional/db/test_migrations.py", line 551, in test_walk_versions
    self._migrate_up(config, engine, dest, curr, with_data=True)
  File "neutron/tests/functional/db/test_migrations.py", line 537, in _migrate_up
    migration.do_alembic_command(config, 'upgrade', dest)
  File "neutron/db/migration/cli.py", line 109, in do_alembic_command
    getattr(alembic_command, cmd)(config, *args, **kwargs)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/command.py", line 254, in upgrade
    script.run_env()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/script/base.py", line 416, in run_env
    util.load_python_file(self.dir, 'env.py')
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/util/pyfiles.py", line 93, in load_python_file
    module = load_module_py(module_id, path)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/util/compat.py", line 75, in load_module_py
    mod = imp.load_source(module_id, path, fp)
  File "neutron/db/migration/alembic_migrations/env.py", line 120, in <module>
    run_migrations_online()
  File "neutron/db/migration/alembic_migrations/env.py", line 114, in run_migrations_online
    context.run_migrations()
  File "<string>", line 8, in run_migrations
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/runtime/environment.py", line 817, in run_migrations
    self.get_context().run_migrations(**kw)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/runtime/migration.py", line 323, in run_migrations
    step.migration_fn(**kw)
  File "/opt/stack/new/neutron/neutron/db/migration/alembic_migrations/versions/mitaka/expand/3894bccad37f_add_timestamp_to_base_resources.py", line 36, in upgrade
    sa.Column(column_name, sa.DateTime(), nullable=True)
  File "<string>", line 8, in add_column
  File "<string>", line 3, in add_column
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/operations/ops.py", line 1551, in add_column
    return operations.invoke(op)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/operations/base.py", line 318, in invoke
    return fn(self, operation)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/operations/toimpl.py", line 123, in add_column
    schema=schema
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/ddl/impl.py", line 172, in add_column
    self._exec(base.AddColumn(table_name, column, schema=schema))
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/alembic/ddl/impl.py", line 118, in _exec
    return conn.execute(construct, *multiparams, **params)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 945, in execute
    return meth(self, multiparams, params)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/sql/ddl.py", line 68, in _execute_on_connection
    return connection._execute_ddl(self, multiparams, params)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1002, in _execute_ddl
    compiled
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
    context)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1398, in _handle_dbapi_exception
    util.raise_from_cause(newraise, exc_info)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
    cursor.execute(statement, parameters)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
    result = self._query(query)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
    conn.query(q)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
    result.read()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
    first_packet = self.connection._read_packet()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/connections.py", line 987, in _read_packet
    packet_header = self._read_bytes(4)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/connections.py", line 1021, in _read_bytes
    data = self._rfile.read(num_bytes)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/pymysql/_socketio.py", line 59, in readinto
    return self._sock.recv_into(b)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 360, in recv_into
    return self._recv_loop(self.fd.recv_into, 0, buffer, nbytes, flags)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 348, in _recv_loop
    self._read_trampoline()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 319, in _read_trampoline
    timeout_exc=socket.timeout("timed out"))
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/greenio/base.py", line 203, in _trampoline
    mark_as_closed=self._mark_as_closed)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/hubs/__init__.py", line 162, in trampoline
    return hub.switch()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
    return self.greenlet.switch()
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 346, in run
    self.wait(sleep_time)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/hubs/poll.py", line 85, in wait
    presult = self.do_poll(seconds)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/eventlet/hubs/epolls.py", line 62, in do_poll
    return self.poll.poll(seconds)
  File "/opt/stack/new/neutron/.tox/dsvm-functional/local/lib/python2.7/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
    raise TimeoutException()
IndexError: tuple index out of range

It's interesting that ALL of them fail in the same job (something wrong with the db backend?) Counterparts for postgresql didn't fail.

The tests in question are quite long. (Tool psql test to pass in 55secs, while mysql failed after 200s+). We see that mysqld is the most intensive process during those 200secs (see dstat). Is it really just slow?

Several suggestions here:
- we should probably squash scripts, they span till Mitaka right now.
- there are no mysqld logs in functional job. Should we add those?
- there is no per-testcase log file for the tests, probably because the tests are special snowflakes that don't use common base test class that would set logdir.

In good runs, mysql flavours of the test work just fine, not taking much longer than postgresql.

Changed in neutron:
importance: Undecided → High
status: New → Confirmed
tags: added: functional-tests gate-failure
Slawek Kaplonski (slaweq) wrote :

No hits in last 30 days for such error: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22IndexError%3A%20tuple%20index%20out%20of%20range%5C%22%20AND%20build_name%3Aneutron-functional

I will close it for now. If You think that it's still problem, please reopen this bug

Changed in neutron:
status: Confirmed → Incomplete
Jakub Libosvar (libosvar) wrote :
Changed in neutron:
status: Incomplete → Confirmed
Miguel Lavalle (minsel) on 2018-06-26
Changed in neutron:
assignee: nobody → Miguel Lavalle (minsel)

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

Changed in neutron:
assignee: Miguel Lavalle (minsel) → Slawek Kaplonski (slaweq)
status: Confirmed → In Progress

Reviewed: https://review.openstack.org/610003
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=c2c37272bf788aac63399127cddd487dc0f15c38
Submitter: Zuul
Branch: master

commit c2c37272bf788aac63399127cddd487dc0f15c38
Author: Slawek Kaplonski <email address hidden>
Date: Fri Oct 12 12:35:10 2018 +0200

    [Functional] Increase test_timeout for db migration tests

    In Neutron we hit quite often same issue as Manila, see [1] for
    details.
    It looks that solution for this problem may be increase timeout
    for test_walk_version functional tests.
    Higher timeout will be applied for tests for both pgsql and mysql
    backends but it is mostly needed for mysql because 'pymysql' works
    much slower on slow nodes than 'psycopg2'

    This patch adds also new decorator to set individual timeout for
    tests.

    [1] https://bugs.launchpad.net/manila/+bug/1501272

    Change-Id: I5f344af6dc3e5a6ee5f52c250b6c719e1b43e02d
    Closes-Bug: #1687027

Changed in neutron:
status: In Progress → Fix Released

Reviewed: https://review.openstack.org/611354
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=026d911832256fa2f79ff808b99d578e43dd2c7f
Submitter: Zuul
Branch: stable/rocky

commit 026d911832256fa2f79ff808b99d578e43dd2c7f
Author: Slawek Kaplonski <email address hidden>
Date: Fri Oct 12 12:35:10 2018 +0200

    [Functional] Increase test_timeout for db migration tests

    In Neutron we hit quite often same issue as Manila, see [1] for
    details.
    It looks that solution for this problem may be increase timeout
    for test_walk_version functional tests.
    Higher timeout will be applied for tests for both pgsql and mysql
    backends but it is mostly needed for mysql because 'pymysql' works
    much slower on slow nodes than 'psycopg2'

    This patch adds also new decorator to set individual timeout for
    tests.

    [1] https://bugs.launchpad.net/manila/+bug/1501272

    Change-Id: I5f344af6dc3e5a6ee5f52c250b6c719e1b43e02d
    Closes-Bug: #1687027
    (cherry picked from commit c2c37272bf788aac63399127cddd487dc0f15c38)

tags: added: in-stable-rocky
tags: added: in-stable-queens

Reviewed: https://review.openstack.org/611357
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=db07fe8698dc24b8a6b7f09a96492d1bb959cc74
Submitter: Zuul
Branch: stable/queens

commit db07fe8698dc24b8a6b7f09a96492d1bb959cc74
Author: Slawek Kaplonski <email address hidden>
Date: Fri Oct 12 12:35:10 2018 +0200

    [Functional] Increase test_timeout for db migration tests

    In Neutron we hit quite often same issue as Manila, see [1] for
    details.
    It looks that solution for this problem may be increase timeout
    for test_walk_version functional tests.
    Higher timeout will be applied for tests for both pgsql and mysql
    backends but it is mostly needed for mysql because 'pymysql' works
    much slower on slow nodes than 'psycopg2'

    This patch adds also new decorator to set individual timeout for
    tests.

    [1] https://bugs.launchpad.net/manila/+bug/1501272

    Change-Id: I5f344af6dc3e5a6ee5f52c250b6c719e1b43e02d
    Closes-Bug: #1687027
    (cherry picked from commit c2c37272bf788aac63399127cddd487dc0f15c38)

tags: added: in-stable-ocata

Reviewed: https://review.openstack.org/611360
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=1cb8901b4213648a7fec1978e98905c6eac8bcd9
Submitter: Zuul
Branch: stable/ocata

commit 1cb8901b4213648a7fec1978e98905c6eac8bcd9
Author: Slawek Kaplonski <email address hidden>
Date: Fri Oct 12 12:35:10 2018 +0200

    [Functional] Increase test_timeout for db migration tests

    In Neutron we hit quite often same issue as Manila, see [1] for
    details.
    It looks that solution for this problem may be increase timeout
    for test_walk_version functional tests.
    Higher timeout will be applied for tests for both pgsql and mysql
    backends but it is mostly needed for mysql because 'pymysql' works
    much slower on slow nodes than 'psycopg2'

    This patch adds also new decorator to set individual timeout for
    tests.

    [1] https://bugs.launchpad.net/manila/+bug/1501272

    Change-Id: I5f344af6dc3e5a6ee5f52c250b6c719e1b43e02d
    Closes-Bug: #1687027
    (cherry picked from commit c2c37272bf788aac63399127cddd487dc0f15c38)

tags: added: neutron-proactive-backport-potential

Reviewed: https://review.openstack.org/611358
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f26eed6677965de51fe8d88f9750c1b6a5becce5
Submitter: Zuul
Branch: stable/pike

commit f26eed6677965de51fe8d88f9750c1b6a5becce5
Author: Slawek Kaplonski <email address hidden>
Date: Fri Oct 12 12:35:10 2018 +0200

    [Functional] Increase test_timeout for db migration tests

    In Neutron we hit quite often same issue as Manila, see [1] for
    details.
    It looks that solution for this problem may be increase timeout
    for test_walk_version functional tests.
    Higher timeout will be applied for tests for both pgsql and mysql
    backends but it is mostly needed for mysql because 'pymysql' works
    much slower on slow nodes than 'psycopg2'

    This patch adds also new decorator to set individual timeout for
    tests.

    [1] https://bugs.launchpad.net/manila/+bug/1501272

    Change-Id: I5f344af6dc3e5a6ee5f52c250b6c719e1b43e02d
    Closes-Bug: #1687027
    (cherry picked from commit c2c37272bf788aac63399127cddd487dc0f15c38)

tags: added: in-stable-pike
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers