heat 500 error "could not refresh instance"

[Sean Dague]

Heat has a race in the devstack-gate where a 500 error is thrown with the "could not refresh instance" message. This is seen as a tempest error like the following:

======================================================================
2013-06-20 15:28:33.906 | ERROR: tempest.api.orchestration.stacks.test_stacks.StacksTestJSON.test_stack_list_responds[gate,smoke]
2013-06-20 15:28:33.906 | ----------------------------------------------------------------------
2013-06-20 15:28:33.943 | _StringException: Traceback (most recent call last):
2013-06-20 15:28:33.943 | File "/opt/stack/new/tempest/tempest/api/orchestration/stacks/test_stacks.py", line 37, in test_stack_list_responds
2013-06-20 15:28:33.943 | resp, body = self.client.list_stacks()
2013-06-20 15:28:33.943 | File "/opt/stack/new/tempest/tempest/services/orchestration/json/orchestration_client.py", line 42, in list_stacks
2013-06-20 15:28:33.943 | resp, body = self.get(uri)
2013-06-20 15:28:33.943 | File "/opt/stack/new/tempest/tempest/common/rest_client.py", line 269, in get
2013-06-20 15:28:33.943 | return self.request('GET', url, headers)
2013-06-20 15:28:33.943 | File "/opt/stack/new/tempest/tempest/common/rest_client.py", line 394, in request
2013-06-20 15:28:33.943 | resp, resp_body)
2013-06-20 15:28:33.943 | File "/opt/stack/new/tempest/tempest/common/rest_client.py", line 480, in _error_checker
2013-06-20 15:28:33.943 | raise exceptions.ComputeFault(message)
2013-06-20 15:28:33.943 | ComputeFault: Got compute fault
2013-06-20 15:28:33.943 | Details: 500 Internal Server Error
2013-06-20 15:28:33.943 |
2013-06-20 15:28:33.944 | The server has either erred or is incapable of performing the requested operation.
2013-06-20 15:28:33.944 |
2013-06-20 15:28:33.944 | Remote error: InvalidRequestError Could not refresh instance '' [u'Traceback (most recent call last):\n', u' File "/opt/stack/new/heat/heat/openstack/common/rpc/amqp.py", line 424, in _process_data\n **args)\n', u' File "/opt/stack/new/heat/heat/openstack/common/rpc/dispatcher.py", line 172, in dispatch\n result = getattr(proxyobj, method)(ctxt, **kwargs)\n', u' File "/opt/stack/new/heat/heat/engine/service.py", line 53, in wrapped\n return func(self, ctx, *args, **kwargs)\n', u' File "/opt/stack/new/heat/heat/engine/service.py", line 185, in list_stacks\n return list(format_stack_details(stacks))\n', u' File "/opt/stack/new/heat/heat/engine/service.py", line 182, in format_stack_details\n yield api.format_stack(stack)\n', u' File "/opt/stack/new/heat/heat/engine/api.py", line 74, in format_stack\n api.STACK_UPDATED_TIME: timeutils.isotime(stack.updated_time),\n', u' File "/opt/stack/new/heat/heat/engine/timestamp.py", line 41, in __get__\n o.refresh(attrs=[self.attribute])\n', u' File "/opt/stack/new/heat/heat/db/sqlalchemy/models.py", line 83, in refresh\n session.refresh(self, attrs)\n', u' File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1167, in refresh\n mapperutil.instance_str(instance))\n', u"InvalidRequestError: Could not refresh instance ''\n"].
2013-06-20 15:28:33.944 |

