[SOLVED] Mysql error after restart

bdario70 · April 16, 2018, 3:12pm

Hello,

I’m running ERPNext VM on Virtualbox.
After a reboot mysql daemon doesn’t start anymore.

If I hit the command service mysql restart I get the following error in /var/log/syslog:

Apr 16 15:02:05 ubuntu systemd[1]: Starting MariaDB 10.2.14 database server...
Apr 16 15:02:05 ubuntu mysqld[3591]: 2018-04-16 15:02:05 140493702396096 [Note] /usr/sbin/mysqld (mysqld 10.2.14-Ma
riaDB-10.2.14+maria~xenial-log) starting as process 3591 ...
Apr 16 15:02:05 ubuntu mysqld[3591]: 2018-04-16 15:02:05 140493702396096 [Warning] Could not increase number of max
_open_files to more than 16364 (request: 20991)
Apr 16 15:02:07 ubuntu systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 16 15:02:07 ubuntu systemd[1]: Failed to start MariaDB 10.2.14 database server.
Apr 16 15:02:07 ubuntu systemd[1]: mariadb.service: Unit entered failed state.
Apr 16 15:02:07 ubuntu systemd[1]: mariadb.service: Failed with result 'exit-code'.

When I hit bench mysql I get the following error:
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)

How to solve it? Thanks

Dario

bdario70 · April 16, 2018, 3:22pm

I also tried to run systemctl status mariadb.service

and this is the answer i get:

root@ubuntu:~# systemctl status mariadb.service
● mariadb.service - MariaDB 10.2.14 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: exit-code) since Mon 2018-04-16 15:20:17 UTC; 14s ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 4559 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=1/FAILURE)
  Process: 4269 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=
  Process: 4260 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 4257 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
 Main PID: 4559 (code=exited, status=1/FAILURE)
   Status: "MariaDB server is down"

Apr 16 15:20:14 ubuntu systemd[1]: Starting MariaDB 10.2.14 database server...
Apr 16 15:20:15 ubuntu mysqld[4559]: 2018-04-16 15:20:15 139814115379392 [Note] /usr/sbin/mysqld (mysqld 10.2.14-MariaDB-10.2.14+maria~xenial-log) starting as process 4559 ...
Apr 16 15:20:15 ubuntu mysqld[4559]: 2018-04-16 15:20:15 139814115379392 [Warning] Could not increase number of max_open_files to more than 16364 (request: 20991)
Apr 16 15:20:17 ubuntu systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 16 15:20:17 ubuntu systemd[1]: Failed to start MariaDB 10.2.14 database server.
Apr 16 15:20:17 ubuntu systemd[1]: mariadb.service: Unit entered failed state.
Apr 16 15:20:17 ubuntu systemd[1]: mariadb.service: Failed with result 'exit-code'.

bdario70 · April 16, 2018, 3:34pm

this is the result of the command journalctl -xe

