3

So I'm having troubles starting the MariaDB service. I have tried all the suggested answers I found on the site, but I think I can't even debug it properly.

I'll tell you what happened before the problem occurs. Someone killed a proccess in MariaDB with show processlist; and kill <proccess_id>. And then that proccess went into rollback state. So they decided to restart the entire server. Once the restart completed I couldn't get the service to run anymore.

I'm using Ubuntu 18.04 and MariaDB 10.3.16 version.

The error message is Starting mysql (via systemctl): mysql.serviceJob for mariadb.service failed because a timeout was exceeded. See "systemctl status mariadb.service" and "journalctl -xe" for details.

This is the result from the systemctl status mariadb.service

mariadb.service - MariaDB 10.3.16 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 Thu 2021-02-11 18:27:37 UTC; 11min ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 5667 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 5522 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/SUCCESS)
  Process: 5515 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 5505 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
 Main PID: 5667 (code=exited, status=0/SUCCESS)

Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: FTS optimize thread exiting.
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Starting shutdown...
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Buffer pool(s) load aborted due to user instigated abort at 210211 18:27:35
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
Feb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: m2021-02-11 18:27:37 0 [Note] InnoDB: Shutdown completed; log sequence number 42815100399; transaction id 1094205
Feb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:37 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Feb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:37 0 [Note] /usr/sbin/mysqld: Shutdown complete
Feb 11 18:27:37 14499.k.time4vps.cloud systemd[1]: mariadb.service: Failed with result 'timeout'.
Feb 11 18:27:37 14499.k.time4vps.cloud systemd[1]: Failed to start MariaDB 10.3.16 database server.

And this is the result from the journalctl -xe

-- The result is RESULT.
Feb 11 18:25:37 14499.k.time4vps.cloud sudo[5425]: pam_unix(sudo:session): session closed for user root
Feb 11 18:25:52 14499.k.time4vps.cloud systemd[1]: Starting MariaDB 10.3.16 database server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mariadb.service has begun starting up.
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: To roll back: 1 transactions, 16049750 rows
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="mknod" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="wrc" denied_mask="wrc" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="file_lock" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="wk" denied_mask="wk" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="file_lock" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="wk" denied_mask="wk" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/sys/devices/system/cpu/online" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=0
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/sys/devices/system/cpu/online" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=0
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: Waiting for purge to start
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/innodb_index_stats.ibd" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=11Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="file_lock" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/innodb_index_stats.ibd" pid=5667 comm="mysqld" requested_mask="wk" denied_mask="wk" fsuFeb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/tutapi_36zYq/constant_contact_settings.ibd" pid=5667 comm="mysqld" requested_mask="wr" denied_maskFeb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="file_lock" profile="/usr/sbin/mysqld" name="/var/lib/mysql/tutapi_36zYq/constant_contact_settings.ibd" pid=5667 comm="mysqld" requested_mask="wk" deniedFeb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: 10.3.16 started; log sequence number 42815098217; transaction id 1094204
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ib_buffer_pool" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql/mariadb-bin.000217" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql/mariadb-bin.state" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:34 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:34 0 [Note] Plugin 'FEEDBACK' is disabled.
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/user.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="signal" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" requested_mask="send" denied_mask="send" signal=usr1 peer="/usr/sbin/mysqld"
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="signal" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" requested_mask="receive" denied_mask="receive" signal=usr1 peer="/usr/sbin/mysqld"
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/user.MYI" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/user.MYD" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/db.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/db.MYI" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/db.MYD" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/host.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/host.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/host.MYI" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/host.MYD" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/proxies_priv.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=1Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/proxies_priv.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=1Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/proxies_priv.MYI" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouidFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/proxies_priv.MYD" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouidFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/roles_mapping.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/roles_mapping.frm" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/roles_mapping.MYI" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouiFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/mysql/roles_mapping.MYD" pid=5667 comm="mysqld" requested_mask="wr" denied_mask="wr" fsuid=113 ouiFeb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] Server socket created on IP: '::'.
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/lib/mysql/multi-master.info" pid=5667 comm="mysqld" requested_mask="wrc" denied_mask="wrc" fsuid=113 ouid=11Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] Reading of all Master_info entries succeeded
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] Added new Master_info '' to hash table
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/dev/null" pid=5667 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=113 ouid=0
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="create" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="create" denied_mask="create" addr=nFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="getsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="getopt" denied_mask="getopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=5667 comm="mysqld" requested_mFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="create" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="create" denied_mask="create" addr=nFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="getsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="getopt" denied_mask="getopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=5667 comm="mysqld" requested_mFeb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="unlink" profile="/usr/sbin/mysqld" name="/run/mysqld/mysqld.sock" pid=5667 comm="mysqld" requested_mask="d" denied_mask="d" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] /usr/sbin/mysqld: ready for connections.
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: Version: '10.3.16-MariaDB-1:10.3.16+maria~xenial-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] Event Scheduler: Purging the queue. 0 events
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: FTS optimize thread exiting.
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="mknod" profile="/usr/sbin/mysqld" name="/var/log/mysql/mariadb-bin.state" pid=5667 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=113 ouid=113
Feb 11 18:27:35 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql/mariadb-bin.state" pid=5667 comm="mysqld" requested_mask="wrc" denied_mask="wrc" fsuid=113 ouid=11Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Starting shutdown...
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Buffer pool(s) load aborted due to user instigated abort at 210211 18:27:35
Feb 11 18:27:35 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:35 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
Feb 11 18:27:36 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="create" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="create" denied_mask="create" addr=nFeb 11 18:27:36 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="getsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="getopt" denied_mask="getopt" adFeb 11 18:27:36 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:36 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:36 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=5667 comm="mysqld" requested_mFeb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:37 0 [Note] InnoDB: Shutdown completed; log sequence number 42815100399; transaction id 1094205
Feb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="unlink" profile="/usr/sbin/mysqld" name="/var/lib/mysql/ibtmp1" pid=5667 comm="mysqld" requested_mask="d" denied_mask="d" fsuid=113 ouid=113
Feb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:37 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Feb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="unlink" profile="/usr/sbin/mysqld" name="/run/mysqld/mysqld.pid" pid=5667 comm="mysqld" requested_mask="d" denied_mask="d" fsuid=113 ouid=113
Feb 11 18:27:37 14499.k.time4vps.cloud mysqld[5667]: 2021-02-11 18:27:37 0 [Note] /usr/sbin/mysqld: Shutdown complete
Feb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="create" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="create" denied_mask="create" addr=nFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="signal" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" requested_mask="send" denied_mask="send" signal=term peer="/usr/sbin/mysqld"
Feb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="signal" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" requested_mask="receive" denied_mask="receive" signal=term peer="/usr/sbin/mysqld"
Feb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="getsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="getopt" denied_mask="getopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=5667 comm="mysqld" requested_mFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="create" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="create" denied_mask="create" addr=nFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="getsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="getopt" denied_mask="getopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="setsockopt" profile="/usr/sbin/mysqld" pid=5667 comm="mysqld" family="unix" sock_type="dgram" protocol=0 requested_mask="setopt" denied_mask="setopt" adFeb 11 18:27:37 14499.k.time4vps.cloud audit[5667]: AVC apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=5667 comm="mysqld" requested_mFeb 11 18:27:37 14499.k.time4vps.cloud systemd[1]: mariadb.service: Failed with result 'timeout'.
Feb 11 18:27:37 14499.k.time4vps.cloud systemd[1]: Failed to start MariaDB 10.3.16 database server.
-- Subject: Unit mariadb.service has failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mariadb.service has failed.

