OpenStack DBaaS (Trove)

Mysql restore fails because the mysql does not start correctly

Bug #1791878 reported by Shi Yan on 2018-09-11

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack DBaaS (Trove)	Fix Released	Undecided	Shi Yan

Bug Description

I am using the bionic-rocky image to test the mysql db backup and restore. The package version is:

trove-guestagent
1:10.0.0-0ubuntu2~cloud0

But the restore is failed during the post_restore phase.

From the trove instance trove-guestagent.log, we could see that innobackupex has been performed successfully but the mysql cannot start.

2018-09-11 02:26:48.856 615 INFO trove.guestagent.strategies.restore.mysql_impl [-] Innobackupex prepare finished successfully.
2018-09-11 02:26:48.857 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo chown -f -R mysql: /var/lib/mysql/data execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:26:48.880 615 DEBUG oslo_concurrency.processutils [-] CMD "sudo chown -f -R mysql: /var/lib/mysql/data" returned: 0 in 0.023s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:26:48.916 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo chmod -R +444 /tmp/tmpMtWa3_ execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:26:48.935 615 DEBUG oslo_concurrency.processutils [-] CMD "sudo chmod -R +444 /tmp/tmpMtWa3_" returned: 0 in 0.019s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:26:48.936 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo mkdir /var/run/mysqld execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:26:48.951 615 DEBUG oslo_concurrency.processutils [-] CMD "sudo mkdir /var/run/mysqld" returned: 0 in 0.015s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:26:48.952 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo chown mysql:mysql /var/run/mysqld /tmp/tmpnUjYxJ.err execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:26:48.968 615 DEBUG oslo_concurrency.processutils [-] CMD "sudo chown mysql:mysql /var/run/mysqld /tmp/tmpnUjYxJ.err" returned: 0 in 0.015s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:26:49.361 615 INFO trove.guestagent.strategies.restore.mysql_impl [-] Starting MySQL
2018-09-11 02:26:49.362 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/bin/mysqladmin ping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:26:49.380 615 DEBUG oslo_concurrency.processutils [-] CMD "/usr/bin/mysqladmin ping" returned: 1 in 0.018s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:26:49.382 615 DEBUG oslo_concurrency.processutils [-] u'/usr/bin/mysqladmin ping' failed. Not Retrying. execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:457
2018-09-11 02:26:49.382 615 DEBUG trove.guestagent.strategies.restore.mysql_impl [-] MySQL is not running. mysql_is_running /usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py:54
2018-09-11 02:27:08.101 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/bin/mysqladmin ping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:27:08.120 615 DEBUG oslo_concurrency.processutils [-] CMD "/usr/bin/mysqladmin ping" returned: 1 in 0.018s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:27:08.121 615 DEBUG oslo_concurrency.processutils [-] u'/usr/bin/mysqladmin ping' failed. Not Retrying. execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:457
2018-09-11 02:27:08.122 615 DEBUG trove.guestagent.strategies.restore.mysql_impl [-] MySQL is not running. mysql_is_running /usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py:54
2018-09-11 02:27:31.331 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/bin/mysqladmin ping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:27:31.355 615 DEBUG oslo_concurrency.processutils [-] CMD "/usr/bin/mysqladmin ping" returned: 1 in 0.024s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:27:31.356 615 DEBUG oslo_concurrency.processutils [-] u'/usr/bin/mysqladmin ping' failed. Not Retrying. execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:457
2018-09-11 02:27:31.356 615 DEBUG trove.guestagent.strategies.restore.mysql_impl [-] MySQL is not running. mysql_is_running /usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py:54
2018-09-11 02:27:32.978 615 DEBUG oslo_service.periodic_task [-] Running periodic task Manager.update_status run_periodic_tasks /usr/lib/python2.7/dist-packages/oslo_service/periodic_task.py:215
2018-09-11 02:27:32.979 615 DEBUG trove.guestagent.datastore.manager [-] Update status called. update_status /usr/lib/python2.7/dist-packages/trove/guestagent/datastore/manager.py:251
2018-09-11 02:27:32.980 615 INFO trove.guestagent.datastore.service [-] DB server is not installed or is in restart mode, so for now we'll skip determining the status of DB on this instance.
2018-09-11 02:28:01.357 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/bin/mysqladmin ping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:28:01.375 615 DEBUG oslo_concurrency.processutils [-] CMD "/usr/bin/mysqladmin ping" returned: 1 in 0.018s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:28:01.377 615 DEBUG oslo_concurrency.processutils [-] u'/usr/bin/mysqladmin ping' failed. Not Retrying. execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:457
2018-09-11 02:28:01.378 615 DEBUG trove.guestagent.strategies.restore.mysql_impl [-] MySQL is not running. mysql_is_running /usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py:54
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall [-] Dynamic backoff interval looping call 'trove.common.utils.poll_and_check' failed: LoopingCallTimeOut: Looping call timed out after 71.92 seconds
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall Traceback (most recent call last):
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 197, in _run_loop
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall idle = idle_for_func(result, watch.elapsed())
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 394, in _idle_for
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall % self._error_time)
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall LoopingCallTimeOut: Looping call timed out after 71.92 seconds
2018-09-11 02:28:01.378 615 ERROR oslo.service.loopingcall
2018-09-11 02:28:01.389 615 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo rm -f -R /tmp/tmpnUjYxJ.err execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2018-09-11 02:28:01.412 615 DEBUG oslo_concurrency.processutils [-] CMD "sudo rm -f -R /tmp/tmpnUjYxJ.err" returned: 0 in 0.023s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent [-] Error restoring backup b59d8279-0a37-4264-b978-8dbb6fcf7a98.: LoopingCallTimeOut: Looping call timed out after 71.92 seconds
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent Traceback (most recent call last):
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/backup/backupagent.py", line 173, in execute_restore
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent content_size = runner.restore()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/base.py", line 76, in restore
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent self.post_restore()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py", line 225, in post_restore
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent self.reset_root_password()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py", line 151, in reset_root_password
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent self._start_mysqld_safe_with_init_file(init_file, err_log_file)
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py", line 105, in _start_mysqld_safe_with_init_file
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent base.RestoreError("Reset root password failed:"
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/guestagent/strategies/restore/mysql_impl.py", line 70, in poll_until_then_raise
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent time_out=self.RESET_ROOT_RETRY_TIMEOUT)
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/trove/common/utils.py", line 214, in poll_until
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent sleep_time=sleep_time, time_out=time_out).wait()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent return hubs.get_hub().switch()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent return self.greenlet.switch()
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 197, in _run_loop
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent idle = idle_for_func(result, watch.elapsed())
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent File "/usr/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 394, in _idle_for
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent % self._error_time)
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent LoopingCallTimeOut: Looping call timed out after 71.92 seconds
2018-09-11 02:28:01.414 615 ERROR trove.guestagent.backup.backupagent
2018-09-11 02:28:01.429 615 ERROR trove.guestagent.datastore.mysql_common.manager [-] Error performing restore from backup b59d8279-0a37-4264-b978-8dbb6fcf7a98.: LoopingCallTimeOut: Looping call timed out after 71.92 seconds

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-09-12: Fix proposed to trove (master)

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

