db purge records fails for very large number

[Ravi Shekhar Jethani]

The command:
$ nova-manage db archive_deleted_rows <NUMBER> --verbose
fails for very large NUMBER value on nova master

Nova version:
openstack@openstack-136:/opt/stack/nova$ git log -1
commit 29641bd9778b51ac5794dfed9d4b881c5d47dc50
Merge: 21e79d5 9fbe683
Author: Jenkins <email address hidden>
Date: Wed Feb 10 06:03:00 2016 +0000

    Merge "Top 100 slow tests: api.openstack.compute.test_api"

Example:

openstack@openstack-136:~$ nova-manage db archive_deleted_rows 2147483547647747477747474775366545456499999 --verbose
2016-02-09 22:17:10.713 ERROR oslo_db.sqlalchemy.exc_filters [-] DBAPIError exception wrapped from (pymysql.err.ProgrammingError) (1064, u"You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '2147483547647747477747474775366545456499999' at line 4") [SQL: u'INSERT INTO shadow_instance_actions_events (created_at, updated_at, deleted_at, deleted, id, event, action_id, start_time, finish_time, result, traceback, host, details) SELECT instance_actions_events.created_at, instance_actions_events.updated_at, instance_actions_events.deleted_at, instance_actions_events.deleted, instance_actions_events.id, instance_actions_events.event, instance_actions_events.action_id, instance_actions_events.start_time, instance_actions_events.finish_time, instance_actions_events.result, instance_actions_events.traceback, instance_actions_events.host, instance_actions_events.details \nFROM instance_actions_events \nWHERE instance_actions_events.deleted != %s ORDER BY instance_actions_events.id \n LIMIT %s'] [parameters: (0, 2147483547647747477747474775366545456499999L)]
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters context)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 146, in execute
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters result = self._query(query)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 296, in _query
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters conn.query(q)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 781, in query
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 942, in _read_query_result
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters result.read()
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1138, in read
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 906, in _read_packet
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters packet.check_error()
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 367, in check_error
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 112, in _check_mysql_exception
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters raise errorclass(errno, errorvalue)
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters ProgrammingError: (1064, u"You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '2147483547647747477747474775366545456499999' at line 4")
2016-02-09 22:17:10.713 TRACE oslo_db.sqlalchemy.exc_filters
Command failed, please check log for more info
2016-02-09 22:17:10.716 CRITICAL nova [-] DBError: (pymysql.err.ProgrammingError) (1064, u"You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '2147483547647747477747474775366545456499999' at line 4") [SQL: u'INSERT INTO shadow_instance_actions_events (created_at, updated_at, deleted_at, deleted, id, event, action_id, start_time, finish_time, result, traceback, host, details) SELECT instance_actions_events.created_at, instance_actions_events.updated_at, instance_actions_events.deleted_at, instance_actions_events.deleted, instance_actions_events.id, instance_actions_events.event, instance_actions_events.action_id, instance_actions_events.start_time, instance_actions_events.finish_time, instance_actions_events.result, instance_actions_events.traceback, instance_actions_events.host, instance_actions_events.details \nFROM instance_actions_events \nWHERE instance_actions_events.deleted != %s ORDER BY instance_actions_events.id \n LIMIT %s'] [parameters: (0, 2147483547647747477747474775366545456499999L)]

