Bug 1548929 - OSP12->13 undercloud upgrade gets stuck because mariadb.service is stuck in deactivating state during yum cleanup
Summary: OSP12->13 undercloud upgrade gets stuck because mariadb.service is stuck in d...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: instack-undercloud
Version: 13.0 (Queens)
Hardware: Unspecified
OS: Unspecified
high
urgent
Target Milestone: beta
: 13.0 (Queens)
Assignee: Damien Ciabrini
QA Contact: Yurii Prokulevych
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-02-26 03:36 UTC by Marius Cornea
Modified: 2018-06-27 13:46 UTC (History)
15 users (show)

Fixed In Version: instack-undercloud-8.4.0-2.el7ost
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-06-27 13:45:51 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
OpenStack gerrit 547560 'None' MERGED Mariadb online upgrade after yum update 2020-07-31 09:32:04 UTC
OpenStack gerrit 554306 'None' MERGED Mariadb online upgrade after yum update 2020-07-31 09:32:01 UTC
Red Hat Product Errata RHEA-2018:2086 None None None 2018-06-27 13:46:28 UTC

Description Marius Cornea 2018-02-26 03:36:17 UTC
Description of problem:
OSP12->13 undercloud upgrade gets stuck because mariadb.service is stuck in deactivating during yum cleanup

Version-Release number of selected component (if applicable):
[root@undercloud-0 ~]# rpm -qa | grep mariadb
mariadb-10.1.20-2.el7ost.x86_64
mariadb-5.5.56-2.el7.x86_64
mariadb-common-10.1.20-2.el7ost.x86_64
mariadb-libs-10.1.20-2.el7ost.x86_64
mariadb-libs-5.5.56-2.el7.x86_64
mariadb-config-10.1.20-2.el7ost.x86_64
mariadb-errmsg-10.1.20-2.el7ost.x86_64
mariadb-server-5.5.56-2.el7.x86_64
mariadb-server-10.1.20-2.el7ost.x86_64
instack-undercloud-8.2.1-0.20180214022816.8a7609e.el7ost.noarch
instack-8.1.1-0.20180210031553.1fe782a.el7ost.noarch


How reproducible:
100%

Steps to Reproduce:
1. Deploy OSP12 undercloud
2.sudo yum -y update python-tripleoclient
3. openstack undercloud upgrade

Actual results:
During yum cleanup the upgrade process gets stuck because mariadb service is stuck in deactivating state.

Expected results:
Undercloud upgrade process doesn't get stuck.

Additional info:
[root@undercloud-0 ~]# systemctl status mariadb
● mariadb.service - MariaDB 10.1 database server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/mariadb.service.d
           └─limits.conf
   Active: deactivating (stop-sigterm) since Sun 2018-02-25 22:31:33 EST; 2min 3s ago
 Main PID: 1730 (mysqld_safe)
   CGroup: /system.slice/mariadb.service
           ├─1730 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─3260 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mariadb/mariadb.log --open-files-limit=-1 --pid-file=/var/run/mariadb/mariadb.pid --socket=/var/lib...

Feb 25 22:22:53 undercloud-0.redhat.local systemd[1]: Starting MariaDB database server...
Feb 25 22:22:54 undercloud-0.redhat.local mariadb-prepare-db-dir[1484]: Database MariaDB is probably initialized in /var/lib/mysql already, nothing is done.
Feb 25 22:22:54 undercloud-0.redhat.local mariadb-prepare-db-dir[1484]: If this is not the case, make sure the /var/lib/mysql is empty before running mariadb-prepare-db-dir.
Feb 25 22:23:04 undercloud-0.redhat.local mysqld_safe[1730]: 180225 22:23:04 mysqld_safe Logging to '/var/log/mariadb/mariadb.log'.
Feb 25 22:23:05 undercloud-0.redhat.local mysqld_safe[1730]: 180225 22:23:05 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
Feb 25 22:23:07 undercloud-0.redhat.local systemd[1]: Started MariaDB database server.
Feb 25 22:29:04 undercloud-0.redhat.local systemd[1]: Current command vanished from the unit file, execution of the command list won't be resumed.
Feb 25 22:31:33 undercloud-0.redhat.local systemd[1]: Stopping MariaDB 10.1 database server...


[root@undercloud-0 ~]# tail /var/log/mariadb/mariadb.log 
180225 22:23:07 [ERROR] mysqld: Table './mysql/proxies_priv' is marked as crashed and should be repaired
180225 22:23:07 [Warning] Checking table:   './mysql/proxies_priv'
180225 22:23:07 [ERROR] mysql.proxies_priv: 1 client is using or hasn't closed the table properly
180225 22:23:07 [Note] Event Scheduler: Loaded 0 events
180225 22:23:07 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.56-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
180225 22:23:07 [Note] Hostname 'undercloud-0.redhat.local' does not resolve to '192.168.24.1'.
180225 22:23:07 [Note] Hostname 'undercloud-0.redhat.local' has the following IP addresses:
180225 22:23:07 [Note]  - 127.0.0.1

