MariaDB doesn't start after zypper upgrade to mariadb-10.2.22-lp150.2.9.1.x86_64

MariaDB runs as a server on a LEAP 15.0 machine. Last evening, zypper up was executed as a cron job, service mariadb stopped and I can’t (re)start it.

systemctl status mariadb.service produces

— mariadb.service - MySQL server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2019-03-21 09:18:25 CET; 37min ago
  Process: 8452 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper upgrade (code=exited, status=1/FAILURE)
  Process: 8438 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper install (code=exited, status=0/SUCCESS)

Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Stale files from previous upgrade detected, cleaned them up
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Running protected MySQL...
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Waiting for MySQL to start
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: 2019-03-21  9:17:24 140332755601600 [Note] /usr/sbin/mysqld (mysqld 10.2.22-MariaDB-log) starting as process 8478 ...
Mar 21 09:18:25 DGS-LDBS-03 mysql-systemd-helper[8452]: MySQL is still dead
Mar 21 09:18:25 DGS-LDBS-03 mysql-systemd-helper[8452]: MySQL didn't start, can't continue
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Control process exited, code=exited status=1
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: Failed to start MySQL server.
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Unit entered failed state.
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Failed with result 'exit-code'

and journalctl -xe produces

Mar 21 09:17:24 DGS-LDBS-03 systemd[1]: Starting MySQL server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit mariadb.service has begun starting up.
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Checking MySQL configuration for obsolete options...
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Trying to run upgrade of MySQL databases...
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Stale files from previous upgrade detected, cleaned them up
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Running protected MySQL...
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: Waiting for MySQL to start
Mar 21 09:17:24 DGS-LDBS-03 mysql-systemd-helper[8452]: 2019-03-21  9:17:24 140332755601600 [Note] /usr/sbin/mysqld (mysqld 10.2.22-MariaDB-log) starting as process 8478 ...
Mar 21 09:18:25 DGS-LDBS-03 mysql-systemd-helper[8452]: MySQL is still dead
Mar 21 09:18:25 DGS-LDBS-03 mysql-systemd-helper[8452]: MySQL didn't start, can't continue
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Control process exited, code=exited status=1
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: Failed to start MySQL server.
-- Subject: Unit mariadb.service has failed
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit mariadb.service has failed.
-- 
-- The result is failed.
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Unit entered failed state.
Mar 21 09:18:25 DGS-LDBS-03 systemd[1]: mariadb.service: Failed with result 'exit-code'.

How do I fix this and get MariaDB running again?

Which indications for the misbehaviour does the MariaDB Server administration tool (mysqladmin) deliver?

There’s also an administration tool to check the database for incompatibilities with the current MariaDB Server: “mysql_upgrade”.

Both state that they cannot connect to local MySQL server through socket ‘var/run/mysql/mysql.sock’, which does not surprise me as mysql is not running.
BTW, mysqladmin suggests to check that mysqld is running, but I only have service mysql (or mariadb, which does the same).

On this system, with KDE Plasma as the UI and the KDE PIM active, and therefore also Akonadi, the following needs to be noted:


 # systemctl status mysql.service mariadb.service mariadb.target 
● mariadb.service - MySQL server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2019-03-21 08:43:59 CET; 6h ago
  Process: 2302 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper upgrade (code=exited, status=0/SUCCESS)
  Process: 2268 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper install (code=exited, status=0/SUCCESS)
 Main PID: 2322 (mysqld)
   Status: "Taking your SQL requests now..."
    Tasks: 30 (limit: 4915)
   CGroup: /system.slice/mariadb.service
           └─2322 /usr/sbin/mysqld --defaults-file=/etc/my.cnf --user=mysql

