OpenStack Heat

heat 500 error "could not refresh instance"

Bug #1193132 reported by Sean Dague
50
This bug affects 6 people
Affects Status Importance Assigned to Milestone
OpenStack Heat
Fix Released
Critical
Steve Baker
OpenStack Heat 2013.2 "havana"

Bug Description

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

Sean Dague (sdague)
no longer affects: devstack
Steve Baker (steve-stevebaker)
Changed in heat:
assignee: nobody → Steve Baker (steve-stevebaker)
Revision history for this message
Steve Baker (steve-stevebaker) wrote :

It looks like this affects postgres only

Changed in heat:
status: New → Confirmed
importance: Undecided → Critical
milestone: none → havana-2
Revision history for this message
Steve Baker (steve-stevebaker) wrote :

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>'

Revision history for this message
Sean Dague (sdague) wrote :

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.

Revision history for this message
Steve Baker (steve-stevebaker) wrote :

I'm testing a fix locally now.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to heat (master)

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

Changed in heat:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to heat (master)

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

Changed in heat:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in heat:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in heat:
milestone: havana-2 → 2013.2
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.