MySQL Bugs: #41908: Trying to start MySQL while another instance is starting: confusing error messag

Bug #41908	Trying to start MySQL while another instance is starting: confusing error messag
Submitted:	7 Jan 2009 2:33	Modified:	6 Jan 2017 19:33
Reporter:	Roel Van de Paar	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: General	Severity:	S3 (Non-critical)
Version:	5.0, 5.1, 6.0 bzr	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	InnoDB Crash, innodb recovery, pid, pid file

Description:
MySQL creates the pid file after InnoDB init (Confirmed via log file delete test and an strace)

Harrison also verified that in the code the pid file is created after network listening starts which is after InnoDB (and other initialization)

This gives an issue when InnoDB is doing crash recovery and/or log file re-creation, and at the same time a second instance is started using mysqld_safe;

mysqld_safe checks for a pid file, does not find one and starts a second instance. 

Although it is not able to lock the InnoDB files (as they are in use), it creates a 'messy' situation.

It also gives issues for users when they have a daemon monitoring tool that checks for pid existence and restarts the process if none is found.

How to repeat:
Issue a large insert query to a InnoDB table, kill -9 mysqld while transaction is writing to InnoDB table on disk, restart using mysqld_safe (InnoDB recovery will start), start second instance using mysqld_safe while InnoDB recovery is in progress.

Suggested fix:
Review why it necessary for the pid file to be created after InnoDB. If possible to change, create pid first.

Thank you for the report.

Verified as described.

How to repeat.

Create test file:

--source include/have_innodb.inc
select 1;

Run ./mysql-test-run.pl --record --force bug41908 --manual-gdb

In gdb: b my_create

First run completes. Don't leave gdb, then run test again. Type `run` in gdb, then check be sure pid file creates after InnoDB data and log files:

(gdb) run
Starting program: /Users/apple/bzr/mysql-5.0/sql/mysqld --no-defaults --basedir=/Users/apple/bzr/mysql-5.0/mysql-test --character-sets-dir=/Users/apple/bzr/mysql-5.0/sql/share/charsets --secure-file-priv=/Users/apple/bzr/mysql-5.0/mysql-test/var --log-bin-trust-function-creators --default-character-set=latin1 --language=/Users/apple/bzr/mysql-5.0/sql/share/english --tmpdir=/Users/apple/bzr/mysql-5.0/mysql-test/var/tmp --connect-timeout=60 --pid-file=/Users/apple/bzr/mysql-5.0/mysql-test/var/run/master.pid --port=9306 --socket=/Users/apple/bzr/mysql-5.0/mysql-test/var/tmp/master.sock --datadir=/Users/apple/bzr/mysql-5.0/mysql-test/var/master-data --log=/Users/apple/bzr/mysql-5.0/mysql-test/var/log/master.log --log-slow-queries=/Users/apple/bzr/mysql-5.0/mysql-test/var/log/master-slow.log --log-bin=/Users/apple/bzr/mysql-5.0/mysql-test/var/log/master-bin --server-id=1 --innodb_data_file_path=ibdata1:10M:autoextend --local-infile --skip-ndbcluster --key_buffer_size=1M --sort_buffer=256K --max_heap_table_size=1M --ssl-ca=/Users/apple/bzr/mysql-5.0/mysql-test/std_data/cacert.pem --ssl-cert=/Users/apple/bzr/mysql-5.0/mysql-test/std_data/server-cert.pem --ssl-key=/Users/apple/bzr/mysql-5.0/mysql-test/std_data/server-key.pem --gdb --core-file --open-files-limit=1024
Reading symbols for shared libraries . done
Error in re-setting breakpoint 1:
Function "mysql_parse" not defined.

Breakpoint 2, my_create (FileName=0xbfffe778 "/Users/apple/bzr/mysql-5.0/mysql-test/var/master-data/apple.lower-test", CreateFlags=438, access_flags=2, MyFlags=0) at my_create.c:39
39        DBUG_ENTER("my_create");
(gdb) c
Continuing.
Current language:  auto; currently c
090113 13:29:30 [Warning] Setting lower_case_table_names=2 because file system for /Users/apple/bzr/mysql-5.0/mysql-test/var/master-data/ is case insensitive
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
090113 13:29:31  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
090113 13:29:32  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
090113 13:29:32  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
090113 13:29:33  InnoDB: Started; log sequence number 0 0
[Switching to process 9245 thread 0x2803]