2016-02-09 22:17:10.716 TRACE nova Traceback (most recent call last):
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/bin/nova-manage", line 10, in <module>
2016-02-09 22:17:10.716 TRACE nova sys.exit(main())
2016-02-09 22:17:10.716 TRACE nova File "/opt/stack/nova/nova/cmd/manage.py", line 1448, in main
2016-02-09 22:17:10.716 TRACE nova ret = fn(*fn_args, **fn_kwargs)
2016-02-09 22:17:10.716 TRACE nova File "/opt/stack/nova/nova/cmd/manage.py", line 951, in archive_deleted_rows
2016-02-09 22:17:10.716 TRACE nova table_to_rows_archived = db.archive_deleted_rows(max_rows)
2016-02-09 22:17:10.716 TRACE nova File "/opt/stack/nova/nova/db/api.py", line 1945, in archive_deleted_rows
2016-02-09 22:17:10.716 TRACE nova return IMPL.archive_deleted_rows(max_rows=max_rows)
2016-02-09 22:17:10.716 TRACE nova File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 6129, in archive_deleted_rows
2016-02-09 22:17:10.716 TRACE nova tablename, max_rows=max_rows - total_rows_archived)
2016-02-09 22:17:10.716 TRACE nova File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 6084, in _archive_deleted_rows_for_table
2016-02-09 22:17:10.716 TRACE nova conn.execute(insert)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute
2016-02-09 22:17:10.716 TRACE nova return meth(self, multiparams, params)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2016-02-09 22:17:10.716 TRACE nova return connection._execute_clauseelement(self, multiparams, params)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2016-02-09 22:17:10.716 TRACE nova compiled_sql, distilled_params
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2016-02-09 22:17:10.716 TRACE nova context)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-02-09 22:17:10.716 TRACE nova util.raise_from_cause(newraise, exc_info)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-02-09 22:17:10.716 TRACE nova reraise(type(exception), exception, tb=exc_tb)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-02-09 22:17:10.716 TRACE nova context)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-02-09 22:17:10.716 TRACE nova cursor.execute(statement, parameters)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 146, in execute
2016-02-09 22:17:10.716 TRACE nova result = self._query(query)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 296, in _query
2016-02-09 22:17:10.716 TRACE nova conn.query(q)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 781, in query
2016-02-09 22:17:10.716 TRACE nova self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 942, in _read_query_result
2016-02-09 22:17:10.716 TRACE nova result.read()
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1138, in read
2016-02-09 22:17:10.716 TRACE nova first_packet = self.connection._read_packet()
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 906, in _read_packet
2016-02-09 22:17:10.716 TRACE nova packet.check_error()
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 367, in check_error
2016-02-09 22:17:10.716 TRACE nova err.raise_mysql_exception(self._data)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-02-09 22:17:10.716 TRACE nova _check_mysql_exception(errinfo)
2016-02-09 22:17:10.716 TRACE nova File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 112, in _check_mysql_exception
2016-02-09 22:17:10.716 TRACE nova raise errorclass(errno, errorvalue)
2016-02-09 22:17:10.716 TRACE nova DBError: (pymysql.err.ProgrammingError) (1064, u"You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '2147483547647747477747474775366545456499999' at line 4") [SQL: u'INSERT INTO shadow_instance_actions_events (created_at, updated_at, deleted_at, deleted, id, event, action_id, start_time, finish_time, result, traceback, host, details) SELECT instance_actions_events.created_at, instance_actions_events.updated_at, instance_actions_events.deleted_at, instance_actions_events.deleted, instance_actions_events.id, instance_actions_events.event, instance_actions_events.action_id, instance_actions_events.start_time, instance_actions_events.finish_time, instance_actions_events.result, instance_actions_events.traceback, instance_actions_events.host, instance_actions_events.details \nFROM instance_actions_events \nWHERE instance_actions_events.deleted != %s ORDER BY instance_actions_events.id \n LIMIT %s'] [parameters: (0, 2147483547647747477747474775366545456499999L)]
2016-02-09 22:17:10.716 TRACE nova

Instead of a stacktrace user should get a user friendly message like: "max rows must be <= 2147483647"

[OpenStack Infra (hudson-openstack)]

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

[Abhishek Kekane (abhishek-kekane)]

Similarly glance-manage db purge 1 111111111111111111111111111111111111111111111111111111111111111 fails and give long stack trace.

[OpenStack Infra (hudson-openstack)]

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

[Dinesh Bhor (dinesh-bhor)]

Hi all,

There is also an issue with 'age_in_days' and 'max_rows' positional arguments type validation for glance.

Command:
$ glance-manage db purge "something"

LOG:
2016-02-16 21:59:00.799 CRITICAL glance [-] ValueError: invalid literal for int() with base 10: 'something'

2016-02-16 21:59:00.799 TRACE glance Traceback (most recent call last):
2016-02-16 21:59:00.799 TRACE glance File "/usr/local/bin/glance-manage", line 10, in <module>
2016-02-16 21:59:00.799 TRACE glance sys.exit(main())
2016-02-16 21:59:00.799 TRACE glance File "/opt/stack/glance/glance/cmd/manage.py", line 344, in main
2016-02-16 21:59:00.799 TRACE glance return CONF.command.action_fn(*func_args, **func_kwargs)
2016-02-16 21:59:00.799 TRACE glance File "/opt/stack/glance/glance/cmd/manage.py", line 156, in purge
2016-02-16 21:59:00.799 TRACE glance age_in_days = int(age_in_days)
2016-02-16 21:59:00.799 TRACE glance ValueError: invalid literal for int() with base 10: 'something'
2016-02-16 21:59:00.799 TRACE glance