Comment 4 Yolanda Robla 2018-03-03 08:11:33 UTC
Hitting that as well:

[root@undercloud-0 mariadb]# systemctl status mariadb
● mariadb.service - MariaDB 10.1 database server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/mariadb.service.d
           └─limits.conf
   Active: failed (Result: exit-code) since vie 2018-03-02 19:49:15 EST; 7h ago
  Process: 26712 ExecStartPre=/usr/libexec/mysql-check-socket (code=exited, status=1/FAILURE)
 Main PID: 365
   CGroup: /system.slice/mariadb.service
           ├─365 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─883 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mariadb/mariadb.log --open-files-limit=-1 --pid-file=/var/run/mariadb/mariadb.pid --socket=/var/lib/...

mar 02 19:49:14 undercloud-0.redhat.local systemd[1]: Starting MariaDB 10.1 database server...
mar 02 19:49:14 undercloud-0.redhat.local mysql-check-socket[26712]: Socket file /var/lib/mysql/mysql.sock exists.
mar 02 19:49:15 undercloud-0.redhat.local mysql-check-socket[26712]: Is another MySQL daemon already running with the same unix socket?
mar 02 19:49:15 undercloud-0.redhat.local mysql-check-socket[26712]: Please, stop the process    883 or remove /var/lib/mysql/mysql.sock manually to start the service.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: mariadb.service: control process exited, code=exited status=1
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: Failed to start MariaDB 10.1 database server.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: Unit mariadb.service entered failed state.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: mariadb.service failed.
[root@undercloud-0 mariadb]# journalctl -xe | grep mariad
-- Subject: Unit mariadb.service has begun shutting down
-- Unit mariadb.service has begun shutting down.
mar 02 19:37:51 undercloud-0.redhat.local systemd[1]: mariadb.service stop-sigterm timed out. Skipping SIGKILL.
mar 02 19:38:52 undercloud-0.redhat.local systemd[1]: mariadb.service: control process exited, code=exited status=3
mar 02 19:42:51 undercloud-0.redhat.local systemd[1]: mariadb.service stop-post timed out. Terminating.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: Unit mariadb.service entered failed state.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: mariadb.service failed.
-- Subject: Unit mariadb.service has begun start-up
-- Unit mariadb.service has begun starting up.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: mariadb.service: control process exited, code=exited status=1
-- Subject: Unit mariadb.service has failed
-- Unit mariadb.service has failed.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: Unit mariadb.service entered failed state.
mar 02 19:47:51 undercloud-0.redhat.local systemd[1]: mariadb.service failed.
-- Subject: Unit mariadb.service has begun start-up
-- Unit mariadb.service has begun starting up.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: mariadb.service: control process exited, code=exited status=1
-- Subject: Unit mariadb.service has failed
-- Unit mariadb.service has failed.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: Unit mariadb.service entered failed state.
mar 02 19:49:15 undercloud-0.redhat.local systemd[1]: mariadb.service failed.

