stack deletion error in logs due to snapshot handling

[Patrick Crews]

The following error occurs when heat hits the end of a list of stack snapshots. It is appearing to cause stack-delete operations to hang indefinitely, though it could also be tied to another bug - https://bugs.launchpad.net/heat/+bug/1412961

Originally thought this was due to having deleted the snapshot images via other means. However, still seeing this error without touching snapshot images via nova / horizon / glance.

In the output below, tried deleting a stack with several snapshots.
All were handled well until the end of the list.

2015-01-20 15:49:42.789 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] running from (pid=11340) step /opt/stack/heat/heat/engine/scheduler.py:219
2015-01-20 15:49:42.838 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] sleeping from (pid=11340) _sleep /opt/stack/heat/heat/engine/scheduler.py:164
2015-01-20 15:49:43.839 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] running from (pid=11340) step /opt/stack/heat/heat/engine/scheduler.py:219
2015-01-20 15:49:43.839 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] complete from (pid=11340) step /opt/stack/heat/heat/engine/scheduler.py:225
2015-01-20 15:49:43.840 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] starting from (pid=11340) start /opt/stack/heat/heat/engine/scheduler.py:191
2015-01-20 15:49:43.840 DEBUG heat.engine.scheduler [-] Task delete_snapshot from Server "wordpress_instance" [106a764d-09a5-4b7a-b2a4-dbbb229154c0] Stack "test-stack-0" [33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9] running from (pid=11340) step /opt/stack/heat/heat/engine/scheduler.py:219
2015-01-20 15:49:43.890 DEBUG heat.engine.stack_lock [-] Engine b24c2aa7-9cc1-49a9-825a-98d0bb3dac19 released lock on stack 33f1cda8-e3cd-4aa1-95fe-04eefdbb7ca9 from (pid=11340) release /opt/stack/heat/heat/engine/stack_lock.py:123
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 455, in fire_timers
    timer()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/timer.py", line 58, in __call__
    cb(*args, **kw)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 212, in main
    result = function(*args, **kwargs)
  File "/opt/stack/heat/heat/engine/service.py", line 113, in _start_with_trace
    return func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
    return f(*args, **kwargs)
  File "/opt/stack/heat/heat/engine/stack.py", line 982, in delete
    self.delete_snapshot(snapshot)
  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
    return f(*args, **kwargs)
  File "/opt/stack/heat/heat/engine/stack.py", line 1087, in delete_snapshot
    scheduler.TaskRunner(rsrc.delete_snapshot, data)()
  File "/opt/stack/heat/heat/engine/scheduler.py", line 174, in __call__
    self.start(timeout=timeout)
  File "/opt/stack/heat/heat/engine/scheduler.py", line 199, in start
    self.step()
  File "/opt/stack/heat/heat/engine/scheduler.py", line 222, in step
    next(self._runner)
  File "/opt/stack/heat/heat/engine/scheduler.py", line 321, in wrapper
    subtask = parent.throw(*sys.exc_info())
  File "/opt/stack/heat/heat/engine/resource.py", line 798, in delete_snapshot
    yield self.action_handler_task('delete_snapshot', args=[data])
  File "/opt/stack/heat/heat/engine/scheduler.py", line 295, in wrapper
    step = next(subtask)
  File "/opt/stack/heat/heat/engine/resource.py", line 506, in action_handler_task
    handler_data = handler(*args)
  File "/opt/stack/heat/heat/engine/resources/server.py", line 1179, in handle_delete_snapshot
    image_id = snapshot['resource_data']['snapshot_image_id']
KeyError: 'snapshot_image_id'

[Patrick Crews (patrick-crews)]

Am still discerning the effects (if any) of this bug to the user.
Am also hitting this bug: https://bugs.launchpad.net/heat/+bug/1412961, which is causing stack operations to hang forever after one of these test runs.

[Angus Salkeld (asalkeld)]

We need a better reproducer. I tried the following and it worked fine:

 cat template.yaml
heat_template_version: 2015-04-30
resources:
  server:
    type: OS::Nova::Server
    properties:
      flavor: m1.tiny
      image: cirros-0.3.2-x86_64-uec
      key_name: heat_key

heat stack-create -f template test
# wait for create complete
heat stack-snapshot test
# wait for snapshot complete
heat stack-snapshot test
# wait for snapshot complete
heat stack-delete test
# deleted fine

Can we have some good (and hopefully simple) steps to reproduce the bug please?