(an example is here - http://logs.openstack.org/31834/8/gate/gate-tempest-devstack-vm-postgres-full/24700/console.html.gz)

With the heat-engine log showing:

2013-06-20 15:21:00.480 17453 ERROR heat.openstack.common.rpc.amqp [-] Exception during message handling
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp Traceback (most recent call last):
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/openstack/common/rpc/amqp.py", line 424, in _process_data
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp **args)
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/engine/service.py", line 53, in wrapped
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp return func(self, ctx, *args, **kwargs)
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/engine/service.py", line 185, in list_stacks
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp return list(format_stack_details(stacks))
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/engine/service.py", line 182, in format_stack_details
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp yield api.format_stack(stack)
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/engine/api.py", line 74, in format_stack
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp api.STACK_UPDATED_TIME: timeutils.isotime(stack.updated_time),
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/engine/timestamp.py", line 41, in __get__
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp o.refresh(attrs=[self.attribute])
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/new/heat/heat/db/sqlalchemy/models.py", line 83, in refresh
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp session.refresh(self, attrs)
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1167, in refresh
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp mapperutil.instance_str(instance))
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp InvalidRequestError: Could not refresh instance '<Stack at 0x2c95a90>'
2013-06-20 15:21:00.480 17453 TRACE heat.openstack.common.rpc.amqp

[Steve Baker (steve-stevebaker)]

It looks like this affects postgres only

[Steve Baker (steve-stevebaker)]

Here is a clean stacktrace
File "/opt/stack/new/heat/heat/openstack/common/rpc/amqp.py", line 424, in _process_data
  **args)
File "/opt/stack/new/heat/heat/openstack/common/rpc/dispatcher.py", line 172, in dispatch
  result = getattr(proxyobj, method)(ctxt, **kwargs)
File "/opt/stack/new/heat/heat/engine/service.py", line 53, in wrapped
  return func(self, ctx, *args, **kwargs)
File "/opt/stack/new/heat/heat/engine/service.py", line 185, in list_stacks
  return list(format_stack_details(stacks))
File "/opt/stack/new/heat/heat/engine/service.py", line 182, in format_stack_details
  yield api.format_stack(stack)
File "/opt/stack/new/heat/heat/engine/api.py", line 74, in format_stack
  api.STACK_UPDATED_TIME: timeutils.isotime(stack.updated_time),
File "/opt/stack/new/heat/heat/engine/timestamp.py", line 41, in __get__
  o.refresh(attrs=[self.attribute])
File "/opt/stack/new/heat/heat/db/sqlalchemy/models.py", line 83, in refresh
  session.refresh(self, attrs)
File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1167, in refresh
  mapperutil.instance_str(instance))
heat.openstack.common.rpc.amqp InvalidRequestError: Could not refresh instance '<Stack at 0x2c95a90>'

[Sean Dague (sdague)]

This has failed in the gate at least 9 times in the last couple of days - http://logstash.openstack.org/#eyJzZWFyY2giOiJcIkVSUk9SOiB0ZW1wZXN0LmFwaS5vcmNoZXN0cmF0aW9uLnN0YWNrcy50ZXN0X3N0YWNrcy5TdGFja3NUZXN0SlNPTi50ZXN0X3N0YWNrX2xpc3RfcmVzcG9uZHNcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTM3MTc2NTUwMDYwOH0=

So it is one of the higher reset bugs right now.

[Steve Baker (steve-stevebaker)]

I'm testing a fix locally now.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/33894
Committed: http://github.com/openstack/heat/commit/90203b89d582b1e8ff673ba1a555683307678fb9
Submitter: Jenkins
Branch: master

commit 90203b89d582b1e8ff673ba1a555683307678fb9
Author: Steve Baker <email address hidden>
Date: Fri Jun 21 10:18:37 2013 +1200

    Do not refresh timestamp from database on read.

    Doing a database refresh on timestamp read is causing errors
    such as:
    heat.openstack.common.rpc.amqp InvalidRequestError:
      Could not refresh instance '<Stack at 0x2c95a90>'

    This has only been seen using postgres, possibly because the problem is
    being masked on mysql due to the driver's lack of concurrency.

    The database refresh seems to be unnecessary, as there appears to be
    no logic which depends on timestamps being accurate (nor is there
    any timestamp comparison logic at all)

    Fixes bug: #1193132
    Change-Id: I22c3c4546a0f44b76a95e473b68b6fbb2e423b90