Stack cannot leave IN_PROGRESS due to Data too long for column 'status_reason'

[Nicholas Randon]

+--------------------------------------+------------+--------------------+----------------------+
| id | stack_name | stack_status | creation_time |
+--------------------------------------+------------+--------------------+----------------------+
| d9fc79f6-24d1-47da-b0ea-b7f8306a4d2f | overcloud | CREATE_IN_PROGRESS | 2014-04-25T13:44:56Z |
+--------------------------------------+------------+--------------------+----------------------+

of 27 nodes using nova bare-metal has run for 2.5 hours and not concluded.

from looking tough the logs we see:

heat-api.log:
2014-04-25 14:59:43.015 5186 WARNING heat.openstack.common.rpc.amqp [req-a868cae8-9aec-4ec2-bebc-e6e7f0b060d2 None] Number of call waiters is greater than warning threshold: 10. There could be a MulticallProxyWaiter leak.

heat-api-cfn.log:
2014-04-25 14:23:11.784 5208 WARNING heat.openstack.common.rpc.amqp [req-506142ca-cbd6-4203-b453-bd522104374e None] Number of call waiters is greater than warning threshold: 10. There could be a MulticallProxyWaiter leak.

heat-engine.log:
2014-04-25 14:44:28.263 5274 ERROR heat.engine.resource [-] CREATE : StructuredDeployment "NovaCompute25Config" Stack "overcloud" [d9fc79f6-24d1-47da-b0ea-b7f8306a4d2f]
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource Traceback (most recent call last):
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/resource.py", line 387, in _do_action
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource pre_func()
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/properties.py", line 314, in validate
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource raise exception.StackValidationFailed(message=msg)
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource StackValidationFailed: Property error : NovaCompute25Config: input_values The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400) (Request-ID: req-c65df80b-91ec-416d-b9e2-3a3092b6df11)
2014-04-25 14:44:28.263 5274 TRACE heat.engine.resource
2014-04-25 14:44:30.031 5274 WARNING heat.common.keystoneclient [req-af57f763-4549-4198-adff-94480e80935d None] stack_user_domain ID not set in heat.conf falling back to using default
2014-04-25 14:44:30.864 5274 WARNING heat.common.keystoneclient [req-bd0d54d1-15d8-4e89-8b29-262c26838bf3 None] stack_user_domain ID not set in heat.conf falling back to using default
2014-04-25 14:44:31.476 5274 WARNING heat.common.keystoneclient [req-54c93cff-0486-4321-aaaf-7bbe6cfe0523 None] stack_user_domain ID not set in heat.conf falling back to using default

2014-04-25 14:44:31.615 5274 ERROR heat.openstack.common.db.sqlalchemy.session [-] DB exception wrapped.
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session Traceback (most recent call last):
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/openstack/common/db/sqlalchemy/session.py", line 439, in _wrap
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session return f(self, *args, **kwargs)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/openstack/common/db/sqlalchemy/session.py", line 705, in flush
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session return super(Session, self).flush(*args, **kwargs)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1903, in flush
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session self._flush(objects)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2021, in _flush
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session transaction.rollback(_capture_exception=True)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 57, in __exit__
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session compat.reraise(exc_type, exc_value, exc_tb)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1985, in _flush
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session flush_context.execute()
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 370, in execute
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session rec.execute(self)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 523, in execute
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session uow
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 59, in save_obj
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session mapper, table, update)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 510, in _emit_update_statements
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session execute(statement, params)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 720, in execute
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session return meth(self, multiparams, params)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 317, in _execute_on_connection
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session return connection._execute_clauseelement(self, multiparams, params)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 817, in _execute_clauseelement
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session compiled_sql, distilled_params
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 947, in _execute_context
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session context)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1108, in _handle_dbapi_exception
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session exc_info
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 185, in raise_from_cause
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session reraise(type(exception), exception, tb=exc_tb)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 940, in _execute_context
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session context)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 435, in do_execute
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session cursor.execute(statement, parameters)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session self.errorhandler(self, exc, value)
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session raise errorclass, errorvalue
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session DataError: (DataError) (1406, "Data too long for column 'status_reason' at row 1") 'UPDATE stack SET status=%s, status_reason=%s WHERE stack.id = %s' ('FAILED', 'Resource CREATE failed: StackValidationFailed: Property error : NovaCompute25Config: input_values The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400) (Request-ID: req-c65df80b-91ec-416d-b9e2-3a3092b6df11)', 'd9fc79f6-24d1-47da-b0ea-b7f8306a4d2f')
2014-04-25 14:44:31.615 5274 TRACE heat.openstack.common.db.sqlalchemy.session
Traceback (most recent call last):
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 346, in fire_timers
    timer()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/eventlet/hubs/timer.py", line 56, in __call__
    cb(*args, **kw)
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/eventlet/greenthread.py", line 194, in main
    result = function(*args, **kwargs)
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/service.py", line 498, in _stack_create
    stack.create()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/parser.py", line 456, in create
    creator(timeout=self.timeout_secs())
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/scheduler.py", line 142, in __call__
    self.run_to_completion(wait_time=wait_time)
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/scheduler.py", line 204, in run_to_completion
    while not self.step():
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/scheduler.py", line 190, in step
    next(self._runner)
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/scheduler.py", line 284, in wrapper
    subtask = parent.throw(*sys.exc_info())
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/parser.py", line 501, in stack_task
    self.state_set(action, stack_status, reason)
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/parser.py", line 414, in state_set
    'status_reason': reason})
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/db/sqlalchemy/models.py", line 74, in update_and_save
    session.commit()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 765, in commit
    self.transaction.commit()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 370, in commit
    self._prepare_impl()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 350, in _prepare_impl
    self.session.flush()
  File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/openstack/common/db/sqlalchemy/session.py", line 461, in _wrap
    raise exception.DBError(e)
