2

My Mariadb version is

$ mysql -V
mysql  Ver 15.1 Distrib 10.3.23-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

My machine is a ubuntu server:

$ uname -a
Linux mypc 5.4.0-42-generic #46-Ubuntu SMP Fri Jul 10 00:24:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

When I run it, I get

$ sudo systemctl start mysql

Job for mariadb.service failed because a timeout was exceeded.
See "systemctl status mariadb.service" and "journalctl -xe" for details.

I have no clue what the logs mean. It runs for a few seconds and then tries shutting down the database server with a timeout. During the timeout, I can even connect to the database via

mysql -u root

no problem, but I know something is failing and shutting down the db server.

I follow the instructions:

when running

systemctl status mariadb.service

, I get

● mariadb.service - MariaDB 10.3.23 database server
     Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mariadb.service.d
             └─migrated-from-my.cnf-settings.conf
     Active: failed (Result: timeout) since Fri 2020-08-07 08:16:58 UTC; 8min ago
       Docs: man:mysqld(8)
             https://mariadb.com/kb/en/library/systemd/
    Process: 19512 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
    Process: 19516 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
    Process: 19526 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/SUCCESS)
    Process: 19577 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=0/SUCCESS)
   Main PID: 19577 (code=exited, status=0/SUCCESS)

Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: FTS optimize thread exiting.
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] Event Scheduler: Purging the queue. 0 events
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Starting shutdown...
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Buffer pool(s) dump completed at 200807  8:16:57
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] InnoDB: Shutdown completed; log sequence number 1701105; transaction id 167
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] /usr/sbin/mysqld: Shutdown complete
Aug 07 08:16:58 mypc systemd[1]: mariadb.service: Failed with result 'timeout'.
Aug 07 08:16:58 mypc systemd[1]: Failed to start MariaDB 10.3.23 database server.

and when running

journalctl -xe

, it gives me this:

Aug 07 08:16:34 mypc sudo[19509]: pam_unix(sudo:auth): Couldn't open /etc/securetty: No such file or directory
Aug 07 08:16:37 mypc sudo[19509]: pam_unix(sudo:auth): Couldn't open /etc/securetty: No such file or directory
Aug 07 08:16:37 mypc sudo[19509]:       me : TTY=pts/0 ; PWD=/etc/apache2/sites-available ; USER=root ; COMMAND=/usr/bin/systemctl start mysql
Aug 07 08:16:37 mypc sudo[19509]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 07 08:16:37 mypc systemd[1]: Starting MariaDB 10.3.23 database server...
-- Subject: A start job for unit mariadb.service has begun execution
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- A start job for unit mariadb.service has begun execution.
-- 
-- The job identifier is 5094.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] /usr/sbin/mysqld (mysqld 10.3.23-MariaDB-1:10.3.23+maria~bionic) starting as process 19577 ...
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Warning] Could not increase number of max_open_files to more than 16364 (request: 32183)
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Using Linux native AIO
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Uses event mutexes
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Number of pools: 1
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Using SSE2 crc32 instructions
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Completed initialization of buffer pool
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Waiting for purge to start
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: 10.3.23 started; log sequence number 1701096; transaction id 166
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Creating #1 encryption thread id 139817862018816 total threads 4.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Creating #2 encryption thread id 139817853626112 total threads 4.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Creating #3 encryption thread id 139817845233408 total threads 4.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Creating #4 encryption thread id 139817560045312 total threads 4.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] Plugin 'FEEDBACK' is disabled.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] Using encryption key id 1 for temporary files
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] InnoDB: Buffer pool(s) load completed at 200807  8:16:37
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] Server socket created on IP: '::'.
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] Reading of all Master_info entries succeeded
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] Added new Master_info '' to hash table
Aug 07 08:16:37 mypc mysqld[19577]: 2020-08-07  8:16:37 0 [Note] /usr/sbin/mysqld: ready for connections.
Aug 07 08:16:37 mypc mysqld[19577]: Version: '10.3.23-MariaDB-1:10.3.23+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
Aug 07 08:16:37 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:37 mypc kernel: audit: type=1400 audit(1596788197.855:100): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc systemd[1]: mariadb.service: start operation timed out. Terminating.
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.615:101): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: FTS optimize thread exiting.
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] Event Scheduler: Purging the queue. 0 events
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Starting shutdown...
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc mysqld[19577]: 2020-08-07  8:16:57 0 [Note] InnoDB: Buffer pool(s) dump completed at 200807  8:16:57
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.643:102): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.743:103): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.843:104): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.943:105): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:57 mypc kernel: audit: type=1400 audit(1596788217.947:106): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] InnoDB: Shutdown completed; log sequence number 1701105; transaction id 167
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Aug 07 08:16:58 mypc mysqld[19577]: 2020-08-07  8:16:58 0 [Note] /usr/sbin/mysqld: Shutdown complete
Aug 07 08:16:58 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:58 mypc audit[19577]: AVC apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:58 mypc kernel: audit: type=1400 audit(1596788218.683:107): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:58 mypc kernel: audit: type=1400 audit(1596788218.683:108): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=19577 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=129 ouid=0
Aug 07 08:16:58 mypc systemd[1]: mariadb.service: Failed with result 'timeout'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- The unit mariadb.service has entered the 'failed' state with result 'timeout'.
Aug 07 08:16:58 mypc systemd[1]: Failed to start MariaDB 10.3.23 database server.
-- Subject: A start job for unit mariadb.service has failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- A start job for unit mariadb.service has finished with a failure.
-- 
-- The job identifier is 5094 and the job result is failed.
Aug 07 08:16:58 mypc sudo[19509]: pam_unix(sudo:session): session closed for user root
Aug 07 08:17:01 mypc CRON[19633]: pam_unix(cron:session): session opened for user root by (uid=0)
Aug 07 08:17:01 mypc CRON[19634]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 07 08:17:01 mypc CRON[19633]: pam_unix(cron:session): session closed for user root
Aug 07 08:17:06 mypc kernel: [UFW BLOCK] IN=enp0s3 OUT= MAC=01:00:5e:00:00:01:80:20:da:7f:64:43:08:00 SRC=192.168.0.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0x00 TTL=1 ID=0 DF PROTO=2