The same issue is present for 'max_rows' positional argument.

Command:
$ glance-manage db purge 1 "something"

LOG:
2016-02-16 23:01:36.484 CRITICAL glance [-] ValueError: invalid literal for int() with base 10: 'something'

2016-02-16 23:01:36.484 TRACE glance Traceback (most recent call last):
2016-02-16 23:01:36.484 TRACE glance File "/usr/local/bin/glance-manage", line 10, in <module>
2016-02-16 23:01:36.484 TRACE glance sys.exit(main())
2016-02-16 23:01:36.484 TRACE glance File "/opt/stack/glance/glance/cmd/manage.py", line 344, in main
2016-02-16 23:01:36.484 TRACE glance return CONF.command.action_fn(*func_args, **func_kwargs)
2016-02-16 23:01:36.484 TRACE glance File "/opt/stack/glance/glance/cmd/manage.py", line 157, in purge
2016-02-16 23:01:36.484 TRACE glance max_rows = int(max_rows)
2016-02-16 23:01:36.484 TRACE glance ValueError: invalid literal for int() with base 10: 'something'
2016-02-16 23:01:36.484 TRACE glance

Integer type validation of 'age_in_days' and 'max_rows' is done in purge_deleted_rows()[1] method
but that code is not reachable as it is going to throw an exception in purge() method [3] itself before
call to the actual purge_deleted_rows() method [1].

To fix this issue we need to shift validation part of 'age_in_days' and 'max_rows'
from purge_deleted_rows() method [1] to purge() method [2].

I will fix all these issues in a single patch.

[1] https://github.com/openstack/glance/blob/master/glance/db/sqlalchemy/api.py#L1236
[2] https://github.com/openstack/glance/blob/master/glance/cmd/manage.py#L154
[3] https://github.com/openstack/glance/blob/master/glance/cmd/manage.py#L156

[Dinesh Bhor (dinesh-bhor)]

Hi All,

The current implementation of glance-manage doesn't support validation of both positional
and optional arguments using args decorator [1]. Adding validation of argument type inside the
method doesn't look nice as it could increase the code footprint and developer would need to
add this validation for all commands wherever arguments are used.

Possible solution:

A] Make all glance-manage arguments positional:
 This requires major change of code in glance-manage and all arguments are
 considered to be required and if we hit 'glance-manage db purge'
 without any arguments then it will give error: too few arguments.

If someone has any other solution please suggest.

The same issue is present in nova.

[1] https://github.com/openstack/glance/blob/master/glance/cmd/manage.py#L150

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/278268
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=02141ae7d7af5a9e04f0c64488dcfc8aeabf82f6
Submitter: Jenkins
Branch: master

commit 02141ae7d7af5a9e04f0c64488dcfc8aeabf82f6
Author: Ravi Shekhar Jethani <email address hidden>
Date: Wed Feb 10 00:58:01 2016 -0800

    Add check to limit maximum value of max_rows

    Currently archive_deleted_rows() fails if we provide
    a very large number as input. This patch adds a check
    to see that max_rows should not exceed db.MAX_INT and
    provides a meaningful error message to the user.

    Change-Id: I66a5d2cc7b7101e987ee89fcc7779bd9d5a4d144
    Closes-Bug: #1543937

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/nova 13.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/293275

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/293275
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=371043656b64904e536f09afcd23e41e8758fe38
Submitter: Jenkins
Branch: master

commit 371043656b64904e536f09afcd23e41e8758fe38
Author: dineshbhor <email address hidden>
Date: Tue Mar 15 04:12:26 2016 +0000

    Fix db purge type validation

    Moved validation for age_in_days and max_rows from
    glance.db.sqlalchemy.api to glance.cmd.manage since
    code from purge_deleted_rows() method of
    glance.db.sqlalchemy.api is unreachable as it is
    throwing ValueError exception for invalid input from
    glance.cmd.manage itself.

    Related-Bug: #1543937
    Change-Id: I4e976fde2a78fd901c233966adc350a0ded41841

