CREATE_FAILED status due to 'Resource CREATE failed: WaitConditionTimeout

[Rabi Mishra]

This is an issue we're seeing at the gate after the waitcondition concurrency fix. I assume there is no bug filed for it yet.

http://logs.openstack.org/12/318312/2/check/gate-heat-dsvm-functional-convg-mysql-lbaasv1/45a7579/console.html#_2016-05-19_15_57_26_353
----
2016-05-19 15:57:26.350 | 2016-05-19 15:57:26.227 |
2016-05-19 15:57:26.350 | 2016-05-19 15:57:26.230 | Captured traceback:
2016-05-19 15:57:26.350 | 2016-05-19 15:57:26.232 | ~~~~~~~~~~~~~~~~~~~
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.234 | Traceback (most recent call last):
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.235 | File "/opt/stack/new/heat/heat_integrationtests/functional/test_os_wait_condition.py", line 107, in test_create_stack_with_multi_signal_waitcondition
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.237 | self.stack_create(template=self.template, parameters=params)
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.240 | File "/opt/stack/new/heat/heat_integrationtests/common/test.py", line 517, in stack_create
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.242 | self._wait_for_stack_status(**kwargs)
2016-05-19 15:57:26.351 | 2016-05-19 15:57:26.244 | File "/opt/stack/new/heat/heat_integrationtests/common/test.py", line 334, in _wait_for_stack_status
2016-05-19 15:57:26.352 | 2016-05-19 15:57:26.246 | fail_regexp):
2016-05-19 15:57:26.352 | 2016-05-19 15:57:26.248 | File "/opt/stack/new/heat/heat_integrationtests/common/test.py", line 300, in _verify_status
2016-05-19 15:57:26.352 | 2016-05-19 15:57:26.250 | stack_status_reason=stack.stack_status_reason)
2016-05-19 15:57:26.353 | 2016-05-19 15:57:26.252 | heat_integrationtests.common.exceptions.StackBuildErrorException: Stack OSWaitCondition-214451522/4e84919f-3468-4d59-bd01-c3c5b0baf960 is in CREATE_FAILED status due to 'Resource CREATE failed: WaitConditionTimeout: resources.wait_condition: 24 of 25 received - Signal 24 received;Signal 20 received;Signal 21 received;Signal 22 received;Signal 23 received;Signal 1 received;signal3;signal2;Signal 6 received;signal4;Signal 7 received;Signal 6 received;Signal 9 received;Signal 8 received;Signal 11 received;Signal 10 received;Signal 13 received;Signal 12 received;Signal 15 received;Signal 14 received;Signal 17 received;Signal 16 received;Signal 19 received;Signal 18 received'
2016-05-19 15:57:26.353 | 2016-05-19 15:57:26.256 |

[Thomas Herve (therve)]

I got this issue with the same data I think: twice Signal 6 received, and stopping at Signal 24.

[Amy Fong (afong2)]

Seeing the issue here:
http://logs.openstack.org/58/430358/1/check/gate-heat-dsvm-functional-orig-mysql-lbaasv2-ubuntu-xenial/527d462/

[Rabi Mishra (rabi)]

After reducing the number of signals from the test, failures are reduced, but we still see it.

http://logs.openstack.org/15/454415/2/check/gate-heat-dsvm-functional-convg-mysql-lbaasv2-py35-ubuntu-xenial-nv/849a181/console.html#_2017-04-12_23_27_26_538835

[Crag Wolfe (cwolfe)]

FWIW, the 3 commits ending with https://review.openstack.org/#/c/451917/ should address the various races around this particular issue. Note the last commit increases the signal count in test_create_stack_with_multi_signal_waitcondition back to the original 25.

[Rabi Mishra (rabi)]

I've seen this issue resurfacing again in the last few days. It's possibly the same reason but failing with a different error in heat engine log. Probably after re-introduction of osic-cloud?

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%20%5C%22heat_integrationtests.common.exceptions.StackBuildErrorException%3A%20Stack%20OSWaitCondition%5C%22

Jun 05 09:15:54.946301 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: ERROR heat.engine.service [None req-07a06e56-a887-4798-810c-81b0fd1b78bb demo None] Unhandled error in asynchronous task: heat.common.exception.ResourceFailure: AttributeError: resources.wait_handle: 'Resource' object has no attribute 'name'
Jun 05 09:15:54.946401 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service Traceback (most recent call last):
Jun 05 09:15:54.946479 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/opt/stack/new/heat/heat/engine/resource.py", line 2222, in _handle_signal
Jun 05 09:15:54.946555 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service signal_result = self.handle_signal(details)
Jun 05 09:15:54.946637 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/opt/stack/new/heat/heat/engine/resources/openstack/heat/wait_condition_handle.py", line 208, in handle_signal
Jun 05 09:15:54.946714 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service return super(HeatWaitConditionHandle, self).handle_signal(details)
Jun 05 09:15:54.946816 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/opt/stack/new/heat/heat/engine/resources/wait_condition.py", line 84, in handle_signal
Jun 05 09:15:54.946898 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service self.metadata_set(details, merge_metadata=merge_signal_metadata)
Jun 05 09:15:54.946978 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 87, in wrapped_f
Jun 05 09:15:54.947067 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service return r.call(f, *args, **kw)
Jun 05 09:15:54.947181 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__.py", line 235, in call
Jun 05 09:15:54.947257 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service do = self.iter(result=result, exc_info=exc_info)
Jun 05 09:15:54.947328 ubuntu-xenial-osic-cloud1-s3700-9130837 heat-engine[2028]: 2017-06-05 09:15:54.944 3797 TRACE heat.engine.service File "/usr/local/lib/python3.5/dist-packages/tenacity/__init__...

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/470942

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/471120

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/470942
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=39f2aa0723b72668832f4c1eec3c31d18fb8cf74
Submitter: Jenkins
Branch: master

commit 39f2aa0723b72668832f4c1eec3c31d18fb8cf74
Author: rabi <email address hidden>
Date: Mon Jun 5 17:26:37 2017 +0530

    Load 'name' field for db resource

    I405888f46451d2657aa28f610f8ca555215ff5cf changed to load only
    a few fields when loading the resource from the db. We should
    load 'name' field for it to be used when rasing ConcurrentTransaction
    exception.

    Change-Id: I699961b75c7c417d03e21b51a2464c39e737ca89
    Related-Bug: #1583679
    Related-Bug: #1680658

[OpenStack Infra (hudson-openstack)]

Change abandoned by Thomas Herve (<email address hidden>) on branch: master
Review: https://review.openstack.org/471120