Changed in trove:
assignee:	nobody → Shi Yan (yanshi-403)
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-10-03: Fix merged to trove (master)

Reviewed: https://review.openstack.org/601886
Committed: https://git.openstack.org/cgit/openstack/trove/commit/?id=803b50d5eade6754fe8c2f2dc6d00b6870ebc3ad
Submitter: Zuul
Branch: master

commit 803b50d5eade6754fe8c2f2dc6d00b6870ebc3ad
Author: Rocky <email address hidden>
Date: Tue Sep 11 22:55:39 2018 +1000

Fix the mysql start up issue after restore

    When the trove guest image is built without the proper permission
    setting for /tmp directory in which ini file is created. (could happen
    when using non-official ways of image building), mysqld_safe will fail
    to reset the root password after mysql restore due to AppArmour
    complaints. As a consequence it fails the whole mysql restore procedure.

Changing init-file ownership fixes this problem and makes the backup and
restore successful.

Co-Authored-By: Jake Yip <email address hidden>

Closes-Bug: #1791878

Change-Id: Ia164345239197f93fb63697212a9b96c900fbe89

Changed in trove:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-03-22: Fix included in openstack/trove 11.0.0.0rc1

This issue was fixed in the openstack/trove 11.0.0.0rc1 release candidate.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.