Breakpoint 2, my_create (FileName=0x5a4320 "/Users/apple/bzr/mysql-5.0/mysql-test/var/run/master.pid", CreateFlags=436, access_flags=1025, MyFlags=16) at my_create.c:39
39        DBUG_ENTER("my_create");
(gdb)

The creation of the pid file is one of the last steps in the server start because writing a new pid file will overwrite any previous value and, hence, the server needs to be sure that it can bind ports and install signal handlers before writing to or overwriting a old pid file.

This is done this way because there are cases where the pid file is left around (server crahses) and the server wouldn't be able to re-start by it self if the pid file is not overwritten (but only overwrites it if can bind ports, etc).

I'm inclined to close this as Won't fix. What is exactly the "messy" situation?

InnoDB: Operating system error number 32 in a file operation.

Attachment: os_error_32.txt (text/plain), 7.27 KiB.

InnoDB: Starting crash recovery.

Attachment: crash_recovery_1.txt (text/plain), 3.57 KiB.

090312 14:57:16 - mysqld got exception 0xc0000005 ; / 090312 14:57:16 InnoDB: Assertion failure in thread 6572 in file G: ...

Attachment: crash1.txt (text/plain), 7.21 KiB.

> I'm inclined to close this as Won't fix. What is exactly the "messy" situation?

If a server is doing InnoDB crash recovery and/or log file re-creation, a second server instance can be started since there is no pid file there yet (as it only gets created *after* InnoDB crash recovery and/or log file re-creation is complete).

I did some more testing on this in Windows with 5.1.31:

o Shutdown server if running
o Move existing ib* files out of the directory they are in
o Set following my.ini[/cnf] setting:

  [mysqld]
  innodb_data_file_path=ibdata1:700M;ibdata2:200M:autoextend
  
o Start 2 consoles, and start mysqld in both of them. 
  
In most cases, one instance will start creating the innodb, the other will give OS error 32's:
http://bugs.mysql.com/file.php?id=11749

Usually, neither of the 2 instances will exit, though this is not always so:

Another time when testing (without a mysql db installed) I got this InnoDB crash recovery:
http://bugs.mysql.com/file.php?id=11750

and both instances exited.

During yet another test, at some point one of the 2 instances crashed. I was able to recreate the crash once more, but not after a system restart.

Here's the output from the crash:
http://bugs.mysql.com/file.php?id=11751

Also notice the following in the crash log (I have no G drive, this is from the developer or builder's machine):
090312 14:57:16  InnoDB: Assertion failure in thread 6572 in file G:\mysql-5.1.31-winbuild\mysql-community-nt-5.1.31-build\storage\innobase\include\buf0buf.ic line 264

See also similar bug #23790, "Calling mysqld while another instance is running, removes pid file."  The two bugs should probably be fixed at the same time, because both require changing server behavior regarding startup protocol.

obviously it's not an InnoDB bug so changing the category.

The behaviour is just incorrect, and since over time the init phase has become longer (with engines and other subsystems getting started), this now causes trouble.

Very simply, this bit of code needs to be moved to straight when mysqld starts, since the PID file indicates when the process is running, not whether MySQL is ready for connections.

A patch to change when the pid file is created and clean up some of the extra functions that have to do with pid file creation

Attachment: create_pid_file_sooner.patch (application/octet-stream, text), 2.16 KiB.

Bug #45522 was marked as duplicate of this one.

I disagree with the solution suggested in the title, whereas I don't think that the problem has only the solution described in the title.
One more manifestation of solution-oriented reporting, that will not get us closer to solving the real customer issue.
Perhaps a fix can be found in mysqld_safe script, or by holding a different system resource at start up that prevents double innodb startup.

For the record, the previous title was "pid file is created after InnoDB init".

A possible implementation (UNIX only), is to use a pipe, a temporary file, or an IPC key to ensure that no other mysqld is running in a given data directory. 
This resource could be acquired/created early in the startup sequence, as an alternative to the PID file, and not visible to the user.
Windows SDK provides a similar mechanism.

See also Bug#23790.

Bug is nearly 2 years old - any updates?

Introducing another locking mechanism at startup means there will be at least three. The existing advisory file locking and pid file are enough as long as the pid file is moved to be the first thing created on startup and the last thing removed.

Posted by developer:
 
Noted in 5.5.5, 5.6.36, 5.7.18, 8.0.1 changelogs.

Starting multiple instances of mysqld_safe after an abnormal server 
exit could result in one mysqld_safe instance killing another. As a
consequence of the bug fix, the mysqld_safe.pid file is no longer
used.

Correction: Noted in 5.5.55 (not 5.5.5) changelog.