Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Duplicate
-
Affects Version/s: 10.0.16
-
Fix Version/s: N/A
-
Component/s: Scripts & Clients
-
Labels:
-
Environment:SLES-12, x86_64
Description
MariaDB - mysqld cannot start when restarting from systemd
s390vsl048:~/tmpmariadb # systemctl restart mysql.service s390vsl048:~/tmpmariadb # mysql -u ssluser -pssluser -D test --ssl-cipher=DHE-RSA-AES256-SHA:AES128-SHA --ssl-ca=/etc/mysql/certs/ca-cert.pem --ssl-cert=/etc/mysql/certs/client-cert.pem --ssl-key=/etc/mysql/certs/client-key.pem ERROR 2013 (HY000): Lost connection to MySQL server at 'reading initial communication packet', system error: 104 "Connection reset by peer"
s390vsl048:~/tmpmariadb # systemctl status mysql.service mysql.service - LSB: Start the MySQL database server Loaded: loaded (/etc/init.d/mysql) Active: active (exited) since Fri 2015-03-06 17:57:33 CET; 3min 21s ago Process: 6875 ExecStop=/etc/init.d/mysql stop (code=exited, status=0/SUCCESS) Process: 6942 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS) Mar 06 17:57:33 s390vsl048 mysql[6942]: Starting service MySQL Starting service MySQL ..done
s390vsl048:~/tmpmariadb # systemctl restart mysql.service Job for mysql.service failed. See "systemctl status mysql.service" and "journalctl -xn" for details.
s390vsl048:~/tmpmariadb # journalctl -xn -- Logs begin at Fri 2015-03-06 17:46:11 CET, end at Fri 2015-03-06 18:01:30 CET. -- Mar 06 17:57:33 s390vsl048 mysql[6942]: Starting service MySQL Starting service MySQL ..done Mar 06 18:00:01 s390vsl048 kernel: type=1006 audit(1425661201.794:45): pid=7221 uid=0 old auid=4294967295 new auid=0 old ses=4294967295 new ses=4 res=1 Mar 06 18:00:01 s390vsl048 cron[7221]: pam_unix(crond:session): session opened for user root by (uid=0) Mar 06 18:00:01 s390vsl048 CRON[7221]: pam_unix(crond:session): session closed for user root Mar 06 18:01:30 s390vsl048 systemd[1]: Stopping LSB: Start the MySQL database server... -- Subject: Unit mysql.service has begun shutting down -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mysql.service has begun shutting down. Mar 06 18:01:30 s390vsl048 mysql[7289]: Shutting down service MySQL ..done Mar 06 18:01:30 s390vsl048 mysql[7318]: Starting service MySQL Starting service MySQL chmod: cannot access '/var/run/mysql/mysqld.pid': No such file or directory Mar 06 18:01:30 s390vsl048 systemd[1]: Failed to start LSB: Start the MySQL database server. -- Subject: Unit mysql.service has failed -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mysql.service has failed. -- -- The result is failed. Mar 06 18:01:30 s390vsl048 systemd[1]: Unit mysql.service entered failed state. Mar 06 18:01:30 s390vsl048 mysql[7318]: ..failed
== mysqld.log ==
150306 17:57:32 [Note] /usr/sbin/mysqld: Shutdown complete 150306 17:57:32 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 150306 17:57:32 [Note] InnoDB: Using mutexes to ref count buffer pool pages 150306 17:57:32 [Note] InnoDB: The InnoDB memory heap is disabled 150306 17:57:32 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 150306 17:57:32 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 150306 17:57:32 [Note] InnoDB: Compressed tables use zlib 1.2.8 150306 17:57:32 [Note] InnoDB: Using Linux native AIO 150306 17:57:32 [Note] InnoDB: Not using CPU crc32 instructions 150306 17:57:32 [Note] InnoDB: Initializing buffer pool, size = 128.0M 150306 17:57:32 [Note] InnoDB: Completed initialization of buffer pool 150306 17:57:32 [Note] InnoDB: Highest supported file format is Barracuda. 150306 17:57:33 [Note] InnoDB: 128 rollback segment(s) are active. 150306 17:57:33 [Note] InnoDB: Waiting for purge to start 150306 17:57:33 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.22-71.0 started; log sequence number 1616797 150306 17:57:33 [Note] Server socket created on IP: '::'. 150306 17:57:33 [Note] Event Scheduler: Loaded 0 events 150306 17:57:33 [Note] /usr/sbin/mysqld: ready for connections. Version: '10.0.16-MariaDB' socket: '/var/run/mysql/mysql.sock' port: 3306 openSUSE package 150306 17:57:33 mysqld_safe Number of processes running now: 1 150306 17:57:33 mysqld_safe mysqld process hanging, pid 7111 - killed 150306 17:57:33 mysqld_safe mysqld restarted 150306 17:57:33 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds 150306 17:57:34 mysqld_safe mysqld from pid file /var/run/mysql/mysqld.pid ended 150306 17:57:35 [Note] InnoDB: Using mutexes to ref count buffer pool pages 150306 17:57:35 [Note] InnoDB: The InnoDB memory heap is disabled 150306 17:57:35 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 150306 17:57:35 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 150306 17:57:35 [Note] InnoDB: Compressed tables use zlib 1.2.8 150306 17:57:35 [Note] InnoDB: Using Linux native AIO 150306 17:57:35 [Note] InnoDB: Not using CPU crc32 instructions 150306 17:57:35 [ERROR] mysqld: Can't create/write to file '/var/tmp/mysql.DjJntU/ibuao7B9' (Errcode: 2 "No such file or directory") 2015-03-06 17:57:35 3fffd051730 InnoDB: Error: unable to create temporary file; errno: 2 150306 17:57:35 [ERROR] Plugin 'InnoDB' init function returned error. 150306 17:57:35 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 150306 17:57:35 [ERROR] Unknown/unsupported storage engine: InnoDB 150306 17:57:35 [ERROR] Aborting 150306 17:57:35 [Note] /usr/sbin/mysqld: Shutdown complete
Workaround: - use stop and start
================================
s390vsl048:~/tmpmariadb # systemctl stop mysql.service s390vsl048:~/tmpmariadb # systemctl status mysql.service mysql.service - LSB: Start the MySQL database server Loaded: loaded (/etc/init.d/mysql) Active: failed (Result: exit-code) since Fri 2015-03-06 18:01:30 CET; 54s ago Process: 7289 ExecStop=/etc/init.d/mysql stop (code=exited, status=0/SUCCESS) Process: 7318 ExecStart=/etc/init.d/mysql start (code=exited, status=1/FAILURE) Mar 06 18:01:30 s390vsl048 mysql[7318]: Starting service MySQL Starting service MySQL chmod: cannot access '/var/run/mysql/mysqld.pid': No such file or directory Mar 06 18:01:30 s390vsl048 systemd[1]: Failed to start LSB: Start the MySQL database server. Mar 06 18:01:30 s390vsl048 systemd[1]: Unit mysql.service entered failed state. Mar 06 18:01:30 s390vsl048 mysql[7318]: ..failed
s390vsl048:~/tmpmariadb # systemctl start mysql.service
s390vsl048:~/tmpmariadb # systemctl status mysql.service
mysql.service - LSB: Start the MySQL database server
Loaded: loaded (/etc/init.d/mysql)
Active: active (running) since Fri 2015-03-06 18:02:29 CET; 1s ago
Process: 7289 ExecStop=/etc/init.d/mysql stop (code=exited, status=0/SUCCESS)
Process: 7542 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS)
CGroup: /system.slice/mysql.service
|-7366 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql...
`-7487 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-fil...
Mar 06 18:02:29 s390vsl048 mysql[7542]: ..done
s390vsl048:~/tmpmariadb # mysql -u ssluser -pssluser -D test --ssl-cipher=DHE-RSA-AES256-SHA:AES128-SHA --ssl-ca=/etc/mysql/certs/ca-cert.pem --ssl-cert=/etc/mysql/certs/client-cert.pem --ssl-key=/etc/mysql/certs/client-key.pem
Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 2
Server version: 10.0.16-MariaDB openSUSE package
Note:
Cannot reproduce on every system but looks like on s390 is 100 reproducible.
Gliffy Diagrams
Attachments
Issue Links
- is part of
-
MDEV-427 Provide a systemd script for MariaDB
-
- In Review
-
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Hi Elena,
(sorry for late answer)
Yes it is still happening:
s390vsl020:~/tmpmariadb # systemctl restart mysql.service Job for mysql.service failed. See "systemctl status mysql.service" and "journalctl -xn" for details. s390vsl020:~/tmpmariadb # systemctl status mysql.service mysql.service - LSB: Start the MySQL database server Loaded: loaded (/etc/init.d/mysql) Active: failed (Result: exit-code) since Wed 2015-04-15 11:39:41 CEST; 9s ago Process: 32954 ExecStop=/etc/init.d/mysql stop (code=exited, status=0/SUCCESS) Process: 32981 ExecStart=/etc/init.d/mysql start (code=exited, status=1/FAILURE) Apr 15 11:39:41 s390vsl020 mysql[32981]: Starting service MySQL Starting service MySQL chmod: cannot access '/var/run/mysql/mysqld.pid': No such file or directory Apr 15 11:39:41 s390vsl020 systemd[1]: Unit mysql.service entered failed state. Apr 15 11:39:41 s390vsl020 mysql[32981]: ..failed s390vsl020:~/tmpmariadb # journalctl -xn -- Logs begin at Thu 2015-04-09 16:18:57 CEST, end at Wed 2015-04-15 11:39:41 CEST. -- Apr 15 11:30:01 s390vsl020 CRON[32475]: pam_unix(crond:session): session closed for user root Apr 15 11:38:49 s390vsl020 systemd[1]: Configuration file /usr/lib/systemd/system/wdmd.service is marked executable. Please remove executable permission bits. Proceeding anyway. Apr 15 11:38:56 s390vsl020 systemd[1]: Stopping LSB: Start the MySQL database server... -- Subject: Unit mysql.service has begun shutting down -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mysql.service has begun shutting down. Apr 15 11:38:58 s390vsl020 mysql[32677]: Shutting down service MySQL ..done Apr 15 11:38:58 s390vsl020 mysql[32727]: Starting service MySQL Starting service MySQL ..done Apr 15 11:39:40 s390vsl020 systemd[1]: Stopping LSB: Start the MySQL database server... -- Subject: Unit mysql.service has begun shutting down -- Defined-By: systemd -- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel -- -- Unit mysql.service has begun shutting down. Apr 15 11:39:40 s390vsl020 mysql[32954]: Shutting down service MySQL ..done Apr 15 11:39:41 s390vsl020 mysql[32981]: Starting service MySQL Starting service MySQL chmod: cannot access '/var/run/mysql/mysqld.pid': No such file or directory Apr 15 11:39:41 s390vsl020 systemd[1]: Unit mysql.service entered failed state. Apr 15 11:39:41 s390vsl020 mysql[32981]: ..failed s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33193 29773 0 11:41 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33211 29773 0 11:42 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33215 29773 0 11:42 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33219 29773 0 11:42 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33222 29773 0 11:42 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # ps -ef | grep mysqld root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33226 29773 0 11:43 pts/0 00:00:00 grep --color=auto mysqld s390vsl020:~/tmpmariadb # date;ps -ef | grep mysqld Wed Apr 15 11:43:22 CEST 2015 root 33031 1 0 11:39 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --mysqld=mysqld --user=mysql --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock --datadir=/var/lib/mysql mysql 33140 33031 0 11:39 ? 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/mysqld.log --pid-file=/var/run/mysql/mysqld.pid --socket=/var/run/mysql/mysql.sock root 33234 29773 0 11:43 pts/0 00:00:00 grep --color=auto mysqld
Also I was suspicious before, it can be related to setting up ssl connection - like creating new ssl user, generating certificates, opening session as ssl user etc.
After that I saw this problem.
And last time after the reboot of machine I could not reproduce it again.
(however I may be wrong)
So, there is nothing wrong with the actual server startup, mysqld_safe starts once, survives, and starts mysqld which also survives. The whole problem is simply the service script not being able to chmod on the pid file, apparently because the pid file doesn't get created in time.
I don't know if it can be related to SSL – I suppose hypothetically it's possible if some SSL-related activity happens upon startup before creating the pid file, thus delaying it a little bit. I didn't check it though.
Daniel's changes look rather invasive, I don't know if they'll make it to the 10.0 which is well post-GA.
On the other hand, this particular problem can probably have a simple workaround. Currently chmod on the pid file is the very last thing the service script does, then it exits with the status of the operation. While with the socket file there is a wait, and even after the wait its absence is not considered an error, with the pid file it's much simpler – a single attempt to chmod and then exit. I suppose adding at least a timed wait on the pid file should highly reduce the probability of the failure, if not eliminate it completely.
Daniel's changes look rather invasive
Predominately in the socket activation mode of systemd.
Removing 'Requires=%p.socket' from the mariadb.service would make this run in the Type=Notify mode which also bypasses the pid file/mysqld_safe issues and all of the socket activation code (https://github.com/MariaDB/server/pull/26/files#diff-e7d51f293adc9257284fbdec858056dfR6149 because sd_listen_fds() return 0). The storage engine notify commands could also be removed from 10.0 if this is too much.
some SSL-related activity happens upon startup before creating the pid file, thus delaying it a little bit. I didn't check it though.
init_ssl is called in mysqd just before the bit that creates the pid. While it initializes a few variables and reads the ssl server side key/certs it doesn't seem to be that intensive.
The whole problem is simply the service script not being able to chmod on the pid file, apparently because the pid file doesn't get created in time
Looks like it too me too. And why is it doing a chmod on a pid file anyway? No idea.
As far as I understand, it's not a MariaDB bug, both mysqld and mysqld_safe work correctly. This is an issue with the systemd service script, but we do not have systemd service script (yet). You're having a problem with a third-party systemd service script, we cannot fix it.
But there is MDEV-427 which is about a native MariaDB systemd support. When it will be released, you will be able to use our systemd service script, which will not have this issue.
https://github.com/MariaDB/server/pull/26 changes the service definition to avoid pid files
probably needs galera related socket activation for the galera ports. I'm tempted to wait until the first part is merged.