db migration issue on CentOS

[Tom Barron]

manila has some CentOS jobs in which the devstack install has recently been failing during the Cinder DB migrations:

2018-12-12 14:29:30.192 | INFO migrate.versioning.api [-] done
2018-12-12 14:29:30.192 | INFO migrate.versioning.api [-] 125 -> 126... 
2018-12-12 14:29:30.201 | INFO migrate.versioning.api [-] done
2018-12-12 14:29:30.201 | INFO migrate.versioning.api [-] 126 -> 127... 
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters [-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1071, u'Specified key was too long; max key length is 767 bytes') [SQL: u'\nALTER TABLE quota_usages CHANGE COLUMN resource resource VARCHAR(300)'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1071, u'Specified key was too long; max key length is 767 bytes')
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  context)
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  cursor.execute(statement, parameters)
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 170, in execute
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  result = self._query(query)
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 328, in _query
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  conn.query(q)
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 516, in query
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-12-12 14:29:30.212 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 727, in _read_query_result
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  result.read()
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1066, in read
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  first_packet = self.connection._read_packet()
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 683, in _read_packet
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  packet.check_error()
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/protocol.py", line 220, in check_error
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  err.raise_mysql_exception(self._data)
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 109, in raise_mysql_exception
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters  raise errorclass(errno, errval)
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1071, u'Specified key was too long; max key length is 767 bytes')
2018-12-12 14:29:30.213 | ERROR oslo_db.sqlalchemy.exc_filters 
2018-12-12 14:29:30.214 | Error during database migration: (pymysql.err.InternalError) (1071, u'Specified key was too long; max key length is 767 bytes') [SQL: u'\nALTER TABLE quota_usages CHANGE COLUMN resource resource VARCHAR(300)'] (Background on this error at: http://sqlalche.me/e/2j85)
2018-12-12 14:29:30.327 | + lib/cinder:init_cinder:1 : exit_trap

We don't see the same issue on the corresponding (experimental) ubuntu bionic job.

Both jobs use PyMySQL 0.9.2.

[LIU Yulong (dragon889)]

+1
I can confirm this.

Error at this db upgrade version:
https://github.com/openstack/cinder/blob/master/cinder/db/sqlalchemy/migrate_repo/versions/127_change_project_resource_attribute_for_quota_usages.py

Basicly because of the mariadb length utf8 limitation.

My env:
devstack master branch
$ uname -r
3.10.0-862.14.4.el7.x86_64

mariadb-10.1.20-2.el7.x86_64

=== my.cnf===
[client]
default-character-set = utf8

[mysqld]
query_cache_size = 0
query_cache_type = OFF
max_connections = 1024
sql_mode = TRADITIONAL
bind-address = 0.0.0.0
default-storage-engine = InnoDB
innodb_file_per_table
collation-server = utf8_general_ci
init-connect = 'SET NAMES utf8'
character-set-server = utf8

[mysql]
default-character-set = utf8

[Eduardo Gonzalez (egonzalez90)]

Is also seen in kolla job http://logs.openstack.org/41/619341/12/check/kolla-ansible-ubuntu-source-ceph/811cb0b/secondary1/logs/kolla/cinder/cinder-manage.txt.gz#_2018-12-14_13_17_59_667

2018-12-14 13:17:59.654 13 INFO migrate.versioning.api [-] 126 -> 127...
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters [-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1071, u'Specified key was too long; max key length is 767 bytes') [SQL: u'\nALTER TABLE quota_usages CHANGE COLUMN resource resource VARCHAR(300)'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1071, u'Specified key was too long; max key length is 767 bytes')
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters context)
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 170, in execute
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query)
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 328, in _query
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q)
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 516, in query
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 727, in _read_query_result
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters result.read()
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1066, in read
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 683, in _read_packet
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error()
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/protocol.py", line 220, in check_error
2018-12-14 13:17:59.667 13 ERROR oslo_db.sqlalchemy.exc_filters...

[Jay Bryant (jsbryant)]

We have discussed this issue in the IRC channel today. Given that the change that caused this (https://review.openstack.org/#/c/611530/8) is covering an edge case it seems that this is something we should be able to work around.

In discussion we talked about changing the migration to catch the failure and check for the DB type. In the case that the DB is mariadb then make the failure non-fatal. There is some precedence for doing something like this: https://github.com/openstack/cinder/blob/master/cinder/db/sqlalchemy/migrate_repo/versions/085_cinder_init.py#L782

[Dr. Jens Harbott (j-harbott)]

Just noting that the error is also seen in the devstack-platform-centos-7 job, maybe Cinder wants to add that job to their project.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/626146
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=cea54bb54430f38ca4b2f28394e7f47b14555e5a
Submitter: Zuul
Branch: master

commit cea54bb54430f38ca4b2f28394e7f47b14555e5a
Author: Gorka Eguileor <email address hidden>
Date: Wed Dec 19 11:51:18 2018 +0100

    Ignore migration 127 error on MariaDB

    Older MariaDB, and InnoDB with 4K page sizes [1], don't support a text fields
    to have more than 767 bytes, which means that we cannot extend the quota_usage
    _resource to 300 characters on migration 127.

    Since this migration is to cover a corner case, we ignore the exception
    during the migration if we are on a MySQL DB engine.

    [1]: https://mariadb.com/kb/en/library/innodb-limitations/#page-sizes

    Closes-Bug: #1808598
    Change-Id: Id990b98f0ac7aaedf48a77ebee2b083fcbdaaee7

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 14.0.0.0rc1 release candidate.