I also found something in the syslog that someone might finds useful.

Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] /usr/sbin/mysqld (mysqld 10.3.16-MariaDB-1:10.3.16+maria~xenial-log) starting as process 7371 ...
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Using Linux native AIO
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Uses event mutexes
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Number of pools: 1
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Using SSE2 crc32 instructions
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: Completed initialization of buffer pool
Feb 11 19:00:57 14499 mysqld[7371]: 2021-02-11 19:00:57 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: To roll back: 1 transactions, 16049750 rows
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: 10.3.16 started; log sequence number 42815100399; transaction id 1094204
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Feb 11 19:02:38 14499 mysqld[7371]: 2021-02-11 19:02:38 0 [Note] Plugin 'FEEDBACK' is disabled.
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] Server socket created on IP: '::'.
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] Reading of all Master_info entries succeeded
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] Added new Master_info '' to hash table
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] /usr/sbin/mysqld: ready for connections.
Feb 11 19:02:39 14499 mysqld[7371]: Version: '10.3.16-MariaDB-1:10.3.16+maria~xenial-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] Event Scheduler: Purging the queue. 0 events
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] InnoDB: FTS optimize thread exiting.
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] InnoDB: Starting shutdown...
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] InnoDB: Buffer pool(s) load aborted due to user instigated abort at 210211 19:02:39
Feb 11 19:02:39 14499 mysqld[7371]: 2021-02-11 19:02:39 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
Feb 11 19:02:41 14499 mysqld[7371]: 2021-02-11 19:02:41 0 [Note] InnoDB: Shutdown completed; log sequence number 42815100674; transaction id 1094205
Feb 11 19:02:41 14499 mysqld[7371]: 2021-02-11 19:02:41 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Feb 11 19:02:41 14499 mysqld[7371]: 2021-02-11 19:02:41 0 [Note] /usr/sbin/mysqld: Shutdown complete
Feb 11 19:02:41 14499 systemd[1]: mariadb.service: Failed with result 'timeout'.
Feb 11 19:02:41 14499 systemd[1]: Failed to start MariaDB 10.3.16 database server.

It's a pretty big log so I tried to post things around the error there were shown. I can see that something is initiating the shutdown but I'm not experienced enough to find out what. I tried the appArmory thing in the posts I read but that did nothing. Any help would be appreciated.

0
2

Ubuntu-18.04 has systemd v229.

It wasn't until v236 that systemd gained the ability to extend timeout at request of MariaDB

As such the large rollback is exceeding the default 90 second allowed service startup and systemd is oblivious as to why.

If upgrading distribution isn't an option you can increase the timeout in the systemd service for MariaDB

1
  • This is actually what did the trick for me, except I went the hard way of trying to boot-up the service god knows how many times until the rollback finished, because I noticed every time I try to start it the rollback rows kept reducing. After the rollback finished the service started without problems. – Ivan Janev Feb 12 at 11:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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