Several OSTF test fail: ClientException: Unexpected API Error. <class 'sqlalchemy.exc.ProgrammingError'> (HTTP 500)

Nova API logs:

2016-09-06 03:15:02.287 11428 DEBUG oslo_concurrency.lockutils [-] Acquired semaphore "singleton_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-09-06 03:15:02.289 11428 DEBUG oslo_concurrency.lockutils [-] Releasing semaphore "singleton_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-09-06 03:15:02.235 11858 DEBUG oslo_db.sqlalchemy.engines [req-a55cfeec-cf17-41ba-bfa0-ed8b990b0675 - - - - -] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:256
2016-09-06 03:15:02.324 11429 DEBUG oslo_concurrency.lockutils [-] Acquired semaphore "singleton_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-09-06 03:15:02.342 11429 DEBUG oslo_concurrency.lockutils [-] Releasing semaphore "singleton_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-09-06 03:15:02.452 12084 INFO oslo_service.service [-] Child 11428 exited with status 1
2016-09-06 03:15:02.490 12084 DEBUG oslo_service.service [-] Started child 11915 _start_child /usr/lib/python2.7/dist-packages/oslo_service/service.py:475
2016-09-06 03:15:02.550 12084 INFO oslo_service.service [-] Child 11429 exited with status 1
2016-09-06 03:15:02.667 12084 DEBUG oslo_service.service [-] Started child 11923 _start_child /usr/lib/python2.7/dist-packages/oslo_service/service.py:475
2016-09-06 03:15:03.306 11915 DEBUG oslo_db.sqlalchemy.engines [req-306febd7-3f59-49ef-ab24-127303c76c48 - - - - -] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:256
2016-09-06 03:15:03.325 11923 DEBUG oslo_db.sqlalchemy.engines [req-fc808806-e531-4dc2-9512-6ce6dc34c81d - - - - -] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:256
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service [req-c9831327-9d76-46d7-b24e-e572f2bbd0bd - - - - -] Error starting thread.
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service Traceback (most recent call last):
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/oslo_service/service.py", line 680, in run_service
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service service.start()
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/nova/service.py", line 434, in start
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service self.binary)
2016-09-06 03:15:04.361 11507 ERROR oslo_service.service File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2016-09-06 03:15:04.361 11...

Timur,

Please note the error message

2016-09-06 03:15:04.361 11507 ERROR oslo_service.service OperationalError: (_mysql_exceptions.OperationalError) (1054, "Unknown column 'services.last_seen_up' in 'field list'") [SQL: u'SELECT services.created_at AS services_created_at, services.updated_at AS services_updated_at, services.deleted_at AS services_deleted_at, services.deleted AS services_deleted, services.id AS services_id, services.host AS services_host, services.`binary` AS services_binary, services.topic AS services_topic, services.report_count AS services_report_count, services.disabled AS services_disabled, services.disabled_reason AS services_disabled_reason, services.last_seen_up AS services_last_seen_up, services.forced_down AS services_forced_down, services.version AS services_version \nFROM services \nWHERE services.deleted = %s AND services.host = %s AND services.`binary` = %s \n LIMIT %s'] [parameters: (0, '10.109.6.9', 'nova-osapi_compute', 1)]

^ you must be running tests *before* migration scripts have been applied.

E.g. this particular column is added in migration #294:

https://github.com/openstack/nova/blob/stable/mitaka/nova/db/sqlalchemy/migrate_repo/versions/294_add_service_heartbeat.py

nova-* services *must not* be started before "nova-manage db sync" has completed successfully.

Please check your job template - looks like you try to use services too early, when they have not been properly configured yet (one might also argue that services must not be even started before Puppet manifests finished applying of the configuration).

it is strange because we run these tests only after the fresh deployment.

Hi MOS Puppet team,

in the traceback, we can see that we don't have the required column in the table. It looks like nova-api started earlier than we successfully execute nova-db-sync command (we think it can be a problem) or because of other reasons.

Could you please take a look and help to investigate and fix the issue?

Thank you!

2016-09-02T02:45:04.746478+00:00 notice: (/Stage[main]/Nova::Db::Sync_api/Exec[nova-db-sync-api]/returns) error: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction')

http://paste.openstack.org/show/567180/

Ivan, thank you for your help!

It is MySQL Deadlock issue, Fuel Sustaining team, could you please take a look?

