odd error from heat list after a delete

[Angus Salkeld]

[root@bigiron functional]# heat list
ERROR:Failed to list. Got error:
ERROR:Internal Server error: <ErrorResponse><Error><Message>The request processing has failed due to an internal error:Could not refresh instance '&lt;Stack at 0x4239090&gt;'</Message><Code>InternalFailure</Code><Type>Server</Type></Error></ErrorResponse>
I was not able to reproduce.

I think I deleted a stack followed by a heat list.

This may or MAY NOT be the backtrace - I wasn't able to correlate it.

2012-09-12 09:02:35 ERROR [heat.openstack.common.rpc.amqp] Exception during message handling
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/openstack/common/rpc/amqp.py", line 275, in process_data
rval = self.proxy.dispatch(ctxt, version, method, **args)
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/openstack/common/rpc/dispatcher.py", line 145, in dispatch
return getattr(proxyobj, method)(ctxt, **kwargs)
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/engine/manager.py", line 115, in show_stack
return {'stacks': [format_stack_detail(s) for s in stacks]}
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/engine/manager.py", line 113, in format_stack_detail
return api.format_stack(stack)
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/engine/api.py", line 93, in format_stack
STACK_CREATION_TIME: heat_utils.strtime(stack.created_time),
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/engine/resources.py", line 99, in __get_
o.refresh(attrs=[self.attribute])
File "/usr/lib/python2.7/site-packages/heat-6-py2.7.egg/heat/db/sqlalchemy/models.py", line 78, in refresh
session.refresh(self, attrs)
File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1059, in refresh
mapperutil.instance_str(instance))
InvalidRequestError: Could not refresh instance ''
2012-09-12 09:02:35 ERROR [heat.openstack.common.rpc.common] Returning exception Could not refresh instance '' to caller

zane
======

This is caused by the entry being deleted out of the database between when we start listing stacks and when we go to look up the latest updated time (which is reloaded on demand).

Eventually we will stop deleting stacks from the database as soon as we are done with them and this problem will be much less likely to occur.

sdake
=====
Reading the sqlalchemy docs, it looks like multiple unique sessions will automatically reference count and not allow the above to happen. From the docs:

http://docs.sqlalchemy.org/en/rel_0_7/orm/session.html

"
Objects become detached if their owning session is discarded. They are still functional in the detached state if the user has ensured that their state has not been expired before detachment, but they will not be able to represent the current state of database data. Because of this, it’s best to consider persisted objects as an extension of the state of a particular Session, and to keep that session around until all referenced objects have been discarded.

An exception to this is when objects are placed in caches or otherwise shared among threads or processes, in which case their detached state can be stored, transmitted, or shared. However, the state of detached objects should still be transferred back into a new Session using Session.add() or Session.merge() before working with the object (or in the case of merge, its state) again.
"

Since we are using goofy greenthreads, I expect we are having a concurrency problem. I am not certain how greenthreads and sqlalchemy should operate based upon the above detached operating model. Note the code expires the objects on commit. It may be that we need unique objects for each unique thread, but again I don't understand how the threadlocal functionality is supposed to work with greenthreads (is it supposed to work?) as each API operation is a unique operation.

One simple hack would be to get rid of the expire on commit, but I'm not clear on when we should expire in this condition.

Brain hurts. bedtime.

zane
=====
It's happening because we explicitly go and retrieve the last updated time from the database (see https://github.com/heat-api/heat/blob/master/heat/engine/resources.py#L99). We do this because the object is cached by the session, and therefore just reading the last updated time may not give us the real last updated time if the object has been updated in the database since we cached it. we don't store a cached copy of the db object after loading the Stack or Resource.

I think the best solution is probably just to ignore the exception if this fails and report whatever last updated time we had cached.

[Pablo Andres Fuente (pablo-a-fuente)]

I think this was fixed in this bug: https://bugs.launchpad.net/heat/+bug/1193132

[Steve Baker (steve-stevebaker)]

wow, this is an old one