nova-manage db archive_deleted_rows fails with pgsql on low row count

[Attila Fazekas]

# nova-manage db archive_deleted_rows 100000 fails with postgresql, when I do not have at least 100000 rows for archive.

# nova delete 27d7de76-3d41-4b37-8980-2a783f8296ac
# nova list
+--------------------------------------+--------+--------+------------+-------------+------------------+
| ID | Name | Status | Task State | Power State | Networks |
+--------------------------------------+--------+--------+------------+-------------+------------------+
| 526d13d4-420d-4b5c-b469-bd997ef4da99 | server | ACTIVE | - | Running | private=10.1.0.4 |
| d01ce4e4-a33d-4583-96a4-b9a942d08dd8 | server | ACTIVE | - | Running | private=10.1.0.6 |
+--------------------------------------+--------+--------+------------+-------------+------------------+
# /usr/bin/nova-manage db archive_deleted_rows 1 #### SUCESSS ####
# nova delete 526d13d4-420d-4b5c-b469-bd997ef4da99
# nova delete d01ce4e4-a33d-4583-96a4-b9a942d08dd8
# nova list
+----+------+--------+------------+-------------+----------+
| ID | Name | Status | Task State | Power State | Networks |
+----+------+--------+------------+-------------+----------+
+----+------+--------+------------+-------------+----------+
# /usr/bin/nova-manage db archive_deleted_rows 3 ##### FAILURE ####
Command failed, please check log for more info
2014-04-10 13:40:06.716 CRITICAL nova [req-43b1f10f-9ece-4aae-8812-cd77f6556d38 None None] ProgrammingError: (ProgrammingError) column "locked_by" is of type shadow_instances0locked_by but expression is of type instances0locked_by
LINE 1: ...ces.cell_name, instances.node, instances.deleted, instances....
                                                             ^
HINT: You will need to rewrite or cast the expression.
 'INSERT INTO shadow_instances SELECT instances.created_at, instances.updated_at, instances.deleted_at, instances.id, instances.internal_id, instances.user_id, instances.project_id, instances.image_ref, instances.kernel_id, instances.ramdisk_id, instances.launch_index, instances.key_name, instances.key_data, instances.power_state, instances.vm_state, instances.memory_mb, instances.vcpus, instances.hostname, instances.host, instances.user_data, instances.reservation_id, instances.scheduled_at, instances.launched_at, instances.terminated_at, instances.display_name, instances.display_description, instances.availability_zone, instances.locked, instances.os_type, instances.launched_on, instances.instance_type_id, instances.vm_mode, instances.uuid, instances.architecture, instances.root_device_name, instances.access_ip_v4, instances.access_ip_v6, instances.config_drive, instances.task_state, instances.default_ephemeral_device, instances.default_swap_device, instances.progress, instances.auto_disk_config, instances.shutdown_terminate, instances.disable_terminate, instances.root_gb, instances.ephemeral_gb, instances.cell_name, instances.node, instances.deleted, instances.locked_by, instances.cleaned, instances.ephemeral_key_uuid \nFROM instances \nWHERE instances.deleted != %(deleted_1)s ORDER BY instances.id \n LIMIT %(param_1)s' {'param_1': 1, 'deleted_1': 0}