Thank you!

the fail:

node-1.test.domain.local/mysqld.log:2016-09-02T02:45:04.537997+00:00 err: 2016-09-02 02:45:04 13875 [Warning] WSREP: TO isolation failed for: 3, schema: nova_api, sql: CREATE INDEX flavor_extra_specs_flavor_id_key_idx ON flavor_extra_specs (flavor_id, `key`). Check wsrep connection state and retry the query.

is happens right during the split-brain process:

node-1.test.domain.local/ocf-mysql-wss.log:496:2016-09-02T02:45:04.149886+00:00 err: ERROR: p_mysqld: check_if_galera_pc(): But I'm running a new cluster, PID:13875, this is a split-brain!

20 seconds later the galera cluster recovered:

node-1.test.domain.local/mysqld.log:2016-09-02T02:45:24.605658+00:00 err: 2016-09-02 02:45:24 17094 [Note] WSREP: New cluster view: global state: bf1c6c99-70b4-11e6-ad87-6a2b8c2d2a6a:965, view# 5: Primary, number of nodes: 3, my index: 2, protocol version 3
node-1.test.domain.local/mysqld.log:2016-09-02T02:45:24.606194+00:00 err: 2016-09-02 02:45:24 17094 [Note] WSREP: SST complete, seqno: 965

the cluster installed with fuel-ha-utils package version 9.0.0-1~u14.04+mos8568 which contain the fix for split-brain: https://review.openstack.org/#/c/361943/

all fine with mysql/galera but nova-manage don't handle deadlocks exeptions even the parameter nova/db_max_retries set to 20. nova-manage should retry in case of deadlock error before error is raised.

We have the same issues for Heat:

https://bugs.launchpad.net/mos/+bug/1620638

Maksim,

Regardless of the fact whether it does 20 retries or not, if "nova-manage db sync" fails, deployment must be stopped at this point with a failure. Or, alternatively, the whole "nova-manage db sync" call must be retried.

Moreover, the migration is performed by migrate library - Nova just propagates the error up the stack, so that nova-manage exits with a proper error code. It's up to a deployment tool (or operator) to handle the problem at this point (taking into account the fact that MySQL does not support transactional DDL and retries are not guaranteed to be idempotent, because applying of migration scripts might have failed in the middle of the process).

https://bugs.launchpad.net/fuel/+bug/1619740/comments/5 clearly states db sync step failed - the corresponding deployment task should have also failed rather than silently continuing, as if everything succeeded. At this point the deployment must be in error state, not in complete state.

Roman, thanks for the feedback, the deployment shouldn't be stopped instead of nova-manage should be executed once more, so this should be fixed in the nova puppet modules.

Fix proposed to branch: master
Review: https://review.openstack.org/366978

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/#/c/366971/

Reviewed: https://review.openstack.org/366978
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=a1b1289d2ce5f1b88b8dbda5bcd84bcb1f4bd633
Submitter: Jenkins
Branch: master

commit a1b1289d2ce5f1b88b8dbda5bcd84bcb1f4bd633
Author: Maksim Malchuk <email address hidden>
Date: Wed Sep 7 23:46:26 2016 +0300

    Tweak 'nova-db-sync' and 'nova-db-sync-api' execs

    This change adds retries to not fail on 'nova-manage' execution

    Closes-Bug: #1619740
    Change-Id: I33637b17a18f8809f0a5f3778c57d5066fd56b8d
    Signed-off-by: Maksim Malchuk <email address hidden>

Reviewed: https://review.openstack.org/366971
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=6ff84695316f07362552883f302afcaaef53b26c
Submitter: Jenkins
Branch: stable/mitaka

commit 6ff84695316f07362552883f302afcaaef53b26c
Author: Maksim Malchuk <email address hidden>
Date: Wed Sep 7 23:46:26 2016 +0300

    Tweak 'nova-db-sync' and 'nova-db-sync-api' execs

    This change adds retries to not fail on 'nova-manage' execution

    Closes-Bug: #1619740
    Change-Id: I33637b17a18f8809f0a5f3778c57d5066fd56b8d
    Signed-off-by: Maksim Malchuk <email address hidden>

SWARM runs for 9.1 #50-#58 passed.

This issue was fixed in the openstack/fuel-library 10.0.0rc1 release candidate.

This issue was fixed in the openstack/fuel-library 10.0.0 release.