Configs:

/etc/mysql/mysql.cnf

...

!includedir /etc/mysql/conf.d/
!includedir /etc/mysql/mysql.conf.d/

[mysqld]
early-plugin-load="keyring_file.so"

and

/etc/mysql/my.cnf

!includedir /etc/mysql/conf.d/

[mysqld]
#early-plugin-load="keyring_file.so"
# at-rest encryption
plugin_load_add              = file_key_management
file_key_management_filename = /etc/mysql/rest/keyfile.enc
file_key_management_filekey  = FILE:/etc/mysql/rest/keyfile.passwd
file_key_management_encryption_algorithm = AES_CBC
 
innodb_encrypt_tables            = ON
innodb_encrypt_temporary_tables  = ON
innodb_encrypt_log               = ON
innodb_encryption_threads        = 4
innodb_encryption_rotate_key_age = 1
encrypt-tmp-disk-tables          = 1
encrypt-tmp-files                = 1
encrypt-binlog                   = 1
aria_encrypt_tables              = ON

I removed all encryption related config lines and ran

sudo systemctl start mysql

It did not help.

Improve this question

1 Answer 1

Reset to default
2

It appears you're having issues with apparmor, still loading the MySQL apparmor profile.

According to this page, MariaDB's recommendation is to disable the mysqld profile like so:

$ sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
$ sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld 

# Verify
$ sudo aa-status

It seems that MariaDB recommends not running MariaDB with an apparmor profile:

# This file is intensionally [sic] empty to disable apparmor by default for newer
# versions of MariaDB, while providing seamless upgrade from older versions
# and from mysql, where apparmor is used.
#
# By default, we do not want to have any apparmor profile for the MariaDB
# server. It does not provide much useful functionality/security, and causes
# several problems for users who often are not even aware that apparmor
# exists and runs on their system.
#
# Users can modify and maintain their own profile, and in this case it will
# be used.
#
# When upgrading from previous version, users who modified the profile
# will be promptet to keep or discard it, while for default installs
# we will automatically disable the profile.
Improve this answer
1
  • Good answer (Welcome back), Derek !!! +1
    – RolandoMySQLDBA
    Aug 7, 2020 at 15:41

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.