DBError: (DataError) (1406, "Data too long for column 'status_reason' at row 1") 'UPDATE stack SET status=%s, status_reason=%s WHERE stack.id = %s' ('FAILED', 'Resource CREATE failed: StackValidationFailed: Property error : NovaCompute25Config: input_values The server could not comply with the request since it is either malformed or otherwise incorrect. (HTTP 400) (Request-ID: req-c65df80b-91ec-416d-b9e2-3a3092b6df11)', 'd9fc79f6-24d1-47da-b0ea-b7f8306a4d2f')

This patch was applied to heat: http://review.openstack.org/r/I80be5d3de8744813d974f2e9860c148ad258f385 and all it dependent
Heat sha1 at: ed84893b7dfda14a94b9d507baf14df2e33ca8e0

[Nicholas Randon (nicholas-randon)]

This can be re-produce by making sure all real H/W is powered off before deploying

[Steve Baker (steve-stevebaker)]

The MulticallProxyWaiter message looks to be unrelated to the "Data too long for column 'status_reason'"

I think it is time we increased the size of status_reason *and* explicitly truncated the contents before saving

[Nicholas Randon (nicholas-randon)]

Added a devtest option to turn off all H/W IPMI controlled nodes to help here: https://review.openstack.org/#/c/90952/1

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/90863
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=50005bc9b1a1af8ec473e8b1ec1e788e7a8c05eb
Submitter: Jenkins
Branch: master

commit 50005bc9b1a1af8ec473e8b1ec1e788e7a8c05eb
Author: Steve Baker <email address hidden>
Date: Wed Apr 30 12:00:24 2014 +1200

    Truncate status_reason to column length

    This avoids a DataError "Data too long for column 'status_reason'"
    when status_reason is longer than 255 chars.

    This is implemented in the class StateAware which is extended
    by Stack, Resource, and SoftwareDeployment.

    Change-Id: I520803e54f9045fce2dc3b6a1b5c3be5052080aa
    Closes-Bug: #1312815

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/95922

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/95922
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=4b9ff4ff9e966915cf7538e963457db9b4031ba0
Submitter: Jenkins
Branch: stable/icehouse

commit 4b9ff4ff9e966915cf7538e963457db9b4031ba0
Author: Steve Baker <email address hidden>
Date: Wed Apr 30 12:00:24 2014 +1200

    Truncate status_reason to column length

    This avoids a DataError "Data too long for column 'status_reason'"
    when status_reason is longer than 255 chars.

    This is implemented in the class StateAware which is extended
    by Stack, Resource, and SoftwareDeployment.

    Change-Id: I520803e54f9045fce2dc3b6a1b5c3be5052080aa
    Closes-Bug: #1312815

[Moshe Elisha (melisha)]

Hey,

This is reproducible in the latest DevStack code (Kilo).

In heat/engine/stack.py state_set method, the reason is used as is when invoking "stack.update_and_save" and it is not truncated.

My two cents - I think status_reason should not be limited and should be longtext - if the reason is long than it is long, it is better to keep the full string so the user could understand the reason.

Logs and stack template attached in zip.

[Steve Baker (steve-stevebaker)]

I'm not against making status_reason longtext in the long term, but at this stage in the Kilo development cycle I'd rather just make sure status_reason is truncated where necessary

[Steve Baker (steve-stevebaker)]

LongStatusReason.zip is impractically large to examine, could you just attach/paste the relevant snippets?

[Steve Baker (steve-stevebaker)]

Also, could you raise a new bug? reopening this released and backported bug won't be possible.

[Moshe Elisha (melisha)]

Sure. The new bug is https://bugs.launchpad.net/heat/+bug/1434290 with truncated logs.
I understand the consideration why not change to longtext for Kilo. Thanks.