Mär 21 08:43:57 xxx systemd[1]: Starting MySQL server...
Mär 21 08:43:58 xxx mysql-systemd-helper[2322]: 2019-03-21  8:43:58 139767379118272 [Note] /usr/sbin/mysqld (mysqld >
Mär 21 08:43:59 xxx systemd[1]: Started MySQL server.

● mariadb.service - MySQL server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2019-03-21 08:43:59 CET; 6h ago
  Process: 2302 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper upgrade (code=exited, status=0/SUCCESS)
  Process: 2268 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper install (code=exited, status=0/SUCCESS)
 Main PID: 2322 (mysqld)
   Status: "Taking your SQL requests now..."
    Tasks: 30 (limit: 4915)
   CGroup: /system.slice/mariadb.service
           └─2322 /usr/sbin/mysqld --defaults-file=/etc/my.cnf --user=mysql

Mär 21 08:43:57 xxx systemd[1]: Starting MySQL server...
Mär 21 08:43:58 xxx mysql-systemd-helper[2322]: 2019-03-21  8:43:58 139767379118272 [Note] /usr/sbin/mysqld (mysqld >
Mär 21 08:43:59 xxx systemd[1]: Started MySQL server.

● mariadb.target - MySQL target allowing to control multi setup
   Loaded: loaded (/usr/lib/systemd/system/mariadb.target; static; vendor preset: disabled)
   Active: inactive (dead)
 # 

N.B.: The MySQL and MariaDB systemd services are both disabled

MySQL/MariaDB are being started, due to KDE Akonadi, via a link:


 # ls -l **/etc/systemd/system/multi-user.target.wants/**
 . 
 . 
lrwxrwxrwx  1 root root   37  5. Jan 2017  mysql.service -> /usr/lib/systemd/system/mysql.service
 . 
 . 
 # 

The MySQL/MariaDB daemon (PID #2322) was started by the command “/usr/sbin/mysqld --defaults-file=/etc/my.cnf --user=mysql”.

Perhaps you could attempt to start the daemon by means of this command, and then report back on the errors being raised.

You could also take a look at the Bash script “/usr/lib/mysql/mysql-systemd-helper” with particular attention being paid to the sections “upgrade” and “install” – it could be that, something is not quite correct with respect to the creation of a new empty database in “/var/lib/mysql/” (owner “mysql”, group “root”, neither group nor world access … ).

The systemd file “/usr/lib/systemd/system/mariadb.service” is a world readable text file which calls “/usr/lib/mysql/mysql-systemd-helper” three times …

The output from

systemctl status mysql.service mariadb.service mariadb.target
is

● mariadb.service - MySQL server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2019-03-21 15:50:58 CET; 1h 21min ago
  Process: 22022 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper upgrade (code=exited, status=1/FAILURE)
  Process: 22008 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper install (code=exited, status=0/SUCCESS)

mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Stale files from previous upgrade detected, cleaned them up
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Running protected MySQL...
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Waiting for MySQL to start
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: 2019-03-21 15:49:57 139628729120960 [Note] /usr/sbin/mysqld (mysqld 10.2.22-MariaDB-log) starting as process 22048 ...
mrt 21 15:50:58 DGS-LDBS-03 mysql-systemd-helper[22022]: MySQL is still dead
mrt 21 15:50:58 DGS-LDBS-03 mysql-systemd-helper[22022]: MySQL didn't start, can't continue
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Control process exited, code=exited status=1
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: Failed to start MySQL server.
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Unit entered failed state.
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Failed with result 'exit-code'.

● mariadb.service - MySQL server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2019-03-21 15:50:58 CET; 1h 21min ago
  Process: 22022 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper upgrade (code=exited, status=1/FAILURE)
  Process: 22008 ExecStartPre=/usr/lib/mysql/mysql-systemd-helper install (code=exited, status=0/SUCCESS)

mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Stale files from previous upgrade detected, cleaned them up
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Running protected MySQL...
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: Waiting for MySQL to start
mrt 21 15:49:57 DGS-LDBS-03 mysql-systemd-helper[22022]: 2019-03-21 15:49:57 139628729120960 [Note] /usr/sbin/mysqld (mysqld 10.2.22-MariaDB-log) starting as process 22048 ...
mrt 21 15:50:58 DGS-LDBS-03 mysql-systemd-helper[22022]: MySQL is still dead
mrt 21 15:50:58 DGS-LDBS-03 mysql-systemd-helper[22022]: MySQL didn't start, can't continue
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Control process exited, code=exited status=1
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: Failed to start MySQL server.
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Unit entered failed state.
mrt 21 15:50:58 DGS-LDBS-03 systemd[1]: mariadb.service: Failed with result 'exit-code'.

● mariadb.target - MySQL target allowing to control multi setup
   Loaded: loaded (/usr/lib/systemd/system/mariadb.target; static; vendor preset: disabled)
   Active: inactive (dead)

ls -l /etc/systemd/system/multi-user.target.wants/
gives the output as in your post.

The command

/usr/sbin/mysqld --defaults-file=/etc/my.cnf --user=mysql
starts PID #24517 without any errors that I can see
, apart from the minor issue that it doesn’t return to bash (I didn’t put & after the command). But PID#24517 is running, and has the name mysqld.
The command mysql starts a mysql client and I can access my data.
But
systemctl status mysql.service mariadb.service mariadb.target
produces the same output as above.

I hope this information can help you to help me further.
(The machine has no GUI.)

And

/usr/lib/systemd/system/mariadb.service
(dated July 10, 2018) contains

# It's not recommended to modify this unit file because your changes
# would be overwritten during the package update.
#
# However, there are 2 methods how to customize this unit file:
#
# 1) Copy this unit file from /usr/lib/systemd/system to
# /etc/systemd/system and modify the chosen settings.
#
# 2) Create a directory named mariadb.service.d/ within /etc/systemd/system
# and place a drop-in file name.conf there that only changes the specific
# settings one is interested in.
#
# see systemd.unit(5) for details
#
# Example - increasing of the TimeoutSec= limit
#      mkdir /etc/systemd/system/mariadb.service.d
#      cat > /etc/systemd/system/mariadb.service.d/timeout.conf << EOF
#      [Service]
#      TimeoutSec=600 
#      EOF

[Unit]
Description=MySQL server
Wants=basic.target
Conflicts=mariadb.target
After=basic.target network.target 

[Service]
Restart=on-abort
Type=notify
ExecStartPre=/usr/lib/mysql/mysql-systemd-helper  install
ExecStartPre=/usr/lib/mysql/mysql-systemd-helper  upgrade
ExecStart=/usr/lib/mysql/mysql-systemd-helper     start

# Configures the time to wait for start-up/stop
TimeoutSec=300

[Install]
WantedBy=multi-user.target
Alias=mysql.service 

I found the direct cause of the problem.
I added extra traces to

/usr/lib/mysql/mysql-systemd-helper
in the mysql_upgrade function, so that I could see some more.
That way I found out where the error log of the protected MySQL was located and its contents where

2019-03-22  7:57:43 140585421793472 [ERROR] Can't open shared library '/usr/lib64/mysql/plugin/server-audit.so' (errno: 2, cannot open shared object file: No such file or directory)
2019-03-22  7:57:43 140585421793472 [ERROR] Couldn't load plugin 'server_audit' from 'server-audit.so'.
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Uses event mutexes
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Using Linux native AIO
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Number of pools: 1
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Using SSE2 crc32 instructions
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Initializing buffer pool, total size = 6G, instances = 8, chunk size = 128M
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Completed initialization of buffer pool
2019-03-22  7:57:43 140578270426880 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-03-22  7:57:43 140585421793472 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: Waiting for purge to start
2019-03-22  7:57:44 140585421793472 [Note] InnoDB: 5.7.25 started; log sequence number 925131129705
2019-03-22  7:57:44 140578411861760 [Note] InnoDB: Loading buffer pool(s) from /MariaDB/ib_buffer_pool
2019-03-22  7:57:44 140578411861760 [Note] InnoDB: Buffer pool(s) load completed at 190322  7:57:44
2019-03-22  7:57:44 140585421793472 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-22  7:57:44 140585421793472 [ERROR] /usr/sbin/mysqld: unknown variable 'server_audit_file_path=/var/log/mysql/server_audit.log'
2019-03-22  7:57:44 140585421793472 [ERROR] Aborting


I then sought the missing library and found

/usr/lib64/mysql/plugin/server_audit.so
instead of
/usr/lib64/mysql/plugin/server-audit.so
.
After copying the existing to the missing one, I could run
systemctl start mariadn
without a problem.

So I now have a workaround for the problem, but that may well get corrupted with updates. Replacing the copy of server_audit.so by a symbolic link will reduce the risk, but it still remains a workaround.
Should I register a bug report for this?

(The ERROR at the bottom of the error log is probably related to the missing server-audit.so, as the mentioned log exists and is maintained by the service once running.)

I should add that

/var/log/mysql/mysqld.log
nows mentions on start up

2019-03-22  9:58:30 140053116582080 [Note] Loaded 'server-audit.so' with offset 0x7f60a28be000
2019-03-22  9:58:31 140053116582080 [ERROR] Plugin 'SERVER_AUDIT' already installed
...

and also that it appears to be impossible to connect to mariadb from external locations.

@Dnk1287:

Several things:

  1. With the user “root”, execute “zypper verify”.
  2. With the user “root”, execute “rpm --rebuilddb” and then “rpm --verify --all | less” (especially needed if you have WordPress installed … ).
  3. With the user “root”, execute “rpmconfigcheck”.

When that’s done, given that, the machine has no GUI, the link in “/etc/systemd/system/multi-user.target.wants/” which starts the MariaDB/MySQL (probably due to Akonadi and KDE being installed) is almost certainly not needed – consider removing everything GUI related from the machine (which should also remove that link) …

In any case, the MariaDB/MySQL daemon only needs to be started once – either, let it start via the link in “/etc/systemd/system/multi-user.target.wants/” or, by enabling the service in systemd – only one method – not both …

Congrats on sussing out your problem.

I’ve found that if you can login locally but can’t from external locations, your security may need to be reset.
Nowadays, MariaDB and MySQL come with a security initialization script, you can either invoke the command directly or create an Heredoc answer file as I describe in the following link so that there is an archive of your settings (and can be re-applied easily)

https://en.opensuse.org/User:Tsu2/MySQL_and_Mariadb

TSU


 > rpm --query --whatprovides /usr/lib64/mysql/plugin/server_audit.so
mariadb-10.2.22-lp150.2.9.1.x86_64
 > 

On this system, the Server Audit plugin named as it is doesn’t raise any errors.

On the other hand, your application seems to expect a hyphenated plugin name – I’m wondering if a MariaDB/MySQL Release Note mentions this renaming of the Server Audit plugin file …

Hi,

server_audit.so is actually the right form and 15.0 packages have never had server-audit.so - your mariadb package must have originated from somewhere else (such as MariaDB itself or a 3rd party repo) or your configuration files are messed up.

1, 2 and 3 all go without errors (apart from several thousands of ‘missing’ kernel drivers with

rpm --verify --all
.
I originally installed MariaDB with
zypper in mariadb
, the used repository is
openSUSE-Leap-15.0-Update
.
To be sure, I removed MariaDB (and removed the copied server-audit.so) and installed it again.
The same problem appeared, but this time I knew what to look for and I found the real cause: in my
/etc/my.cnf
was


[mysqld]
plugin_dir=/usr/lib64/mysql/plugin/
plugin_load=server_audit=server-audit.so

After fixing this typo, MariaDB started without a hitch.
I can only think of me modifying

/etc/my.cnf
in the past without restarting MariaDB and the update from version 10.2.15 to 10.2.22 being the innocent cause of the problem becoming apparent. I will check my backups to find out when the configuration was changed.

zypper enable mariadb
puts a symlink in both
/etc/systemd/system/mysql.service
and
/etc/systemd/system/multi-user.target.wants/
.

Thank you very much for your help!

I don’t think that is the case here, the security settings are still fine. It probably has to to with the TLS settings. I want to find out first when any TLS
setting in my configuration was changed, given the cause of the server_audit.so problem. That I can’t do before Monday.

My packages originate from Leap 15.0, my configuration had an unnoticed typo, see my reply to dcurtisfra’s post.
Your suggestion was spot on (I figured it out just minutes before I read your post).
Thank you for your help.

Addendum:
The typo in my.cnf was introduced (by me) in November28, 2018 and the update merely was the trigger that made the error noticeable.
The external connections that were no longer possible must have been caused by the updater; in my.cnf the line

bind-address = 127.0.0.1

had been added. That is, that line wasn’t there the day before.
Commenting out the abovementioned line restored the external (TLS)connections, so all is well again.

Summary: I made a typo and my confidence in and admiration for openSUSE Linux and MariaDB has increased even further. Everybody who helped, thanks again!