2014-04-10 13:40:06.716 14789 TRACE nova Traceback (most recent call last):
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/bin/nova-manage", line 10, in <module>
2014-04-10 13:40:06.716 14789 TRACE nova sys.exit(main())
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/cmd/manage.py", line 1376, in main
2014-04-10 13:40:06.716 14789 TRACE nova ret = fn(*fn_args, **fn_kwargs)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/cmd/manage.py", line 902, in archive_deleted_rows
2014-04-10 13:40:06.716 14789 TRACE nova db.archive_deleted_rows(admin_context, max_rows)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/db/api.py", line 1915, in archive_deleted_rows
2014-04-10 13:40:06.716 14789 TRACE nova return IMPL.archive_deleted_rows(context, max_rows=max_rows)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 146, in wrapper
2014-04-10 13:40:06.716 14789 TRACE nova return f(*args, **kwargs)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 5647, in archive_deleted_rows
2014-04-10 13:40:06.716 14789 TRACE nova max_rows=max_rows - rows_archived)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 146, in wrapper
2014-04-10 13:40:06.716 14789 TRACE nova return f(*args, **kwargs)
2014-04-10 13:40:06.716 14789 TRACE nova File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 5617, in archive_deleted_rows_for_table
2014-04-10 13:40:06.716 14789 TRACE nova result_insert = conn.execute(insert_statement)
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 662, in execute
2014-04-10 13:40:06.716 14789 TRACE nova params)
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
2014-04-10 13:40:06.716 14789 TRACE nova compiled_sql, distilled_params
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
2014-04-10 13:40:06.716 14789 TRACE nova context)
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
2014-04-10 13:40:06.716 14789 TRACE nova exc_info
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 196, in raise_from_cause
2014-04-10 13:40:06.716 14789 TRACE nova reraise(type(exception), exception, tb=exc_tb)
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
2014-04-10 13:40:06.716 14789 TRACE nova context)
2014-04-10 13:40:06.716 14789 TRACE nova File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 324, in do_execute
2014-04-10 13:40:06.716 14789 TRACE nova cursor.execute(statement, parameters)
2014-04-10 13:40:06.716 14789 TRACE nova ProgrammingError: (ProgrammingError) column "locked_by" is of type shadow_instances0locked_by but expression is of type instances0locked_by
2014-04-10 13:40:06.716 14789 TRACE nova LINE 1: ...ces.cell_name, instances.node, instances.deleted, instances....
2014-04-10 13:40:06.716 14789 TRACE nova ^
2014-04-10 13:40:06.716 14789 TRACE nova HINT: You will need to rewrite or cast the expression.
2014-04-10 13:40:06.716 14789 TRACE nova 'INSERT INTO shadow_instances SELECT instances.created_at, instances.updated_at, instances.deleted_at, instances.id, instances.internal_id, instances.user_id, instances.project_id, instances.image_ref, instances.kernel_id, instances.ramdisk_id, instances.launch_index, instances.key_name, instances.key_data, instances.power_state, instances.vm_state, instances.memory_mb, instances.vcpus, instances.hostname, instances.host, instances.user_data, instances.reservation_id, instances.scheduled_at, instances.launched_at, instances.terminated_at, instances.display_name, instances.display_description, instances.availability_zone, instances.locked, instances.os_type, instances.launched_on, instances.instance_type_id, instances.vm_mode, instances.uuid, instances.architecture, instances.root_device_name, instances.access_ip_v4, instances.access_ip_v6, instances.config_drive, instances.task_state, instances.default_ephemeral_device, instances.default_swap_device, instances.progress, instances.auto_disk_config, instances.shutdown_terminate, instances.disable_terminate, instances.root_gb, instances.ephemeral_gb, instances.cell_name, instances.node, instances.deleted, instances.locked_by, instances.cleaned, instances.ephemeral_key_uuid \nFROM instances \nWHERE instances.deleted != %(deleted_1)s ORDER BY instances.id \n LIMIT %(param_1)s' {'param_1': 1, 'deleted_1': 0}
2014-04-10 13:40:06.716 14789 TRACE nova

Relevant package versions:
postgresql-server-9.3.4-1.fc20.x86_64
postgresql-9.3.4-1.fc20.x86_64
postgresql-libs-9.3.4-1.fc20.x86_64
postgresql-devel-9.3.4-1.fc20.x86_64
python-sqlalchemy-0.8.5-1.fc20.x86_64
python-psycopg2-2.5.1-2.fc20.x86_64

[Attila Fazekas (afazekas)]

It is delayed-action bomb, if the test cases order changes or we add new test case it could cause high gate failure rate.

The issue reproduced here:
https://review.openstack.org/#/c/100183/1

[Attila Fazekas (afazekas)]

message: "RemoteError: Remote error\: DBDeadlock (OperationalError)" AND tags:"screen-n-cpu.txt"

Looks like my demo change also triggered a mysql issue in the icehouse jobs:
http://logs.openstack.org/83/100183/1/check/check-tempest-dsvm-full-icehouse/dd311fb/logs/screen-n-cpu.txt.gz#_2014-06-16_08_57_54_538

[Salvatore Orlando (salvatore-orlando)]

This bug is triggered very frequently on neutron-full-pg and neutron-full-pg-2 jobs

[Markus Zoeller (markus_z) (mzoeller)]

This is an automated cleanup. This bug report has been closed because it
is older than 18 months and there is no open code change to fix this.
After this time it is unlikely that the circumstances which lead to
the observed issue can be reproduced.

If you can reproduce the bug, please:
* reopen the bug report (set to status "New")
* AND add the detailed steps to reproduce the issue (if applicable)
* AND leave a comment "CONFIRMED FOR: <RELEASE_NAME>"
  Only still supported release names are valid (LIBERTY, MITAKA, OCATA, NEWTON).
  Valid example: CONFIRMED FOR: LIBERTY