Bug 1370653

Summary:	Deploying overcloud fails at step4 of the controllers
Product:	[Community] RDO	Reporter:	David Hill <dhill>
Component:	rdo-manager	Assignee:	Hugh Brock <hbrock>
Status:	CLOSED NOTABUG	QA Contact:	Shai Revivo <srevivo>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	Liberty	CC:	chris.brown, dhill, hbrock, mburns, pbandark
Target Milestone:	---
Target Release:	trunk
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2017-06-22 20:32:16 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description David Hill 2016-08-26 22:30:24 UTC

Description of problem:
Deploying overcloud fails at step4 of the controllers with the following errors:

Aug 26 05:25:07 overcloud-controller-0.localdomain os-collect-config[4461]: b_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters [-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1060, u\"Duplicate column name 'modified_at'\") [SQL: u'\\nALTER TABLE services ADD modified_at DATETIME']\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py\", line 1139, in _execute_context\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     context)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py\", line 450, in do_execute\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/cursors.py\", line 146, in execute\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/cursors.py\", line 296, in _query\u001b[0m\n\u001
Aug 26 05:25:07 overcloud-controller-0.localdomain os-collect-config[4461]: b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/connections.py\", line 781, in query\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/connections.py\", line 942, in _read_query_result\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     result.read()\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/connections.py\", line 1138, in read\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/connections.py\", line 906, in _read_packet\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-man
Aug 26 05:25:07 overcloud-controller-0.localdomain os-collect-config[4461]: age db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/connections.py\", line 367, in check_error\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/err.py\", line 120, in raise_mysql_exception\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters   File \"/usr/lib/python2.7/site-packages/pymysql/err.py\", line 115, in _check_mysql_exception\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1060, u\"Duplicate column name 'modified_at'\")\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.144 18485 ERROR oslo_db.sqlalchemy.exc_filters \u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 CRITICAL cinder [-] DBError: (pymysql.err.InternalError) (1060, u\"Duplicate column name 'modified_at'\") [SQL: u'\\nALTER TABLE services ADD modified_at DATETIME']\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_syn
Aug 26 05:25:07 overcloud-controller-0.localdomain os-collect-config[4461]: c]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder Traceback (most recent call last):\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder   File \"/usr/bin/cinder-manage\", line 10, in <module>\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder     sys.exit(main())\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder   File \"/usr/lib/python2.7/site-packages/cinder/cmd/manage.py\", line 592, in main\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder     fn(*fn_args)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder   File \"/usr/lib/python2.7/site-packages/cinder/cmd/manage.py\", line 231, in sync\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder     return db_migration.db_sync(version)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder   File \"/usr/lib/python2.7/site-packages/cinder/db/migration.py\", line 61, in db_sync\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder     init_version=init_version)\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder   File \"/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/migration.py\", line 79, in db_sync\u001b[0m\n\u001b[mNotice: /Stage[main]/Cinder::Db::Sync/Exec[cinder-manage db_sync]/returns: 2016-08-26 05:22:39.151 18485 ERROR cinder     migration = versioning_api.upgrade(engine, repository, version)\u001b[0m\n\


Version-Release number of selected component (if applicable):


How reproducible:
Always

Steps to Reproduce:
1. Create overcloud images 
2. Try deploying an overcloud
3.

Actual results:
Fails
Deploying overcloud fails at step4 of the controllers
[stack@undercloud-0-liberty cloud]$ heat resource-list -n5 overcloud | grep -vi complete
+---------------------------------------------+-----------------------------------------------+--------------------------------------------------------------------------+-----------------+---------------------+---------------------------------------------------------------------------------------------------------------+
| resource_name                               | physical_resource_id                          | resource_type                                                            | resource_status | updated_time        | stack_name                                                                                                    |
+---------------------------------------------+-----------------------------------------------+--------------------------------------------------------------------------+-----------------+---------------------+---------------------------------------------------------------------------------------------------------------+
| ComputeNodesPostDeployment                  | 9e573066-f57f-4793-a9d7-f3dabf261822          | OS::TripleO::ComputePostDeployment                                       | CREATE_FAILED   | 2016-08-26T04:31:08 | overcloud                                                                                                     |
| ControllerNodesPostDeployment               | 804ca95c-5103-4a24-9e59-8b72b721392e          | OS::TripleO::ControllerPostDeployment                                    | CREATE_FAILED   | 2016-08-26T04:31:08 | overcloud                                                                                                     |
| ControllerOvercloudServicesDeployment_Step4 | 1a226697-9eb3-46c7-bb45-63a2c96a15d2          | OS::Heat::StructuredDeployments                                          | CREATE_FAILED   | 2016-08-26T05:15:53 | overcloud-ControllerNodesPostDeployment-b55fbpzb3luy                                                          |
| 0                                           | decbfbd0-3a4b-4a67-98da-8e4ce4a1dfdc          | OS::Heat::StructuredDeployment                                           | CREATE_FAILED   | 2016-08-26T05:20:33 | overcloud-ControllerNodesPostDeployment-b55fbpzb3luy-ControllerOvercloudServicesDeployment_Step4-mthncnqlu5h3 |
| 1                                           | 7a9c57a9-5efd-4b54-8d9c-ccab08406cfd          | OS::Heat::StructuredDeployment                                           | CREATE_FAILED   | 2016-08-26T05:20:33 | overcloud-ControllerNodesPostDeployment-b55fbpzb3luy-ControllerOvercloudServicesDeployment_Step4-mthncnqlu5h3 |
| 2                                           | 25e2c981-0ccf-4e27-ab9b-cf23599a3493          | OS::Heat::StructuredDeployment                                           | CREATE_FAILED   | 2016-08-26T05:20:34 | overcloud-ControllerNodesPostDeployment-b55fbpzb3luy-ControllerOvercloudServicesDeployment_Step4-mthncnqlu5h3 |
+---------------------------------------------+-----------------------------------------------+--------------------------------------------------------------------------+-----------------+---------------------+---------------------------------------------------------------------------------------------------------------+


Expected results:
Succeeds

Additional info:
Installing it on RHEL 7.2

Comment 1 David Hill 2016-08-27 02:44:53 UTC

This looks like a race condition because if I re-run the openstack overcloud deploy command , it will update the stack and successfully complete.

Comment 2 David Hill 2016-09-05 23:09:25 UTC

I can reproduce this issue with Mitaka as well.  A redeployment will update it and it'll finish successfully.

Comment 3 David Hill 2016-09-06 22:56:29 UTC

This issue is also affecting Newton.

Comment 4 Pratik Pravin Bandarkar 2017-01-24 15:56:25 UTC

I am also hitting this issue with mitaka. Do we have any workaround for the issue ?

Comment 5 Christopher Brown 2017-06-22 16:03:21 UTC

David,

Sorry no response to this ticket. Are you still seeing this issue?

Thanks

Comment 6 David Hill 2017-06-22 20:32:16 UTC

I haven't hit this issue for a while so I guess it's safe to close this bz.