root@ubuntu:~# journalctl -xe
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,028 INFO spawned: 'frappe-bench-frappe-short-worker-0' with pid 1806
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,034 INFO spawned: 'frappe-bench-frappe-web' with pid 1807
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,058 INFO spawned: 'frappe-bench-node-socketio' with pid 1808
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,062 INFO spawned: 'frappe-bench-redis-queue' with pid 1809
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,094 INFO spawned: 'frappe-bench-redis-cache' with pid 1810
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,102 INFO spawned: 'frappe-bench-redis-socketio' with pid 1811
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,283 INFO success: frappe-bench-frappe-default-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (s
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,283 INFO success: frappe-bench-frappe-schedule entered RUNNING state, process has stayed up for > than 1 seconds (startsecs
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,284 INFO success: frappe-bench-frappe-long-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (star
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,284 INFO success: frappe-bench-frappe-short-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (sta
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-frappe-web entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-node-socketio entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-redis-queue entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,286 INFO success: frappe-bench-redis-cache entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,286 INFO success: frappe-bench-redis-socketio entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu sudo[1842]:   frappe : TTY=pts/0 ; PWD=/home/frappe ; USER=root ; COMMAND=/bin/su -
Apr 16 15:27:29 ubuntu sudo[1842]: pam_unix(sudo:session): session opened for user root by frappe(uid=0)
Apr 16 15:27:29 ubuntu su[1843]: Successful su for root by root
Apr 16 15:27:29 ubuntu su[1843]: + /dev/pts/0 root:root
Apr 16 15:27:29 ubuntu su[1843]: pam_unix(su:session): session opened for user root by frappe(uid=0)
Apr 16 15:27:29 ubuntu su[1843]: pam_systemd(su:session): Cannot create session: Already running in a session
Apr 16 15:32:12 ubuntu systemd[1]: Starting MariaDB 10.2.14 database server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has begun starting up.
Apr 16 15:32:12 ubuntu mysqld[2497]: 2018-04-16 15:32:12 139974933432512 [Note] /usr/sbin/mysqld (mysqld 10.2.14-MariaDB-10.2.14+maria~xenial-log) starting as process 2497 ...
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 16 15:32:14 ubuntu systemd[1]: Failed to start MariaDB 10.2.14 database server.
-- Subject: Unit mariadb.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has failed.
--
-- The result is failed.
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Unit entered failed state.
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Failed with result 'exit-code'.
lines 1653-1691/1691 (END)
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,028 INFO spawned: 'frappe-bench-frappe-short-worker-0' with pid 1806
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,034 INFO spawned: 'frappe-bench-frappe-web' with pid 1807
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,058 INFO spawned: 'frappe-bench-node-socketio' with pid 1808
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,062 INFO spawned: 'frappe-bench-redis-queue' with pid 1809
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,094 INFO spawned: 'frappe-bench-redis-cache' with pid 1810
Apr 16 15:27:28 ubuntu supervisord[1749]: 2018-04-16 15:27:28,102 INFO spawned: 'frappe-bench-redis-socketio' with pid 1811
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,283 INFO success: frappe-bench-frappe-default-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,283 INFO success: frappe-bench-frappe-schedule entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,284 INFO success: frappe-bench-frappe-long-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,284 INFO success: frappe-bench-frappe-short-worker-0 entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-frappe-web entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-node-socketio entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,285 INFO success: frappe-bench-redis-queue entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,286 INFO success: frappe-bench-redis-cache entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu supervisord[1749]: 2018-04-16 15:27:29,286 INFO success: frappe-bench-redis-socketio entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Apr 16 15:27:29 ubuntu sudo[1842]:   frappe : TTY=pts/0 ; PWD=/home/frappe ; USER=root ; COMMAND=/bin/su -
Apr 16 15:27:29 ubuntu sudo[1842]: pam_unix(sudo:session): session opened for user root by frappe(uid=0)
Apr 16 15:27:29 ubuntu su[1843]: Successful su for root by root
Apr 16 15:27:29 ubuntu su[1843]: + /dev/pts/0 root:root
Apr 16 15:27:29 ubuntu su[1843]: pam_unix(su:session): session opened for user root by frappe(uid=0)
Apr 16 15:27:29 ubuntu su[1843]: pam_systemd(su:session): Cannot create session: Already running in a session
Apr 16 15:32:12 ubuntu systemd[1]: Starting MariaDB 10.2.14 database server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has begun starting up.
Apr 16 15:32:12 ubuntu mysqld[2497]: 2018-04-16 15:32:12 139974933432512 [Note] /usr/sbin/mysqld (mysqld 10.2.14-MariaDB-10.2.14+maria~xenial-log) starting as process 2497 ...
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
Apr 16 15:32:14 ubuntu systemd[1]: Failed to start MariaDB 10.2.14 database server.
-- Subject: Unit mariadb.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has failed.
--
-- The result is failed.
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Unit entered failed state.
Apr 16 15:32:14 ubuntu systemd[1]: mariadb.service: Failed with result 'exit-code'.

keshav · April 16, 2018, 3:49pm

How much RAM & Diskspace have you allocated to your VM?

bdario70 · April 17, 2018, 7:24am

Hello @keshav, thank you for your reply.

Base memory is 4 GB. 4x CPU.

Storage virtual size is approx 40 GB dynamically allocated but actual size is approx 6.2 GB.

This is the output of the command df -h

root@ubuntu:~# df -h
Filesystem                   Size  Used Avail Use% Mounted on
udev                         478M     0  478M   0% /dev
tmpfs                        100M  3.1M   97M   4% /run
/dev/mapper/ubuntu--vg-root   37G  5.6G   30G  16% /
tmpfs                        497M     0  497M   0% /dev/shm
tmpfs                        5.0M     0  5.0M   0% /run/lock
tmpfs                        497M     0  497M   0% /sys/fs/cgroup
/dev/sda1                    472M   56M  393M  13% /boot
tmpfs                        100M     0  100M   0% /run/user/900

Thanks, Dario

bdario70 · April 17, 2018, 8:43am

Hello,

I’ve SOLVED the issue by myself, I’d like to share the solution with the community.
This post helped me to SOLVE the issue:

I’ve found the following error in /var/lib/mysql/mysql-error.log

2018-04-16 16:22:15 140293027571904 [ERROR] Found 1 prepared transactions! It means that mysqld was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a crash. You have to start mysqld with --tc-heuristic-recover switch to commit or rollback pending transactions.
2018-04-16 16:22:15 140293027571904 [ERROR] Aborting

Then I followed the instruction listed in the above post so I hit the following command:
mysqld --tc-heuristic-recover=ROLLBACK

and then
service mysql start

And everything started to work again.

Thanks for your help

Dario