[Bhagyashri Shewale (bhagyashri-shewale)]

Hi all,

There is same issue in cinder if we give the 'age_in_days' positional arguments value as long number.

Command:
$ cinder-manage db purge 18065656675675675756786976879809080675675

LOG:

2016-05-13 18:34:21.239 DEBUG oslo_db.sqlalchemy.engines [req-e6ba6d96-6e30-4086-88dc-5db604c9cecb None None] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION from (pid=23371) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:256
2016-05-13 18:34:21.415 INFO cinder.db.sqlalchemy.api [req-e6ba6d96-6e30-4086-88dc-5db604c9cecb None None] Purging deleted rows older than age=18065656675675675756786976879809080675675 days from table=transfers
2016-05-13 18:34:21.417 CRITICAL cinder [req-e6ba6d96-6e30-4086-88dc-5db604c9cecb None None] OverflowError: Python int too large to convert to C long

2016-05-13 18:34:21.417 TRACE cinder Traceback (most recent call last):
2016-05-13 18:34:21.417 TRACE cinder File "/usr/local/bin/cinder-manage", line 10, in <module>
2016-05-13 18:34:21.417 TRACE cinder sys.exit(main())
2016-05-13 18:34:21.417 TRACE cinder File "/opt/stack/cinder/cinder/cmd/manage.py", line 604, in main
2016-05-13 18:34:21.417 TRACE cinder fn(*fn_args)
2016-05-13 18:34:21.417 TRACE cinder File "/opt/stack/cinder/cinder/cmd/manage.py", line 235, in purge
2016-05-13 18:34:21.417 TRACE cinder db.purge_deleted_rows(ctxt, age_in_days)
2016-05-13 18:34:21.417 TRACE cinder File "/opt/stack/cinder/cinder/db/api.py", line 1064, in purge_deleted_rows
2016-05-13 18:34:21.417 TRACE cinder return IMPL.purge_deleted_rows(context, age_in_days=age_in_days)
2016-05-13 18:34:21.417 TRACE cinder File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 176, in wrapper
2016-05-13 18:34:21.417 TRACE cinder return f(*args, **kwargs)
2016-05-13 18:34:21.417 TRACE cinder File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 4260, in purge_deleted_rows
2016-05-13 18:34:21.417 TRACE cinder deleted_age = timeutils.utcnow() - dt.timedelta(days=age_in_days)
2016-05-13 18:34:21.417 TRACE cinder OverflowError: Python int too large to convert to C long

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/322757
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=25f5eed56faa81969a0e0cd6a732f789deaddb0c
Submitter: Jenkins
Branch: master

commit 25f5eed56faa81969a0e0cd6a732f789deaddb0c
Author: bhagyashris <email address hidden>
Date: Wed May 18 18:04:30 2016 +0530

    Add check to limit maximum value of age_in_days

    If you pass age_in_days value greater than unix epoch
    then it raises OverflowError. Added check to ensure
    age_in_days is within unix epoch time to fix this problem.

    Removed the redundant check for age_in_days value from
    cinder.db.sqlalchemy.api module which is already checked
    at cinder.cmd.manage module.

    Closes-Bug: #1543937
    Change-Id: Ib418627fb8527a1275c2656d1451f1e1dfeb72ef

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/280571
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=9338e5c046679d665537b4355f0279d14aedd62d
Submitter: Jenkins
Branch: master

commit 9338e5c046679d665537b4355f0279d14aedd62d
Author: Dinesh Bhor <email address hidden>
Date: Tue Feb 16 01:36:15 2016 -0800

    Add check to limit maximum value of max_rows

    Currently 'glance-manage db purge' fails if given a
    very large number for max_rows.

    Moved and renamed validate_mysql_int() from
    glance.common.utils to glance.db.sqlalchemy.api as
    _validate_db_int() since it is related to database
    only so that it can be used to validate max_rows
    for maximum limit.

    Closes-Bug: #1543937
    Change-Id: Id16694807c180632c1785e9b1ebe8d1c79d885ab

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/glance 13.0.0.0b3 development milestone.

[Thierry Carrez (ttx)]

This issue was fixed in the openstack/cinder 9.0.0.0b3 development milestone.