[root@undercloud-0 mariadb]# cat mariadb.log 
180302 17:40:40 [Warning] Failed to setup SSL
180302 17:40:40 [Warning] SSL error: SSL_CTX_set_default_verify_paths failed
180302 17:40:40 [Warning] Failed to setup SSL
180302 17:40:40 [Warning] SSL error: SSL_CTX_set_default_verify_paths failed
180302 17:40:41 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
180302 17:40:41 [Warning] option 'open_files_limit': unsigned value 18446744073709551615 adjusted to 4294967295
180302 17:40:41 [Warning] option 'open_files_limit': unsigned value 18446744073709551615 adjusted to 4294967295
180302 17:40:41 [Note] /usr/libexec/mysqld (mysqld 5.5.56-MariaDB) starting as process 9119 ...
180302 17:40:41 InnoDB: The InnoDB memory heap is disabled
180302 17:40:41 InnoDB: Mutexes and rw_locks use GCC atomic builtins
180302 17:40:41 InnoDB: Compressed tables use zlib 1.2.7
180302 17:40:41 InnoDB: Using Linux native AIO
180302 17:40:41 InnoDB: Initializing buffer pool, size = 128.0M
180302 17:40:41 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
180302 17:40:41  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
180302 17:40:41  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
180302 17:40:41  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: 127 rollback segment(s) active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
180302 17:40:41  InnoDB: Waiting for the background threads to start
180302 17:40:42 Percona XtraDB (http://www.percona.com) 5.5.52-MariaDB-38.3 started; log sequence number 0
180302 17:40:42 [Note] Plugin 'FEEDBACK' is disabled.
180302 17:40:42 [Warning] Failed to setup SSL
180302 17:40:42 [Warning] SSL error: SSL_CTX_set_default_verify_paths failed
180302 17:40:42 [Note] Server socket created on IP: '192.0.2.1'.
180302 17:40:42 [Note] Event Scheduler: Loaded 0 events
180302 17:40:42 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.56-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
180302 17:41:18 [Note] Hostname 'undercloud-0.redhat.local' does not resolve to '192.0.2.1'.
180302 17:41:18 [Note] Hostname 'undercloud-0.redhat.local' has the following IP addresses:
180302 17:41:18 [Note]  - 127.0.0.1

180302 19:03:03 [Note] /usr/libexec/mysqld: Normal shutdown

180302 19:03:03 [Note] Event Scheduler: Purging the queue. 0 events
180302 19:03:03  InnoDB: Starting shutdown...
180302 19:03:06  InnoDB: Shutdown completed; log sequence number 111885898
180302 19:03:06 [Note] /usr/libexec/mysqld: Shutdown complete

180302 19:03:06 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
180302 19:03:06 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
180302 19:03:06 [Warning] option 'open_files_limit': unsigned value 18446744073709551615 adjusted to 4294967295
180302 19:03:06 [Warning] option 'open_files_limit': unsigned value 18446744073709551615 adjusted to 4294967295
180302 19:03:06 [Note] /usr/libexec/mysqld (mysqld 5.5.56-MariaDB) starting as process 883 ...
180302 19:03:06 InnoDB: The InnoDB memory heap is disabled
180302 19:03:06 InnoDB: Mutexes and rw_locks use GCC atomic builtins
180302 19:03:06 InnoDB: Compressed tables use zlib 1.2.7
180302 19:03:06 InnoDB: Using Linux native AIO
180302 19:03:06 InnoDB: Initializing buffer pool, size = 128.0M
180302 19:03:06 InnoDB: Completed initialization of buffer pool
180302 19:03:06 InnoDB: highest supported file format is Barracuda.
180302 19:03:07  InnoDB: Waiting for the background threads to start
180302 19:03:08 Percona XtraDB (http://www.percona.com) 5.5.52-MariaDB-38.3 started; log sequence number 111885898
180302 19:03:08 [Note] Plugin 'FEEDBACK' is disabled.
180302 19:03:08 [Note] Server socket created on IP: '192.0.2.1'.
180302 19:03:08 [Note] Event Scheduler: Loaded 0 events
180302 19:03:08 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.56-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
180302 19:05:25 [Note] Hostname 'undercloud-0.redhat.local' does not resolve to '192.0.2.1'.
180302 19:05:25 [Note] Hostname 'undercloud-0.redhat.local' has the following IP addresses:
180302 19:05:25 [Note]  - 127.0.0.1

Comment 5 mathieu bultel 2018-03-15 10:34:48 UTC
@Maria PM ack ?

Comment 7 Damien Ciabrini 2018-03-28 12:11:45 UTC
patch landed in queens

Comment 9 Yurii Prokulevych 2018-04-04 09:23:33 UTC
Verified with instack-undercloud-8.4.0-2.el7ost.noarch

Excerpt from uc's update log:
...
2018-04-04 04:13:06,356 INFO: Current mariadb version is: 5.5.56
2018-04-04 04:13:06,760 INFO: Available mariadb version is: 10.1.20
2018-04-04 04:13:06,761 INFO: Major versions differ (5.5 vs 10.1), database needs an upgrade
2018-04-04 04:13:06,761 INFO: Stopping OpenStack database before upgrade
2018-04-04 04:13:08,215 INFO: Database stopped successfully
2018-04-04 04:13:08,215 INFO: Updating full system
...
2018-04-04 04:19:47,606 INFO: Start OpenStack database after upgrade
2018-04-04 04:19:48,354 INFO: Database started successfully
2018-04-04 04:19:48,355 INFO: Run online upgrade of the database
2018-04-04 04:19:48,420 INFO: Phase 1/6: Checking and upgrading mysql database
2018-04-04 04:19:48,435 INFO: Processing databases
...
2018-04-04 04:19:49,784 INFO: Phase 6/6: Running 'FLUSH PRIVILEGES'
2018-04-04 04:19:49,784 INFO: OK
2018-04-04 04:19:49,790 INFO: Database upgraded successfully
2018-04-04 04:19:49,791 INFO: Restart OpenStack database for upgrade to take effect
2018-04-04 04:19:52,533 INFO: Database restarted successfully

Comment 13 errata-xmlrpc 2018-06-27 13:45:51 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2018:2086


Note You need to log in before you can comment on or make changes to this bug.