These times don't match with the log above, but messages all the same. The cfn log doesn't seem to mention any errors nor the return code; the only indication of error is the second-to-last line in the engine logs. From the few hours i spent looking at this yesterday the culprit appears to be that the updated template isn't present in the raw_template table and so isn't considered part of the stack by the time the CFN signal comes in. I'm not sure I understand enough of the big picture around stack-update to dive in and fix it though.
On the instance /var/log/upstart/os-collect-config.log:
<< SNIP SUCCESSFUL KEYSTONE AUTH REQUEST AND RESPONSE >>
2014-06-10 14:33:51.218 DEBUG heat.openstack.common.rpc.amqp req-f341e7a2-e528-4d5f-86aa-338c44c8f6de None smclellan Expected exception during message handling (The Resource (test-demo-test_heat_sw_deployment) could not be found in Stack test1.) from (pid=16255) _process_data /opt/stack/heat/heat/openstack/common/rpc/amqp.py:473
2014-06-10 14:33:51.219 DEBUG heat.openstack.common.rpc.amqp req-f341e7a2-e528-4d5f-86aa-338c44c8f6de None smclellan UNIQUE_ID is 30bfbaaaefee441eaaf7ed8e1ff9ab35. from (pid=16255) _add_unique_id /opt/stack/heat/heat/openstack/common/rpc/amqp.py:342
2014-06-10 14:33:51.220 DEBUG amqp req-f341e7a2-e528-4d5f-86aa-338c44c8f6de None smclellan Closed channel #1 from (pid=16255) _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:104
heat-cfn:
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Matched POST /signal/arn:openstack:heat::15a41777be7244daacd242a02b862814:stacks/test1/d8eb8c11-81de-4ed3-81c4-87a0a8a15af0/resources/test-demo-test_heat_sw_deployment from (pid=22051) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Route path: '/signal/{arn:.*}', defaults: {'action': u'signal', 'controller': <heat.common.wsgi.Resource object at 0x2faa050>} from (pid=22051) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Match dict: {'action': u'signal', 'controller': <heat.common.wsgi.Resource object at 0x2faa050>, 'arn': u'arn:openstack:heat::15a41777be7244daacd242a02b862814:stacks/test1/d8eb8c11-81de-4ed3-81c4-87a0a8a15af0/resources/test-demo-test_heat_sw_deployment'} from (pid=22051) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2014-06-10 14:33:51.083 DEBUG heat.openstack.common.rpc.amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Making synchronous call on engine ... from (pid=22051) multicall /opt/stack/heat/heat/openstack/common/rpc/amqp.py:554
2014-06-10 14:33:51.084 DEBUG heat.openstack.common.rpc.amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a MSG_ID is 4829fe8f22f64569a3538a776b8f8439 from (pid=22051) multicall /opt/stack/heat/heat/openstack/common/rpc/amqp.py:557
2014-06-10 14:33:51.084 DEBUG heat.openstack.common.rpc.amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a UNIQUE_ID is d8a291698bd9403f93446c85bc8c702f. from (pid=22051) _add_unique_id /opt/stack/heat/heat/openstack/common/rpc/amqp.py:342
2014-06-10 14:33:51.086 DEBUG amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Closed channel #1 from (pid=22051) _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:104
2014-06-10 14:33:51.087 DEBUG amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a using channel_id: 1 from (pid=22051) __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:80
2014-06-10 14:33:51.087 DEBUG amqp req-928bfa9b-16d6-4b27-bf72-74cafe1bb78e None 15a41777be7244daacd242a02b862814-d8eb8c11-81de-4ed3-81c4-87a0a8a Channel open from (pid=22051) _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:438
These times don't match with the log above, but messages all the same. The cfn log doesn't seem to mention any errors nor the return code; the only indication of error is the second-to-last line in the engine logs. From the few hours i spent looking at this yesterday the culprit appears to be that the updated template isn't present in the raw_template table and so isn't considered part of the stack by the time the CFN signal comes in. I'm not sure I understand enough of the big picture around stack-update to dive in and fix it though.
On the instance /var/log/ upstart/ os-collect- config. log:
[2014-06-10 14:33:50,783] (heat-config) [INFO] Completed /var/lib/ heat-config/ hooks/script 10.24.0. 4:8000/ v1/signal/ arn%3Aopenstack %3Aheat% 3A%3A15a41777be 7244daacd242a02 b862814% 3Astacks% 2Ftest1% 2Fd8eb8c11- 81de-4ed3- 81c4-87a0a8a15a f0%2Fresources% 2Ftest- demo-test_ heat_sw_ deployment? Timestamp= 2014-06- 10T14%3A33% 3A15Z&Signature Method= HmacSHA256& AWSAccessKeyId= 538c7f0cb61140d 998e04c62647124 e1&SignatureVer sion=2& Signature= pjub03wXQoSlYjT 9gYZkNu0ntFGLts CMm04REsp3mLU% 3D with {"deploy_stdout": "Testing me some heat software config\n", "deploy_stderr": "", "deploy_ status_ code": 0}
[2014-06-10 14:33:50,789] (heat-config) [DEBUG] Signalling to http://
[2014-06-10 14:33:51,254] (heat-config) [DEBUG] Response <Response [400]>
dib-run-parts Tue Jun 10 14:33:51 UTC 2014 55-heat-config completed
h-eng:
2014-06-10 14:33:51.087 DEBUG heat.openstack. common. rpc.amqp received {u'_msg_id': u'4829fe8f22f64 569a3538a776b8f 8439', u'_context_ request_ id': u'req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e', u'_context_ trust_id' : None, u'_context_ auth_token' : '<SANITIZED>', u'_context_ user_id' : u'f53f6d31c4a04 22a845a5b4d4400 d5a9', u'_context_ username' : None, u'_reply_q': u'reply_ c499de3c7e8f442 686a2288c5a994a 90', u'_context_ show_deleted' : False, u'namespace': None, u'_context_ is_admin' : False, u'version': u'1.0', u'_context_user': None, u'method': u'resource_signal', u'_context_roles': [u'heat_ stack_user' ], u'_context_ auth_url' : u'http:// 10.24.0. 4:5000/ v2.0', u'args': {u'resource_name': u'test- demo-test_ heat_sw_ deployment' , u'details': {u'deploy_stdout': u'Testing me some heat software config\n', u'deploy_stderr': u'', u'deploy_ status_ code': 0}, u'stack_identity': {u'stack_name': u'test1', u'stack_id': u'd8eb8c11- 81de-4ed3- 81c4-87a0a8a15a f0', u'tenant': u'15a41777be724 4daacd242a02b86 2814', u'path': u''}}, u'_unique_id': u'd8a291698bd94 03f93446c85bc8c 702f', u'_context_ tenant_ id': u'7b0358237da24 700b8a750544a25 cd1c', u'_context_ password' : '<SANITIZED>', u'_context_ trustor_ user_id' : None, u'_context_ aws_creds' : u'{"ec2Credenti als": {"access": "538c7f0cb61140 d998e04c6264712 4e1", "signature": "pjub03wXQoSlYj T9gYZkNu0ntFGLt sCMm04REsp3mLU= "}}', u'_context_tenant': u'15a41777be724 4daacd242a02b86 2814-d8eb8c11- 81de-4ed3- 81c4-87a0a8a' } from (pid=16255) _safe_log /opt/stack/ heat/heat/ openstack/ common/ rpc/common. py:280 common. rpc.amqp unpacked context: {'username': None, 'user_id': u'f53f6d31c4a04 22a845a5b4d4400 d5a9', 'show_deleted': False, 'roles': [u'heat_ stack_user' ], 'tenant_id': u'7b0358237da24 700b8a750544a25 cd1c', 'auth_token': '<SANITIZED>', 'trust_id': None, 'is_admin': False, 'user': None, 'request_id': u'req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e', 'auth_url': u'http:// 10.24.0. 4:5000/ v2.0', 'password': '<SANITIZED>', 'aws_creds': u'{"ec2Credenti als": {"access": "538c7f0cb61140 d998e04c6264712 4e1", "signature": "pjub03wXQoSlYj T9gYZkNu0ntFGLt sCMm04REsp3mLU= "}}', 'tenant': u'15a41777be724 4daacd242a02b86 2814-d8eb8c11- 81de-4ed3- 81c4-87a0a8a' , 'trustor_user_id': None} from (pid=16255) _safe_log /opt/stack/ heat/heat/ openstack/ common/ rpc/common. py:280 common. policy req-f341e7a2- e528-4d5f- 86aa-338c44c8f6 de None smclellan Rule context_is_admin will be now enforced from (pid=16255) enforce /opt/stack/ heat/heat/ openstack/ common/ policy. py:288 common. fileutils req-f341e7a2- e528-4d5f- 86aa-338c44c8f6 de None smclellan Reloading cached file /etc/heat/ policy. json from (pid=16255) read_cached_file /opt/stack/ heat/heat/ openstack/ common/ fileutils. py:61 common. policy req-f341e7a2- e528-4d5f- 86aa-338c44c8f6 de None smclellan Rules successfully reloaded from (pid=16255) load_rules /opt/stack/ heat/heat/ openstack/ common/ policy. py:242
2014-06-10 14:33:51.087 DEBUG heat.openstack.
2014-06-10 14:33:51.095 DEBUG heat.openstack.
2014-06-10 14:33:51.095 DEBUG heat.openstack.
2014-06-10 14:33:51.096 DEBUG heat.openstack.
<< SNIP SUCCESSFUL KEYSTONE AUTH REQUEST AND RESPONSE >>
2014-06-10 14:33:51.218 DEBUG heat.openstack. common. rpc.amqp req-f341e7a2- e528-4d5f- 86aa-338c44c8f6 de None smclellan Expected exception during message handling (The Resource (test-demo- test_heat_ sw_deployment) could not be found in Stack test1.) from (pid=16255) _process_data /opt/stack/ heat/heat/ openstack/ common/ rpc/amqp. py:473
2014-06-10 14:33:51.219 DEBUG heat.openstack. common. rpc.amqp req-f341e7a2- e528-4d5f- 86aa-338c44c8f6 de None smclellan UNIQUE_ID is 30bfbaaaefee441 eaaf7ed8e1ff9ab 35. from (pid=16255) _add_unique_id /opt/stack/ heat/heat/ openstack/ common/ rpc/amqp. py:342 e528-4d5f- 86aa-338c44c8f6 de None smclellan Closed channel #1 from (pid=16255) _do_close /usr/local/ lib/python2. 7/dist- packages/ amqp/channel. py:104
2014-06-10 14:33:51.220 DEBUG amqp req-f341e7a2-
heat-cfn:
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Matched POST /signal/ arn:openstack: heat::15a41777b e7244daacd242a0 2b862814: stacks/ test1/d8eb8c11- 81de-4ed3- 81c4-87a0a8a15a f0/resources/ test-demo- test_heat_ sw_deployment from (pid=22051) __call__ /usr/lib/ python2. 7/dist- packages/ routes/ middleware. py:100 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Route path: '/signal/{arn:.*}', defaults: {'action': u'signal', 'controller': <heat.common. wsgi.Resource object at 0x2faa050>} from (pid=22051) __call__ /usr/lib/ python2. 7/dist- packages/ routes/ middleware. py:102 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Match dict: {'action': u'signal', 'controller': <heat.common. wsgi.Resource object at 0x2faa050>, 'arn': u'arn:openstack :heat:: 15a41777be7244d aacd242a02b8628 14:stacks/ test1/d8eb8c11- 81de-4ed3- 81c4-87a0a8a15a f0/resources/ test-demo- test_heat_ sw_deployment' } from (pid=22051) __call__ /usr/lib/ python2. 7/dist- packages/ routes/ middleware. py:103 common. rpc.amqp req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Making synchronous call on engine ... from (pid=22051) multicall /opt/stack/ heat/heat/ openstack/ common/ rpc/amqp. py:554 common. rpc.amqp req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a MSG_ID is 4829fe8f22f6456 9a3538a776b8f84 39 from (pid=22051) multicall /opt/stack/ heat/heat/ openstack/ common/ rpc/amqp. py:557 common. rpc.amqp req-928bfa9b- 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a UNIQUE_ID is d8a291698bd9403 f93446c85bc8c70 2f. from (pid=22051) _add_unique_id /opt/stack/ heat/heat/ openstack/ common/ rpc/amqp. py:342 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Closed channel #1 from (pid=22051) _do_close /usr/local/ lib/python2. 7/dist- packages/ amqp/channel. py:104 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a using channel_id: 1 from (pid=22051) __init__ /usr/local/ lib/python2. 7/dist- packages/ amqp/channel. py:80 16d6-4b27- bf72-74cafe1bb7 8e None 15a41777be7244d aacd242a02b8628 14-d8eb8c11- 81de-4ed3- 81c4-87a0a8a Channel open from (pid=22051) _open_ok /usr/local/ lib/python2. 7/dist- packages/ amqp/channel. py:438
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b-
2014-06-10 14:33:51.082 DEBUG routes.middleware req-928bfa9b-
2014-06-10 14:33:51.083 DEBUG heat.openstack.
2014-06-10 14:33:51.084 DEBUG heat.openstack.
2014-06-10 14:33:51.084 DEBUG heat.openstack.
2014-06-10 14:33:51.086 DEBUG amqp req-928bfa9b-
2014-06-10 14:33:51.087 DEBUG amqp req-928bfa9b-
2014-06-10 14:33:51.087 DEBUG amqp req-928bfa9b-