yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1360650] Re: test_db_archive_deleted_rows failing in postgres jobs with ProgrammingError

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: "Davanum Srinivas \(DIMS\)" <davanum@xxxxxxxxx>
Date: Tue, 09 Sep 2014 12:41:00 -0000
Reply-to: Bug 1360650 <1360650@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Doesn't seem to be happening anymore...Let's reopen if necessary.

** Changed in: nova
       Status: Confirmed => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1360650

Title:
  test_db_archive_deleted_rows failing in postgres jobs with
  ProgrammingError

Status in OpenStack Compute (Nova):
  Invalid

Bug description:
  http://logs.openstack.org/99/106299/12/gate/gate-tempest-dsvm-neutron-
  pg-full/19a6b7d/console.html

  This is mostly in the neutron jobs:

  2014-08-23 17:15:04.731 | tempest.cli.simple_read_only.test_nova_manage.SimpleReadOnlyNovaManageTest.test_db_archive_deleted_rows
  2014-08-23 17:15:04.731 | -------------------------------------------------------------------------------------------------------
  2014-08-23 17:15:04.731 | 
  2014-08-23 17:15:04.731 | Captured traceback:
  2014-08-23 17:15:04.732 | ~~~~~~~~~~~~~~~~~~~
  2014-08-23 17:15:04.732 |     Traceback (most recent call last):
  2014-08-23 17:15:04.732 |       File "tempest/cli/simple_read_only/test_nova_manage.py", line 84, in test_db_archive_deleted_rows
  2014-08-23 17:15:04.732 |         self.nova_manage('db archive_deleted_rows 50')
  2014-08-23 17:15:04.732 |       File "tempest/cli/__init__.py", line 117, in nova_manage
  2014-08-23 17:15:04.732 |         'nova-manage', action, flags, params, fail_ok, merge_stderr)
  2014-08-23 17:15:04.733 |       File "tempest/cli/__init__.py", line 53, in execute
  2014-08-23 17:15:04.733 |         result_err)
  2014-08-23 17:15:04.733 |     CommandFailed: Command '['/usr/local/bin/nova-manage', 'db', 'archive_deleted_rows', '50']' returned non-zero exit status 1.
  2014-08-23 17:15:04.733 |     stdout:
  2014-08-23 17:15:04.733 |     Command failed, please check log for more info
  2014-08-23 17:15:04.733 |     
  2014-08-23 17:15:04.734 |     stderr:
  2014-08-23 17:15:04.734 |     2014-08-23 17:02:31.331 CRITICAL nova [req-414244fa-d6c7-4868-8b78-8fe40f119b52 None None] ProgrammingError: (ProgrammingError) column "locked_by" is of type shadow_instances0locked_by but expression is of type instances0locked_by
  2014-08-23 17:15:04.734 |     LINE 1: ...ces.cell_name, instances.node, instances.deleted, instances....
  2014-08-23 17:15:04.734 |                                                                  ^
  2014-08-23 17:15:04.734 |     HINT:  You will need to rewrite or cast the expression.
  2014-08-23 17:15:04.735 |      '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': 39, 'deleted_1': 0}
  2014-08-23 17:15:04.735 |     2014-08-23 17:02:31.331 22441 TRACE nova Traceback (most recent call last):
  2014-08-23 17:15:04.735 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/local/bin/nova-manage", line 10, in <module>
  2014-08-23 17:15:04.735 |     2014-08-23 17:02:31.331 22441 TRACE nova     sys.exit(main())
  2014-08-23 17:15:04.736 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/cmd/manage.py", line 1401, in main
  2014-08-23 17:15:04.736 |     2014-08-23 17:02:31.331 22441 TRACE nova     ret = fn(*fn_args, **fn_kwargs)
  2014-08-23 17:15:04.736 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/cmd/manage.py", line 920, in archive_deleted_rows
  2014-08-23 17:15:04.736 |     2014-08-23 17:02:31.331 22441 TRACE nova     db.archive_deleted_rows(admin_context, max_rows)
  2014-08-23 17:15:04.736 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/db/api.py", line 1959, in archive_deleted_rows
  2014-08-23 17:15:04.737 |     2014-08-23 17:02:31.331 22441 TRACE nova     return IMPL.archive_deleted_rows(context, max_rows=max_rows)
  2014-08-23 17:15:04.737 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 149, in wrapper
  2014-08-23 17:15:04.737 |     2014-08-23 17:02:31.331 22441 TRACE nova     return f(*args, **kwargs)
  2014-08-23 17:15:04.737 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 5677, in archive_deleted_rows
  2014-08-23 17:15:04.737 |     2014-08-23 17:02:31.331 22441 TRACE nova     max_rows=max_rows - rows_archived)
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 149, in wrapper
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova     return f(*args, **kwargs)
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 5647, in archive_deleted_rows_for_table
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova     conn.execute(insert_statement)
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
  2014-08-23 17:15:04.738 |     2014-08-23 17:02:31.331 22441 TRACE nova     params)
  2014-08-23 17:15:04.739 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
  2014-08-23 17:15:04.739 |     2014-08-23 17:02:31.331 22441 TRACE nova     compiled_sql, distilled_params
  2014-08-23 17:15:04.739 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
  2014-08-23 17:15:04.739 |     2014-08-23 17:02:31.331 22441 TRACE nova     context)
  2014-08-23 17:15:04.739 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
  2014-08-23 17:15:04.740 |     2014-08-23 17:02:31.331 22441 TRACE nova     exc_info
  2014-08-23 17:15:04.740 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 196, in raise_from_cause
  2014-08-23 17:15:04.740 |     2014-08-23 17:02:31.331 22441 TRACE nova     reraise(type(exception), exception, tb=exc_tb)
  2014-08-23 17:15:04.740 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
  2014-08-23 17:15:04.740 |     2014-08-23 17:02:31.331 22441 TRACE nova     context)
  2014-08-23 17:15:04.741 |     2014-08-23 17:02:31.331 22441 TRACE nova   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
  2014-08-23 17:15:04.741 |     2014-08-23 17:02:31.331 22441 TRACE nova     cursor.execute(statement, parameters)
  2014-08-23 17:15:04.741 |     2014-08-23 17:02:31.331 22441 TRACE nova ProgrammingError: (ProgrammingError) column "locked_by" is of type shadow_instances0locked_by but expression is of type instances0locked_by
  2014-08-23 17:15:04.741 |     2014-08-23 17:02:31.331 22441 TRACE nova LINE 1: ...ces.cell_name, instances.node, instances.deleted, instances....
  2014-08-23 17:15:04.741 |     2014-08-23 17:02:31.331 22441 TRACE nova                                                              ^
  2014-08-23 17:15:04.810 |     2014-08-23 17:02:31.331 22441 TRACE nova HINT:  You will need to rewrite or cast the expression.
  2014-08-23 17:15:04.810 |     2014-08-23 17:02:31.331 22441 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': 39, 'deleted_1': 0}
  2014-08-23 17:15:04.810 |     2014-08-23 17:02:31.331 22441 TRACE nova 

  message:"ProgrammingError: (ProgrammingError) column \"locked_by\" is
  of type shadow_instances0locked_by but expression is of type
  instances0locked_by"

  2680 hits in 7 days, check and gate, all fails, only in postgresql
  jobs:

  http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiUHJvZ3JhbW1pbmdFcnJvcjogKFByb2dyYW1taW5nRXJyb3IpIGNvbHVtbiBcXFwibG9ja2VkX2J5XFxcIiBpcyBvZiB0eXBlIHNoYWRvd19pbnN0YW5jZXMwbG9ja2VkX2J5IGJ1dCBleHByZXNzaW9uIGlzIG9mIHR5cGUgaW5zdGFuY2VzMGxvY2tlZF9ieVwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDA4ODE1MzYyODUyfQ==

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1360650/+subscriptions
References

[Bug 1360650] [NEW] test_db_archive_deleted_rows failing in postgres jobs with ProgrammingError
From: Matt Riedemann, 2014-08-23